一次堆外OOM問題的排查過程

阿新 • • 發佈：2018-12-30

背景

線上服務有一臺機器訪問不通（一個管理平臺),在公司的服務治理平臺上檢視服務的狀況是正常的，說明程序還在。程序並沒有完全crash掉。去線上檢視機器日誌，發現了大量的OOM異常:

017-03-15 00:00:00.041 [WARN] qtp1947699202-120772 nio handle failed
java.lang.OutOfMemoryError: Direct buffer memory
        at java.nio.Bits.reserveMemory(Bits.java:658) ~[?:1.7.0_76]
        at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123) ~[?:1.7.0_76]
        at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:306) ~[?:1.7.0_76]
        at sun.nio.ch.Util.getTemporaryDirectBuffer(Util.java:174) ~[?:1.7.0_76]
        at sun.nio.ch.IOUtil.read(IOUtil.java:195) ~[?:1.7.0_76]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379) ~[?:1.7.0_76]
        at org.eclipse.jetty.io.nio.ChannelEndPoint.fill(ChannelEndPoint.java:235) ~[jetty-io-8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint.fill(SelectChannelEndPoint.java:326) ~[jetty-io-8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.http.HttpParser.fill(HttpParser.java:1040) ~[jetty-http-8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:280) ~[jetty-http-8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235) ~[jetty-http-8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82) ~[jetty-server-8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:628) [jetty-io-8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52) [jetty-io-8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608) [jetty-util-8.1.10.v20130312.jar:8.1.10.v20130312]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543) [jetty-util-8.1.10.v20130312.jar:8.1.10.v20130312]
        at java.lang.Thread.run(Thread.java:745) [?:1.7.0_76]
        at java.lang.Thread.run(Thread.java:745) [?:1.7.0_76]

2017-03-15 00:00:00.718 [WARN] elasticsearch[Thundra][transport_client_worker][T#6]{New I/O worker #6} AbstractNioSelector Unexpected exception in the selector loop.
java.lang.OutOfMemoryError: Direct buffer memory
        at java.nio.Bits.reserveMemory(Bits.java:658) ~[?:1.7.0_76]
        at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123) ~[?:1.7.0_76]
        at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:306) ~[?:1.7.0_76]
        at org.jboss.netty.channel.socket.nio.SocketReceiveBufferAllocator.newBuffer(SocketReceiveBufferAllocator.java:64) ~[netty-3.10.5.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.SocketReceiveBufferAllocator.get(SocketReceiveBufferAllocator.java:41) ~[netty-3.10.5.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:62) ~[netty-3.10.5.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108) ~[netty-3.10.5.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337) [netty-3.10.5.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89) [netty-3.10.5.Final.jar:?]
        at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) [netty-3.10.5.Final.jar:?]
        at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty-3.10.5.Final.jar:?]
        at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) [netty-3.10.5.Final.jar:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [?:1.7.0_76]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [?:1.7.0_76]
        at java.lang.Thread.run(Thread.java:745) [?:1.7.0_76]

可以發現是Direct buffer memory的native memory滿了，無法分配堆外記憶體。由於jetty使用的是nio，nio裡面大量的使用native memeory。無法分配native memory之後，導致所有的請求都無效

排查

趕快去看了下監控系統上面記憶體和執行緒的一些監控指標

檔案描述符、runable執行緒數、directbuffer 已經達到了2G（我們-Xmx的值），老年代已經1G多了。但是沒有fullGC。youngc次數也不是很多，但是出現問題的機器young gc明顯比沒出現問題的機器多

根據上面的指標，初步定位是由執行緒建立的網路連線造成了native memory不夠。最上面的log日誌顯示除了jetty之外還有一個就是ElasticSearch client的worker執行緒也出現的分配OOM。回想上次開發新功能的時候，會建立大量的ES client連線，會不會是這個問題。檢視程式碼發現確實是因為建立了大量的ES連線，但是並沒有主動close掉。導致執行緒數暴增，由於ElasticSearch client是用的netty做的網路層，使用了大量的DirectByteBuffer.引用一直存在(client執行緒一直存在)，無法GC掉，DirectByteBuffer物件，導致native memory也無法回收。下圖是用jprofile測試ElasticSearch client的時候發現的。可以得到的是ElasticSearch client確實會產生大量的DirectByteBuffer

old gen為什麼會多呢？

那為什麼old gen的物件這麼多呢？其實就是一大堆的bytebuffer冰山物件進入了oldgen ，然而fullgc都沒有發生，bytebuffer不會被回收，但是這個時候native memory已經被分配完了，所以OOM了。查了資料發現我們在JVM引數中添加了這個:-XX:+DisableExplicitGC.這個引數會導致顯示呼叫System.gc()無效。然而在分配native memory中有這樣一段程式碼:

// These methods should be called whenever direct memory is allocated or
// freed.  They allow the user to control the amount of direct memory
// which a process may access.  All sizes are specified in bytes.
static void reserveMemory(long size, int cap) {
    synchronized (Bits.class) {
        if (!memoryLimitSet && VM.isBooted()) {
            maxMemory = VM.maxDirectMemory();
            memoryLimitSet = true;
        }
        // -XX:MaxDirectMemorySize limits the total capacity rather than the
        // actual memory usage, which will differ when buffers are page
        // aligned.
        if (cap <= maxMemory - totalCapacity) {
            reservedMemory += size;
            totalCapacity += cap;
            count++;
            return;
        }
    }
    //提醒jvm該gc了，回收下死掉的物件
    System.gc();
    try {
        Thread.sleep(100);
    } catch (InterruptedException x) {
        // Restore interrupt status
        Thread.currentThread().interrupt();
    }
    synchronized (Bits.class) {
        //計算可分配的是否已經超過maxMemeory，超過則丟擲OOM異常
        if (totalCapacity + cap > maxMemory)
            throw new OutOfMemoryError("Direct buffer memory");
        reservedMemory += size;
        totalCapacity += cap;
        count++;
    }
 
}

通過這段程式碼發現，每次分配native memory的時候會通知jvm進行一次GC。如果我們配置了上面的jvm引數會導致這行程式碼不起任何作用。old gen裡面的物件就算死掉也不會回收，除非old gen本身滿了，但是通過上面的old gen使用了1G，還沒有到old gen的最大值。沒有full gc所以native memory一直沒有被回收。其實就算我們沒有設定jvm引數估計也會OOM ，因為bytebuffer因為執行緒只有的關係不會全部死掉。大部分bytebuffer也不會被回收

關於DirectByteBuffer

Perm中主要放一些class和meta資訊，常量池，靜態欄位等。這些東西都放在所謂的方法區中，在hotspot中也就是“持久帶”。
對於習慣在HotSpot虛擬機器上開發和部署程式的開發者來說，很多人願意把方法區稱為“永久代”（Permanent Generation），本質上兩者並不等價，僅僅是因為HotSpot虛擬機器的設計團隊選擇把GC分代收集擴充套件至方法區，或者說使用永久代來實現方法區而已
用-Xmx -Xms -Xmn 指定堆的最大值、初始值、和年輕帶的大小，由上圖可知young區也分為Eden 、from 、to上個區，比例預設是8:1:1 可以用-XX:SurvivorRatio設定年輕代中Eden區與Survivor區的大小比值
堆內記憶體由JVM gc統一管理回收,關於垃圾回收演算法，這裡不再贅述

堆外記憶體（off-heap memory)

