問題描述

• 線上突然出現(xiàn)Dubbo超時調(diào)用，時間剛好為Consumer端設(shè)置的超時時間。
• 有好幾個不同的接口都報超時了
• 第1次調(diào)用超時，第2次（或第3次）重試調(diào)用非?？?#xff08;正常水平）
• Dubbo調(diào)用超時的情況集中出現(xiàn)了3次，每次都是過一會自動恢復(fù)

排查

排查日志

看到調(diào)用超時，首先就拿著traceId去服務(wù)提供方查日志。 奇怪的是，在服務(wù)提供方的業(yè)務(wù)日志里面，只有正常的調(diào)用日志（耗時正常），沒有超時調(diào)用的日志。 從正常的調(diào)用日志里面看，一切都是正常的，看不出所以然。 給人的感覺就是超時那次請求的調(diào)用沒有達到服務(wù)提供方。

此時系統(tǒng)活動情況

通過系統(tǒng)歷史監(jiān)控，我們發(fā)現(xiàn)除了gc比平時稍微高一點外（也在正常水位），沒有其他的異常；CPU、內(nèi)存、網(wǎng)絡(luò)等指標都在正常范圍。

查看Dubbo線程活動情況

第2次系統(tǒng)集中超時報警的做的第一件事就是登錄到那臺服務(wù)器查看dubbo線程活動情況：看下能不能找到阻塞在哪一行代碼。很遺憾，所有的dubbo線程都沒有阻塞，都是正常的WAITING狀態(tài)。

并沒有明顯表明阻塞在某段代碼，這可難倒我們了：如果沒有阻塞的話，為什么dubbo調(diào)用方會報超時？繼續(xù)看代碼

該接口是否存在阻塞的代碼？

硬著頭皮重新看代碼每一個分支，突然發(fā)現(xiàn)底層的一個方法中有http調(diào)用！會不會是這個http調(diào)用導(dǎo)致的超時？如果是的話，那么不同的接口調(diào)用超時的情況就說的通了，因為上層大部分接口都會調(diào)用這個底層方法。

懷揣著激動的心，仔細看了http調(diào)用的邏輯：用的是JDK提供的HttpURLConnection，其中只用了HttpURLConnection#getContentLength方法，并且也在finally代碼塊中將這個連接關(guān)閉了。好像也不是這個引起的，起初還以為getContentLength會把文件給下載下來，但是看了接口文檔以后發(fā)現(xiàn)只會去讀頭信息中的ContentLength。

/*** Returns the value of the {@code content-length} header field.* <p>* <b>Note</b>: {@link #getContentLengthLong() getContentLengthLong()}* should be preferred over this method, since it returns a {@code long}* instead and is therefore more portable.</p>** @return the content length of the resource that this connection's URL* references, {@code -1} if the content length is not known,* or if the content length is greater than Integer.MAX_VALUE.*/public int getContentLength() {long l = getContentLengthLong();if (l &gt; Integer.MAX_VALUE)return -1;return (int) l;}

代碼阻塞的情況可能性也不大，因為重試請求不會超時：如果代碼阻塞，那么重試請求大概率也會超時。

數(shù)據(jù)訪問層是否有異常情況

既然代碼沒有阻塞，那么有沒有可能是數(shù)據(jù)訪問層的異常造成的呢？畢竟不止一個接口存在超時的問題，如果是底層數(shù)據(jù)訪問層的異常導(dǎo)致，那么也說得通。

重點排查了mysql，但結(jié)果是令人失望的：并沒有慢SQL；并且dubbo超時期間，mysql實例的CPU和內(nèi)存水位都是正常的。

除了mysql、redis實例本身指標正常外，基于上面同樣的理由：如果數(shù)據(jù)訪問層有問題，那么重試基本上也會超時。所以數(shù)據(jù)訪問層導(dǎo)致超時的線索也被排除。

有沒有可能是Dubbo層面的問題

排查再次陷入僵局，逼迫著我們重新梳理排查思路：

除了代碼阻塞

除了數(shù)據(jù)訪問層異常

除了超時請求，其他請求的日志都是正常的

那么還有可能會導(dǎo)致超時呢？會不會是Dubbo本身異常導(dǎo)致的？

此時有一個關(guān)鍵的線索進入我們的視野：超時的那次請求去哪兒了？

在服務(wù)提供方的日志里面沒有超時請求的的日志，只有重試請求成功的業(yè)務(wù)日志。太奇怪了，就算超時總的留下日志的吧，日志都不留，欺負我胖虎嗎？！

到這里想到超時的請求可能是一個突破口，于是開始看Dubbo的相關(guān)的源碼和文檔。

從官方文檔中的服務(wù)端調(diào)用鏈一層層往下查

在AllChannelHandler源碼中看到了令人興奮的注釋：

興奮之余，為了避免理解偏差，還特地用百度翻譯了一下

滿了，那么服務(wù)端不會返回，直到客戶端超時！這不是正式我們碰到的問題嗎？！ 并且此時還沒有進入業(yè)務(wù)代碼，所以沒有打印業(yè)務(wù)日志，這樣就可以解釋為什么沒有服務(wù)提供方?jīng)]有超時請求的日志了。

別激動，這里明明有返回threadpool is exhausted異常信息，怎么能說沒有返回呢？ 別急，這是另外一個項目引用的dubbo，版本是2.6.2。 回到出問題的那個項目，查看dubbo版本：2.8.6，查看AllChannelHandler源碼：是的在2.8.6版本中，并沒有這個返回錯誤

題好像找到了，OK，剩下的就是驗證了。

驗證

準備

• 將DubboServerHandler線程池的最大線程數(shù)調(diào)到5
• 使用Apache Bench進行壓測：200請求、并發(fā)10個線程

case1：復(fù)現(xiàn)問題

• Dubbo使用2.8.6版本
• 預(yù)期：部分請求超時報錯，重試耗時正常
• 壓測結(jié)果符合預(yù)期：部分接口報錯超時，并且重試請求耗時正常

case2：驗證猜想

• Dubbo使用2.6.2版本
• 預(yù)期：部分請求報錯線程池耗盡threadpool is exhausted，并且重試大概率也會報該錯誤
• 壓測結(jié)果符合預(yù)期

至此，基本判定線上Dubbo調(diào)用超時的問題就是因為線程池耗盡引起的。

這個超時問題前前后后查了一周左右，排查過程中試了很多排查方向，為了敘述方便就沒有展開。

避坑指南

合理設(shè)置Dubbo線程池大小。默認是200

合理設(shè)置超時時間。如果真出現(xiàn)了Dubbo調(diào)用超時的情況，合理的超時時間能夠避免服務(wù)調(diào)用方被打爆

Dubbo接口必須有返回值。從AllChannelHandler#received的源碼和注釋中可以看到只有有返回值的接口才會返回線程池耗盡的錯誤信息；其它的情況則不會將錯誤信息返回給調(diào)用方，直到調(diào)用方超時。

總結(jié)

以上是生活随笔為你收集整理的dubbo官方文档_不可忽视的Dubbo线程池的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。