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