記一次OOM問題排查過程


上周運維反饋線上程序出現了OOM,程序日志中的輸出為

Exception in thread "http-nio-8080-exec-1027" java.lang.OutOfMemoryError: Java heap space
Exception in thread "http-nio-8080-exec-1031" java.lang.OutOfMemoryError: Java heap space

看線程名稱應該是tomcat的nio工作線程,線程在處理程序的時候因為無法在堆中分配更多內存出現了OOM,幸好JVM啟動參數配置了-XX:+HeapDumpOnOutOfMemoryError,使用MAT打開拿到的hprof文件進行分析。

第一步就是打開Histogram看看占用內存最大的是什么對象:

可以看到byte數組占用了接近JVM配置的最大堆的大小也就是8GB,顯然這是OOM的原因。
第二步看一下究竟是哪些byte數組,數組是啥內容:

可以看到很明顯這和HTTP請求相關,一個數組大概是10M的大小。
第三步通過查看GC根查看誰持有了數組的引用:

這符合之前的猜測,是tomcat的線程在處理過程中分配了10M的buffer在堆上。至此,馬上可以想到一定是什么參數設置的不合理導致了這種情況,一般而言tomcat不可能為每一個請求分配如此大的buffer。
第四步就是檢查代碼里是否有tomcat或服務器相關配置,看到有這么一個配置:

max-http-header-size: 10000000

至此,基本已經確定了八九不離十就是這個不合理的最大http請求頭參數導致的問題。
到這里還有3個疑問:

  1. 即使一個請求分配10M內存,堆有8GB,難道當時有這么多並發嗎?800個tomcat線程?
  2. 參數只是設置了最大請求頭10M,為什么tomcat就會一次性分配這么大的buffer呢?
  3. 為什么會有如此多的tomcat線程?感覺程序沒這么多並發。

先來看問題1,這個可以通過MAT在dump中繼續尋找答案。
可以打開線程視圖,搜索一下tomcat的工作線程,發現線程數量的確很多有401個,但是也只是800的一半:

再回到那些大數組的清單,按照堆分配大小排序,往下看:

可以發現除了有10008192字節的數組還有10000000字節的數組,查看引用路徑可以看到這個正好是10M的數組是output buffer,區別於之前看到的input buffer:

好吧,這就對了,一個線程分配了輸入輸出兩個buffer,占用20M內存,一共401個線程,占用8GB,所以OOM了。
還引申出一個問題為啥有這么多工作線程,

再來看看問題2,這就需要來找一下源碼了,首先max-http-header-size是springboot定義的參數,查看springboot代碼可以看到這個參數對於tomcat設置的是MaxHttpHeaderSize:


然后來看看tomcat源碼:

進一步看一下input buffer:


buffer大小是MaxHttpHeaderSize+ReadBuffer大小,后者默認是8192字節:

   <attribute name="socket.appReadBufSize" required="false">
        <p>(int)Each connection that is opened up in Tomcat get associated with
        a read ByteBuffer. This attribute controls the size of this buffer. By
        default this read buffer is sized at <code>8192</code> bytes. For lower
        concurrency, you can increase this to buffer more data. For an extreme
        amount of keep alive connections, decrease this number or increase your
        heap size.</p>
      </attribute>

這也就是為什么之前看到大量的buffer是10008192字節的。顯然還有一批內容是空的10000000字節的buffer應該是output buffer,來看看源碼:

嗯這是一個header buffer,所以正好是10000000字節。

至於問題3,顯然我們的應用程序是配置過最大線程的(查看配置后發現的確,我們配置為了2000,好吧有點大),否則也不會有401個工作線程(默認150),如果當時並發並不大的話就一種可能,請求很慢,雖然並發不大,但是因為請求執行的慢就需要更多線程,比如TPS是100,但是平均RT是4s的話,就是400線程了。這個問題的答案還是可以通過MAT去找,隨便看幾個線程可以發現很多線程都在等待一個外部服務的返回,這說明外部服務比較慢,去搜索當時的程序日志可以發現有很多"feign.RetryableException: Read timed out executing的日志"。。。。追殺下游去!慢點,我們的feign的timeout也需要再去設置一下,別被外部服務拖死了。


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM