問(wèn)題描述

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

分析過(guò)程

系統(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)用依賴(lài)服務(wù)的時(shí)候，會(huì)記錄下【時(shí)間戳，依賴(lài)類(lèi)別，調(diào)用的接口，響應(yīng)時(shí)間，狀態(tài)碼】等指標(biāo)信息。
通過(guò)監(jiān)控及日志信息，出現(xiàn)問(wè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毫秒】，看來(lái)鍋是自己的。

Review代碼

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

代碼示例

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

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

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

線(xiàn)程模型

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

線(xiàn)程模型

業(yè)務(wù)線(xiàn)程池

線(xiàn)程池初始化

線(xiàn)程池配置

拒絕策略

拒絕策略

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

問(wèn)題根因

SSLSessionContext’s ssl session緩存(which is a SoftReference cache) 超時(shí)時(shí)間默認(rèn)是86400s (24小時(shí))，ssl session緩存大小默認(rèn)是沒(méi)有限制的，導(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)用同樣需要注意上面的問(wèn)題。