凌晨两点告警群里的曲线像跳水一样往下扎。Nginx 这台反向代理的 P99 延迟从平时的 20ms 直接飙到了 800ms用户那边已经在骂页面转圈了。我第一反应是查后端结果发现后端应用负载稳定得一批响应时间也正常。查 Nginx 自己的 access logupstream_response_time并不高但request_time高得离谱。换句话说时间既没花在 Nginx 处理上也没花在后端上那它到底去哪儿了排障排到这种两边都正常的诡异局面常规手段基本就废了。top、vmstat、ss、netstat 翻来覆去看CPU 不高、内存不紧、连接数也没满什么异常都看不见。那段时间里我意识到靠墙外观测已经不够了得进内核里看看。于是我用 eBPF 花了大概五分钟直接在运行中的生产内核里抓到了真凶不是 Nginx 本身的问题而是内核网络路径上的 conntrack 表锁竞争把所有软中断时间都耗在了查找连接状态上。这篇文章就是一次完整的实战复盘我把当时的排查思路、bpftrace 命令、内核热栈分析方法和事后验证过程原原本本写下来希望能帮你省掉几个小时的弯路。1. 问题现场一条诡异的 Nginx 高延迟告警1.1 现象与第一轮排查先说拓扑。这台机器是标准的 Nginx 反向代理前端挂 HTTPS后端接了三台应用服务器。Nginx 配置里开了 8 个 worker_processes每个 worker 用默认的 epoll 事件模型。问题出现的时间有规律晚高峰流量一起来延迟曲线就开始抽风但机器本身的负载并不高load average 一直不到 2。第一轮排查我做了三件事。第一件事是看 Nginx 日志。日志里有两个关键字段$request_time和$upstream_response_time。正常情况下这两个值接近因为 Nginx 把请求转发给后端拿到响应再返回时间差极小。但告警期间$request_time在 500ms 到 1s 之间波动$upstream_response_time却始终在 30ms 以内。这个对比说明时间消耗不在上游而在本机某个环节。第二件事是用 ss 看连接状态。ss -s显示 TCP 连接总数 2 万左右TIME_WAIT 占了很大一部分。这个数量不算夸张但这个细节我后来才意识到是一把重要钥匙。第三件事是用 top 确认 CPU 和中断分布。top -H之后发现某个 CPU 核的%si软中断长期在 30% 到 50%其他核的%si只有个位数。当时我没太在意软中断因为从整体 CPU 看确实不算高谁也没想到问题会出在软中断。这三步做完结论很尴尬没有结论。Nginx 的配置找不出毛病后端响应正常TCP 连接数也没到上限。排障陷入僵局我甚至开始怀疑是不是 Nginx 版本有 bug或者某个第三方模块出了问题。1.2 为什么 top、ss 这些常规工具会失灵后来我仔细想了一下这类诡异问题的根源在于常规监控工具观测的是系统和进程的宏观健康指标而真正的问题可能藏在一条特定的内核代码路径里。举个例子top告诉我们 CPU 利用率 30%但它没法告诉我们是哪一行内核代码吃掉的时间。ss能告诉我们 TIME_WAIT 连接多但没法告诉我们每来一个 SYN 包内核要在 conntrack 表里做多少次哈希查找、这些查找有没有在抢同一把锁。perf top其实能做一部分但默认情况下它需要依赖采样频率和符号解析现场执行时还会因为权限、内核配置等问题打断排查节奏。更麻烦的是这类内核路径问题通常有很强的瞬时性延迟偶发可能一分钟就出现几次。等你打开监控高峰期已经过去了。我们需要的是能在问题发生的那几分钟里直接看到内核函数调用栈和耗时分布的工具。这就是 eBPF 上场的时候了。2. 为什么 eBPF 能在内核查案2.1 从 BCC 到 bpftrace选择什么工具动手之前先聊聊工具选型。目前主流的 eBPF 工具链有 BCC 和 bpftrace 两家。BCC 是一个完整的 Python 框架适合做复杂工具和长期监控很多现成的工具集比如tcplife、tcpconnect、runqlat都是基于 BCC 实现的。bpftrace 则是一个单行脚本式的探针语言语法类似 awk适合快速定位问题可能在十分钟内用完就扔。这次场景是线上紧急排障需要的是快速回答一个问题我选了 bpftrace。理由有三个第一单行命令可以直接在 shell 里跑不需要写 Python 文件第二它支持kprobe、kretprobe、profile等钩子能抓内核函数调用和调用栈第三输出自带直方图hist()和计数器能瞬间看到耗时分布比人肉分析 perf 数据快得多。如果你没有安装 bpftrace发行版自带的包管理器一般都能直接装。Debian/Ubuntu 上执行apt install bpftraceCentOS/RHEL 上执行yum install bpftrace或dnf install bpftrace。装完先跑一个sudo bpftrace -e BEGIN { printf(hello, eBPF\n); exit(); }能输出 hello 说明内核配置和权限都没问题。2.2 三个基础概念钩子、探针、映射eBPF 技术本身不复杂但新手容易卡在概念上。我用大白话拆一下。第一个概念是钩子。内核代码执行路径上的很多关键函数都可以挂探针。比如你想知道 TCP 建立连接时发生了什么就可以挂tcp_v4_connect想知道收包路径上谁最慢就挂netif_receive_skb或者nf_conntrack_in。eBPF 程序就挂在这些钩子上内核每次执行到这个函数就会执行你写的探针程序。第二个概念是探针类型。最常用的是kprobe和kretprobe分别在函数入口和函数返回时触发。入口能拿到参数返回能拿到耗时和返回值两者配合就能精确测量单个内核函数的花费时间。还有profile类型它类似于 perf 的采样器按固定频率采样当前 CPU 正在执行的内核栈把所有采样点堆起来就是一张热栈图。第三个概念是映射。eBPF 程序要记录数据不能直接用全局变量得用 BPF map。最简单的 map 类型是哈希表和数组bpftrace 里的name变量就自动对应了一个 map。你用[key] count()做的所有统计底层都在往 map 里写数据。理解了这三个概念再看那些看起来很唬人的 bpftrace 命令实际上就是三件事在某个钩子上挂程序、按条件记录数据、周期性地把 map 内容打印出来。2.3 这次的追踪思路设计动手之前先画了一条追踪链路。对外表现为 Nginx 高延迟Nginx 本身又是事件驱动模型它不消费太多 CPU。那么请求在 Nginx 侧的时间一定花在了阻塞等待上。Nginx 等待的事情无非两种情况等待 socket 可读可写或者等待内核完成某个处理过程。于是我的追踪思路分成三层。第一层是系统调用层跟踪 Nginx worker 进程的 accept、read、write、epoll_wait 等系统调用的次数和耗时。如果延迟出在 accept 或 read说明 Nginx 的事件循环堵了如果出在 write说明 socket 发送缓冲区堵了。第二层是内核网络路径层跟踪收包路径上的关键函数比如netif_receive_skb、nf_conntrack_in、tcp_v4_rcv。现代服务器收一个包会走网卡驱动 - GRO - softirq - 协议栈 - socket 队列这一路任何一个函数卡住都会让 Nginx 的事件循环晚那么几毫秒积累起来就是用户侧的秒级延迟。第三层是 CPU 调度层用profile采样器看整机 CPU 在内核态和用户态的时间分布定位到底哪段代码占用了最多的 CPU 时间。这套思路的好处是层层递进先用系统调用层砍掉用户态嫌疑再用内核网络层锁定内核路径最后用采样确认热点函数。执行完这三层基本不可能找不到问题。3. 实战5分钟找到真凶的操作复盘3.1 第一步先确认 Nginx 的进程模型上层追踪前先确认 Nginx 到底跑在哪些进程里。Nginx 有一个 master 进程和一堆 worker 进程所有网络事件都发生在 worker。如果探针挂错了进程数据会乱成粥。我用pgrep -f nginx列出所有相关 PID然后区分出 master 和 worker。一般 master 进程会显示为nginx: master processworker 会显示为nginx: worker process。我这里的机器有 8 个 workerPID 大约分布在 12000 到 12008 之间。另外我还确认了一下 Nginx 的监听端口。用ss -lntp | grep 443可以看到监听 443 的进程 PID确保待会过滤进程号的时候不会漏。命令如下pgrep -f nginx: worker process ss -lntp | grep :443这一步花费不到半分钟但非常关键。因为后面所有 bpftrace 命令里都托一个comm nginx或者pid 12001的过滤条件条件不对数据就是废的。3.2 第二步追踪系统调用看时间消费在哪里第一层探测我直接追踪 Nginx 相关进程的系统调用频率和耗时。bpftrace 里可以用tracepoint:syscalls:sys_enter_*来捕获所有系统调用但这样数据量大且不聚焦。我更倾向于直接用tracepoint:syscalls:sys_exit_read等几个关键点。一次比较常用的分析命令是这样sudo bpftrace -e tracepoint:syscalls:sys_enter_accept4 /comm nginx/ { accept[tid] nsecs; } tracepoint:syscalls:sys_exit_accept4 /accept[tid]/ { accept_usec hist((nsecs - accept[tid]) / 1000); delete(accept[tid]); }同样思路对 read、write、epoll_wait 各跑一遍。跑完结果让我很意外accept 和 epoll_wait 的阻塞时间都很正常没有堆积。也就是说Nginx 的事件循环本身没有卡死大多数时间它正常地在 epoll 上等待事件。那我之前看到的$request_time高又从哪来的继续往下一层看。3.3 第三步内核热栈采样隐藏的 CPU 时间现身系统调用层面没问题就把目光转向内核态。我用profile钩子做一个全内核栈采样以 99Hz 的频率采样 5 秒钟然后统计所有调用栈的出现次数。一个调用栈出现得越多说明那个路径上消耗的 CPU 时间越多。命令长这样sudo bpftrace -e profile:hz:99 { [kstack] count(); } interval:s:5 { print(); clear(); exit(); }我把 5 秒内的热栈输出拉出来看前几名里有一串函数非常扎眼[ __do_softirq1 run_timer_softirq1 net_rx_action1 nf_conntrack_in1 __nf_conntrack_find_get1 nf_conntrack_find_get1 spin_lock_bh1 ]: 4210为了让这段更容易理解我把栈从下往上还原一下CPU 在跑软中断进入net_rx_action处理网络收包网络包钩子调用了 netfilter 框架而 netfilter 框架的 conntrack 模块尝试查找连接跟踪记录的时候遇到了自旋锁也就是spin_lock_bh。这个锁等待消耗了 4210 个采样点远远超过其他函数。看到这个结果的时候我基本已经确定嫌疑人了。但还需要验证一把于是做了第四步。3.4 第四步确认 conntrack 锁竞争的细节虽然热栈已经指向 conntrack我还是用两个角度做了交叉验证。第一直接统计nf_conntrack_in这个函数单次执行的耗时分布。这里用到 kprobe 和 kretprobe分别记录函数入口和出口的时间戳相减得到单次执行耗时sudo bpftrace -e kprobe:nf_conntrack_in { start[tid] nsecs; } kretprobe:nf_conntrack_in /start[tid]/ { ct_in_usec hist((nsecs - start[tid]) / 1000); delete(start[tid]); }执行结果里绝大多数采样落在 1 到 4 微秒区间但尾巴拖到了 100 多微秒。在 Nginx 这种高并发场景下一个请求涉及多个包每个包多等几十微秒再叠加 CPU 核上的其他软中断排队延迟自然就上去了。第二看一下系统当前的 conntrack 统计信息。cat /proc/net/stat/nf_conntrack的前几列是查找、新建、删除等操作的累计计数conntrack -S也能看实时数据。我这边看到的 insert 和 find 次数高得吓人说明这台机器几乎每个包都要走 conntrack 查表逻辑。再结合top -H之前显示的 CPU0 软中断偏高整个链路就串起来了高并发新建连接导致 TIME_WAIT 大量累积每个进来的 TCP 包都要做 conntrack 哈希查找。网络软中断集中在 CPU0 上而 conntrack 查表又要争夺锁最终把所有收包处理拖慢了。3.5 第五步修复与复测验证定位到问题之后修复方案就清晰了。我做三件事第一在网卡上开启 RPSReceive Packet Steering把软中断分散到多个 CPU 核避免单核成为瓶颈。具体操作是把/sys/class/net/eth0/queues/rx-0/rps_cpus写成一个覆盖多个核的 CPU 掩码。这个操作是临时的重启就没了如果要长期生效需要把配置写进启动脚本。第二调整 conntrack 参数。通过/proc/sys/net/netfilter/nf_conntrack_max增大连接跟踪表容量同时按比例增加哈希桶大小减少哈希冲突。修改之前先看看当前值sysctl -a | grep conntrack可以一次性列出相关参数。第三在 Nginx 配置里给上游连接开启 keepalive复用现有后端连接减少新建连接频率。这是从源头削减 conntrack 压力的手段效果比单纯调内核参数更持久。三个改动做完再跑一遍热栈采样spin_lock_bh相关的栈基本消失了软中断也平均分散到了 4 个核上。监控曲线上的 P99 延迟从 800ms 回到了 25ms 左右。整个定位过程从挂上 bpftrace 到点出真凶大概就是五分钟。4. 内核层Nginx高延迟原因排查速查表4.1 三种常见原因锁竞争、软中断、调度延迟这次的经历让我意识到Nginx 高延迟的内核原因其实可以归纳成几大类。我把常见场景整理成一张速查表方便以后再遇到类似问题时快速对照。问题类型常见症状可能的内核热点高频排查命令软中断集中单核top中某个核%si高其他核空闲net_rx_action、process_backlog、enqueue_to_backlog采样 kstack查看网络收包路径conntrack 锁竞争高并发新建连接、TIME_WAIT 多nf_conntrack_in、__nf_conntrack_find_get、spin_lock_bhkprobe 统计nf_conntrack_in耗时内核锁竞争CPU 整体不高但延迟偶发futex_wait、mutex_lock、rwsem_down_read_failed采样 ustack kstack关注锁等待栈CPU 调度延迟进程大量进入 R 状态但响应慢schedule、try_to_wake_up、enqueue_task_fair使用runqlat统计运行队列延迟内存回收/页面分配延迟大流量下周期性抖动__alloc_pages_slowpath、shrink_page_listkprobe 统计分配耗时这个表的核心价值是告诉你看到表象之后应该去哪里挂探针。不要一个个函数试错先用热栈采样把大致方向框出来再针对热点函数做耗时统计。4.2 bpftrace 在日常排障中的几条实用命令除了这次实战用到的命令我再补充几条日常排障常用的 bpftrace 命令熟悉之后可以组合使用。统计某进程所有系统调用耗时分布sudo bpftrace -e tracepoint:syscalls:sys_enter_* /comm nginx/ { syscall[tid] nsecs; } tracepoint:syscalls:sys_exit_* /syscall[tid]/ { usec hist((nsecs - syscall[tid]) / 1000); delete(syscall[tid]); }统计所有内核函数的调用次数找出高频路径sudo bpftrace -e kprobe:* { [func] count(); }注意上面的命令在 BPF 支持不完善或生产环境的高负载下会带来额外开销不建议长时间运行。更优雅的做法是先采样热栈找到真正的热点函数再针对性跟踪。统计某个内核函数延迟分布的标准模板sudo bpftrace -e kprobe:函函数名 { start[tid] nsecs; } kretprobe:函数名 /start[tid]/ { usec hist((nsecs - start[tid]) / 1000); delete(start[tid]); }这套模板可以直接复制替换函数名就能用。我建议你把hist()的输出习惯读图直方图尾巴越长说明长尾延迟越严重比平均值有意义得多。还有一个实用技巧想看某个进程当前在内核里的工作状态可以用sudo bpftrace -e kprobe:finish_task_switch { [kstack] count(); }虽然效率低但偶尔能抓出一些诡异的内核路径。5. 一些踩坑记录和我的总结5.1 bpftrace 使用中容易翻车的几个点eBPF 工具上手容易但细节处坑不少。这里列出我踩过的几个实际问题。第一个坑是内核符号缺失。部分内核没开CONFIG_KPROBES或CONFIG_BPF_EVENTSkprobe 挂上去直接报错。加载之前先跑sudo bpftrace -e BEGIN { printf(ok\n); exit(); }验证基础能力能省去不必要的怀疑。另外老内核没有 BTF有些工具会挂不上一般升级内核或使用 CO-RE 版本工具能解决。第二个坑是权限问题。bpftrace 需要 root 权限还需要内核允许非特权 BPF。如果容器环境或加固系统限制了CAP_BPF、CAP_SYS_ADMIN探针会加载失败。生产环境排障时尽量直接在有 root 的物理机或特权容器里跑别在受限容器里折腾。第三个坑是探针开销。kprobe:*这种全量挂载在高峰期跑时间长了会给系统增加明显开销可能放大延迟本身。我建议线上操作时给 bpftrace 命令加上interval:s:N { exit(); }限制执行时长采样 5 到 10 秒出结果就停避免影响业务。第四个坑是过滤条件错误导致数据污染。Nginx 有 worker 进程也有 master 进程如果不加comm nginx而用pid过滤数据会混入其他进程。如果你用pgrep拿到的 PID 是 master 进程的探针可能一次都触发不了。先确认 PID 归属再写过滤条件。5.2 这类问题为什么容易诡异以及我的经验总结这次问题之所以诡异是因为所有常规指标都在正常范围内唯独用户体验差。CPU 不高、内存不紧、连接数没爆用系统管理员那套老办法怎么也看不出来。但换个角度想当你已经确认应用层正常时剩下的进展只能靠系统有没有异常路径这时候 eBPF 的价值就体现出来了。我个人的体会是eBPF 排障的核心能力不在于能看到内核而在于能带着问题去内核里做实验。传统方式里内核是个黑盒你只能猜有了探针之后你可以直接测量用数据修正直觉。每一个 kprobe 都像给内核装了一个仪表盘直方图一打问题分布一目了然。以后再遇到类似的诡异延迟我的建议是先别急着调参数改代码花五分钟做一个内核热栈采样看看 CPU 时间到底去哪儿了。可能大部分时间结论是正常也可能像这次一样一眼就看见真凶。哪怕一次没抓到它给你的方向也比盲调参数有价值得多。毕竟能被观察到的系统才有资格被优化。
