記一次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也須要再去設置一下，別被外部服務拖死了。