直播一次问题排查过程

标签： 未分类 GC JVM | 发表时间：2018-05-14 21:16 | 作者：TiuVe2
出处：http://www.importnew.com

现象

收到系统报警，查看一台机器频繁FULLGC，且该服务超时。
这是一台4核8G的机器, 使用jdk1.8.0_45-b14。

我们可以直接通过jstat等来观察。这次我先通过CPU开始。
top查看后该java进程的运行状况为

Tasks: 161 total,   3 running, 158 sleeping,   0 stopped,   0 zombie
Cpu(s): 32.1%us,  1.9%sy,  0.0%ni, 65.9%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:   8059416k total,  7733088k used,   326328k free,   147536k buffers
Swap:  2096440k total,        0k used,  2096440k free,  2012212k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
15178 x   20   0 7314m 4.2g  10m S 98.9 55.1   4984:05 java

RES 占用4.2g CPU占用98%

top -H -p 15178

后发现

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
15234 x   20   0 7314m 4.2g  10m R 70.2 55.1 781:50.32 java
15250 x   20   0 7314m 4.2g  10m S 52.9 55.1 455:12.27 java

一个PID为 15234 的轻量级进程，对应于java中的线程的本地线程号。
通过 printf '%x\n' 15234计算出16进制的 3b82
通过jstack -l 15178 然后搜索该线程,发现其为
"Concurrent Mark-Sweep GC Thread" os_prio=0 tid=0x00007ff3e4064000 nid=0x3b82 runnable

定位了确实由GC导致的系统不可用。

jinfo -flags

查看该VM参数

Non-default VM flags: -XX:CICompilerCount=3 -XX:CMSFullGCsBeforeCompaction=0 -XX:CMSInitiatingOccupancyFraction=80 -XX:+DisableExplicitGC -XX:ErrorFile=null -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=null -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=348913664 -XX:MaxTenuringThreshold=6 -XX:MinHeapDeltaBytes=196608 -XX:NewSize=348913664 -XX:OldPLABSize=16 -XX:OldSize=1798569984 -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCMSCompactAtFullCollection -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC

jmap -heap 查看统计结果

Debugger attached successfully.
Server compiler detected.
JVM version is 25.45-b02
using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC
Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 2147483648 (2048.0MB)
   NewSize                  = 348913664 (332.75MB)
   MaxNewSize               = 348913664 (332.75MB)
   OldSize                  = 1798569984 (1715.25MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)
Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 314048512 (299.5MB)
   used     = 314048512 (299.5MB)
   free     = 0 (0.0MB)
   100.0% used
Eden Space:
   capacity = 279183360 (266.25MB)
   used     = 279183360 (266.25MB)
   free     = 0 (0.0MB)
   100.0% used
From Space:
   capacity = 34865152 (33.25MB)
   used     = 34865152 (33.25MB)
   free     = 0 (0.0MB)
   100.0% used
