Java后端服務(wù)間歇性響應(yīng)慢的問題排查與解決

更新時(shí)間：2025年03月23日 09:20:45 作者：蕭易客

之前在公司內(nèi)其它團(tuán)隊(duì)找到幫忙排查的一個(gè)后端服務(wù)連接超時(shí)問題,問題的表現(xiàn)是服務(wù)部署到線上后出現(xiàn)間歇性請求響應(yīng)非常慢（大于10s）,但是后端業(yè)務(wù)分析業(yè)務(wù)日志時(shí)卻沒有發(fā)現(xiàn)慢請求,所以本文給大家介紹了Java后端服務(wù)間歇性響應(yīng)慢的問題排查與解決,需要的朋友可以參考下

分享一個(gè)之前在公司內(nèi)其它團(tuán)隊(duì)找到幫忙排查的一個(gè)后端服務(wù)連接超時(shí)問題，問題的表現(xiàn)是服務(wù)部署到線上后出現(xiàn)間歇性請求響應(yīng)非常慢（大于10s），但是后端業(yè)務(wù)分析業(yè)務(wù)日志時(shí)卻沒有發(fā)現(xiàn)慢請求，另外由于服務(wù)容器livenessProbe也出現(xiàn)超時(shí)，導(dǎo)致容器出現(xiàn)間歇性重啟。

復(fù)現(xiàn)

該服務(wù)基于spring-boot開發(fā)，通過spring-mvc框架對外提供一些web接口，業(yè)務(wù)簡化后代碼如下:

@Controller
@SpringBootApplication
public class Bootstrap {

    public static void main(String[] args) {
        SpringApplication.run(Bootstrap.class, args);
    }
    
    @GetMapping("/ping")
    public String ping() {
        return "pong";
    }
}

客戶端訪問該服務(wù)（記為backend）的路徑為: client => ingress => backend，客戶端的代碼簡化如下，其實(shí)就是在一個(gè)循環(huán)里面持續(xù)訪問ingress（這里以一個(gè)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)

下面是一個(gè)docker-compose文件構(gòu)造了一個(gè)最小可復(fù)現(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

完整的復(fù)現(xiàn)代碼在Shawyeok/128-slowbackend，讀者看到這里可以先嘗試通過上面步驟把環(huán)境運(yùn)行起來自己動手分析一下原因。

分析

今天終于抽出時(shí)間來完成這篇文章，讀者在看下面分析過程之前，我建議還是先動手用docker-compose把案例復(fù)現(xiàn)一下，然后自己嘗試分析，分析過程肯定會遇到這樣那樣的問題，直到dead-end或者分析完了再回過頭看我的分析過程，這樣在實(shí)際工作中遇到類似問題的時(shí)候我想更有可能callback。

當(dāng)然，如果你有別的思路和手段分析這個(gè)問題，非常歡迎在評論區(qū)分享你的見解。

下面開始回顧一下我當(dāng)時(shí)記錄的分析過程。

嘗試問題重現(xiàn)時(shí)抓取threaddump（進(jìn)入到backend容器執(zhí)行命令jstack -l <pid>），主要觀察tomcat工作線程池（線程名：http-nio-0.0.0.0-8080-exec-*）的線程狀態(tài)，發(fā)現(xiàn)都是處于等待從線程池隊(duì)列獲取任務(wù)的狀態(tài)，并未見工作線程卡在一些業(yè)務(wù)操作上：

"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

同時(shí)通過在服務(wù)提供方tcpdump抓包分析，到目前分析結(jié)論是延遲發(fā)生在backend這一端（但并不能再縮小問題范圍，kernel處理慢或者內(nèi)部隊(duì)列堆積都有可能）：

為了縮小問題范圍，嘗試開啟tomcat的訪問日志和內(nèi)部DEBUG日志，看請求具體什么時(shí)間點(diǎn)到達(dá)tomcat的隊(duì)列，什么時(shí)間點(diǎn)開始執(zhí)行用戶代碼，以及什么時(shí)候處理完的，這樣就可以進(jìn)一步確定延遲發(fā)生在哪個(gè)過程。

# 程序啟動添加下面參數(shù)
# 開啟tomcat訪問日志
--server.tomcat.accesslog.enabled=true
# 開啟tomcat內(nèi)部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處理的請求的詳細(xì)過程：

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
...

但這個(gè)時(shí)候注意到一個(gè)Logger比較眼熟：o.apache.tomcat.util.threads.LimitLatch，而且有Limit字眼，難道延遲是由于tomcat內(nèi)部在競爭某種資源？仔細(xì)看這個(gè)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時(shí)真相就在眼前了，卻給忽略了，這很致命~

現(xiàn)在這個(gè)問題表層的原因已經(jīng)清楚了：由于該服務(wù)配置的tomcat連接數(shù)太少，觸發(fā)了LimitLatch限制，阻塞等待老的連接釋放（這點(diǎn)可以通過抓包分析得以驗(yàn)證，被阻塞的請求得以響應(yīng)之前總是有一個(gè)TCP連接釋放）

查看源碼中src/main/resources/application.yml文件，有如下配置：

server.tomcat.max-connections: 10

這里因?yàn)槭亲詈啅?fù)現(xiàn)Demo，這個(gè)配置單獨(dú)放在這里是非?？梢傻?，然而現(xiàn)實(shí)情況中它可能隱藏在大量的配置中，你未必能注意到，特別是線上排查問題時(shí)往往情況都比較急。

查看當(dāng)前和tomcat 8080端口建立的連接，剛好是10個(gè)，查看spring boot文檔默認(rèn)值是8192（server.tomcat.max-connections），關(guān)于這個(gè)當(dāng)初為什么要添加上面最大連接數(shù)的配置，我就不好細(xì)說了，總之是人為方面的原因。

再看nginx的配置，worker_processes配置為16，是大于10的，因此當(dāng)backend的連接數(shù)達(dá)到10時(shí)，acceptor線程就會阻塞等待，直到有連接釋放，這就是為什么會出現(xiàn)間歇性請求響應(yīng)慢的現(xiàn)象。

worker_processes 16;

解決這個(gè)問題，就是把max-connections的配置刪掉即可，但是這個(gè)問題如果細(xì)究的話你可以還會注意其它的點(diǎn)。

問題的表現(xiàn)，往往以多種形式呈現(xiàn)。

在這個(gè)case中，我們也可以通過ss命令查看tcp syn連接隊(duì)列的當(dāng)前狀態(tài)，會發(fā)現(xiàn)Recv-Q這一列始終大于0，說明有連接正在等待用戶線程accept(2)。

tomcat線程模型

我們看一下tomcat線程模型，在一個(gè)新連接上發(fā)起一次http請求會首先經(jīng)過Acceptor線程，這個(gè)線程只負(fù)責(zé)接收新的連接然后放到連接隊(duì)列中，后續(xù)的解析http報(bào)文、執(zhí)行應(yīng)用邏輯、發(fā)送響應(yīng)結(jié)果都在Worker線程池中執(zhí)行。