天天看點

HttpClient SSL Session預設設定導緻線程阻塞幾分鐘的案例分析

作者:大禹的足迹

問題描述

幾年前在做某學習APP的時候,評論服務(comment)通路評論後端服務(comment-server)正常RT在【幾毫秒 ~ 幾十毫秒】,偶爾(每隔幾天)RT達到幾十秒甚至幾分鐘,造成使用者看不到評論清單,發表評論失敗等不好的體驗。

分析過程

系統互動關系

HttpClient SSL Session預設設定導緻線程阻塞幾分鐘的案例分析

系統互動關系

  • 網關與comment之間通訊協定是LWP(LaiWang Protocol)
  • comment與SLB之間通訊協定是https

comment調用comment-server逾時?

在應用調用依賴服務的時候,會記錄下【時間戳,依賴類别,調用的接口,響應時間,狀态碼】等名額資訊。

通過監控及日志資訊,出現問題的時候與SLB互動的RT是【452秒】,初步定位是【SLB】或【comment-server】處理慢導緻的,是以聯系了運維同學、負責【comment-server】的同學一起排查。

與SLB互動耗時

HttpClient SSL Session預設設定導緻線程阻塞幾分鐘的案例分析

SLB日志

其中request_time:0.004秒,upstream_response_time:0.004秒

comment-server處理耗時

HttpClient SSL Session預設設定導緻線程阻塞幾分鐘的案例分析

應用日志

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

Review代碼

應用通路SLB使用的是Apache HttpClient,代碼抽象表達如下:

HttpClient SSL Session預設設定導緻線程阻塞幾分鐘的案例分析

代碼示例

這個代碼哪裡似乎有問題?

GC導緻的阻塞?

通過檢視GC Log,發現CMS GC耗時較長,與逾時的時間點是能夠對應上的,終于發現了線索。

發生CMS GC的時候,線程都在忙些什麼呢?這時候LWP架構的線程dump起到了關鍵作用,下面對LWP簡單做下介紹。

線程模型

LWP是一個RPC架構,網絡通訊架構使用的是netty。

HttpClient SSL Session預設設定導緻線程阻塞幾分鐘的案例分析

線程模型

業務線程池

線程池初始化

HttpClient SSL Session預設設定導緻線程阻塞幾分鐘的案例分析

線程池配置

拒絕政策

HttpClient SSL Session預設設定導緻線程阻塞幾分鐘的案例分析

拒絕政策

線上程blocked的時候,LWP架構列印出了當時的線程棧資訊,發現所有業務線程都阻塞在了SSL互動過程中。

問題根因

SSLSessionContext’s ssl session緩存(which is a SoftReference cache) 逾時時間預設是86400s (24小時),ssl session緩存大小預設是沒有限制的,導緻CMS GC處理SoftReference的時候耗時較長導緻的。

算是JDK的一個Bug,如下:

HttpClient SSL Session預設設定導緻線程阻塞幾分鐘的案例分析

JDK Bug描述

解決辦法

設定SSLContext執行個體的sessionCacheSize、sessionTimeout,示例:

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

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

繼續閱讀