一则推送api使用不当导致的服务端内存溢出问题分析

  • 2019 年 10 月 7 日
  • 筆記

一直稳定运行的服务突然挂掉了，看了下日志是内存溢出。该服务器的垃圾回收都使用的是默认的，因为访问量目前不大，压根没有优化的必要。初步猜想是有内存泄漏的情况存在，因为该服务一直访问量不大并且已经稳定运行了两月有余。

现象

服务器上出现了这个异常:

查看top结果:

可以看到主要有两个现象:

  • 内存溢出
  • cpu飙到很高

找占用cpu最高的线程

步骤5执行后，发现找到的占用cpu比较高的线程都是GC线程。这也是top出的结果中该进程占用cpu达200%多的原因。这也与报错中的下面这段信息一致:

Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded

GC overhead limt exceed检查是Hotspot VM 1.6定义的一个策略，通过统计GC时间来预测是否要OOM了，提前抛出异常，防止OOM发生。Sun 官方对此的定义是：并行/并发回收器在GC回收时间过长时会抛出OutOfMemroyError。过长的定义是，超过98%的时间用来做GC并且回收了不到2%的堆内存。用来避免内存过小造成应用不能正常工作。

这种问题的一般解决办法是:增加参数，-XX:-UseGCOverheadLimit，关闭这个特性，同时增加heap大小。

执行jmap -heap:

可以看到老年代已经用完。

执行jstat:

可见full gc发生的次数超过想像。

dump堆栈从其他角度分析

  • jmap -dump:live,format=b,file=dump.file 16549 命令dump了一份

dump分析结果为:

可以看到有大量的NioEventLoop线程，导致java.lang.Thread占用很高。

搜索相似问题

  • 搜了一下官网，找到一个类似的:https://discuss.elastic.co/t/netty4utils-fatal-error-on-the-network-layer/149574 给出的解决方案如下:
Following changes in Client JVM fixed this issue(Can you let me know Is this required at java Client end, if yes then it would be nice if you mention this in ES documents for TransportClient):    -Dio.netty.noUnsafe=true  -Dio.netty.noKeySetOptimization=true  -Dio.netty.recycler.maxCapacityPerThread=0  -Dio.netty.allocator.type=unpooled

看了下，这个问题是在elasticsearch 5.X中会出现的，而当前使用的是elasticsearch 6.2版本的，对于这个问题应该是已经修复了的。于是查了一下目前项目中使用的es的transport jar包中client的配置:

发现这几个参数是默认加上的。关于netty配置项的说明可以参考这篇博客:https://www.jianshu.com/p/ed43572052ae

es测试

翻了下es 6.2版本的transportClient的源码，仔细过了一遍流程，发现并没有什么问题。

workCount的值是依据下面这个定的: 

public static final Setting<Integer> WORKER_COUNT =          new Setting<>("transport.netty.worker_count",              (s) -> Integer.toString(EsExecutors.numberOfProcessors(s) * 2),              (s) -> Setting.parseInt(s, 1, "transport.netty.worker_count"), Property.NodeScope);      public static int numberOfProcessors(final Settings settings) {           return PROCESSORS_SETTING.get(settings);    }      public static final Setting<Integer> PROCESSORS_SETTING =            Setting.intSetting("processors", Runtime.getRuntime().availableProcessors(), 1, Property.NodeScope);

netty client端的执行线程数在没有指定的话是根据cpu核数来定的，整个TransportClient使用的又是单例，按理说是不会产生大量的NioEventLoop对象的。

想到排除法，于是写测试用例，运行并监控: EsPoolManager的代码:

测试用例代码:

对于该用例的jmx结果为:

dump堆栈后信息为:

可以看出，只启动elasticsearch的transportClient时，在堆栈中看到的占用内存的是PoolArena对象，没有见到NioEventLoop对象。

对比服务器上的堆栈信息:

发现占用内存最多的NioEventLoop对象并没有出现，这就有点百思不得其解了。

极光推送部分

继续查日志，发现日志中有很多百度极光推送的错误。。。怀疑是不是极光推送的锅。于是查看极光推送的代码。

使用的是极光推送java api的3.2.15 版本，业务代码是直接调用下面的方法进行推送消息的，每发送一条消息都会new一个JPushClient对象。

