ARTICLE DETAIL

资讯详情

深耕网站建设与运营推广的一线实战洞察。

服务器间歇性卡顿排查记:指标全绿,真凶竟是系统时钟跳变

服务器间歇性卡顿排查记:指标全绿,真凶竟是系统时钟跳变 服务器卡顿这件事干运维的多少都经历过。可一旦卡顿变成间歇性发作、指标全绿、重启就好一阵那就不是普通故障而是专门来磨人的。前阵子我就被这么一台服务器折腾了整整三天症状是接口偶尔超时、页面转圈持续十几秒又自己恢复频率没规律白天多晚上少CPU、内存、磁盘、网络四项基础指标愣是全无异常。最后竟然是在日志的时间戳里找到了突破口——系统时钟在同步过程中发生了跳变连锁引发了从 Kafka 到数据库连接池一整条链路的间歇性假死。这篇复盘我会把三天里的排查思路、踩过的坑、以及最后定位到时间服务器配置问题的完整过程都写出来给同样被诡异卡顿折磨的运维、后端和 SRE 朋友做个参考。尤其适合那些netstat 看了、top 也盯了、GC 日志也翻了但就是找不到原因的场景。1. 故障现象与第一轮排查看起来一切正常1.1 卡顿到底是什么样业务方最早是在下午两点左右反馈的说某个核心接口偶发超时前端页面转圈几秒到十几秒后自动恢复。一开始我以为是网络抖动或者数据库慢查询但看监控大屏接口平均响应时间并没有明显抬升只有零星几个 P99 尖刺。这种尖刺型卡顿最迷惑人因为它不像持续高负载那样一眼就能看出来更像是一种间歇性的阻塞。更诡异的是同样的现象在上午、下午、晚上都会出现完全找不到时间规律。我们试过重启应用重启后能好一阵但几个小时后又会冒出来。当时有个同事开玩笑说服务器跟人一样累了要喘口气话是玩笑但也说明这问题根本不是简单的资源耗尽——要是 CPU 或内存持续被打满不会自己恢复得那么干净。1.2 常规三板斧CPU、内存、磁盘、网络全查了一遍按照常规排查流程我第一轮先把系统资源四项全过了一遍top看 CPU 和负载整体负载不高单核也没有飙满的迹象用户态和内核态占比都正常。free -h看内存还有不少余量没有触发 OOMswap 使用量也是 0。iostat -x 1看磁盘util 基本在 10% 以下await 也不高排除了磁盘性能瓶颈。网络方面ping网关丢包率 0带宽占用也没达到上限。这一轮做完结论很明确服务器本身看起来是健康的。但业务卡顿是真实存在的那问题大概率不在资源层而在应用层或者链路层。这时候我犯了个先入为主的错误——把注意力集中到了 Java 应用和容器上后面证明这个方向本身没错但我在里面绕了很大一圈。1.3 排查工具与命令记录第一轮排查我把常用的几条命令都跑了一遍这里贴出来供参考也是给后来人留个底# 实时查看系统负载和CPU占用 top -d 1 # 查看内存使用量和swap free -h # 查看磁盘IO的详细指标util、await、svctm等 iostat -x 1 # 每秒采样一次系统整体状态r、b、si、so、wa列重点关注 vmstat 1 # 查看网络连接数、TIME_WAIT等 ss -s这几条命令组合起来基本能排查掉 70% 的常规性能问题。vmstat里的 b 列阻塞进程数如果持续大于 0说明有进程在等 IOr 列运行队列如果长期大于 CPU 核数说明 CPU 不够。但这次我盯了半天这两列都非常平静平静得反而让人心里发毛。后来我才意识到这种一切指标都正常本身就是最重要的线索——它说明问题不在资源消耗而在某个隐蔽的阻塞点上而这个阻塞点很可能藏在应用的调用链或者系统的时间轴上。2. 深入应用层Java 应用、Docker 容器、中间件的假嫌疑2.1 Java 层GC、线程 Dump、连接池这台服务器上跑的是 Java 服务容器化部署所以第一反应就是看 JVM。我先把 GC 日志调出来翻了一遍发现 Young GC 频率稍微有点高但每次停顿都在几十毫秒以内没有 Full GC也没有明显的GC 长暂停迹象。为了保险起见我还用jstat -gcutil连续采样了半小时老年代使用率一直平稳。接下来是线程 Dump。卡顿发生的时候我直接在服务器上执行了jstack抓了三次间隔 10 秒。结果很有意思——所有线程基本都在正常的 WAITING 或 RUNNABLE 状态没有死锁也没有线程卡在锁上。数据库连接池这边也查了druid或hikari的活跃连接数离上限还有很大距离。按理说应用层最常见的三类问题内存溢出、线程阻塞、连接池耗尽到这里全部排除了。但有一个细节让我隐隐觉得不对劲有一次线程 Dump 里某几个业务线程的RUNNABLE状态持续时间特别长但 trace 停在一个 Socket 读写的地方。当时我以为是网络 IO 慢没往深处想实际上这已经是时钟跳变影响网络超时计算的早期信号了只是那时候还没意识到。2.2 Docker 容器层内存与 CPU steal既然宿主机的资源指标正常我把目光转到了容器层。docker stats看了一圈容器内的 CPU 和内存使用率同样不高。唯一让我多看了一眼的是 CPU steal 指标——有几次采样里 steal 值跳到了 5%~8%。CPU steal 的意思是当你的虚拟机/容器所在的宿主机 CPU 资源紧张时hypervisor 会抢走你的 CPU 时间片这个被抢的部分就是 steal。如果 steal 持续过高业务确实会表现为间歇性卡顿。于是我开始怀疑是宿主机上的其他虚拟机在吵还专门去查了宿主机上有哪些邻居在跑甚至联系虚拟化团队帮忙查宿主机负载。这一步查了快一天最后发现 steal 只是偶尔出现幅度不大根本没有到影响业务的程度。这是个典型的干扰项浪费了不少时间。更关键的是我在容器里执行date的时候隐约发现时间好像跟宿主机差了那么一点点但当时手头事情太多以为容器会自己同步时间就没当回事。现在回头看那个瞬间的犹豫就是整个排查过程里最值钱的一刻可惜被错过了。2.3 中间件链路Kafka lag、Redis、数据库慢查询应用层查不出问题我开始怀疑是不是下游中间件在拖后腿。先看了 Kafka 消费组的状态kafka-consumer-groups.sh --describe跑了一下lag 并没有持续堆积只是在卡顿瞬间会突然冒出几个卡顿结束后又恢复正常。这个特征很关键——说明消费者不是一直跟不上而是偶尔被卡住一下等缓过来之后又能追上进度。这跟持续性能不足是两码事更像是消费者侧的阻塞。Redis 这边redis-cli --latency测了一下延迟平均值正常但偶尔也会蹦出几个几百毫秒的尖刺。数据库慢查询日志里只有零星的几条构不成系统性瓶颈。当时我盯着这些偶发尖刺看了很久脑子里一直盘旋着一个想法应用、容器、中间件好像都掺了一脚但谁都不是真正的元凶。这种感觉就像你追一个黑影追到每个拐角都看到它的衣角但就是抓不住。事后复盘才明白这些尖刺其实都是同一个原因在不同环节的表现——系统时间跳变时所有依赖时间的组件会同时出现短暂异常分布在调用链各处的超时、重试、心跳机制被一次性触发造成一种全线告警但全线找不到根因的假象。3. 关键转折从数据到元数据时钟才是罪魁祸首3.1 为什么想到看系统时间真正让我转向时间这个方向的是一次非常偶然的发现。卡顿发生后我习惯性地去翻应用日志想看看报了什么错。结果发现某个服务的日志中间有一段真空期——前后两条日志的时间戳之间直接跳过了十几秒但这段时间服务并没有宕机进程还活着请求也还在进来。一开始我以为是日志采集丢了数据但对比了多个服务后发现所有服务都在同一时间段出现了同样的时间戳断层。这时候我才猛地反应过来不是日志丢了是系统时钟本身跳了一下。我立刻在服务器上执行了三条命令date hwclock -r chronyc tracking结果显示系统时间确实发生过一次回拨而且chronyc tracking里的System time字段显示了一个不小的偏移量。也就是说这台服务器的时间同步服务chrony在运行过程中执行了一次时间跳跃把系统时钟硬生生拨了回去。很多应用不会感知系统时间变化但涉及超时计算、心跳、序列号生成的程序受的影响会非常大。3.2 时钟跳变的危害Kafka、连接池、日志全中招系统时间跳变为什么会导致业务卡顿我结合现象梳理了几个典型的连锁反应网络超时TCP 的重传超时、连接超时、读写超时都是基于系统时钟计算的。时间突然回拨会导致一些尚未超时的连接被误判为超时连接被提前断开应用层收到异常后进入重试逻辑重试期间业务就会表现为短暂卡顿。Kafka 元数据刷新Kafka 客户端会周期性地刷新 metadata刷新间隔和超时判断依赖本地时钟。时钟跳变后客户端可能在同一瞬间发起大量元数据请求或者误判 broker 不可用导致消费变慢、lag 突增。分布式锁和会话过期如果系统里用了 Redis 分布式锁或者依赖短会话超时的组件时间回拨会直接导致锁提前过期或者会话失效进而引发并发冲突和重试风暴。日志排序与监控误判时间戳断层会让日志分析工具和链路追踪系统产生错乱排查的时候很容易被误导以为日志丢了或者应用卡死了。可以说时钟一抖整个分布式链路里凡是依赖时间判断状态的组件都会在同一时刻抽风一次。抽风之后一切恢复正常这就完美解释了我前面看到的所有指标全都正常但业务就是间歇性卡顿的现象。3.3 时间服务器的配置是怎么出问题的接下来就是定位根因了。我打开/etc/chrony.conf认认真真看了一遍时间服务器配置cat /etc/chrony.conf问题一下就暴露出来了配置文件里同时配置了好几个时间服务器但内网防火墙的出站规则只放通了少数几个 UDP 123 端口导致 chrony 实际上只能跟其中极少数时间源正常通信。更麻烦的是当主时间源不可达或者偏移量过大的时候chrony 默认会在偏移超过某个阈值后执行 step 操作——也就是直接把系统时间拨到目标值而不是一点点地微调。这个拨的动作就是造成系统时间跳变的直接原因。我顺便查了 chrony 的日志/var/log/chrony/里面清楚地记录了某几个时间点执行了 step。把这些时间点和业务卡顿的时间点放在一起对比吻合度接近 100%。到了这一步三天来所有的奇怪现象终于全部解释通了。3.4 为什么这个根因藏了三天复盘下来这个根因之所以藏了三天有几个客观原因卡顿是间歇性的时钟跳变不是每分钟都在发生而是隔几个小时才触发一次每次只跳几百毫秒到几秒。这种频率和幅度常规监控根本不会报警。监控阈值太粗大部分监控系统盯的是 CPU、内存、磁盘、网络这类资源指标很少有人会去监控系统时钟的偏移量。我们自己的监控里也没有这一项等于在盲区里找东西。容器层面加了干扰应用跑在容器里容器跟宿主机共享时间空间但很多同事习惯性地认为容器和宿主机的时间是隔离的反而忽略了容器内时间也会跳变这个事实。日志断层被误读日志时间戳的真空期其实是最直接的线索但它太容易被解释成日志丢失采集器故障很少有人会顺着它想到系统时钟。这些因素叠加在一起让一条本来很明显的线索硬生生被埋了三天。4. 根因验证与修复方案一次完整的闭环4.1 复现与验证定位到方向之后我没有急着改配置而是先做了一次复现验证。我手动执行了chronyc makestep这个命令会强制 chrony 立刻把系统时间拨到正确值相当于人为制造一次和我们观察到的一模一样的时间跳变。命令执行完的几秒钟内业务方立刻报了接口超时监控上也出现了熟悉的 P99 尖刺和 Kafka lag 跳动。复现成功说明时钟跳变和业务卡顿之间的因果关系是确定的。为了进一步确认时间源的问题我还用tcpdump抓了 NTP 流量tcpdump -i eth0 udp port 123 -n -c 100从抓包结果看出站到部分公共时间服务器的 NTP 请求长时间没有响应只有极少数内网可用的时间源能正常回包。这也解释了为什么 chrony 会积累偏移进而触发 step——它并不是不想同步而是根本够不到足够多可用的时间源。4.2 修复步骤详解确认根因后我按下面几步做了修复每一步都有明确的意图第一步精简并修正时间服务器配置。把配置里不可达的公共时间服务器全部删掉只保留一个内网可用的 NTP 服务器作为首选再留一个备用的可靠公共时间源。这里有一个原则时间服务器的数量不是越多越好如果大部分不可达反而会让 chrony 的选源逻辑变差。哪怕只有一个高可用的内网时间源也比一堆半死不活的外部源强。# /etc/chrony.conf 修改后的核心配置示例 server ntp.internal.example.com iburst server ntp.public.example.net iburst makestep 0 -1这里的makestep 0 -1是关键。它表示关闭运行中的自动 step只允许在服务启动时做一次时间校正。默认的makestep 1 3意思是前三次同步如果偏移超过 1 秒就执行 step运行中很容易触发。改成0 -1后运行中即使偏移再大chrony 也只做频率调整slew不会粗暴地把时间拨回去。这样虽然同步速度会慢一点但系统时间是平滑过渡的对应用几乎无感。第二步重启 chrony 服务并验证状态systemctl restart chronyd chronyc tracking重点看Leap status是否为Normal以及System time的偏移量是否在逐渐收敛。如果显示的是Step或者Leap说明还在跳变状态需要继续等它稳定。第三步处理容器场景的隐患。这台服务器上的应用是用 Docker 跑的默认容器和宿主机共享时间空间所以宿主机时钟修复后容器里的时间也会跟着恢复正常。但我额外检查了一遍确认容器里没有单独跑 ntpd 或者 chrony——如果容器里再启动一个时间同步进程跟宿主机的 chrony 打架时间跳变的问题会卷土重来。这是很多人容易忽略的坑顺手就记下来了。第四步补充监控。我把系统时钟偏移量chronyc tracking里的 System time 字段加进了监控设置了阈值告警一旦偏移超过 200ms 就报警。另外把 NTP 可达性也做了拨测防止时间源再次失效时无人发现。4.3 修复后的观察修复完成后我观察了整整一周。期间没有再出现一次业务卡顿Kafka lag 曲线也变得非常平滑接口 P99 尖刺完全消失。说实话当看到连续三天的监控曲线都平得像一条直线时我心里才真正踏实下来——三天里反复折磨我们的那个幽灵被彻底赶走了。这次经历让我养成了两个习惯一是排查任何间歇性故障之前先顺手看一眼系统时间二是所有服务器的初始化脚本里都必须带上时间同步的完整配置而不是让运维去默认设置。前者是救火后者是防火。5. 服务器卡顿排查方法论与避坑清单5.1 排查顺序建议经过这次折腾我总结了一套针对指标全绿但业务卡顿类问题的排查顺序按这个顺序走可以省下大量时间先看时间date、chronyc tracking/ntpq -p、hwclock -r确认系统时钟是否平滑。这一步只要 10 秒但能排除掉一大类隐蔽问题。再看 DNS 和连接dig一个域名看解析耗时ss -s看连接数ss -tnp看有没有大量出站连接处于 SYN-SENT 状态。然后才是应用层GC 日志、线程 Dump、连接池状态、中间件指标。最后才轮到资源层深挖CPU steal、IO 等待、网络重传等。为什么把时间放在第一位因为时钟是很多组件的共同时间基准一旦它出问题所有依赖时间的环节都会在同一个时刻出现间歇性异常表现上就像全线告警但全线查不出问题。这种特征本身就是指向时钟问题的最强信号。5.2 这次踩过的坑以及下次可以省下的时间复盘这次排障我踩了三个很典型的坑写出来希望大家绕开坑一过度依赖监控大盘。监控指标是聚合后的结果很多隐蔽问题在聚合后是看不出来的。这次要不是我去翻了原始日志的时间戳可能现在还在查 CPU steal。教训是监控用来发现问题但定位问题一定要回到原始数据。坑二被 CPU steal 分散了注意力。steal 的出现让我花了半天去查宿主机邻居结果是个干扰项。现在想想当时如果看仔细一点就会发现 steal 的幅度和卡顿频率根本不匹配——如果真是 steal 导致CPU 时间片被抢应该是持续的、有规律的而不是隔几个小时才抖一下。坑三忽略了明显的前置线索。容器里执行date时发现时间有轻微偏差那个瞬间如果停下来深挖可能两小时就能搞定结果我生生拖了三天。很多故障的根因其实在最开始就已经露出过马脚就看我们有没有抓住。5.3 常用排查工具速查表最后给一份这次用到的工具速查表涵盖系统层、应用层和时间相关三类方便大家排查时对照工具主要用途常见异常信号vmstat 1查看运行队列、阻塞进程、swapb 列持续非0、si/so 频繁iostat -x 1查看磁盘IO利用率util 长期80%、await 波动大top -d 1查看CPU、负载、进程占用单核飙满、进程CPU高free -h查看内存和swapswap使用量增长、available偏低ss -s / ss -tnp查看网络连接状态TIME_WAIT 堆积、SYN-SENT 异常多jstat -gcutil查看Java GC占用old区持续上涨、GC频繁jstack抓取线程快照BLOCKED线程堆积、锁等待docker stats查看容器资源占用容器CPU/内存异常增长chronyc tracking查看系统时钟同步状态System time 偏移大、Leap status异常ntpq -p查看NTP时间源状态远程源 reach 值低、offset 过大tcpdump抓包分析网络/协议异常NTP请求无响应、TCP重传多dmesg -T查看内核日志有硬件错误、OOM、文件系统告警这份表格里我特别想强调chronyc tracking和ntpq -p这两条。它们在日常运维里太容易被忽略了但恰恰是这类诡异卡顿排查中最有力的武器。写在最后以前我总觉得服务器卡顿排查拼的是对复杂问题的分析能力。经历过这次三天大战之后我反而觉得拼的更多是耐心和对异常信号的敏感度。系统时间跳变这种问题原理一点都不复杂难的是在满屏正常指标里你还能记得去看看那条太正常了的时间线。现在每次有新服务器上线我都会第一时间确认 chrony 配置和时钟监控是否到位这个习惯已经刻进肌肉记忆了。毕竟谁都不想再被一个藏在时间轴后面的幽灵折磨整整三天。
返回列表