問題描述

幾年前在做某學(xué)習(xí)APP的時(shí)候，評(píng)論服務(wù)（comment）訪問評(píng)論后端服務(wù)（comment-server）正常RT在【幾毫秒 ~ 幾十毫秒】，偶爾（每隔幾天）RT達(dá)到幾十秒甚至幾分鐘，造成用戶看不到評(píng)論列表，發(fā)表評(píng)論失敗等不好的體驗(yàn)。

分析過程

系統(tǒng)交互關(guān)系

系統(tǒng)交互關(guān)系

• 網(wǎng)關(guān)與comment之間通訊協(xié)議是LWP（LaiWang Protocol）
• comment與SLB之間通訊協(xié)議是https

comment調(diào)用comment-server超時(shí)？

在應(yīng)用調(diào)用依賴服務(wù)的時(shí)候，會(huì)記錄下【時(shí)間戳，依賴類別，調(diào)用的接口，響應(yīng)時(shí)間，狀態(tài)碼】等指標(biāo)信息。
通過監(jiān)控及日志信息，出現(xiàn)問題的時(shí)候與SLB交互的RT是【452秒】，初步定位是【SLB】或【comment-server】處理慢導(dǎo)致的，所以聯(lián)系了運(yùn)維同學(xué)、負(fù)責(zé)【comment-server】的同學(xué)一起排查。

與SLB交互耗時(shí)

SLB日志

其中request_time：0.004秒，upstream_response_time：0.004秒

comment-server處理耗時(shí)

應(yīng)用日志

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

Review代碼

應(yīng)用訪問SLB使用的是Apache HttpClient，代碼抽象表達(dá)如下：

代碼示例

這個(gè)代碼哪里似乎有問題？

GC導(dǎo)致的阻塞？

通過查看GC Log，發(fā)現(xiàn)CMS GC耗時(shí)較長(zhǎng)，與超時(shí)的時(shí)間點(diǎn)是能夠?qū)?yīng)上的，終于發(fā)現(xiàn)了線索。
發(fā)生CMS GC的時(shí)候，線程都在忙些什么呢？這時(shí)候LWP框架的線程dump起到了關(guān)鍵作用，下面對(duì)LWP簡(jiǎn)單做下介紹。

線程模型

LWP是一個(gè)RPC框架，網(wǎng)絡(luò)通訊框架使用的是netty。

線程模型

業(yè)務(wù)線程池

線程池初始化

線程池配置

拒絕策略

拒絕策略

在線程blocked的時(shí)候，LWP框架打印出了當(dāng)時(shí)的線程棧信息，發(fā)現(xiàn)所有業(yè)務(wù)線程都阻塞在了SSL交互過程中。

問題根因

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

JDK Bug描述

解決辦法

設(shè)置SSLContext實(shí)例的sessionCacheSize、sessionTimeout，示例：

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

不僅https，對(duì)于使用SSL通訊的應(yīng)用同樣需要注意上面的問題。