排查load过高/gc过久问题

最新推荐文章于 2024-10-25 11:25:48 发布

hh6plus

最新推荐文章于 2024-10-25 11:25:48 发布

阅读量1.1k

点赞数 2

分类专栏：运维

运维专栏收录该内容

16 篇文章

订阅专栏

转载自：http://ju.outofmemory.cn/entry/149977
当jvm的gc很久+很频繁时，会导致服务load高，服务5xx响应明显增多等问题。
通过dump+MAT可以排查为什么生成了这么多garbage。（jmap使用：https://blog.youkuaiyun.com/ligeforrent/article/details/70474203）
MAT中Overview可能很小只有几十M，是因为Overview只显示有GCRoot的对象。
unreachable_objects可能会有成百上千M，里面都是可被回收的garbage。可以和jmap -histo pid 给出的占用信息相互印证。但是也有可能都是eden区的不必过分担心的对象，混淆视野。所以需要在fgc前，和fgc后ygc前，分别jmap一次，进行比对。
unreachable_objects无法分析持有关系，但是通过Overview中的持有关系，可以推测garbage生前的情况。
以下是原文。

mem dump中unreachable objects分析

Xunjun Yin 2014-12-08 291 阅读

dump

现象

某个大版本上线后，某服务频繁报警: load过高，但很快就会恢复，即间歇性load过高，原因难以定位。

观察

从报警系统观察报警时间分布，有一些周期性，但周期会在1小时到2小时之间，不稳定
- 初步排除是定时任务导致
观察gc日志，发现报警时间点与gc时间开销较高的点比较吻合，因此着重观察GC
发现JVM GC相关的配置不是很合理，做了简单的优化：将old区的并行收集改为CMS，情况有所改善，但问题依然存在
该现象是上线后才出现的，可以认定是业务逻辑所致。着重查看了业务逻辑的diff，因业务逻辑改动较多，未能直接找到原因。
既然是GC所致，就先看看GC为何这么慢吧！

初步定位

用jmap做了两份内存的dump，一份是old快满（用jstat来实时观察）即即将发生full gc之前的dump，另一份是GC刚刚结束的dump
- 这样可以明显地对二者做对比。
用mat打开（在机群上开了个vncserver，在本地用vncviewer连接上）两份dump,发现两份dump中reachable objects均只有400m不到，而unreachable objects有3G多
观察unreachable objects，按shallow heap大小排序，忽略byte和char等基本类型（复杂类型数据都是由基本类型组成的）发现TreeMap占了300M+，让人怀疑。
然而因为是unreachable的，无法直接查看这些TreeMap对象的上用。如何才有知道到底谁引用它们呢？在代码里grep了一下，发现自己项目中没有任何地方用到TreeMap，从页抢断应该是第三方库用到的。
从另外一个角度考虑，我可以先看一下reachable objects中TreeMap的引用。
发现其中对treeMap有引用的对象中，个数较多的是JDBC4ResultSet和ShardedJedis。先看前者在unreachable objects中的情况，共有22158个垃圾对象。
在mat的dominator tree中看JDBC4ResultSet的大小，可以知道每个JDBC4ResultSet的retained heap大小为4.928k（也有不同，但出入不大），从而22158个的retained heap大小为22158 * 5k 约100M，远小于heap区的大小，因此不是造成问题的原因，忽略。
再看后者ShardedJedis，从unreachable objects中可以看到共有4214个垃圾对象。
同时从dominator tree中可以看出每个ShardedJedis的Retained heap大小为323k,从而4214个的retained heap大小的4214*323k约为1.4G
至此，可以基本认定sharedeJedis为主要的垃圾，load间歇性过高的原因正是因为这些垃圾快速的生成和回收所致。

进一步分析

看一下我们对SharededJedisPool的配置：

  #最大分配的对象数
  redis.pool.maxActive=500
  #最大能够保持idel状态的对象数
  redis.pool.maxIdle=100
  #当池内没有返回对象时，最大等待时间
  redis.pool.maxWait=200
  #当调用borrow Object方法时，是否进行有效性检查
  redis.pool.testOnBorrow=false
  #当调用return Object方法时，是否进行有效性检查
  redis.pool.testOnReturn=false

