問題描述

幾年前在做某學習APP的時候，評論服務（comment）訪問評論后端服務（comment-server）正常RT在【幾毫秒 ~ 幾十毫秒】，偶爾（每隔幾天）RT達到幾十秒甚至幾分鐘，造成用戶看不到評論列表，發表評論失敗等不好的體驗。

分析過程

系統交互關系

系統交互關系

• 網關與comment之間通訊協議是LWP（LaiWang Protocol）
• comment與SLB之間通訊協議是https

comment調用comment-server超時？

在應用調用依賴服務的時候，會記錄下【時間戳，依賴類別，調用的接口，響應時間，狀態碼】等指標信息。
通過監控及日志信息，出現問題的時候與SLB交互的RT是【452秒】，初步定位是【SLB】或【comment-server】處理慢導致的，所以聯系了運維同學、負責【comment-server】的同學一起排查。

與SLB交互耗時

SLB日志

其中request_time：0.004秒，upstream_response_time：0.004秒

comment-server處理耗時

應用日志

處理耗時【4毫秒】，看來鍋是自己的。

Review代碼

應用訪問SLB使用的是Apache HttpClient，代碼抽象表達如下：

代碼示例

這個代碼哪里似乎有問題？

GC導致的阻塞？

通過查看GC Log，發現CMS GC耗時較長，與超時的時間點是能夠對應上的，終于發現了線索。
發生CMS GC的時候，線程都在忙些什么呢？這時候LWP框架的線程dump起到了關鍵作用，下面對LWP簡單做下介紹。

線程模型

LWP是一個RPC框架，網絡通訊框架使用的是netty。

線程模型

業務線程池

線程池初始化

線程池配置

拒絕策略

拒絕策略

在線程blocked的時候，LWP框架打印出了當時的線程棧信息，發現所有業務線程都阻塞在了SSL交互過程中。

問題根因

SSLSessionContext’s ssl session緩存(which is a SoftReference cache) 超時時間默認是86400s (24小時)，ssl session緩存大小默認是沒有限制的，導致CMS GC處理SoftReference的時候耗時較長導致的。
算是JDK的一個Bug，如下：

JDK Bug描述

解決辦法

設置SSLContext實例的sessionCacheSize、sessionTimeout，示例：

sslContext.getClientSessionContext().setSessionCacheSize(1024);
sslContext.getClientSessionContext().setSessionTimeout(60);

不僅https，對于使用SSL通訊的應用同樣需要注意上面的問題。