和堆內記憶體相對應，堆外記憶體就是把記憶體物件分配在Java虛擬機器的堆以外的記憶體，這些記憶體直接受作業系統管理（而不是虛擬機器），這樣做的結果就是能夠在一定程度上減少垃圾回收對應用程式造成的影響。堆外記憶體預設是和-Xmx預設一樣大，也可以使用-XX:MaxDirectMemorySize指定堆外記憶體大小

作為JAVA開發者我們經常用java.nio.DirectByteBuffer物件進行堆外記憶體的管理和使用，它會在物件建立的時候就分配堆外記憶體。DirectByteBuffer類是在Java Heap外分配記憶體，對堆外記憶體的申請主要是通過成員變數unsafe來操作。關於Cleaner回收native memory又是另一個重要的點了。比如：為什麼不用finalize來回收native memory。另外找機會寫.

我們可以知道的是，隨著DirectByteBuffer被GC掉之後，被分配的native memory會被回收

DirectByteBuffer(int cap) {                
    super(-1, 0, cap, cap);
    //記憶體是否按頁分配對齊
    boolean pa = VM.isDirectMemoryPageAligned();
    //獲取每頁記憶體大小
    int ps = Bits.pageSize();
    //分配記憶體的大小，如果是按頁對齊方式，需要再加一頁記憶體的容量
    long size = Math.max(1L, (long)cap + (pa ? ps : 0));
    //用Bits類儲存總分配記憶體(按頁分配)的大小和實際記憶體的大小
    Bits.reserveMemory(size, cap);
 
    long base = 0;
    try {
       //在堆外記憶體的基地址，指定記憶體大小
        base = unsafe.allocateMemory(size);
    } catch (OutOfMemoryError x) {
        Bits.unreserveMemory(size, cap);
        throw x;
    }
    unsafe.setMemory(base, size, (byte) 0);
    //計算堆外記憶體的基地址
    if (pa && (base % ps != 0)) {
        // Round up to page boundary
        address = base + ps - (base & (ps - 1));
    } else {
        address = base;
    }
    //當this物件即directByteBuffer被gc回收時，釋放native memory（為什麼不用）
    cleaner = Cleaner.create(this, new Deallocator(base, size, cap));
    att = null;
}
  