该配置与dump中的pool配置一致。
通过netstat grep redisserver的端口，可以查到只有100个连接，即可预估在“够用”的情况下，redis的连接池中通常只会有100个左右（大多为空闲）
那么问题来了：为什么会有这么多ShardedJedis的垃圾呢？
我们redis连接池是用GenericObjectPool来管理的, 需要时从里面借(borrow object)，用完了再还回去(return object)。如果借的时候不够，就会new一个SharededJedis来给借用者。同时还有一个清理机制，每隔一段时间去把多余的空闲对象清理掉。从上图中可以看出，这个清理机制的间隔时间_timeBetweenEvictionRunsMills是30000ms，即30s.

进一步，这些ShardedJedis能度过Young GC并进入old区，必然是在young区gc时没有被清理，从而可推断该进程做一次young GC的周期会远小于GenericObjectPool的清理周期。用jstat –gctuil查看：

  [love@love21 ~]$ jstat -gcutil 21416 1000
    S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT
.67   0.00  43.38  16.74  52.69  56012 2064.246   143   24.948 2089.193
.67   0.00  77.59  16.74  52.69  56012 2064.246   143   24.948 2089.193
.00   7.91   1.92  16.84  52.69  56013 2064.278   143   24.948 2089.225
.00   7.91  34.35  16.84  52.69  56013 2064.278   143   24.948 2089.225
.00   7.91  64.58  16.84  52.69  56013 2064.278   143   24.948 2089.225
.00   7.91  78.19  16.84  52.69  56013 2064.278   143   24.948 2089.225
.43   0.00   0.00  16.90  52.69  56014 2064.311   143   24.948 2089.258
.43   0.00  22.36  16.90  52.69  56014 2064.311   143   24.948 2089.258
.43   0.00  55.95  16.90  52.69  56014 2064.311   143   24.948 2089.258
.43   0.00  90.86  16.90  52.69  56014 2064.311   143   24.948 2089.258
.00   8.99  18.07  16.95  52.69  56015 2064.344   143   24.948 2089.292
.00   8.99  51.25  16.95  52.69  56015 2064.344   143   24.948 2089.292
.00   8.99  72.06  16.95  52.69  56015 2064.344   143   24.948 2089.292
.00   8.99  92.20  16.95  52.69  56015 2064.344   143   24.948 2089.292
.41   0.00  30.01  17.07  52.69  56016 2064.379   143   24.948 2089.326
.41   0.00  65.24  17.07  52.69  56016 2064.379   143   24.948 2089.326
.41   0.00  97.34  17.07  52.69  56016 2064.379   143   24.948 2089.326

可以看到约5s左右就会进行一次young GC，与推断相符。
现在，基本有了一些思路：1. 业务中有向GenericObjectPool borrow大量的object(应该远大于100)的逻辑，2. 并且很可能是定时性的任务(crontab 或 scheduleTask).

结合上述两点并结合代码最新的改动，发现有地方将获取50个数据对象改为了获取250个，而为了提交性能，会用future模式开多个线程并发向一个ThreadPoolExecutor 提交大量的任务，并且该任务对redis有请求操作，而这个ThreadPoolExecutor的coreSize是200(注意，远大于redis pool的100):

  private static final ThreadPoolExecutor executor = new ThreadPoolExecutor(200, 400, 3600, TimeUnit.SECONDS, 
          new LinkedBlockingQueue<Runnable>(500), new ThreadFactory() {
              private AtomicInteger id = new AtomicInteger(0);
              @Override
              public Thread newThread(Runnable r) {
                  Thread thread = new Thread(r);
                  thread.setName("Love-" + id.addAndGet(1));
                  return thread;
              }
          }, new ThreadPoolExecutor.CallerRunsPolicy());