To Space:
   capacity = 34865152 (33.25MB)
   used     = 0 (0.0MB)
   free     = 34865152 (33.25MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 1798569984 (1715.25MB)
   used     = 2657780412087605496 (2.5346569176555684E12MB)
   free     = 15057529128475 MB
   1.4777186518907263E11% used
32778 interned Strings occupying 3879152 bytes.

使用 jstat -gcutil 15178 1s观察一段时间GC状况

jstat -gccause 15178 1s
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT    LGCC                 GCC
100.00   0.00 100.00 100.00  97.78  95.59   1906   26.575 61433 217668.188 217694.763 Allocation Failure   Allocation Failure
  0.00   0.00  96.51 100.00  97.78  95.59   1906   26.575 61433 217672.991 217699.566 Allocation Failure   No GC
100.00   0.00 100.00 100.00  97.78  95.59   1906   26.575 61434 217672.991 217699.566 Allocation Failure   Allocation Failure
100.00   0.00 100.00 100.00  97.78  95.59   1906   26.575 61434 217672.991 217699.566 Allocation Failure   Allocation Failure
100.00   0.00 100.00 100.00  97.78  95.59   1906   26.575 61434 217672.991 217699.566 Allocation Failure   Allocation Failure

可以看到Old区满了，并且Eden区域的对象没有触发YGC直接晋升到Old区中，但是Full GC没有释放出空间。这是由于在当老年代的连续空间小于新生代所有对象大小时，MinorGC前会检查下平均每次晋升到Old区的大小是否大于Old区的剩余空间，如果大于或者当前的设置HandlePromotionFailure为false则直接触发FullGc,否则会先进行MinorGC。
关于FullGC和MajorGC的区别，可以不要太纠结.

jmap -histo 15178 | less 查看一下对象实例数量和空间占用
看到前面的一种数据各占用几百兆内存。总和在1935483656，和堆空间基本相同。

num     #instances         #bytes  class name
----------------------------------------------
   1:      14766305      796031864  [C
   2:      14763842      354332208  java.lang.String
   3:       8882440      213178560  java.lang.Long
   4:       1984104      174601152  com.x.x.x.model.Order
   5:       3994139       63906224  java.lang.Integer
   6:       1984126       63492032  java.util.concurrent.FutureTask
   7:       1984371       47624904  java.util.Date
   8:       1984363       47624712  java.util.concurrent.LinkedBlockingQueue$Node
   9:       1984114       47618736  java.util.concurrent.Executors$RunnableAdapter
  10:       1984104       47618496  com.x.x.fyes.service.impl.OrderServiceImpl$$Lambda$11/284227593
  11:        262144       18874368  org.apache.logging.log4j.core.async.RingBufferLogEvent
  12:          7841       15312288  [B
  13:         17412        8712392  [Ljava.lang.Object;
  14:        262144        6291456  org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapper
  15:         12116        4299880  [I
  16:         99594        3187008  java.util.HashMap$Node
  17:         16318        1810864  java.lang.Class
  18:          2496        1637376  io.netty.util.internal.shaded.org.jctools.queues.MpscArrayQueue
  19:         49413        1185912  java.net.InetSocketAddress$InetSocketAddressHolder
  20:         49322        1183728  java.net.InetAddress$InetAddressHolder
  21:         49321        1183704  java.net.Inet4Address
  22:          6116        1134384  [Ljava.util.HashMap$Node;
  23:         49412         790592  java.net.InetSocketAddress
  24:          6249         549912  java.lang.reflect.Method
  25:         11440         457600  java.util.LinkedHashMap$Entry
  26:           704         431264  [Ljava.util.WeakHashMap$Entry;
  27:         12680         405760  java.util.concurrent.ConcurrentHashMap$Node
  28:          6286         352016  java.util.LinkedHashMap
  29:          9272         296704  java.lang.ref.WeakReference
  30:           139         281888  [Ljava.nio.channels.SelectionKey;
  31:           616         258464  [Ljava.util.concurrent.ConcurrentHashMap$Node;
  32:          5709         228360  java.lang.ref.SoftReference
  33:          3840         217944  [Ljava.lang.String;
  34:          4493         215664  java.util.HashMap
  35:            65         210040  [Ljava.nio.ByteBuffer;
  36:           859         188144  [Z
  37:          5547         177504  java.util.concurrent.locks.ReentrantLock$NonfairSync
  38:          4391         175640  java.util.TreeMap$Entry
  39:           404         174400  [Lio.netty.util.Recycler$DefaultHandle;
  40:          4348         173920  java.util.WeakHashMap$Entry
  41:          4096         163840  org.jboss.netty.util.internal.ConcurrentIdentityHashMap$Segment
  42:          2033         162640  java.lang.reflect.Constructor
  43:          6489         155736  java.util.ArrayList
  44:          3750         150000  java.lang.ref.Finalizer

主要寻找这个列表中的业务对象和集合对象
其中的 Order和 OrderServiceImpl$$Lambda$11/284227593引起了我的注意。
找到该位置代码后，其代码为

private ExecutorService executorService = Executors.newFixedThreadPool(10, new DefaultThreadFactory("cacheThread"));
    @Override
    public Order save(Order order) {
        order.setCreated(new Date(order.getCreateTime()));
        Order save = orderRepository.save(order);
        executorService.submit(() -> {
            orderCacheService.cacheOrder(save);
            OrderModel orderModel = new OrderModel();
            BeanUtils.copyProperties(save, orderModel);
            Result result = fyMsgOrderService.saveOrder(orderModel);
            LOGGER.info("Msg Return {}", JSON.toJSONString(result));
        });
        return save;
    }

大体逻辑是先保存到ES中，然后使用线程数量无界队列大小为10的固定线程池执行保存到远程缓存以及使用RPC发送给另一个服务。
这段代码写的有些随性。
dump后等待下载dump文件的同时, 在thread stack中查找这个方法所在类的相关线程状态
基本如下所示:

"cacheThread-1-3" #152 prio=5 os_prio=0 tid=0x00007ff32e408800 nid=0x3c24 waiting on condition [0x00007ff2f33f4000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x0000000089acd400> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
        at com.github.liuzhengyang.simplerpc.core.RpcClientWithLB.sendMessage(RpcClientWithLB.java:251)
        at com.github.liuzhengyang.simplerpc.core.RpcClientWithLB$2.invoke(RpcClientWithLB.java:280)
        at com.sun.proxy.$Proxy104.saveOrder(Unknown Source)
        at com.x.x.fyes.service.impl.OrderServiceImpl.lambda$save$0(OrderServiceImpl.java:48)
        at com.x.x.fyes.service.impl.OrderServiceImpl$$Lambda$11/284227593.run(Unknown Source)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
        at java.lang.Thread.run(Thread.java:745)
   Locked ownable synchronizers:
        - <0x00000000990675e8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

可见很多线程都在发送完成RPC请求后，在RPC结果队列中等待该消息返回结果。
这时查看RPC提供者的状态, 服务所在机器的负载比较低，该提供者的日志已经不再刷新，但是curl localhost:8080能得到相应。最后的几行日志中显示

2017-03-18 19:19:38.725 ERROR 17977 --- [ntLoopGroup-3-1] c.g.l.simplerpc.core.RpcServerHandler    : Exception caught on [id: 0xa104b32a, L:/10.4.124.148:8001 - R:/10.12.74.172:53722],
io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 16777216 byte(s) of direct memory (used: 1828716544, max: 1834483712)
    at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:631) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:585) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:709) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.buffer.PoolArena$DirectArena.newChunk(PoolArena.java:698) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:237) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.buffer.PoolArena.allocate(PoolArena.java:213) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.buffer.PoolArena.allocate(PoolArena.java:141) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:287) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:179) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:170) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:131) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:73) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:117) ~[netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:642) [netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:565) [netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:479) [netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:441) [netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144) [netty-all-4.1.7.Final.jar!/:4.1.7.Final]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_45]
2017-03-18 19:19:38.725  INFO 17977 --- [ntLoopGroup-3-1] io.netty.handler.logging.LoggingHandler  : [id: 0xa104b32a, L:/10.4.124.148:8001 - R:/10.12.74.172:53722] CLOSE
2017-03-18 19:19:38.725  INFO 17977 --- [ntLoopGroup-3-1] io.netty.handler.logging.LoggingHandler  : [id: 0xa104b32a, L:/10.4.124.148:8001 ! R:/10.12.74.172:53722] INACTIVE
2017-03-18 19:19:38.725  INFO 17977 --- [ntLoopGroup-3-1] io.netty.handler.logging.LoggingHandler  : [id: 0xa104b32a, L:/10.4.124.148:8001 ! R:/10.12.74.172:53722] UNREGISTERED

可见在申请DirectMemory时遇到了OOM Error，这个异常是netty内部的异常，所以没有导致进程退出。。google该异常message后发现了很多类似的关于netty的issue。

一个ThreadExecutor的包括引用的总大小占据了1.7g，查看引用该对象的线程的线程栈和之前猜测的一致。

这个实例的ourgoing reference中指向workQueue的大小基本占据了1.7g。这也提醒了我们在使用Executor或Queue要考虑队列的长度问题，是否要设计长度以及溢出时如何处理。

但是第二个系统的内存状况很奇怪，heap各个区域都很少，异常日志显示DirectMemory申请失败。dump下的内存只有500M左右，top中查看进程使用的物理内存在2.6G左右。查看异常处代码可以看到当没有使用 io.netty.maxDirectMemory参数设置Netty最大使用的DirectMemory大小时。会自动选择一个最大大小。
在线程栈中可以看出这个发生在Accecptor收到Selector可处理任务后，在其中读数据时，为什么会申请16777216bytes 大约在16M的一个直接内存呢？
在其中的 AbstractNioByteChannel中

byteBuf = allocHandle.allocate(allocator);

而allocHandle的实现 DefaultMaxMessagesRecvByteBufAllocator

@Override
public ByteBuf allocate(ByteBufAllocator alloc) {
    return alloc.ioBuffer(guess());
}

申请buffer的initialCapacity是通过guess()方法得到的。
guess实现在 AdaptiveRecvByteBufAllocator中，这个类通过反馈的方式调整下次申请的buffer大小。调整的大小数组是前32小的值都是每次增加16byte, 达到512byte后按照每次乘二的方式。如果实际读到的数据小于上一个数组位置的值，下次申请回收缩，相反大于后面的数组位置时也会进行增加，不过增加的间隔是4，也就是出现16M的情况之前的申请大小是1M并且实际读到的数据大于等于2M。

上述日志表明，当前已经申请的DirectMemory加上将要申请的16M左右DirectMemory超过了1.8G的DirectMemoryLimit。

那netty中使用的DirectByteBuffer什么时候进行释放呢,需要仔细研究下netty代码了。
可以在 PlatformDependent中看到与 incrementMemoryCounter相对的还有 decrementMemoryCounter方法负责减少DIRECT_MEMORY_COUNTER的值，其中 freeDirectNoCleaner方法调用了 UNSAFE.freeMemory(address)进行直接内存的释放, 跟踪调用链找到了 PoolArena的free和reallocate方法，reallocate会在PooledByteBuf中调用capacity进行。

现在通过设置-Dio.netty.maxDirectMemory=0并增加-Dio.netty.leakDetectionLevel=advanced继续观察。

附一段查看JDK8的DirectMemory的程序  https://gist.github.com/liuzhengyang/a0d25510d706c6f4c0805b367ad502da ，使用方式见 https://gist.github.com/rednaxelafx/1593521

相关文章

相关 [直播 问题] 推荐：

直播一次问题排查过程

- - ImportNew
收到系统报警，查看一台机器频繁FULLGC，且该服务超时. 这是一台4核8G的机器, 使用jdk1.8.0_45-b14. 我们可以直接通过jstat等来观察. top查看后该java进程的运行状况为. RES 占用4.2g CPU占用98%. TIME+ COMMAND 15234 x 20 0 7314m 4.2g 10m R 70.2 55.1 781:50.32 java 15250 x 20 0 7314m 4.2g 10m S 52.9 55.1 455:12.27 java.

现场直播

- 纸条 - 新闻跟帖局
核心提示：8月29日上午，福建气象台发布“沿海地区台风警报”与“台风黄色预警信号”称，台风“南玛都”可能于30日白天在福建省中南部沿海登陆. 受台风影响，福建自29日起3日内多地将有大雨到暴雨. [查看原文]好友向您推荐这条跟贴. 网易福建省泉州市网友 [小小小书童] 的原贴：1. 你好，主持人，我现在在泉州惠安西沙湾，现在风力非常大，屁股对准海边保你菊花都被吹开，现场的情况就是这样，现在把画面交给演播室.

E3大展直播

- 杯子 - 译言-电脑/网络/数码科技
来源Live from Microsoft\'s E3 2011 keynote!.   1:59PM 是否期待今年用声控操作Xbox上的一切呢.   1:58PM 2012年假期发布.    1:57PM Xbox 360新纪元即将到来  .   1:56PM 使命召唤的下载内容将会首先登陆XBOX 360.

HTML5 视频直播（一）

- - JerryQu 的小站
前不久工作中遇到了在移动 WEB 端直播视频的需求，研究了一下相关技术，记录一下. 目前 WEB 上主流的视频直播方案有 HLS 和 RTMP，移动 WEB 端目前就只有 HLS 能用，我们重点介绍它. HTTP Live Streaming（简称 HLS）是一个基于 HTTP 的视频流协议，由 Apple 公司实现，Mac OS 上的 QuickTime、Safari 以及 iOS 上的 Safari 都能很好的支持 HLS，高版本 Android 也增加了对 HLS 的支持.

[原]用RED5做直播

- - 上善若水 厚德载物
服务端用Java web或red5 server即可，直播和收看都是用Flash Builder 4做的flash. red5最新版已经更新到1.0.5 ，需要JDK8的支持. RED5主页： https://github.com/Red5. 服务器端用Java做web工程，主类继续ApplicationAdapter 空实现即可.

Web 直播流的解析

- - IT瘾-geek
Web 进制操作是一个比较底层的话题，因为平常做业务的时候根本用不到太多，或者说，根本用不到. 现在比较流行的就是音视频的处理，怎么说呢. 如果，有涉及直播的话，那么这应该就是一个非常. 我这里就不废话了，先主要看一下里面的基础内容. 首先，一开始我们是怎么接触到底层的 bit 流呢. 记住：只有一个对象我们可以搞到 bit 流 --> ArrayBuffer.

WebRTC 点对点直播

- - SegmentFault 最新的文章
摘自： villainhr. WebRTC 全称为： Web Real-Time Communication. 它是为了解决 Web 端无法捕获音视频的能力，并且提供了 peer-to-peer（就是浏览器间）的视频交互. 实际上，细分看来，它包含三个部分：. MediaStream:捕获音视频流.

[直播]正直播CNN乔布斯逝世特别报道

- 洞箫 - cnBeta.COM
现在正在直播美国CNN的乔布斯逝世特别报道. 点击进入直播间（iOS用户暂不可观看）（海外入口）.

稿费问题

- Ruixing F - 创造社新任社长宋石男
据说现在全中国靠给平媒自由撰稿为生的，超不过1000人，而且不少处于相当窘迫的境况，就算想买根绳子来上吊，都买不起质量好的，结果绳子老断. 作为自由撰稿人的一员，我对此深有体会. 1999年国家版权局出台的基本稿酬标准，每千字30元-100元，至今仍为全国发行的报刊的“行业指导价”. 业内估计，全国报刊的稿费中位数大约也就在100元.

lvs 问题

- - 操作系统 - ITeye博客
1： LVS连接的持久时间. 1）同一个ip发来请求到同一台RS的持久超时时间. ipvsadm -A -t 192.168.169.100:80 -s rr -p 120     #该客户的请求120秒内被分配给同一台web.  2）一个链接创建后空闲时的超时时间（分别是：tcp的空闲超时时间、lvs收到客户端tcp fin的超时时间、udp的超时时间）.