Java后端服務間歇性響應慢的問題排查與解決
分享一個之前在公司內其它團隊找到幫忙排查的一個后端服務連接超時問題，問題的表現(xiàn)是服務部署到線上后出現(xiàn)間歇性請求響應非常慢（大于10s），但是后端業(yè)務分析業(yè)務日志時卻沒有發(fā)現(xiàn)慢請求，另外由于服務容器livenessProbe也出現(xiàn)超時，導致容器出現(xiàn)間歇性重啟。
復現(xiàn)
該服務基于spring-boot開發(fā)，通過spring-mvc框架對外提供一些web接口，業(yè)務簡化后代碼如下:
@Controller
@SpringBootApplication
public class Bootstrap {
public static void main(String[] args) {
SpringApplication.run(Bootstrap.class, args);
}
@GetMapping("/ping")
public String ping() {
return "pong";
}
}
客戶端訪問該服務（記為backend）的路徑為: client => ingress => backend，客戶端的代碼簡化如下，其實就是在一個循環(huán)里面持續(xù)訪問ingress（這里以一個nginx代替）：
import time
import requests
while True:
try:
start = time.time()
r = requests.get('http://nginx/ping', timeout=(3, 10))
spend = int((time.time() - start) * 1000)
r.raise_for_status()
print(f'{time.strftime("%Y-%m-%dT%H:%M:%S")} OK {spend}ms {r.content.decode("utf-8")}')
except requests.HTTPError as err:
print(f'{time.strftime("%Y-%m-%dT%H:%M:%S")} HTTP error: {err}')
except Exception as err:
print(f'{time.strftime("%Y-%m-%dT%H:%M:%S")} Error: {err}')
time.sleep(0.1)
下面是一個docker-compose文件構造了一個最小可復現(xiàn)的環(huán)境：
version: '3'
services:
backend:
image: shawyeok/128-slowbackend:backend
nginx:
image: shawyeok/128-slowbackend:nginx
depends_on:
- backend
client:
image: shawyeok/128-slowbackend:client
depends_on:
- nginx
通過docker-compose啟動后，檢查client容器的日志，你將會在client看到間歇性出現(xiàn)read timeout的記錄
$ docker-compose up -d $ docker ps $ docker logs -f xxx-client-1 2024-05-23T08:02:51 OK 52ms pong 2024-05-23T08:02:51 OK 6ms pong 2024-05-23T08:02:51 OK 3ms pong 2024-05-23T08:02:51 OK 5ms pong 2024-05-23T08:02:51 OK 17ms pong 2024-05-23T08:02:51 OK 14ms pong 2024-05-23T08:02:51 OK 11ms pong 2024-05-23T08:02:51 OK 16ms pong 2024-05-23T08:02:52 OK 7ms pong 2024-05-23T08:02:52 OK 10ms pong 2024-05-23T08:02:52 OK 6ms pong 2024-05-23T08:02:52 OK 8ms pong 2024-05-23T08:03:02 Error: HTTPConnectionPool(host='nginx', port=80): Read timed out. (read timeout=10) 2024-05-23T08:03:12 Error: HTTPConnectionPool(host='nginx', port=80): Read timed out. (read timeout=10) 2024-05-23T08:03:12 OK 15ms pong 2024-05-23T08:03:12 OK 15ms pong 2024-05-23T08:03:12 OK 15ms pong
完整的復現(xiàn)代碼在Shawyeok/128-slowbackend，讀者看到這里可以先嘗試通過上面步驟把環(huán)境運行起來自己動手分析一下原因。
分析
今天終于抽出時間來完成這篇文章，讀者在看下面分析過程之前，我建議還是先動手用docker-compose把案例復現(xiàn)一下，然后自己嘗試分析，分析過程肯定會遇到這樣那樣的問題，直到dead-end或者分析完了再回過頭看我的分析過程，這樣在實際工作中遇到類似問題的時候我想更有可能callback。
當然，如果你有別的思路和手段分析這個問題，非常歡迎在評論區(qū)分享你的見解。
下面開始回顧一下我當時記錄的分析過程。
嘗試問題重現(xiàn)時抓取threaddump（進入到backend容器執(zhí)行命令jstack -l <pid>），主要觀察tomcat工作線程池（線程名：http-nio-0.0.0.0-8080-exec-*）的線程狀態(tài)，發(fā)現(xiàn)都是處于等待從線程池隊列獲取任務的狀態(tài)，并未見工作線程卡在一些業(yè)務操作上：
"http-nio-0.0.0.0-8080-exec-1" #167 daemon prio=5 os_prio=0 tid=0x00007f0461487000 nid=0xb1 waiting on condition [0x00007f043d8fd000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006f99c3ba8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- None
同時通過在服務提供方tcpdump抓包分析，到目前分析結論是延遲發(fā)生在backend這一端（但并不能再縮小問題范圍，kernel處理慢或者內部隊列堆積都有可能）：
為了縮小問題范圍，嘗試開啟tomcat的訪問日志和內部DEBUG日志，看請求具體什么時間點到達tomcat的隊列，什么時間點開始執(zhí)行用戶代碼，以及什么時候處理完的，這樣就可以進一步確定延遲發(fā)生在哪個過程。
# 程序啟動添加下面參數(shù) # 開啟tomcat訪問日志 --server.tomcat.accesslog.enabled=true # 開啟tomcat內部DEBUG日志 --logging.level.org.apache.tomcat=DEBUG --logging.level.org.apache.catalina=DEBUG
在我們的例子中，在compose.yml給backend配置上JAVA_OPTS環(huán)境變量即可
services:
backend:
image: shawyeok/128-slowbackend:backend
environment:
- JAVA_OPTS=-Dserver.tomcat.accesslog.enabled=true -Dlogging.level.org.apache.tomcat=DEBUG -Dlogging.level.org.apache.catalina=DEBUG
開啟日志后可以看到tomcat處理的請求的詳細過程：
2021-09-28 15:35:06.409 DEBUG 1 --- [0-8080-Acceptor] o.apache.tomcat.util.threads.LimitLatch : Counting up[http-nio-0.0.0.0-8080-Acceptor] latch=10 2021-09-28 15:35:06.409 DEBUG 1 --- [0.0-8080-exec-3] o.apache.tomcat.util.threads.LimitLatch : Counting down[http-nio-0.0.0.0-8080-exec-3] latch=9 2021-09-28 15:35:06.409 DEBUG 1 --- [0.0-8080-exec-3] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@f099444:org.apache.tomcat.util.net.NioChannel@50bf632e:java.nio.channels.SocketChannel[connected local=java-security-operation-platform-64f57cf5f9-pvnnn/10.50.63.246:8080 remote=/10.50.63.247:45142]], Read from buffer: [0] 2021-09-28 15:35:06.409 DEBUG 1 --- [0.0-8080-exec-3] org.apache.tomcat.util.net.NioEndpoint : Calling [org.apache.tomcat.util.net.NioEndpoint@44c861c].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@f099444:org.apache.tomcat.util.net.NioChannel@50bf632e:java.nio.channels.SocketChannel[connected local=java-security-operation-platform-64f57cf5f9-pvnnn/10.50.63.246:8080 remote=/10.50.63.247:45142]]) 2021-09-28 15:35:06.410 DEBUG 1 --- [0.0-8080-exec-1] o.apache.catalina.valves.RemoteIpValve : Incoming request /v2/platform/health with originalRemoteAddr [10.50.63.247], originalRemoteHost=[10.50.63.247], originalSecure=[false], originalScheme=[http], originalServerName=[platform-fengkong.zhaopin.com], originalServerPort=[80] will be seen as newRemoteAddr=[192.168.11.63], newRemoteHost=[192.168.11.63], newSecure=[false], newScheme=[http], newServerName=[platform-fengkong.zhaopin.com], newServerPort=[80] 2021-09-28 15:35:06.410 DEBUG 1 --- [0.0-8080-exec-1] org.apache.catalina.realm.RealmBase : No applicable constraints defined 2021-09-28 15:35:06.410 DEBUG 1 --- [0.0-8080-exec-1] o.a.c.authenticator.AuthenticatorBase : Security checking request GET /v2/platform/health ...
但這個時候注意到一個Logger比較眼熟：o.apache.tomcat.util.threads.LimitLatch，而且有Limit字眼，難道延遲是由于tomcat內部在競爭某種資源？仔細看這個Logger的日志：
看到這里就很值得懷疑了，重新查看之前的threadump文件，發(fā)現(xiàn)tomcat Acceptor線程正是block在這里??！
"http-nio-8080-Acceptor" #29 daemon prio=5 os_prio=0 cpu=26.62ms elapsed=112.10s tid=0x00007ffff8ae8000 nid=0x3b waiting on condition [0x00007fff896fe000] java.lang.Thread.State: WAITING (parking) at jdk.internal.misc.Unsafe.park(java.base@11.0.23/Native Method) - parking to wait for <0x0000000083ad3860> (a org.apache.tomcat.util.threads.LimitLatch$Sync) at java.util.concurrent.locks.LockSupport.park(java.base@11.0.23/LockSupport.java:194) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.23/AbstractQueuedSynchronizer.java:885) at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(java.base@11.0.23/AbstractQueuedSynchronizer.java:1039) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@11.0.23/AbstractQueuedSynchronizer.java:1345) at org.apache.tomcat.util.threads.LimitLatch.countUpOrAwait(LimitLatch.java:117) at org.apache.tomcat.util.net.AbstractEndpoint.countUpOrAwaitConnection(AbstractEndpoint.java:1309) at org.apache.tomcat.util.net.Acceptor.run(Acceptor.java:94) at java.lang.Thread.run(java.base@11.0.23/Thread.java:829)
原來上面在分析線程dump時真相就在眼前了，卻給忽略了，這很致命~
現(xiàn)在這個問題表層的原因已經清楚了：由于該服務配置的tomcat連接數(shù)太少，觸發(fā)了LimitLatch限制，阻塞等待老的連接釋放（這點可以通過抓包分析得以驗證，被阻塞的請求得以響應之前總是有一個TCP連接釋放）
查看源碼中src/main/resources/application.yml文件，有如下配置：
server.tomcat.max-connections: 10
這里因為是最簡復現(xiàn)Demo，這個配置單獨放在這里是非?？梢傻?，然而現(xiàn)實情況中它可能隱藏在大量的配置中，你未必能注意到，特別是線上排查問題時往往情況都比較急。
查看當前和tomcat 8080端口建立的連接，剛好是10個，查看spring boot文檔默認值是8192（server.tomcat.max-connections），關于這個當初為什么要添加上面最大連接數(shù)的配置，我就不好細說了，總之是人為方面的原因。
再看nginx的配置，worker_processes配置為16，是大于10的，因此當backend的連接數(shù)達到10時，acceptor線程就會阻塞等待，直到有連接釋放，這就是為什么會出現(xiàn)間歇性請求響應慢的現(xiàn)象。
worker_processes 16;
解決這個問題，就是把max-connections的配置刪掉即可，但是這個問題如果細究的話你可以還會注意其它的點。
問題的表現(xiàn)，往往以多種形式呈現(xiàn)。
在這個case中，我們也可以通過ss命令查看tcp syn連接隊列的當前狀態(tài)，會發(fā)現(xiàn)Recv-Q這一列始終大于0，說明有連接正在等待用戶線程accept(2)。
tomcat線程模型
我們看一下tomcat線程模型，在一個新連接上發(fā)起一次http請求會首先經過Acceptor線程，這個線程只負責接收新的連接然后放到連接隊列中，后續(xù)的解析http報文、執(zhí)行應用邏輯、發(fā)送響應結果都在Worker線程池中執(zhí)行。
通過上面ss命令的截圖，Rec-Q那一列顯示3即說明有三個新連接的請求Acceptor線程還沒有來得及處理，為什么沒有來得及處理呢？即受到了server.tomcat.max-connections配置的約束導致的。
總結
本文主要是分享一個tomcat間歇性響應慢的case，在筆者的第一次排查過程中，其實真相就隱藏在線程dump中，但是最開始的時候錯過了。
以上就是Java后端服務間歇性響應慢的問題排查與解決的詳細內容，更多關于Java服務間歇性響應慢的資料請關注腳本之家其它相關文章！
相關文章
Python爬蟲之爬取2020女團選秀數(shù)據(jù)
本文將對比《青春有你2》和《創(chuàng)造營2020》全體小姐姐，鑒于兩個節(jié)目的數(shù)據(jù)采集和處理過程基本相似，在使用Python做數(shù)據(jù)爬蟲采集的章節(jié)中將只以《創(chuàng)造營2020》為例做詳細介紹。感興趣的同學可以照貓畫虎去實操一下《青春有你2》的數(shù)據(jù)爬蟲采集，需要的朋友可以參考下2021-04-04
Spring?boot?整合RabbitMQ實現(xiàn)通過RabbitMQ進行項目的連接
RabbitMQ是一個開源的AMQP實現(xiàn)，服務器端用Erlang語言編寫，支持多種客戶端，這篇文章主要介紹了Spring?boot?整合RabbitMQ實現(xiàn)通過RabbitMQ進行項目的連接,需要的朋友可以參考下2022-10-10
所謂Iterator模式，即是Iterator為不同的容器提供一個統(tǒng)一的訪問方式。本文以java中的容器為例，模擬Iterator的原理。需要的朋友可以參考下2013-07-07
這篇文章主要介紹了java數(shù)據(jù)類型與變量的安全性介紹，文章圍繞主題展開詳細的內容介紹，具有一定的參考價值，需要的朋友可以參考一下2022-07-07
這篇文章主要介紹了java 使用BigDecimal進行貨幣金額計算的操作，具有很好的參考價值，希望對大家有所幫助。一起跟隨小編過來看看吧2021-02-02
本文主要介紹了Java處理double類型提示2e31的問題解決,文中通過示例代碼介紹的非常詳細,對大家的學習或者工作具有一定的參考學習價值,需要的朋友們下面隨著小編來一起學習學習吧2025-09-09
這篇文章主要介紹了如何利用Java代碼自動生成PPT，具體就是查詢數(shù)據(jù)庫數(shù)據(jù)，然后根據(jù)模板文件（PPT），將數(shù)據(jù)庫數(shù)據(jù)與模板文件（PPT），進行組合一下，生成新的PPT文件。感興趣的可以了解一下2022-02-02
Python安裝Jupyter Notebook配置使用教程詳解
這篇文章主要介紹了Python安裝Jupyter Notebook配置使用教程詳解，文中通過示例代碼介紹的非常詳細，對大家的學習或者工作具有一定的參考學習價值，需要的朋友們下面隨著小編來一起學習學習吧2020-09-09
這篇文章主要為大家分享了最有價值的6道線程池面試題，涵蓋內容全面，包括數(shù)據(jù)結構和算法相關的題目、經典面試編程題等，對hashCode方法的設計、垃圾收集的堆和代進行剖析，感興趣的小伙伴們可以參考一下2021-06-06
UUID保證對在同一時空中的所有機器都是唯一的,通常平臺會提供生成的API,按照開放軟件基金會(OSF)制定的標準計算,用到了以太網卡地址、納秒級時間、芯片ID碼和許多可能的數(shù)字,下面這篇文章主要給大家介紹了關于Java生成UUID的常用方式,需要的朋友可以參考下2023-05-05