private static class Deallocator implements Runnable  {
    private static Unsafe unsafe = Unsafe.getUnsafe();
    private long address;
    private long size;
    private int capacity;
    private Deallocator(long address, long size, int capacity) {
        assert (address != 0);
        this.address = address;
        this.size = size;
        this.capacity = capacity;
    }
 
    public void run() {
        if (address == 0) {
            // Paranoia
            return;
        }
        //回收native memory
        unsafe.freeMemory(address);
        address = 0;
        Bits.unreserveMemory(size, capacity);
    }
}

我們知道了回收堆內的DriectByteBuffer就會回收native memory，出現OOM的情況就是native memory被分配完了。也同時因為這個原因，假設進入Old gen的物件本來已經死了，但是並沒有full gc回收，native memory不能被及時回收。為了避免這種情況，在分配DirectByteByffer的時候會主動呼叫一次System.GC().通知JVM進行一次full gc。定期清理堆中的垃圾，及時的釋放native memory。堆外記憶體溢位

但是用了-XX:+DisableExplicitGC引數後，System.gc()的呼叫就會變成一個空呼叫，完全不會觸發任何GC（但是“函式呼叫”本身的開銷還是存在的).為啥要用這個引數呢？最主要的原因是為了防止某些手賤的同學在程式碼裡到處寫System.gc()的呼叫而STW干擾了程式的正常執行吧。有些應用程式本來可能正常跑一天也不會出一次full GC，但就是因為有人在程式碼裡呼叫了System.gc()而不得不間歇性被暫停。也有些時候這些呼叫是在某些庫或框架裡寫的，改不了它們的程式碼但又不想被這些呼叫干擾也會用這引數。

但是如果使用堆外記憶體，同時使用了這個引數，比如同時滿足下面3個條件，就很容易發生OOM

應用本身在GC堆內的物件行為良好，正常情況下很久都不發生full GC；
應用大量使用了NIO的direct memory，經常、反覆的申請DirectByteBuffer
使用了-XX:+DisableExplicitGC

下面使用一些例項在看看在使用了DisableExplicitGC這個引數之後，到底會發生什麼。

第一種:

native memory滿了，但是young區沒滿，沒有發生young gc回收DirectByteBuffer，所以堆外OOM（如果去掉DisableExplicitGC引數程式會一直有Full GC的資訊輸出，因為分配native memory的時候會主動呼叫System.GC()）

-Xmx64m
-Xms64m
-Xmn32m
-XX:+UseConcMarkSweepGC
-XX:+PrintGCDetails
-XX:+DisableExplicitGC//限制GC限制呼叫
-XX:MaxDirectMemorySize=10M//堆外10M
int i =1;
while(true){
    System.out.println("第"+(i++)+"次");
    ByteBuffer byteBuffer = ByteBuffer.allocateDirect( 1024*1024);
}
  
//輸出
第10次
第11次//10M就分配滿了，分配第11次的時候會OOM
Heap
 par new generation   total 29504K, used 3149K [0x00000007f6e00000, 0x00000007f8e00000, 0x00000007f8e00000)
  eden space 26240K,  12% used [0x00000007f6e00000, 0x00000007f7113578, 0x00000007f87a0000)//eden區只用了12%
  from space 3264K,   0% used [0x00000007f87a0000, 0x00000007f87a0000, 0x00000007f8ad0000)
  to   space 3264K,   0% used [0x00000007f8ad0000, 0x00000007f8ad0000, 0x00000007f8e00000)
 concurrent mark-sweep generation total 32768K, used 0K [0x00000007
Exception in thread "main" java.lang.OutOfMemoryError: Direct buffer memory
    at java.nio.Bits.reserveMemory(Bits.java:658)
    at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
    at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:306)

native memory沒滿，但是young區在native memory滿之前提前滿了，發生young gc回收DirectByteBuffer，不會發生OOM第二種:

如果程式碼換成了下面這種(jvm引數一樣),一次分配的native memory足夠小，會導致在native memory沒有分配滿的情況下，發生young gc會搜DirectByteBuffer。同時會回收native memory

ByteBuffer byteBuffer = ByteBuffer.allocateDirect( 1024/2/2/2/2/2);
//輸出會有
[GC[ParNew: 29503K->3262K(29504K), 0.0369960 secs] 44757K->25060K(62272K), 0.0370220 secs] [Times: user=0.18 sys=0.00, real=0.04 secs]
...
...
Heap
//退出程式時會發現young區並沒有滿
 par new generation   total 29504K, used 12716K [0x00000007f6e00000, 0x00000007f8e00000, 0x00000007f8e00000)
  eden space 26240K,  36% used
 [0x00000007f6e00000, 0x00000007f773b530, 0x00000007f87a0000)
 from space 3264K,  99% used [0x00000007f8ad0000, 0x00000007f8dffbc0, 0x00000007f8e00000)
 to   space 3264K,   0% used

大量DirectByteBuffer物件移動到old gen。沒有Full gc的發生，導致在程式中可能死掉的DirectByteBuffer物件沒有回收掉，native memory則滿了，發生OOM第三種:

-Xmx64m
-Xms64m
-Xmn32m
-XX:+PrintGCDetails
-XX:MaxTenuringThreshold=1//設定進去old gen的壽命是1，預設是15次才進入old gen
-XX:MaxDirectMemorySize=10M
-XX:+DisableExplicitGC//不能顯示full gc
  
int i = 1;
List<ByteBuffer> list = new ArrayList<ByteBuffer>();
while (true) {
            System.out.println("第" + (i++) + "次");
            ByteBuffer.allocate(1024 * 1024);//分配堆內記憶體
            ByteBuffer byteBuffer = ByteBuffer.allocateDirect(1024 / 2 / 2 / 2 );
            list.add(byteBuffer);//保證引用不被younggc
        }
//輸出
[GC[ParNew: 25620K->6K(29504K), 0.0004310 secs] 38176K->12564K(62272K), 0.0004450 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
//中途有一些young gc
//.....
//最終輸出
Heap
//young 區也沒有滿
 PSYoungGen      total 32256K, used 26419K [0x000000010d700000, 0x000000010f700000, 0x000000010f700000)
  eden space 31744K, 82% used [0x000000010d700000,0x000000010f0a4c70,0x000000010f600000)
  from space 512K, 31% used [0x000000010f680000,0x000000010f6a8000,0x000000010f700000)
  to   space 512K, 0% used [0x000000010f600000,0x000000010f600000,0x000000010f680000)
//old gen 已經用了62%了
 ParOldGen       total 32768K, used 20586K [0x000000010b700000, 0x000000010d700000, 0x000000010d700000)
  object space 32768K, 62% used [0x000000010b700000,0x000000010cb1a908,0x000000010d700000)
 PSPermGen       total 21504K, used 3097K [0x0000000106500000, 0x0000000107a00000, 0x000000010b700000)
  object space 21504K, 14% used [0x0000000106500000,0x00000001068065e8,0x0000000107a00000)

如果你在使用Oracle/Sun JDK 6，應用裡有任何地方用了direct memory，那麼使用-XX:+DisableExplicitGC要小心。如果用了該引數而且遇到direct memory的OOM，可以嘗試去掉該引數看是否能避開這種OOM

一次堆外OOM問題的排查過程

背景

排查

關於DirectByteBuffer

一次堆外OOM問題的排查過程

MySQL-記一次備份失敗的排查過程

一次 Java 記憶體洩漏排查過程，漲姿勢

記一次線上問題的排查過程

一次CMS GC問題排查過程（理解原理+讀懂GC日誌）

記錄一次堆外記憶體溢位

一次Mysql死鎖排查過程的全紀錄

一次JobTracker擁堵問題排查過程

記錄一次Mysql死鎖排查過程

Kafka 非同步訊息也會阻塞？記一次 Dubbo 頻繁超時排查過程

解Bug之路-記一次儲存故障的排查過程

記錄一次抽獎超發排查問題過程

解Bug之路-記一次呼叫外網服務概率性失敗問題的排查

記一次改造react腳手架的過程

一次網站性能排查實錄

一次差異備份拿shell過程

一次完整的 HTTP 請求過程

記錄一次郵件容災恢復過程

一次“驚險”的系統修復過程

一次完整的http請求過程

一次堆外OOM問題的排查過程

背景

排查

關於DirectByteBuffer

相關推薦