直播一次問題排查過程

（點選上方公眾號，可快速關註）

來源：劉正陽 ，

liuzhengyang.github.io/2017/03/21/jvmtroubleshooting/

現象

收到系統報警，檢視一臺機器頻繁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。

https://github.com/netty/netty/issues/6221

但是simple-rpc框架中沒有使用ssl

檢查netty版本為4.1.7

一個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」，提升Java技能