机器人那条推送甩得直白:下单链路的 P99 由 80 毫秒一路顶到 2.1 秒,落点在 02:40。

天亮前我埋下的那手

头一日还大亮的时候,我把手伸向了那口异步落库的池子。 核心数由 8 挪到 16,队列由 500 抬到 50000。

弄罢我守着曲线瞧了两分钟,没见起伏,人就退了线。

真出事是两点二十四那一格,导库存的批处理准点放闸,一秒朝里灌 50 个落库任务。

拿进量乘上单条耗时倒过来算:50 × 2.1 秒,这摊活要 105 条线程才接得住,可池子里拢共才 16 条。

〈线程池核心线程数和队列长度怎么定,别照抄核数加一〉

这套算法我是原封抄来的,只是往里填数那一下,我手上拿的还是 80 毫秒那个旧值。

把案发的那口井搬回本机

我头一件做的是复现。

我本机是 12 核,JDK 用的 corretto 1.8.0_412。 池子参数是 core 摆 8、max 摆 16、队列撑到 50000,每条任务只干一件事:请求一发出去,就干等那个不肯回话的下游。 我连着丢了 20 个进去:

PID=12200@localhost
PORT=64666 submitted=20 queued=12 active=8 poolSize=8

这 20 里头,八条被线程拽着在跑,十二条候在队列,池子撑死也就八条线。

我把现场抓下来,照着线程名去筛,挑一根把整段栈原样搁这:

"stock-async-3" #14 prio=5 os_prio=0 tid=0x00000237f17dc000 nid=0x7c78 runnable [0x000000a776cff000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:171)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at java.net.SocketInputStream.read(SocketInputStream.java:127)
	at SocketHog$Task.run(SocketHog.java:65)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:750)

那个假下游由我临时捏的,连接照单收下,读完请求就闷声不响。

八条线程配八份栈,各栈顶端不偏不倚,全钉在同一处网络读上。

搁在从前我一直有个死印象:被下游吊着命的那几根线,抓栈该给写成 WAITING (parking)。 经此一回才算把它瞅真切。

真正卡在 socket 上的那几根,标签显示的是 RUNNABLE。

至于 parking,那是另一码事:池子闲下来、线程挂在取任务那步上空睡的那种。

两种搅到一块儿看,现场八九不离十要读拧。

下游、库、GC 挨个过堂

我先把下游这层掀开。

去翻库存服务自己那本访问日志,它的 P99 由 60 毫秒蹦到了 2.1 秒。

60 毫秒早先量过摆着的,是这一波上线一脚把它踹上了两千一。

接着去核库。

头一晚才刚立起的慢查询日志,阈值卡在 1 秒,那一宿添的新条数是零。

DB 这一路就算先排除了。

轮到 GC。

拿 jstat 一瞅,Full GC 的频次比往常多了些,可它跟 RT 的波峰波谷怎么拼都对不齐,我索性先把它撂到一边。

这一撂,是我隔天清早才拍大腿的地方。

堵点既然齐刷刷朝着同一个下游,这笔账当下就摊得开。

16 条线,一条要 2.1 秒才放行一个,整秒合计也就吐 7.6 个,外头涌进来的却是 50 个。

一进一出,一秒净积 42.4,自批处理放闸直到两点四十,前后十六分钟,垒出来恰是四万零七百。

得掰清:四万讲的是那一刹的排队深度,不是队列那堵天花板。

天花板是五万,撑到两点四十四被灌到了头,冒头之后便来一个弹一个:

java.util.concurrent.RejectedExecutionException
Task BigQueue$2@1540e19d rejected from java.util.concurrent.ThreadPoolExecutor@677327b6
[Running, pool size = 16, active threads = 16, queued tasks = 50000, completed tasks = 8]

这行是我在本机复现那趟逼出来的。

把方括号里那三个数摞起来加:16 + 50000 + 8 = 50024,刚好凑成已经落进池子的活儿总数,被弹出去的那位,正排在它身后。

生产上那条原文我没往稿子里搬,句式轮廓一般无二,这些数我没胆替它现编。

〈线程池被说不该用 Executors,自己 new 这几个参数怎么填〉

那篇里我撂下过这么一句:「抄这一行就知道当时是哪种满」。这一遭当真全靠它认的门。

同一份输出里还夹着个细节:队列 50000 这一把,候在里面的 49,984 个没散尽那阵,线程数还钉死在 8。

非要撑到灌满那一刹才肯补到 16,没灌满那会儿还轮不到 max 出手。

接口 RT 蹿到 2.1 秒走的是同步那一条道,堵它的仍是这一个下游。

这 2.1 秒没能捅破 Feign 那侧的读超时上限 3000,于是一个错都不抛,只是干磨人。

我伸手动的那两处

那一晚救火,我统共动了两下。

先说头一下:拒绝策略由 AbortPolicy 临时拨去 CallerRunsPolicy,先观着。 我本机把 core 压到 2、max 也 2、队列只留 4,丢进去十二个,副作用立竿见影:

CALLER_RUNS submitted12 mainRanTasks=3 workerRanTasks=9 submitLoopBlockedMs=324

那条本该只管派发的线程被拽去亲自跑了 3 个,整个派发循环卡了 324 毫秒。

挪到生产,派发的角色由 Tomcat 的工作线程担着,这样的一条足足 200 个。

这路策略任务是真不丢,只是把慢顺手往下游传,而它偏偏传到最扛不住慢的那层。

顶多十分钟,我又把它拨了回来。

再说第二下:打点那几路不算核心的落库先 return 丢掉,把队列匀出来,专门留给扣库存、下单流水去使。

事后回看,我只往仪表上加了三行:在跑的线程数、排队的长度、被打回的次数。

偏偏这三样出那会儿一个都瞧不见,全凭抓栈再加事后扒日志,一截截凑齐的。

末了还有一桩,我没能当场了结。

四万条作业正蜷在队列里,每一条都死死攥着各自那份等着落库的数据,堆被它们一路托着往上冒。

这条线,我是隔日清早靠一份 jmap 快照才捅破的。

Logo

DAMO开发者矩阵,由阿里巴巴达摩院和中国互联网协会联合发起,致力于探讨最前沿的技术趋势与应用成果,搭建高质量的交流与分享平台,推动技术创新与产业应用链接,围绕“人工智能与新型计算”构建开放共享的开发者生态。

更多推荐