前言有了AI之后处理复杂问题明显加速了。笔者体感大概加速了3倍吧以前一个需要一个星期才能探明根因的复杂问题现在估计只需要2天。主要是大部分数据整理/源码阅读/时间线梳理的繁琐操作都已经外包给AI了。这也使得笔者可以有精力可以解决一些看似ROI很低但成因却有点复杂的问题了。和AI的配合还是非常快乐的就像和一个不知疲倦的、自己对话一样。不过博客就不让AI代笔了这么好的锤炼自己思维的机会让AI写那还不如不写。Bug现场笔者这一两年做的事情主要是完成了异地多活。在将A城市(单元)的流量全部导入B城市(单元)的过程中需要时刻紧盯容量。在流量高峰期时候B单元表现的有惊无险。但在非高峰期某个应用却出现了应用限流的告警。为了防止容量有问题笔者就开始探寻起这次限流的原因。于是观察了一下限流曲线:可以看到在19:16:03秒出现了大约60多个请求限流。流量变大而限流如果单看告警其实很容易就联想到是流量过大而导致限流。但是之前高峰期都没有容量问题为什么现在非高峰期就有呢于是笔者看了一下高峰期的数据请求量大概在400左右并没有被限流。同一时间限流只出现在一台机器上其他机器流量并没有出现类似告警。那基本就否定了流量变高导致限流问题。现在就能直接锁定到单台机器有问题。开始分析单机问题笔者仔细看了一下限流图相对于正常机器来说就感觉是应用机器在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.2570800: 5979920.364: Total time for which application threads were stopped: 0.0248718 seconds, Stopping threads took: 0.0001490 seconds XXXX-XX-XXT19:16:03.2090800: 5979933.316: Total time for which application threads were stopped: 3.9391212 seconds, Stopping threads took: 3.9355932 seconds XXXX-XX-XXT19:16:03.2160800: 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.5ms3.9太过巨大叠加流量没有任何变化以及只有这台机器出问题。很容易的笔者去猜测这台机器出现了某些不寻常的事件那么很直观的就去观测机器的一些常用指标。CPU指标的矛盾这一看就发现了反常的现象。在CPU的秒级监控中(实际是10秒的精度)在19:16:00这个采样点里面CPU.busy跌0了而且是cpu.system/cpu.user都跌0监控读数大约是0.12左右。但是另两个能够反映容器CPU使用率的指标nr_throttled_delta(容器由于CPU被限额次数)和throttled_time(容器由于CPU被限额时间)却有增长。一个从0跳变为4一个从累计的39.0s跳变为42.9s(累计差值刚好3.9s)throttled_time刚好是3.9s这个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。当前机器配置的是100mscpu.cfs_period_us100000 # 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左右。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最为令人瞩目。日志并没有打印任何cpu throttle的信息但日志不打印确可能泄漏出蛛丝马迹。啊哈有时候我们并不需要对某个隐藏状态(cpu throttle)增加更细粒度的观测而只需要找到一个能够随这个隐藏状态稳定变化的已有数据去表示它就行。数据对齐-nr_throttled_delta监控为4由于nr_throttled_delta本身是对于内核nr_throttled在两个时间点做的差值所以肯定是准确的。但是在泄洪时间段的这1s内只找到3段疑似throttle1段YGC为什么会为4呢问了下aiai告诉我很有可能是在后续平稳期出现了一次。但系统平稳期CPU消耗非常平稳以前也不出throttle没道理后续平稳期出了。于是笔者看了一下泄洪区的YGC和平稳区的YGC一个69ms一个23ms不会是YGC的时候也夹杂了cpu throttle吧于是直接让ai做数据对照。在同样Eden/Heap的分布下YGC在泄洪区的耗时为69ms而平稳期只需要23ms。所以很有可能在YGC的这一个的cgroup周期内也发生了一次throttle。这样31就可以解释nr_throttled_delta为4。当然这里并不是强行认定nr_throttled_delta的4次和这31是一一对应的。但是笔者自己造的示波器给出的日志空洞区间可以非常好的将nr_throttled_delta这个监控指标给对齐。下一个问题泄洪区的GAP能否造成3900ms的cpu throttle我们有4段GAP一个59ms2个20msYGC满打满算中间夹杂(69-23)46ms。那么也才59202046)145ms。是如何造成3900ms的这样的巨大的统计值的呢。这时候笔者突然想到我们的CPU配额是8C每个核全部throttle也就才1160ms这个数据完全对不上。如果按照监控的展示我的每个日志空洞加起来需要3900/8487.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多个。如下图所示:笔者稍微思索一下就知道了这个肯定是线程池来不及处理了紧急扩容线程了。这个扩容不是重点但是让笔者突然有了一个灵感这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)*12812,000ms可以轻轻松松超越3900ms那么对应于59ms的日志空洞我们可以根据作出一个什么模型呢?笔者的推理如下: 59ms的日志空洞可以认为应用容器等待了59ms在一个100ms周期内有41ms是疯狂烧CPU的。在41ms烧光了800ms的CPU quota那么平均疯狂run的线程数就是800/4120个就可以达到这个效果然后其余分布在其它核上的多个线程run的时候发现时间片没了就会加入到throttled_list然后开始累计throttled_time。如果一次日志空洞要累计到3900ms那么就可以算出用到3900/5966核(精确描述应该是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_throttledoverrun(大部分情况下为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是5ms6.这样就会造成下面这种现象:如果我们物理机器是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_throttled4在8C限额下完全能烧出throttled_time3.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计算的)。如下图所示:这证实了是IO的说法这时候很自然的笔者就去翻是不是磁盘坏了如果这么长时间磁盘的平均耗时肯定特别长。然后不出所料的有一块盘的disk.io.msec_write在故障时间达到了2.09K也就是2.09s。如下图所示:在此我们又需要看一下这个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.2090800: 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:SafepointTimeoutDelay500不过这个猜想虽然被推翻了但也不是完全没有价值。这一次是等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!如下图所示:那JIT本身是不是safepoint-safe的呢这种问ai就行了ai其实给出来JIT本身有很多不safepoint的地方。 下面是AI的回答:传统 C1/C2 的主体编译阶段 safe但 CompilerThread 的整个生命周期并非始终 safeJVMCI、编译前后、初始化、队列选择及 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 等待该线程不过在这里笔者再次申明这只是最有可能的猜测由于问题发生的现场基本不可能再复现导致无法获取直接的证据导致无法确认。整个故事发生的因果链(包含部分最有可能的猜想)行这么长时间的篇幅之后我们可以进行最后的总结了。整个故障在宏观上已经因果闭环了最后的那个微观猜想由于ROI的原因只能给出可达的路径和旁证。因果链为:t1 命中磁盘坏道 t2 磁盘IO异常导致日志打印受阻queue开始堆积 t3 jvm进行例行safepoint t4 等待全部到safepoint花了3.9s |-这段时间内某些尚未停下的线程发现队列满了 |-磁盘IO导致某个Java 线程迟迟无法到达检查点导致卡了3.9s |-这3.9s中最大的可能是jvm本身触发safepoint-unsafe的JIT触发访问硬盘冷页(例如反优化deoptimize)(这边只是最有可能的猜想) |-或者其它业务依赖磁盘IO的特殊线程导致无法进入SafePoint不过笔者看了代码并没有显然的可能点 t5 safepoint恢复之后处理大量累积的数据,触发应用限流 t6 在恢复后的1s内集中泄洪输出4500条日志包括业务日志和queue is full(通过日志空洞确认) |-在这个时间段内出现4次cpu throttle累积throttled time 3.9s两个监控指标上基本完全相同的3.9s一个是系统停止的原因一个却是系统恢复后的回声。宏观证据闭环与微观路径未决证据等级现场证据支持的结论已确认高峰期约400 QPS没有限流故障时只有单台机器告警不是整体流量或应用总容量不足问题可以收敛到单机已确认59—02秒处理量骤降03秒集中处理五秒平均QPS仍约204请求没有消失而是在应用停顿后集中泄洪限流是果而不是因已确认Stopping threads took: 3.9355932s同时段没有Young GC和Full GCJVM花了约3.9秒等待线程到达Safepoint停顿不是GC本身造成的已确认nr_throttled_delta增加4throttled_time增加3.9s19:16这个统计窗口内确实发生过CPU throttle高置信度推断停顿前容器CPU接近0恢复后1秒集中产生约4500条日志并处理积压请求CPU throttle主要发生在Safepoint恢复后的泄洪阶段而不是前面的3.9秒停顿阶段高置信度推断正常阶段最大日志空洞约2ms恢复阶段出现59ms、20ms、20ms非GC空洞异常YGC比平稳期多约46ms泄洪期间存在多段几十毫秒级停顿与4个受限period在时间尺度上相符可行性验证容器限额8C但未绑核物理机有128个逻辑CPUthrottled_time会累加各per-CPU cfs_rq的受限时长几十毫秒业务停顿能够被多CPU累计放大到3.9秒两个3.9秒相同只是巧合已确认宿主机iowait升至28%目标磁盘msec_write异常SA确认坏道持续增长同一时间宿主机确实发生了严重的磁盘I/O异常高置信度推断磁盘异常、容器CPU跌0和Safepoint等待3.9秒在时间上重合磁盘I/O异常导致某个Java线程迟迟无法到达Safepoint是当前最能解释全部现象的原因候选猜想首次出现queue is fullCode Cache增长0.06MB宿主机存在major faultqueue-full冷门分支可能触发反优化/runtime路径并在访问冷文件页时遭遇磁盘卡顿候选猜想缺少SafepointTimeout、线程栈、进程级major fault和反优化日志unstable_if uncommon trap → runtime冷页major fault → Safepoint等待是当前最完整的候选路径但无法确认其真实发生如何优化其实线上磁盘坏道经常发生相同的应用在相同的流量下肯定发生了不止一次。不管有没有命中safepoint-unsafe的冷路径都会导致应用请求超时只不过这次导致JVM整体暂停了而已。要优化这个小概率的事件ROI事实上很低应用能够自恢复其实已经够了。如果要做到更好其实可以考虑做下面这几件事情:1.磁盘坏道到一定程度的机器需要尽快迁移 2.GC日志本身其实受磁盘IO的影响即使没有这次的hang其本身的IO写入也会影响应用的吞吐也可以考虑到tmpfs如果觉得gc日志过大影响tmpfs的容量可以在tmpfs中只保留最近的日志 3.JVM中增加-XX:SafepointTimeout -XX:SafepointTimeoutDelay500识别出潜在的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大幅度加强了搜索信息和验证信息的速度但最开始的方向还需要笔者去把控否则就会在错误的道路上越走越远。已开启送礼物 解Bug之路-with AI-应用被限流？
前言有了AI之后处理复杂问题明显加速了。笔者体感大概加速了3倍吧以前一个需要一个星期才能探明根因的复杂问题现在估计只需要2天。主要是大部分数据整理/源码阅读/时间线梳理的繁琐操作都已经外包给AI了。这也使得笔者可以有精力可以解决一些看似ROI很低但成因却有点复杂的问题了。和AI的配合还是非常快乐的就像和一个不知疲倦的、自己对话一样。不过博客就不让AI代笔了这么好的锤炼自己思维的机会让AI写那还不如不写。Bug现场笔者这一两年做的事情主要是完成了异地多活。在将A城市(单元)的流量全部导入B城市(单元)的过程中需要时刻紧盯容量。在流量高峰期时候B单元表现的有惊无险。但在非高峰期某个应用却出现了应用限流的告警。为了防止容量有问题笔者就开始探寻起这次限流的原因。于是观察了一下限流曲线:可以看到在19:16:03秒出现了大约60多个请求限流。流量变大而限流如果单看告警其实很容易就联想到是流量过大而导致限流。但是之前高峰期都没有容量问题为什么现在非高峰期就有呢于是笔者看了一下高峰期的数据请求量大概在400左右并没有被限流。同一时间限流只出现在一台机器上其他机器流量并没有出现类似告警。那基本就否定了流量变高导致限流问题。现在就能直接锁定到单台机器有问题。开始分析单机问题笔者仔细看了一下限流图相对于正常机器来说就感觉是应用机器在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.2570800: 5979920.364: Total time for which application threads were stopped: 0.0248718 seconds, Stopping threads took: 0.0001490 seconds XXXX-XX-XXT19:16:03.2090800: 5979933.316: Total time for which application threads were stopped: 3.9391212 seconds, Stopping threads took: 3.9355932 seconds XXXX-XX-XXT19:16:03.2160800: 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.5ms3.9太过巨大叠加流量没有任何变化以及只有这台机器出问题。很容易的笔者去猜测这台机器出现了某些不寻常的事件那么很直观的就去观测机器的一些常用指标。CPU指标的矛盾这一看就发现了反常的现象。在CPU的秒级监控中(实际是10秒的精度)在19:16:00这个采样点里面CPU.busy跌0了而且是cpu.system/cpu.user都跌0监控读数大约是0.12左右。但是另两个能够反映容器CPU使用率的指标nr_throttled_delta(容器由于CPU被限额次数)和throttled_time(容器由于CPU被限额时间)却有增长。一个从0跳变为4一个从累计的39.0s跳变为42.9s(累计差值刚好3.9s)throttled_time刚好是3.9s这个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。当前机器配置的是100mscpu.cfs_period_us100000 # 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左右。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最为令人瞩目。日志并没有打印任何cpu throttle的信息但日志不打印确可能泄漏出蛛丝马迹。啊哈有时候我们并不需要对某个隐藏状态(cpu throttle)增加更细粒度的观测而只需要找到一个能够随这个隐藏状态稳定变化的已有数据去表示它就行。数据对齐-nr_throttled_delta监控为4由于nr_throttled_delta本身是对于内核nr_throttled在两个时间点做的差值所以肯定是准确的。但是在泄洪时间段的这1s内只找到3段疑似throttle1段YGC为什么会为4呢问了下aiai告诉我很有可能是在后续平稳期出现了一次。但系统平稳期CPU消耗非常平稳以前也不出throttle没道理后续平稳期出了。于是笔者看了一下泄洪区的YGC和平稳区的YGC一个69ms一个23ms不会是YGC的时候也夹杂了cpu throttle吧于是直接让ai做数据对照。在同样Eden/Heap的分布下YGC在泄洪区的耗时为69ms而平稳期只需要23ms。所以很有可能在YGC的这一个的cgroup周期内也发生了一次throttle。这样31就可以解释nr_throttled_delta为4。当然这里并不是强行认定nr_throttled_delta的4次和这31是一一对应的。但是笔者自己造的示波器给出的日志空洞区间可以非常好的将nr_throttled_delta这个监控指标给对齐。下一个问题泄洪区的GAP能否造成3900ms的cpu throttle我们有4段GAP一个59ms2个20msYGC满打满算中间夹杂(69-23)46ms。那么也才59202046)145ms。是如何造成3900ms的这样的巨大的统计值的呢。这时候笔者突然想到我们的CPU配额是8C每个核全部throttle也就才1160ms这个数据完全对不上。如果按照监控的展示我的每个日志空洞加起来需要3900/8487.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多个。如下图所示:笔者稍微思索一下就知道了这个肯定是线程池来不及处理了紧急扩容线程了。这个扩容不是重点但是让笔者突然有了一个灵感这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)*12812,000ms可以轻轻松松超越3900ms那么对应于59ms的日志空洞我们可以根据作出一个什么模型呢?笔者的推理如下: 59ms的日志空洞可以认为应用容器等待了59ms在一个100ms周期内有41ms是疯狂烧CPU的。在41ms烧光了800ms的CPU quota那么平均疯狂run的线程数就是800/4120个就可以达到这个效果然后其余分布在其它核上的多个线程run的时候发现时间片没了就会加入到throttled_list然后开始累计throttled_time。如果一次日志空洞要累计到3900ms那么就可以算出用到3900/5966核(精确描述应该是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_throttledoverrun(大部分情况下为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是5ms6.这样就会造成下面这种现象:如果我们物理机器是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_throttled4在8C限额下完全能烧出throttled_time3.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计算的)。如下图所示:这证实了是IO的说法这时候很自然的笔者就去翻是不是磁盘坏了如果这么长时间磁盘的平均耗时肯定特别长。然后不出所料的有一块盘的disk.io.msec_write在故障时间达到了2.09K也就是2.09s。如下图所示:在此我们又需要看一下这个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.2090800: 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:SafepointTimeoutDelay500不过这个猜想虽然被推翻了但也不是完全没有价值。这一次是等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!如下图所示:那JIT本身是不是safepoint-safe的呢这种问ai就行了ai其实给出来JIT本身有很多不safepoint的地方。 下面是AI的回答:传统 C1/C2 的主体编译阶段 safe但 CompilerThread 的整个生命周期并非始终 safeJVMCI、编译前后、初始化、队列选择及 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 等待该线程不过在这里笔者再次申明这只是最有可能的猜测由于问题发生的现场基本不可能再复现导致无法获取直接的证据导致无法确认。整个故事发生的因果链(包含部分最有可能的猜想)行这么长时间的篇幅之后我们可以进行最后的总结了。整个故障在宏观上已经因果闭环了最后的那个微观猜想由于ROI的原因只能给出可达的路径和旁证。因果链为:t1 命中磁盘坏道 t2 磁盘IO异常导致日志打印受阻queue开始堆积 t3 jvm进行例行safepoint t4 等待全部到safepoint花了3.9s |-这段时间内某些尚未停下的线程发现队列满了 |-磁盘IO导致某个Java 线程迟迟无法到达检查点导致卡了3.9s |-这3.9s中最大的可能是jvm本身触发safepoint-unsafe的JIT触发访问硬盘冷页(例如反优化deoptimize)(这边只是最有可能的猜想) |-或者其它业务依赖磁盘IO的特殊线程导致无法进入SafePoint不过笔者看了代码并没有显然的可能点 t5 safepoint恢复之后处理大量累积的数据,触发应用限流 t6 在恢复后的1s内集中泄洪输出4500条日志包括业务日志和queue is full(通过日志空洞确认) |-在这个时间段内出现4次cpu throttle累积throttled time 3.9s两个监控指标上基本完全相同的3.9s一个是系统停止的原因一个却是系统恢复后的回声。宏观证据闭环与微观路径未决证据等级现场证据支持的结论已确认高峰期约400 QPS没有限流故障时只有单台机器告警不是整体流量或应用总容量不足问题可以收敛到单机已确认59—02秒处理量骤降03秒集中处理五秒平均QPS仍约204请求没有消失而是在应用停顿后集中泄洪限流是果而不是因已确认Stopping threads took: 3.9355932s同时段没有Young GC和Full GCJVM花了约3.9秒等待线程到达Safepoint停顿不是GC本身造成的已确认nr_throttled_delta增加4throttled_time增加3.9s19:16这个统计窗口内确实发生过CPU throttle高置信度推断停顿前容器CPU接近0恢复后1秒集中产生约4500条日志并处理积压请求CPU throttle主要发生在Safepoint恢复后的泄洪阶段而不是前面的3.9秒停顿阶段高置信度推断正常阶段最大日志空洞约2ms恢复阶段出现59ms、20ms、20ms非GC空洞异常YGC比平稳期多约46ms泄洪期间存在多段几十毫秒级停顿与4个受限period在时间尺度上相符可行性验证容器限额8C但未绑核物理机有128个逻辑CPUthrottled_time会累加各per-CPU cfs_rq的受限时长几十毫秒业务停顿能够被多CPU累计放大到3.9秒两个3.9秒相同只是巧合已确认宿主机iowait升至28%目标磁盘msec_write异常SA确认坏道持续增长同一时间宿主机确实发生了严重的磁盘I/O异常高置信度推断磁盘异常、容器CPU跌0和Safepoint等待3.9秒在时间上重合磁盘I/O异常导致某个Java线程迟迟无法到达Safepoint是当前最能解释全部现象的原因候选猜想首次出现queue is fullCode Cache增长0.06MB宿主机存在major faultqueue-full冷门分支可能触发反优化/runtime路径并在访问冷文件页时遭遇磁盘卡顿候选猜想缺少SafepointTimeout、线程栈、进程级major fault和反优化日志unstable_if uncommon trap → runtime冷页major fault → Safepoint等待是当前最完整的候选路径但无法确认其真实发生如何优化其实线上磁盘坏道经常发生相同的应用在相同的流量下肯定发生了不止一次。不管有没有命中safepoint-unsafe的冷路径都会导致应用请求超时只不过这次导致JVM整体暂停了而已。要优化这个小概率的事件ROI事实上很低应用能够自恢复其实已经够了。如果要做到更好其实可以考虑做下面这几件事情:1.磁盘坏道到一定程度的机器需要尽快迁移 2.GC日志本身其实受磁盘IO的影响即使没有这次的hang其本身的IO写入也会影响应用的吞吐也可以考虑到tmpfs如果觉得gc日志过大影响tmpfs的容量可以在tmpfs中只保留最近的日志 3.JVM中增加-XX:SafepointTimeout -XX:SafepointTimeoutDelay500识别出潜在的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大幅度加强了搜索信息和验证信息的速度但最开始的方向还需要笔者去把控否则就会在错误的道路上越走越远。已开启送礼物