定时任务背景

团队负责的一个后端服务某天环境出现无法启动的现象，本文通过此次问题排查，引出一些开发规范问题。

现象

  • 测试环境部署后端服务一直无法启动；但是main.log没有任何异常信息
  • 怀疑可能是启动时内存溢出。查看日志目录发现，多了很多hprof文件，起初怀疑可能是Metaspace溢出问题
  • 但是这个项目的类很少，按理说不至于Metaspace溢出，于是查看stdout.log日志文件发现：java.lang.OutOfMemoryError: Java heap space… 竟然是堆内存溢出
  • 但是以我对此服务的了解，更不应该出现启动时堆内存溢出的现象

  • 开始分析hprof内存文件

  • 先看下概况

com.mysql.jdbc.JDBC42ResultSet竟然占了2.08G，main线程也占了2.63G

JDBC42ResultSet一定是某个sql查了一堆数据返回的结果

  • 再去支配树里找一下线索：先层层打开内存占用最大的主线程，找找线索，看看内存里都是哪些业务类的实例：里面竟然有7138519个LinkedCaseInsensitiveMap，但是这个不是我们项目里定义的业务实例，这是spring的JDBCTemplate用来放查询结果的，依然定位不了问题，怀疑有某个逻辑SELECT了某张表中所有数据

    ，找到sql

  • 全局搜索sql，发现是项目中的一个Scheduled定时任务调用了上图的查询sql。好家伙，原来这个后端项目里有这么多@Scheduled定时任务！

    为什么会项目启动时执行？

    因为上图左侧scheduler包下的所有定时任务都是用@Scheduled注解方式开发，并用了fixedRate参数配置定时触发（fixedRate作用：任务运行后隔多久再次触发）。而第一次触发时间就是项目刚启动完时候。

    这些定时任务都在后端服务里执行。

    这会导致以下问题：

    • 如果有一个任务会出现OOM，那么此项目启动后将会直接OOM，然后重启后再次OOM（就是这次的现象）

    • 即使各个任务都不会出现OOM，那么由于代码中有多个Scheduled，可能同时执行时内存膨胀导致OOM

    • 某个任务如果出现一些其他不可预料的问题，那么将直接影响到后端服务的稳定性

    • 后端服务多实例导致定时任务重复执行

    • 定时任务执行时不断刷日志，影响后端服务线上问题排查

      规范

  • 批量查询处理数据时，如果后续数据量可能膨胀过多，应使用分页查询处理，防止OOM

  • 避免在后端服务里使用@Scheduled注解开发定时任务，应按照公司任务调度平台的API开发接入并单独部署

转码服务背景

有业务方反馈图片转码服务大量失败, 持续10分钟左右, 之后就恢复, 失败返回的错误中有oom异常. 收到反馈第一时间查看了机器的日志, 发现日志中并没有异常.最后从内存监控和重启日志的时间点上来看服务发生了重启.

在没有找到OOM发生时的现场的情况下, 可以通过查看运行时的内存信息来定位内存问题, 因为OOM的发生, 是由于java对象大量积压在老生代无法回收导致的, 通常这个积压的过程会持续相对较长的一段时间, 才会发生OOM. 大部分情况下, 不会出现之前一直是正常的, 在短时间内积压大量无法回收的java对象的情况.所以,可以通过下面的三个命令来排查问题.

jmap - heap 显示Java堆详细信息， Heap Configuration展示的是jvm的设置,Heap Usage是堆内存的使用情况, 其中G1 heap是总体情况, G1 Young Generation是年轻代内存情况, G1 Old Generation是老年代内存情况.

jmap -histo

查看指定pid的java进程中, java对象的内存占用量(从大到小排序), 可以持续的观察, 关注那些长时间无法回收的java对象, 或者数量明显异常偏多的java对象.

jmap -histo:live 来手动触发一次Full GC

通过上面的排查我们推测jvm可能不是自己OOM挂掉了, 于是, 我们使用dmesg -T来参看是否有java进程被kill的记录,通过上面的信息,发现JVM确实是被kill掉了, 时间点也与最上面图1系统监控中重启的时间点相吻合.而JVM被kill掉的原因是FFmpeg在申请内存的时候, 系统发现内存不足, 申请不到内存了, 于是, 通过计算的权重kill掉了占用最多内存的JVM.

其中重要的参数有2个:

-XX:InitialRAMPercentage=60 // JVM初始堆内存分配为容器内存的60%

-XX:MaxRAMPercentage=60, // JVM最大堆内存分配为容器内存的60%

而容器内存是16G, JVM启动就申请了8192M, 然后其他配置MetaSpace申请了512M, 堆外内存申请了2G,然后容器本身还需要占用一部分内存, 这样最后剩下的内存就不多了, 转码服务需要执行大量的FFmpeg命令,这些都是独立启动一个进程来执行的,FFmpeg的执行也需要大量的内存, 这样就导致了, FFmpeg在执行的时候申请不到内存,然后, 系统就kill掉了JVM的进程.

解决

在我们的例子中主要是JVM占用了太多内存导致的, 解决的思路有两个, 第一种: 直接调整MaxRAMPercentage减少最大内存, 简单直接. 第二种: 由于我们的内存回收很健康, 所以可以调整-XX:InitialRAMPercentage为40, 这样就不会启动就申请60%, 而是申请40%, 在运行过程中, 由于内存在GC的时候可以正常回收, 所以不会有占满60%的情况