解Bug之路-with AI-应用被限流？
有了AI之后，处理复杂问题明显加速了。笔者体感大概加速了3倍吧，以前一个需要一个星期才能探明根因的复杂问题现在估计只需要2天。主要是大部分数据整理/源码阅读/时间线梳理的繁琐操作都已经外包给AI了。这也使得笔者可以有精力可以解决一些看似ROI很低但成因确有点复杂的问题了。和AI的配合还是非常快乐的就...
解Bug之路-with AI-应用被限流？
前言
有了AI之后，处理复杂问题明显加速了。笔者体感大概加速了3倍吧，以前一个需要一个星期才能探明根因的复杂问题现在估计只需要2天。主要是大部分数据整理/源码阅读/时间线梳理的繁琐操作都已经外包给AI了。这也使得笔者可以有精力可以解决一些看似ROI很低但成因确有点复杂的问题了。和AI的配合还是非常快乐的就像和一个不知疲倦的、自己对话一样。不过博客就不让AI代笔了，这么好的锤炼自己思维的机会让AI写那还不如不写。
Bug现场
笔者这一两年做的事情主要是完成了异地多活。在将A城市(单元)的流量全部导入B城市(单元)的过程中，需要时刻紧盯容量。在流量高峰期时候B单元表现的有惊无险。但在非高峰期某个应用却出现了应用限流的告警。为了防止容量有问题，笔者就开始探寻起这次限流的原因。于是观察了一下限流曲线:
%%{init: {"theme":"base","themeVariables":{"xyChart":{"plotColorPalette":"#31C57A, #EF542C"}}}}%%
xychart-beta
title "19:15:50—19:16:10 请求量（绿色：正常｜红色：拒绝）"
x-axis ["50","51","52","53","54","55","56","57","58","59","00","01","02","03","04","05","06","07","08","09","10"]
y-axis "请求数" 1 --> 1000
bar [188,184,215,191,193,181,206,191,174,39,0,0,0,922,223,188,218,206,186,230,269]
bar [0,0,0,0,0,0,0,0,0,0,0,0,0,62,0,0,0,0,0,0,0]
可以看到在19:16:03秒出现了大约60多个请求限流。
流量变大而限流？
如果单看告警，其实很容易就联想到是流量过大而导致限流。但是之前高峰期都没有容量问题，为什么现在非高峰期就有呢？于是笔者看了一下高峰期的数据，请求量大概在400左右，并没有被限流。
%%{init: {"theme":"base","themeVariables":{"xyChart":{"plotColorPalette":"#31C57A"}}}}%%
xychart-beta
title "11:59:50—12:00:10 正常请求（平均 400/秒）"
x-axis ["50","51","52","53","54","55","56","57","58","59","00","01","02","03","04","05","06","07","08","09","10"]
y-axis "请求数" 1 --> 1000
bar [392,405,398,410,387,401,415,394,408,396,402,389,412,397,406,391,404,399,413,386,395]
同一时间，限流只出现在一台机器上，其他机器流量并没有出现类似告警。
%%{init: {"theme":"base","themeVariables":{"xyChart":{"plotColorPalette":"#31C57A"}}}}%%
xychart-beta
title "19:15:50—19:16:10 正常基线（平均 200/秒）"
x-axis ["50","51","52","53","54","55","56","57","58","59","00","01","02","03","04","05","06","07","08","09","10"]
y-axis "请求数" 1 --> 1000
bar [194,207,199,203,191,212,205,197,208,196,201,189,214,198,206,193,210,195,204,188,190]
那基本就否定了流量变高导致限流问题。现在就能直接锁定到单台机器有问题。
开始分析单机问题
笔者仔细看了一下限流图，相对于正常机器来说，就感觉是应用机器在19:16:59-02秒基本没有处理数据，而是将这些堆积的数据全部放到了19:16:03秒这一秒来处理。仔细算一算这5秒的平均QPS为204QPS，和这个20s的平均QPS基本一致(200左右)。如下图所示: 
那么很直观的，限流本身是果而不是因。由于某些因素导致了应用机器停止处理请求，hang住了4s。行，那就进入单机下钻环节。
首先怀疑GC
应用停止处理请求，这种最容易想到的肯定就是GC STW了。所以笔者就直接去寻找GC日志。因为当前限流监控已经到秒了，我们应该很容易根据日志时间戳判断因果关系(但要仔细甄别时间戳生成时机)。因为用的是JDK8，所以直接去GC日志中去寻找Young GC和Full GC出现的证据。结果是笔者喜闻乐见的在那4s内无Full GC，无Young GC。不过，也并不是一无所获，找到了关键日志:
XXXX-XX-XXT19:15:50.257+0800: 5979920.364: Total time for which application threads were stopped: 0.0248718 seconds, Stopping threads took: 0.0001490 seconds
XXXX-XX-XXT19:16:03.209+0800: 5979933.316: Total time for which application threads were stopped: 3.9391212 seconds, Stopping threads took: 3.9355932 seconds
XXXX-XX-XXT19:16:03.216+0800: 5979933.323: Total time for which application threads were stopped: 0.0023041 seconds, Stopping threads took: 0.0005402 secondsStopped 3.9s！这不就和我们限流被卡顿的4s一致么，看来是突破口。这段日志记录的是JVM为了等所有的线程到SafePoint而花的总时间。对比它之前和之后的两条日志，其它的只花了0.5ms。而这次花了3.9s，下一步就是分析为什么花了这么长时间了。
探寻机器指标
因为正常SafePoint的等待时间只有0.5ms，3.9太过巨大叠加流量没有任何变化以及只有这台机器出问题。很容易的，笔者去猜测这台机器出现了某些不寻常的事件，那么很直观的就去观测机器的一些常用指标。
CPU指标的矛盾
这一看就发现了反常的现象。在CPU的秒级监控中(实际是10秒的精度)，在19:16:00这个采样点里面CPU.busy跌0了，而且是cpu.system/cpu.user都跌0，监控读数大约是0.12左右。
%%{init: {"theme":"base","xyChart":{"width":900,"height":500},"themeCSS":"g.line-plot-0 path { stroke:#3478E5 !important; stroke-width:4px !important; }","themeVariables":{"xyChart":{"plotColorPalette":"#3478E5"}}}}%%
xychart-beta
title "cpu.busy"
x-axis ["19:15:30","19:15:40","19:15:50","19:16:00","19:16:10","19:16:20"]
y-axis "cpu.busy (%)" 0 --> 15
line [11.7,12.3,11.9,0,12.4,11.8]
但是，另两个能够反映容器CPU使用率的指标nr_throttled_delta(容器由于CPU被限额次数)和throttled_time(容器由于CPU被限额时间)却有增长。一个从0跳变为4，一个从累计的39.0s跳变为42.9s(累计差值刚好3.9s)
%%{init: {"theme":"base","themeCSS":"g.line-plot-0 path { stroke:#3478E5 !important; stroke-width:4px !important; }","themeVariables":{"xyChart":{"plotColorPalette":"#3478E5"}}}}%%
xychart-beta
title "nr_throttled_delta（分钟级）"
x-axis ["19:14","19:15","19:16","19:17","19:18"]
y-axis "nr_throttled_delta" 0 --> 5
line [0,0,4,0,0]
throttled_time刚好是3.9s
%%{init: {"theme":"base","themeCSS":"g.line-plot-0 path { stroke:#3478E5 !important; stroke-width:4px !important; }","themeVariables":{"xyChart":{"plotColorPalette":"#3478E5"}}}}%%
xychart-beta
title "throttled_time（分钟级）"
x-axis ["19:14","19:15","19:16","19:17","19:18"]
y-axis "throttled_time（秒）" 38 --> 44
line [39,39,42.9,42.9,42.9]
这个3.9s和SafePoint的3.9s实在是有点一样，难道就是这个throttled_time导致的？不过这个和秒级监控有矛盾，19:16:00的秒级监控CPU消耗是0，但throttled指标又提示我们CPU正在剧烈消耗。不过仔细一想，其实这个矛盾还是能解开的，因为throttled这种指标是分钟级的，它可能是在19:16分这一分钟内出现的，而不是在那次CPU秒级采样的19:15:50-19:16:00这个采样时间内出现。至于CPU跌0原因后面有讲，跟物理机相关CPU都消耗在iowait导致容器CPU时间片没记帐有关。
分析CPU Throttle
那能不能根据这两个一模一样的3.9s(throttled 3.9s和SafePoint卡顿3.9s)判定出来是由于throttled导致的SafePoint呢。这时候就需要看看CGroup的原理，看下CPU Throttle真的能让整个容器失去响应达到3.9s之巨吗？这时候就需要AI出马了，直接让AI分析Kernel代码以及相关资料。AI给出的答案是基本不可能，因为CGroup的quota补充周期是cpu.cfs_period_us。当前机器配置的是100ms
cpu.cfs_period_us=100000 # 100ms也就是说每隔100ms，容器就会被重新补偿时间片quota。那容器就依旧有时间运行，那容器中的应用应该呈现的是一种锯齿状的抖动状态，而不是像静止了一样，hang住3.9s。同时，看一下nr_throttled_delta是4，也就是每一次出现cpu throttled就会平均有1s的throttle，那除非throttled是一直连续的，那么达不到throttle的效果。
假设，一次性用了太多时间片，导致被限流
于是笔者提出了一种假设，在100ms之内，容器用了太多的时间片(例如用了3900ms的时间片)，导致后续一直被限流。好的，直接交给ai去看linux源代码吧(Linux-4.18.10)。结论就是，整个Cgroup容器会被重置quota，对于具体用超了的cfs_rq也就是容器对于某个CPU的账本会由于上次用超了导致这次会被惩罚，但整体容器的时间片quota(额度)是不会由于上次用超而导致这次减少的，具体代码可以看:
void __refill_cfs_bandwidth_runtime(struct cfs_bandwidth *cfs_b)
{
u64 now;
if (cfs_b->quota == RUNTIME_INF)
return;
now = sched_clock_cpu(smp_processor_id());
/* 新周期全局池直接恢复为完整 quota */
/* 看这边直接是通过等于号赋值，而并没有计算上次用超的数据 */
cfs_b->runtime = cfs_b->quota;
cfs_b->runtime_expires =
now + ktime_to_ns(cfs_b->period);
cfs_b->expires_seq++;
}然后，笔者又追问了一下，一次周期中cgroup能烧穿多少时间片。ai给出了一个结果，由于一次调度记帐间隔是1ms(当代服务器物理机配置的CONFIG_HZ基本都是1000，也就是1HZ为1ms)。而每次记帐最多取5ms，所以在通常情况下如果128核物理机最多会烧穿128*5为640ms(当然这个是上界)。所以远远填不平连续hang 3900ms这样巨大的数字鸿沟。而且由于直接重置而不会跨周期累积的原因(注意，这个是cgroup整体不是累积，单cfs_rq还是会补偿之前烧穿的时间片的)。所以这个throttle的3.9s完全无法解释SafePoint的3.9s。 另外，笔者看到ai给出的结果后，笔者突然就想到，ai计算的throttled_time是时间片，而我们找到的SafePoint卡了3.9s确实墙钟(wallclock)。由于我们的容器配置的是8核，那么其实按照8核计算出来，我们在3.9s throttled_time时候感知到的墙钟(wallclock)应该是3.9/8也就是0.5s左右。
timeline
title 8 核并行限流：throttled_time 与 wall-clock 换算
0.0 秒 : 8 个 CPU 核同时开始被限流
: 累计 throttled_time = 0
0.1 秒 : 累计约 0.8 核·秒
0.2 秒 : 累计约 1.6 核·秒
0.3 秒 : 累计约 2.4 核·秒
0.4 秒 : 累计约 3.2 核·秒
0.4875 秒 : 累计 throttled_time = 3.9 核·秒
: wall-clock ≈ 0.5 秒
ai看代码实在是太过强大而且方便，这导致笔者生成假设-推翻假设的速度快了数倍。不过这一轮讨论中，ai也展现出了它的局限(GPT 5.6)，他也和我一样，对于两个3.9s的相似性出现了过拟合，觉得throttle的3.9s就导致了SafePoint的3.9s，并不会主动去考虑其中隐藏的矛盾。只有笔者去持续追问其中的矛盾，他才会逐渐去展开，就感觉是我的Prompt逐渐激活了他的神经元。
CPU throttle出现在什么阶段
由于CPU throttle是分钟级的统计而且出现在19:16分，同时我们的SafePoint的hang时间是是从19:15:59到19:16:03,这个时间太过于接近无法分辨这两的先后。于是我们可以考虑通过CPU的秒级指标来判别，容器本身的cpu.busy的时间是这样计算的:
CPU.busy = (cpuacct.usage(T秒) - cpuacct.usage(T-10秒))/((10秒)*CPU配额数)由于刚才在19:16:50-19:16:00出现了跌0的现象，明显就无法造成cpu throttle。那CPU throttle就只能出现在19:16:00之后，而在19:16:00-19:16:03的时候笔者看了下日志，整个应用的JVM都在等SafePoint，这段时间内没有任何日志输出同时看限流也没有处理任何请求，仅仅靠无法到达SafePoint的某几个线程烧穿8C的Quota也基本不可能。所以笔者倾向于这个CPU throttle实在业务恢复之后由于一瞬间处理了大量的请求导致的CPU疯狂消耗进而产生了throttle。为了辅助证明这一点，笔者就开始通过分析日志时间戳的连续性来判定。
将日志改造为示波器来辅助判定cpu throttle是否出现在业务恢复后
鉴于对于cgroup的了解，一旦在一个cgroup cfs周期内quota被烧穿，后续的cfs_rq在用完自己残留的时间片后会陆续被kernel给throttle，整个cgroup也就是容器应该会呈现出近似STW(Stop the world)的冻结状态，也就是无任何输出，这样就会产生日志空洞，再根据刚才ai对于linux kernel源码的剖析，这个空洞最多也就100ms。 根据上面的特性笔者就可以将日志改造成CPU throttle的示波器，没有秒级指标，我们可以自己造!但是，这个日志输出空洞的判定有两个漏洞:
1.GC会导致STW，进而会导致日志黑洞
|->针对这个问题，只需要在初步计算出的日志空洞基础上排除掉GC时间点即可
2.本身这段时间内就没有请求也会导致日志黑洞
|->针对这个问题，其实有两个筛选条件。第一，根据限流指标看，后续业务恢复后会有一个集中处理的阶段，这时候日志时间戳应该非常连续。所以只需要将日志和之前正常时候的平均QPS比较，只需要取恢复后的那几秒明显高过平常QPS的做日志空洞判定即可。
|->正常时刻业务的流量基本是平稳的，看正常时刻的分布可以推断出一个最大日志时间间隔(当然是去掉了GC的情况)，用这个阈值来筛选日志黑洞。好的，交给AI去写脚本分析吧。分析结果如下:
19:15:50-19:15:58 也就是流量正常的时候，每秒日志量约1100左右。这时候最大的日志空洞也就2ms。
19:15:59.300 - 19:16:03.209 没有任何输出，只在209的时候打印出等待SafePoint为3.9s
19:16:03-19:16:04 这一秒内，集中打印了4500条日志(如果按照流速连续，平均日志空洞应该是0.22ms)
|->在19:16:03.292 打印了AsyncAppender …… queue is full这条日志
|->19:16:03.311->19:16:03.370 有59ms的日志空洞
|->19:16:03.399->16:03.419 有20ms的日志空洞
|->19:16:03.447->19:16:03.516 有69ms的日志空洞，有69ms YGC
|->19:16:03.517->19:16:03.537 有20ms的日志空洞
|->19:16:14.690 YGC 23.5ms，平稳状态对照GC
|->19:16:26.575 YGC 24ms , 平稳状态对照GC
注意，这里的时间戳是log4j在事件生成的那一刻获取的。通过日志输出量分析，在应用恢复后的那一秒有一次集中的请求处理泄洪区，在泄洪的时候出现了明显不正常的日志空洞，在扣掉YGC后。这几个空洞就高度怀疑为CPU被throttle了。当前看到扣除YGC有3段是大于等于20ms的，尤其是一开始的59ms最为令人瞩目。
flowchart LR
subgraph ABNORMAL[" "]
direction LR
AT["异常窗口分区"]:::abnormalTitle
A["03.292<br/>AsyncAppender<br/>queue is full"]:::logged
B["03.292–03.311<br/>有日志"]:::logged
G1["03.311–03.370<br/>空洞 59ms"]:::gap
C["03.370–03.399<br/>有日志"]:::logged
G2["03.399–03.419<br/>空洞 20ms"]:::gap
D["03.420–03.446<br/>有日志"]:::logged
G3["03.447–03.537<br/>日志空洞<br/>YGC 69ms<br/>含 03.517–03.537 空洞20ms"]:::gap
E["03.537 后<br/>日志恢复"]:::logged
AT --> A --> B --> G1 --> C --> G2 --> D --> G3 --> E
end
subgraph STABLE[" "]
direction LR
ST["平稳状态对照分区"]:::stableTitle
F["19:16:14.690<br/>YGC 23.5ms<br/>日志正常"]:::logged
H["19:16:26.575<br/>YGC 24ms<br/>日志正常"]:::logged
ST --> F --> H
end
E -. 对照 .-> ST
classDef logged fill:#dcfce7,stroke:#16a34a,color:#14532d,stroke-width:2px;
classDef gap fill:transparent,stroke:#9ca3af,color:#374151,stroke-width:2px,stroke-dasharray:6 4;
classDef abnormalTitle fill:#ffedd5,stroke:#f97316,color:#9a3412,stroke-width:3px,font-weight:bold;
classDef stableTitle fill:#bbf7d0,stroke:#16a34a,color:#14532d,stroke-width:3px,font-weight:bold;
style ABNORMAL fill:#fff7ed,stroke:#f97316,stroke-width:2px
style STABLE fill:#f0fdf4,stroke:#22c55e,stroke-width:2px
日志并没有打印任何cpu throttle的信息，但日志不打印确可能泄漏出蛛丝马迹。啊哈，有时候我们并不需要对某个隐藏状态(cpu throttle)增加更细粒度的观测，而只需要找到一个能够随这个隐藏状态稳定变化的已有数据去表示它就行。
数据对齐-nr_throttled_delta监控为4
由于nr_throttled_delta本身是对于内核nr_throttled在两个时间点做的差值，所以肯定是准确的。但是在泄洪时间段的这1s内只找到3段疑似throttle+1段YGC，为什么会为4呢？问了下ai，ai告诉我很有可能是在后续平稳期出现了一次。但系统平稳期CPU消耗非常平稳，以前也不出throttle，没道理后续平稳期出了。于是笔者看了一下泄洪区的YGC和平稳区的YGC，一个69ms，一个23ms，不会是YGC的时候也夹杂了cpu throttle吧，于是直接让ai做数据对照。在同样Eden/Heap的分布下，YGC在泄洪区的耗时为69ms，而平稳期只需要23ms。所以很有可能在YGC的这一个的cgroup周期内也发生了一次throttle。这样3+1就可以解释nr_throttled_delta为4。当然，这里并不是强行认定nr_throttled_delta的4次和这3+1是一一对应的。但是，笔者自己造的示波器给出的日志空洞区间可以非常好的将nr_throttled_delta这个监控指标给对齐。
下一个问题，泄洪区的GAP能否造成3900ms的cpu throttle
我们有4段GAP，一个59ms，2个20ms，YGC满打满算中间夹杂(69-23)=46ms。那么也才（59+20+20+46)=145ms。是如何造成3900ms的这样的巨大的统计值的呢。这时候，笔者突然想到，我们的CPU配额是8C，每个核全部throttle也就才1160ms，这个数据完全对不上。如果按照监控的展示，我的每个日志空洞加起来需要3900/8=487.5的gap才对。难道在应用恢复过来之前就有大量的throttle了？ 但以笔者和ai对cgroup的理解，如果throttle的话就应该是刚才我们日志展示的断断续续的小空洞，而应用恢复过来之前是一个3.9s的大空洞，也解释不通。既然解释不通，那我不得不怀疑起throttled_time到底是怎么计算的，直接让ai去读源代码吧。
throttled_time怎么计算的
ai读了一会给出了答案:
throttled_time =
Σ 每个 CPU 的每次
(unthrottle 时刻 - throttle 时刻)源码如下:
void unthrottle_cfs_rq(struct cfs_rq *cfs_rq)
{
struct rq *rq = rq_of(cfs_rq);
struct cfs_bandwidth *cfs_b = tg_cfs_bandwidth(cfs_rq->tg);
cfs_rq->throttled = 0;
update_rq_clock(rq);
raw_spin_lock(&cfs_b->lock);
/* 在每次解除限流的时候对响应的cpu账本+time*/
cfs_b->throttled_time +=
rq_clock(rq) - cfs_rq->throttled_clock;
list_del_rcu(&cfs_rq->throttled_list);
raw_spin_unlock(&cfs_b->lock);
/* ... */
}还非常贴心的指出，我的容器是8C，那么可以远大于100ms，因为是这个是时间片的累加而不是墙钟。我Review了代码后表示认同。但这个还是无法解释为什么会有3900ms，因为8C最多不就800ms么。这时候我继续翻看监控日志，发现这时候在19:16分线程涨了200多个。如下图所示:
---
config:
themeVariables:
xyChart:
plotColorPalette: "#2563EB"
---
xychart-beta
title "分线程数量变化"
x-axis ["19:13", "19:14", "19:15", "19:16", "19:17", "19:18"]
y-axis "线程数（个）" 0 --> 700
line [400, 400, 400, 600, 400, 400]
笔者稍微思索一下就知道了，这个肯定是线程池来不及处理了紧急扩容线程了。这个扩容不是重点，但是让笔者突然有了一个灵感，这200多个线程在8C之内是如何分布的，一共600个线程抢占8个核是不是在疯狂切换，这样岂不是处理起来很慢，但看日志的处理速度并不慢啊1s内处理完了。
等等，真的只有8核在处理吗
等等，真的只有8核在处理吗，我们容器展示的8核和物理机的8核根本不是同一个概念。容器8核的意思是只在单位周期内分配8核相应的时间片，也就是100ms内最多让你用800ms的时间片，并没有限制最多只用到8核！而且我们的容器并没有进行绑核，也就是说他理论上可以用到物理机上的所有核，也就是128核！
重新解释throttled_time的意义
在想通了这个环节后，笔者就突然发现throttled_time其实在一个周期内8核最多使用800ms并没有太多关系。因为很简单的，如果我一次性用128核在前6.25ms之内用满时间片，然后128个核等(100-6.25)*128=12,000ms可以轻轻松松超越3900ms！那么对应于59ms的日志黑洞我们可以根据作出一个什么模型呢?笔者的推理如下: 59ms的日志黑洞，可以认为应用容器等待了59ms，在一个100ms周期内有41ms是疯狂烧CPU的。在41ms烧光了800ms的CPU quota，那么平均疯狂run的线程数就是800/41=20个就可以达到这个效果，然后其余分布在其它核上的多个线程run的时候发现时间片没了，就会加入到throttled_list然后开始累计throttled_time。如果一次日志空洞要累计到3900ms，那么就可以算出用到3900/59=66核(精确描述应该是66个cfs_rq)，当然了这个只是一个上界估算。因为还有其它的日志空洞参与计算。
也就是说少数线程烧穿CPU额度会在未绑核情况下将throttled_time给急剧放大！如下图所示: 
CPU Throttle的原因
在笔者想通了墙钟与时间片的区别/8核只是时间片而不是实际核数以及throttled_time会被多核放大后，基本就已经确信这个3900ms的CPU Throttle实在应用恢复泄洪后疯狂处理导致的了。而且日志中的空洞也能佐证。
CGroup的CPU quota机制
在这里总结一下CGroup的CPU quota机制吧，也是乘着这次的问题好好重新了解了一下cgroup的机制。主要是下面这7点: 1.cfs_rq 是一个cgroup在某个CPU上跑的一个账本专门记录的使用情况runtime等，记为cfs_rq。每个cfs_rq运行时，在tick/sched调度等路径的时候，会进入delta_exec计算，也就是计算当前的bandwidth够不够。tick是1ms一次(CONFIG_HZ配置的是1000)。CFS_RQ每次获取的时候先计算本地够不够，不够就向总帐本(全部cfs_runtime)拿5ms。一旦全局cfs_runtime耗尽了就会进入throttle(严格来说不是直接在这个路径上throttle，而是在调度器中)。加入throttled_cfs_rq列表，记录当前的throttled_clock时间点。 2.一段时间之后，所有的cfs_rq都可能由于在获取cfs_runtime的时候耗尽，同时自己本地也耗尽后，而进入throttle。值得注意的是，cfs_rq可能分布在整个物理机上(如果不绑核的话，当然了NUMA Node可能只会倾向于一半)。 3.nr_throttled的计算。然后重点就来了，我们注册的定时timer,100ms运行一次的那个(可配置)在触发后会进行cfs_runtime的重新分配。不同的cgroup会有不同的timer，所以这些cgroup间相位不同。在这个timer中，如果发现一旦throttled_cfs_rq列表不为空则会对nr_throttled+overrun(大部分情况下为1)。 4.throttled_time的计算: throttled_time 是在每个 cfs_rq 被 unthrottle 时累加的，每次累加值为(当前clock-当时记录的throttled_clock)。 这个unthrottled的时间其实是在refill之后，相应的cfs_rq被重新激活的时候加上。但是我们手工计算的时候就可以直接遍历累加。 5.然后重新refill时间，refill的时候直接给cfs_runtime赋值，不会惩罚之前溢出的部分。但是这个是对全局cgroup runtime不追债，但是对单个cfs_rq需要补平之前的可能的负值，不过溢出较小，因为slice是5ms 6.这样就会造成下面这种现象:如果我们物理机器是64物理核=>逻辑核128C。那么一个CGroup我们按照极端情况128个CFS_RQ，其中只有几个CFS_RQ耗CPU特别多，而且在第50ms的时候这几个CFS_RQ吃完了quota，那么其他的100多个CFS_RQ也可能被迫加接近50ms这个throttled_time。这也就特别像我们应用的工作模型，那几个积压的日志的CFS_RQ消耗CPU特别高，其他大部分是在处理IO，占CFS额度很少。当然了，可能没有这么多，因为CFS_RQ在runnable的时候才会加上throttled_time。我们做一个最简单的模型，就是128个CFS_RQ,16个在那狂烧，其余112个基本不烧但由于时间片耗尽进入了throttled状态，那么16个在50ms内就会少玩，然后这128个就会拉大throtted_time。当然了也有可能其余的也贡献了不少，那么狂烧的cfs_rq就可能只有8个或者更低。总结一下: 少数热点 cfs_rq 在前 50ms 烧完 quota；随后所有在剩余 50ms 内处于 runnable的很多cfs_rq很有可能大部分都在激活后都进入了throttle一起贡献throttle时间，从而把 throttled_time 大幅放大。 7.但是，虽然这么多被狂烧，nr_throttled=4在8C限额下完全能烧出throttled_time=3.9s(上界其实是12.8s-0.8s[因为要算本身的quota]=12s)的效果。但这throttled_time是时间片，不是墙钟。所以很有可能我们感受到的是墙钟50ms，但是throttled_time就有可能达到(6.4s)!注意:这里不用减0.8s的quota
继续探寻SafePoint 3.9s原因
好的，在笔者经过一轮分析后，基本排除了CPU throttle是SafePoint 3.9s hang的原因。那就得看看是什么其它原因了。还记得我们那个诡异的CPU busy跌0吗，如果排除了throttle的原因，那么很有可能是被什么东西给卡住了导致所有的线程不再运行，能卡住的大概率是IO问题。既然是IO问题，我们就去宿主机上找相应的监控吧。这一看果然发现了，秒级监控里面宿主机的cpu.busy是43%(这可是128核)，但是cpu.user和cpu.system只有13和2，大部分的CPU贡献给了iowait高达28%。(注意:当前物理机监控的cpu.busy = 1 - cpu.idle，所以iowait是参与busy计算的)。如下图所示:
%%{init: {
"theme": "base",
"themeVariables": {
"xyChart": {
"plotColorPalette": "#2563eb, #16a34a, #f59e0b, #dc2626"
}
}
}}%%
xychart-beta
title "蓝=CPU.busy｜绿=CPU.user｜橙=CPU.system｜红=CPU.iowait"
x-axis ["15:30", "15:40", "15:50", "16:00", "16:10", "16:20"]
y-axis "CPU（%）" 0 --> 50
line [15.0, 15.5, 15.2, 43.0, 15.4, 15.0]
line [12.7, 13.3, 12.9, 13.0, 13.2, 12.8]
line [2.1, 1.8, 2.2, 2.0, 1.9, 2.1]
line [0.2, 0.4, 0.1, 28.0, 0.3, 0.1]
这证实了是IO的说法，这时候很自然的笔者就去翻是不是磁盘坏了，如果这么长时间磁盘的平均耗时肯定特别长。然后不出所料的，有一块盘的disk.io.msec_write在故障时间达到了2.09K也就是2.09s。如下图所示:
%%{init: {
"theme": "base",
"themeVariables": {
"xyChart": {
"plotColorPalette": "#3478f6"
}
}
}}%%
xychart-beta
title "disk.io.msec_write/device=sde"
x-axis ["19:15:30", "19:15:40", "19:15:50", "19:16:00", "19:16:10", "19:16:20"]
y-axis "msec_write(ms)" 0 --> 2200
line [180, 250, 210, 2000, 260, 190]
在此我们又需要看一下这个msec_write是怎么计算的了，让ai翻了下公式:
disk.msec_write = (/proc/diskstats/msec_write当前 - /proc/diskstats/msec_write60s前)/60也就是说，在这60s内平均每秒的IO耗时累计达到了2s。对比故障之前只有260ms的情况，可以推算出在这60s内IO累计耗时多了(2.0960-0.2660)=109.8s。由于这个监控是分钟级取平均，所以单次IO耗时长达3.9s甚至几十秒都有可能！ 好了，可以确定磁盘的问题了，去找SA去看一下是否有磁盘坏道，SA反映确实有坏道，而且很久之前就扫描出来坏道只不过一直没有处理而已，坏道数量呈现增加态势！
磁盘故障为什么会引起SafePoint卡顿
好了，既然我们已经找到了RootCause也就是磁盘坏道，磁盘监控已经完全证实了这一点。笔者下一步的就是需要解释磁盘为什么会导致SafePoint有问题了。这种事情先让ai(GPT)答吧。GPT很快给出了推测，某个线程打日志的时候卡了，导致SafePoint迟迟不能到达。笔者立马提出了反驳，打日志的时候是不是safepoint-safe的，对于磁盘IO这种进入native状态的操作按照笔者的理解都应该是safepoint-safe的。ai回复有道理，然后看了一圈发现确实磁盘卡顿应该无法影响safepoint，提示我换其它的方向。于是，笔者只能靠自己来思索了。
猜想1:打GC日志本身卡住了
好的，笔者第一个猜想，打GC日志本身卡住了。如果在打印GC日志的时候hang住，是不是也会导致整体陷入STW停滞的状态。当时的应用日志为:
xxxx-XX-XXT19:16:03.209+0800: 5979933.316: Total time for which application threads were stopped: 3.9391212 seconds, Stopping threads took: 3.9355932 seconds好的，直接交给GPT去看JVM源代码吧。GPT给我找出了相关源代码(简化过的伪代码).
void SafepointSynchronize::end() {
// 修改 safepoint 状态
_state = _not_synchronized;
// 重置线程状态，但线程此时可能仍阻塞在 barrier 上
for (JavaThread* thread : all_java_threads) {
thread->safepoint_state()->restart();
}
// 记录 Total，并打印日志
RuntimeService::record_safepoint_end();
// 日志输出完成后，才真正唤醒线程
Threads_lock->unlock();
_wait_barrier->disarm();
}还真是，打日志确实还是在恢复STW之前，这条日志卡住确实有可能将JVM给卡住。但是笔者又给GPT提出问题了，让他看日志中有两个时间，一个是3.9391212s，一个是3.9355932s。这两个时间戳的计算能否和打日志这个猜想对上。GPT看了以后，告诉笔者是对不上的，因为计算耗时的两个时间戳是在SafePoint Begin的时候和End的时候计算的，在这里没有GC日志参与的地方。所以这个3.9s肯定是等待线程全部到达SafePoint的时间。并提示笔者如果想知道到底是什么卡住了SafePoint的话，可以加上:
-XX:+SafepointTimeout
-XX:SafepointTimeoutDelay=500不过这个猜想虽然被推翻了，但也不是完全没有价值。这一次是等SafePoint卡了，说不一定下一次就是这一块打印GC日志的时候卡了，所以一些会导致JVM hang住的日志可以放到tmpfs下面。
一点碎碎念
其实，这个问题只是一个应用的一台机器稍微卡了4s，还是个回调链路，业务方是很难配合笔者去加这个参数的。而且这种磁盘卡顿导致整个JVM卡死的也是非常罕见，作为对比用一台物理机上其它应用虽然打印日志也卡了但是并没有STW。在这种条件下，基本不可能是拿到直接根因的。不过话说回来: 无直接证据下的溯因何尝不是一种乐趣，线上由于资源问题不可能去获取所有的数据，在这种受限条件下的推理才是挑战的乐趣所在，在追逐问题的过程中不知不觉破除了好多迷雾！
猜想2: 缺页异常导致Kernel取读磁盘上的backend文件
首先，在这里提示一下，下面只是笔者根据线上各种监控指标日志以及JVM/Kernel源代码进行的推理了，并没有直接的证据来证明笔者的猜想是正确的，只是这个猜想可以解释所有的数据。
那笔者的下一个假设就来了，是不是有可能某个线程在运行过程中发生了换页，也就是某一段代码路径不在磁盘上然后通过IO路径去磁盘上读了。但笔者想想，就真的这么巧么？正好在磁盘卡顿的时候触发了某个冷路径？首先，笔者就去看一下如果出现缺页异常去找backend文件的话，宿主机肯定要有major fault的监控指标。于是看了下宿主机的pgmajfault.delta指标，发现平常就是至少有50的major fault。也就是说，这个猜想是有可能的。
冷门分支导致读磁盘
咦？笔者转念一想，冷路径？磁盘IO卡顿这个不就是冷路径吗？尤其是那个queue is full的路径这么长时间还是第一次看见，在这个情况下肯定是冷的啊！好的，让AI分析这个可能性。ai给出了一系列的可能性，尤其是log4j在queue满之下的一堆分支。
AsyncLogger.handleRingBufferFull
AsyncLoggerDisruptor.getEventRoute
DefaultAsyncQueueFullPolicy.getRoute
AsyncLoggerDisruptor.enqueueLogMessageWhenQueueFull
StatusLogger.logMessage
……不过ai指出除非更好命中那个磁盘坏道才有可能达到3.9s，真的那么巧吗？不过笔者转念一想，我们线上是HDD磁盘，一旦命中磁盘坏道所有都堵在IO路径上，当时应该基本上所有的IO都卡住才对，AI也认同了我的想法。但下一个问题又来了，这些冷分支和热分支都是在同一个class里面，那整个class的字节码应该是随整个class一起加载了，应该不会触发从磁盘读取才对。
code cache swap了后导致读磁盘
那笔者又顺着这个提出了另一个猜想，慢速代码路径的code cache被swap进了磁盘，自然使用这段路径的时候从swap加载导致卡顿。然后笔者看了一下swap指标，完全没有swap波动，所以这个假设也被否决了。
JIT本身冷门路径磁盘
笔者作为ENTP，其实最不缺的就是提出假设，有了ai之后分析假设实在太快了。笔者就直接提出新的假设，JIT本身是冷路径，因为JIT用的是libjvm.so等，这种文件本身存在的如果一旦长时间不用就直接从page cache驱逐，并不需要swap。如果发生了JIT，那应该code cache的大小会有波动。于是笔者看了下监控指标，果然有波动，增加了0.06M！这个code cache在一个月前就已经不增长了，只在那19:16分故障的那一刻增长了0.06M!如下图所示:
%%{init: {
"theme": "base",
"themeVariables": {
"xyChart": {
"plotColorPalette": "#3478f6"
}
}
}}%%
xychart-beta
title "jvm.memory.codecache.used（19:16:00 增加 0.06MB）"
x-axis ["19:15:30", "19:15:40", "19:15:50", "19:16:00", "19:16:10", "19:16:20"]
y-axis "Code Cache 已用量（MB）" 116.68 --> 116.78
line [116.70, 116.70, 116.70, 116.76, 116.76, 116.76]
那JIT本身是不是safepoint-safe的呢？这种问ai就行了，ai其实给出来JIT本身有很多不safepoint的地方。 下面是AI的回答:
传统 C1/C2 的主体编译阶段 safe，但 CompilerThread 的整个生命周期并非始终 safe；JVMCI、编译前后、初始化、队列选择及 JIT 生成代码本身，都存在延迟 safepoint 的可能。那笔者进一步追问，我需要找到在磁盘IO卡顿情况下，没有swap而且JIT不safepoint-safe的而且冷门的分支路径是什么。ai搜索了半天，给出了一个非常有可能的回答啊，就是反优化(uncommon trap):
rare branch
→ uncommon trap
→ 业务线程进入 _thread_in_vm
→ deoptimization / method resolution / class resolution
→ 触碰冷的 libjvm.so、CDS 或 class/JAR 文件页
→ major fault 遇到磁盘卡顿
→ 业务线程无法变成 safepoint-safe而且反优化可能触发后续重新编译也会造成code cache增长。同时ai也告诉笔者在第一次进入了冷门分支的时候就有可能进入deoptimization这样的反优化。如果对应于当前的情况，最有可能出现的就是queue is full也就是日志队列满这样的反优化！于是笔者看了下queue is full是什么时候打印出来的，然后发现竟然是3.9s之后！但是转念一想，反优化肯定是先反优化这时候读到libjvm.so的冷路径卡住3.9s，然后才能打印出来，也并不矛盾!不过3.9s之后queue is full之前竟然还有一些业务日志输出。不过笔者看了一下，queue is full是StatusLogger而且是以error输出。而且error在生成时间戳之前有一大堆链路，所以queue is full的日志时间戳以及输出顺序已经无法用来判定事件顺序了。 所以，在现有条件下，整个导致SafePoint卡住3.9s最有可能的路径就是log4j在队列满的时候触发了冷门路径反优化导致，发生链条为:
首次 queue-full
→ 命中 unstable_if uncommon trap
→ 线程进入反优化/runtime unsafe 窗口
→ runtime 冷代码页或元数据访问发生磁盘 major fault
→ safepoint 等待该线程不过在这里笔者再次申明，这只是最有可能的猜测，由于问题发生的现场基本不可能再复现导致无法获取直接的证据导致无法确认。
整个故事发生的因果链(包含部分最有可能的猜想)
行，这么长时间的篇幅之后，我们可以进行最后的总结了。因果链为:
t1 命中磁盘坏道
t2 线程打印日志卡住，导致queue堆积
t3 jvm进行例行safepoint
t4 等待全部到safepoint花了3.9s
|->这段时间内某些尚未停下的线程发现队列满了
|->磁盘IO导致某个Java 线程迟迟无法到达检查点，导致卡了3.9s
|->这3.9s中最大的可能是jvm本身触发safepoint-unsafe的JIT，触发访问硬盘冷页(例如反优化deoptimize)(这边只是最有可能的猜想)
t5 safepoint恢复之后处理大量累积的数据,触发应用限流
t6 在恢复后的1s内集中泄洪，输出4500条日志，包括业务日志和queue is full(通过日志空洞确认)
|->在这个时间段内出现4次cpu throttle，累积throttled time 3.9s两个监控指标上基本完全相同的3.9s，一个是系统停止的原因，一个却是系统恢复后的回声。
如何优化
其实线上磁盘坏道经常发生，相同的应用在相同的流量下肯定发生了不止一次。不管有没有命中safepoint-unsafe的冷路径都会导致应用请求超时，只不过这次导致JVM整体暂停了而已。要优化这个小概率的事件ROI事实上很低，应用能够自恢复其实已经够了。如果要做到更好，其实可以考虑做下面这几件事情:
1.磁盘坏道到一定程度的机器需要尽快迁移
2.GC日志本身其实受磁盘IO的影响，即使没有这次的hang其本身的IO写入也会影响应用的吞吐，也可以考虑到tmpfs，如果觉得gc日志过大影响tmpfs的容量可以在tmpfs中只保留最近的日志
3.JVM中增加-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=500识别出潜在的safePoint卡顿问题
4.将JVM本身相关的文件例如libjvm.so等放到tmpfs里面总结
这个问题本身其实没有造成任何实际的业务影响，只不过让一些回调延迟了3.9s而已。但整个追寻的过程还是非常坎坷的，无论是throttle time能达到3.9s还是磁盘为什么会导致JVM卡顿3.9s的分析都很复杂。由于线上资源以及很难复现的限制导致基本不可能拿到完整的证据，而这个小问题明显也不值得我们花大力气去复现。在有AI之前，笔者是没有精力去探索的这么深入的。但有了AI之后，由于生成假设推翻假设速度过快使得笔者可以去追寻这样的问题，笔者的体感这个问题可能本来要一周来完成，现在在ai的加持下只需要两天。至于为什么笔者会追逐这种看似ROI很低的问题，那就是，在线上直接证据非常少的情况下如何能够通过各种监控日志数据等将因果收敛其实是一个非常有意思的挑战，也是笔者工作的源动力之一！
关于AI
笔者当前和AI结队TroubleShooting已经很长时间了，计算数据/阅读源码AI是一流的，至少在体力上应该是远超笔者(不过AI对源码的解释不可全信有时候会忽悠你)。但AI在这种线上微弱信号下生成假设的能力还比较欠缺，他最擅长的是加速假设的展开，快速地去推翻或确认。一句话: AI大幅度加强了搜索信息和验证信息的速度，但最开始的方向还需要笔者去把控，否则就会在错误的道路上越走越远。