/**       * 极光推送方法(采用java SDK)       * @param alias       * @param alert       * @return PushResult       */      public static  PushResult push(String alias, String alert){          ClientConfig clientConfig = ClientConfig.getInstance();          JPushClient jpushClient = new JPushClient(masterSecret, appKey, null, clientConfig);          PushPayload payload = buildPushObject_android_ios_alias_alert(alias,alert);          try {              return jpushClient.sendPush(payload);          } catch (APIConnectionException e) {              log.error("Connection error. Should retry later. ", e);              return null;          } catch (APIRequestException e) {              log.error("Error response from JPush server. Should review and fix it. ", e);              log.info("HTTP Status: " + e.getStatus());              log.info("Error Code: " + e.getErrorCode());              log.info("Error Message: " + e.getErrorMessage());              log.info("Msg ID: " + e.getMsgId());              return null;          }      }         /**           * Create a JPush Client by custom Client configuration.           *           * @param masterSecret API access secret of the appKey.           * @param appKey The KEY of one application on JPush.           * @param proxy The proxy, if there is no proxy, should be null.           * @param conf The client configuration. Can use ClientConfig.getInstance() as default.           */          public JPushClient(String masterSecret, String appKey, HttpProxy proxy, ClientConfig conf) {              _pushClient = new PushClient(masterSecret, appKey, proxy, conf);              _reportClient = new ReportClient(masterSecret, appKey, proxy, conf);              _deviceClient = new DeviceClient(masterSecret, appKey, proxy, conf);              _scheduleClient = new ScheduleClient(masterSecret, appKey, proxy, conf);          }

可以看到PushClient的底层使用的是NettyHttpClient，在它的内部:

可以看到代码中: 

_sslCtx = SslContextBuilder.forClient().trustManager(InsecureTrustManagerFactory.INSTANCE).build();              _workerGroup = new NioEventLoopGroup();              b = new Bootstrap(); // (1)              b.group(_workerGroup); // (2)

在NioEventLoopGroup入参中没有传线程数时，默认使用的是cpu核数乘以2:

private static final int DEFAULT_EVENT_LOOP_THREADS;        static {          DEFAULT_EVENT_LOOP_THREADS = Math.max(1, SystemPropertyUtil.getInt(                  "io.netty.eventLoopThreads", NettyRuntime.availableProcessors() * 2));            if (logger.isDebugEnabled()) {              logger.debug("-Dio.netty.eventLoopThreads: {}", DEFAULT_EVENT_LOOP_THREADS);          }      }

由此猜测，如果使用过程中用的不是单例，同时又没有及时关闭释放NioEventLoop线程时的确会出现大量线程产生，出现内存泄漏。

于是开始编写测试代码先定位下是不是这里的问题，测试代码如下:

jmx信息如下:

可以明显看到NioEventLoop线程还在不停地增加。

dump出堆栈信息查看:

右键Find object in a tree view:

仔细看看上图，是不是和服务器上的堆栈信息很像。没错，正是极光推送的锅。

由于极光推送使用的比较多，所以如果这个问题别人没有碰到过，就应该是api使用的问题了，于是打开https://github.com/jpush/jpush-api-java-client,看到很显眼的几行字：

如果使用 NettyHttpClient(v3.2.15 版本新增），需要在响应返回后手动调用一下 NettyHttpClient 中的 close 方法，否则进程不会退出。代码示例：      try {      PushResult result = jpushClient.sendPush(payload);      LOG.info("Got result - " + result);      Thread.sleep(5000);      // 请求结束后，调用 NettyHttpClient 中的 close 方法，否则进程不会退出。      jpushClient.close();  } catch(InterruptedException e) {      e.printStackTrace();  }    3.2.17 版本后，在 PushClient 中添加了 setHttpClient(IHttpClient client) 方法，用户可以自由切换 ApacheHttpClient，NettyHttpClient 或是 NativeHttpClient。

源码中找啊找，还是没找到jPushClient的close方法，只是在NettyHttpClient中找到了一个close方法:

public void close() {          if (null != _channel) {              _channel.closeFuture().syncUninterruptibly();              _workerGroup.shutdownGracefully();              _channel = null;              _workerGroup = null;          }          System.out.println("Finished request(s)");      }

如此一来也不是没有办法，可以在NettyHttpClient的基础上改造，比如添加自己的JPushClient实现，加上close方法或者升级到3.2.17版本都是可以的。

最终选择和上面的TransportClient一样使用单例，再进行测试：测试代码:

jmx信息:

可见，使用单例JPushClient之后，NioEventLoop线程数量不再暴增，最多等于cpu的核数*2并保持恒定。堆栈信息这里就不再进行分析了。

总结

整个问题的原因已经很清晰了，就是没有能正确使用极光推送api，导致极光推送底层使用的NettyHttpClient被大量创建，每个NettyHttpClient中的NioEventLoop线程也没大量创建并处理存活状态。这些对象进入老 年代后没法进行回收，这样垃圾回收线程就会一直高频率尝试回收，如同死循环一般，导致内存溢出的同时，cpu占用率也飙到很高。感慨的是，小公司，每个人都很忙，没有代码review也是很坑的一件事情。

VirMach 便宜 VPS

QNews

QNews