前言
在机器上跑一些任务/业务的时候,可能经常会遇到cpu”抖”一下的情况,具体可能表现为该任务的cpu利用率突然降下去然后又拉回来、网络流量/磁盘IO等突然降下去又拉回来这样子。而在云虚拟化的场景下,物理机上的qemu进程如果发生抖动,将直接影响云上虚机的稳定性。
造成cpu抖动的常见原因基本就是进程抢占、中断抢占、硬件故障等。
那么,怎么发现抖动,以及发现抖动后怎么去确认抖动原因呢?
工具
什么时候应该去查cpu抖动并定位原因呢?一般有两个时间点:业务监控发现关键指标抖动时、业务上线前。
如果业务已经上线了,业务监控显示指标抖动,这时候就根据具体抖动指标去抽丝剥茧层层分析就好了。当然,我们肯定不希望已经上线的业务发生抖动影响客户(收益),所以,最好能够在业务上线前检测定位并消除抖动。
cyclictest工具
-
介绍
cyclictest工具来自rc-test工具包,详见https://wiki.linuxfoundation.org/realtime/documentation/howto/tools/cyclictest/start
这个工具检测抖动的原理也不复杂,就是起nr_cpu个线程并绑核,每个线程起一个timer定时器,然后设置根据传入的唤醒时间设置timer,当线程唤醒时根据设定的唤醒时间和真实的唤醒时间进行比较,从而得出抖动时间。
编译及使用
编译过程不在此说,按照https://github.com/vianpl/rt-tests编译出一个binary即可。
使用方法呢,cyclictest –help也能看到具体参数,一个典型的输出结果如下所示,比如P99后面的数字就是在测量期间99分位的延迟是几十微秒,最后的max就是在测量期间最大延迟是几百微秒。最上面两行,则是cyclictest检测到某个线程的延迟过大的时候,就把该信息打印出来。
[CPU #100] too large latency 23132 us, now=8235.417495401, next=8235.394362653, delta_tsc=71859581
[CPU #125] too large latency 22815 us, now=8475.691815355, next=8475.668999397, delta_tsc=70884631
T: 0 C: 878266 Median: 22 P99: 39 P99.9: 46 P99.99: 54 P99.999: 68 Max: 188
T: 1 C: 878266 Median: 16 P99: 29 P99.9: 38 P99.99: 48 P99.999: 60 Max: 279
T: 2 C: 878266 Median: 31 P99: 50 P99.9: 56 P99.99: 62 P99.999: 68 Max: 265
T: 3 C: 878265 Median: 23 P99: 37 P99.9: 44 P99.99: 52 P99.999: 66 Max: 247
T: 4 C: 878264 Median: 26 P99: 41 P99.9: 48 P99.99: 55 P99.999: 62 Max: 228
T: 5 C: 878262 Median: 20 P99: 37 P99.9: 47 P99.99: 55 P99.999: 63 Max: 205
T: 6 C: 878261 Median: 25 P99: 43 P99.9: 52 P99.99: 59 P99.999: 67 Max: 268
T: 7 C: 878257 Median: 15 P99: 32 P99.9: 39 P99.99: 45 P99.999: 53 Max: 416
T: 8 C: 878260 Median: 16 P99: 33 P99.9: 43 P99.99: 54 P99.999: 62 Max: 229
T: 9 C: 878259 Median: 23 P99: 43 P99.9: 50 P99.99: 57 P99.999: 65 Max: 239
T: 10 C: 878258 Median: 25 P99: 48 P99.9: 56 P99.99: 61 P99.999: 67 Max: 182
T: 11 C: 878256 Median: 27 P99: 47 P99.9: 53 P99.99: 58 P99.999: 64 Max: 221
T: 12 C: 878256 Median: 24 P99: 41 P99.9: 47 P99.99: 54 P99.999: 62 Max: 192
T: 13 C: 878254 Median: 20 P99: 40 P99.9: 51 P99.99: 61 P99.999: 69 Max: 236
T: 14 C: 878253 Median: 22 P99: 43 P99.9: 52 P99.99: 60 P99.999: 68 Max: 248
T: 15 C: 878252 Median: 15 P99: 32 P99.9: 45 P99.99: 56 P99.999: 63 Max: 219language-c复制代码
这里说一下常用的抓最大延迟的两个参数(–breaktrace和–tracemark),搭配ftrace一起使用,定位max超标的情况。
看一下这两个参数
-b USEC --breaktrace=USEC send break trace command when latency > USEC
--tracemark write a trace mark when -b latency is exceededlanguage-c复制代码
-b XXX就是当cyclictest检测到某个线程的调度延迟超过设定的XXX微秒的时候,就停止cyclictest的运行。
–tracemark这是当上面设置的-b XXX触发的时候,向/sys/kernel/debug/tracing/tracing_on写0停止trace
所以,在排查max抖动超标的时候,可以先打开ftrace的功能,然后使用cyclictets的时候设定-b XXX –tracemark参数。这样,当某个线程出现抖动的时候,cyclictest将停止运行,同时停止ftrace,这时候再根据cyclictest的break trace的输出信息查看哪个cpu上的cyclictest线程出现了抖动,再去/sys/kernel/debug/tracing中查看该cpu的trace结果去分析即可。
(当然,使用这种方法,可能会使原本的抖动变得更大,因为开启ftrace之后本身就会带来额外的开销,造成抖动)
-
注意
使用该工具检测到抖动的时候,需要先排除是否是该工具本身的问题。
比如,我之前遇到个问题,我们在使用cyclictest的–smp参数时,发现抖动很大,经过排查才发现原来cyclictest在每个cpu上都起了两个线程,这俩线程之间肯定是有抢占和竞争的关系的。原因是我们的机器offline了一部分核,而老版本(23年以前)的cyclictest中,获取应起的线程数量是通过numactl工具包中的一个库的numa_num_task_cpus函数实现的,这个函数其实就是去获取了/proc/self中的Cpus_allowed去判断起的cyclictest线程的数量,而Cpus_allowed是不感知offline cpu的。所以才出现当前有X个cpu却起了Y个线程的情况。新版本的cyclictest已经修复了这个问题,使用最新的代码即可。
rtla工具
-
介绍
rtla其实是基于osnoise和timerlat来搞的,这两者都是由内核config控制是否开启的。两者的原理其实和上面的cyclictest类似的,也是通过设置timer然后检测设定时间与实际唤醒时间来检测抖动的。
-
编译
要使用osnoise和timerlat,则必须使能内核相关的config
CONFIG_OSNOISE_TRACER
CONFIG_TIMERLAT_TRACERlanguage-c复制代码
这样,就可以在新内核中的debugfs的available_traces显示相关的tracer了
# cat available_tracers
timerlat osnoise hwlat blk function_graph wakeup_dl wakeup_rt wakeup function noplanguage-c复制代码
其实,这两个tracer就可以直接使用了,不过,不太灵活,可以再继续编译rtla
在内核源码的tools/tracing/rtla下,可以编译这个工具,不过,在编译前,要先看一下README,是有一些依赖需要先安装上的
RTLA depends on the following libraries and tools:
- libtracefs
- libtraceevent
- libcpupower (optional, for --deepest-idle-state)language-c复制代码
安装完相关依赖,编译出rtla的binary即可使用
-
使用
osnoise和timerlat的直接使用,就是和不同的tracer一样的使用方法,echo进current_tracer中即可,这里简单看一下他们的输出
osnoise:很明显,MAX SINGLE NOISE IN US指的就是测量期间内的最大噪声(抖动/调度延迟),后面的Interference counters则是测量期间内硬件、NMI、IRQ等发生的计数。
# tracer: osnoise
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable MAX
# |||| / delay SINGLE Interference counters:
# ||||| RUNTIME NOISE %% OF CPU NOISE +-----------------------------+
# TASK-PID CPU# ||||| TIMESTAMP IN US IN US AVAILABLE IN US HW NMI IRQ SIRQ THREAD
# | | | ||||| | | | | | | | | | |
<...>-221339 [000] ..... 3291315.154441: 10000001052198.947903922002873746
<...>-221340 [001] ..... 3291315.154837: 1000000341599.65850880002743543
<...>-221341 [002] ..... 3291315.154912: 1000000269099.73100471002533152
<...>-221342 [003] ..... 3291315.154959: 1000000282299.7178061002843518
<...>-221343 [004] ..... 3291315.155043: 1000000222399.7777038002503040
<...>-221344 [005] ..... 3291315.155129: 1000000279399.72070431002553133
<...>-221345 [006] ..... 3291315.155162: 1000000283299.71680559002583153language-c复制代码
timerlat:timerlat则直接显示每个timerlat线程的调度延迟时间
<idle>-0 [272] d.h1. 3291728.942768: #48 context irq timer_latency 728 ns
<...>-226346 [272] ..... 3291728.942769: #48 context thread timer_latency 1798 ns
<idle>-0 [331] d.h1. 3291728.942774: #46 context irq timer_latency 735 ns
<...>-226405 [331] ..... 3291728.942775: #46 context thread timer_latency 1895 ns
<idle>-0 [186] d.h1. 3291728.942776: #51 context irq timer_latency 824 ns
<...>-226260 [186] ..... 3291728.942778: #51 context thread timer_latency 1974 ns
<idle>-0 [243] d.h1. 3291728.942779: #49 context irq timer_latency 710 ns
<...>-226317 [243] ..... 3291728.942780: #49 context thread timer_latency 1870 ns
<idle>-0 [214] d.h1. 3291728.942784: #50 context irq timer_latency 782 ns
<...>-226288 [214] ..... 3291728.942785: #50 context thread timer_latency 1772 ns
<idle>-0 [128] d.h1. 3291728.942785: #53 context irq timer_latency 698 nslanguage-c复制代码
可以看到,一般情况下,上面的osnoise可以大致判断什么造成了cpu抖动,比如nmi、irq或者进程抢占等。
但是,如果发生了进程抢占,怎么判断是哪个线程抢占造成了抖动呢?
这种精细活儿,还得rtla来做
rtla version 6.16.0-rc1
usage: rtla COMMAND ...
commands:
osnoise - gives information about the operating system noise(osnoise)
hwnoise - gives information about hardware-related noise
timerlat - measures the timer irq and thread latencylanguage-c复制代码
我最常用的是timerlat的-a XXX参数,这个简直是cyclictest的-b XXX –tracemark的加强版,timerlat的-a XXX在调度延迟大于XXX微秒的时候将自动停止并打印相关栈出来,比如:
000:00:03 | IRQ Timer Latency(us) | Thread Timer Latency(us) | Ret user Timer Latency(us)
CPU COUNT | cur min avg max | cur min avg max | cur min avg max
0 #1 | 2 2 2 2 | 21 21 21 21 | - - - -
---------------|----------------------------------------|----------------------------------------|---------------------------------------
ALL #1 e0 | 2 2 2 | 21 21 21 | - - - |rtla timerlat hit stop tracing
## CPU 0 hit stop tracing, analyzing it ##
IRQ handler delay: 0.00 us(0.00 %)
IRQ latency: 2.02 us
Timerlat IRQ duration: 15.05 us(71.05 %)
Blocking thread: 2.94 us(13.89 %)
swapper/0:0 2.94 us
Blocking thread stack trace
-> timerlat_irq
-> __hrtimer_run_queues
-> hrtimer_interrupt
-> __sysvec_apic_timer_interrupt
-> sysvec_apic_timer_interrupt
-> asm_sysvec_apic_timer_interrupt
-> mwait_idle
-> default_enter_idle
-> cpuidle_enter_state
-> cpuidle_enter
-> cpuidle_idle_call
-> do_idle
-> cpu_startup_entry
-> rest_init
-> start_kernel
-> x86_64_start_reservations
-> x86_64_start_kernel
-> common_startup_64
------------------------------------------------------------------------
Thread latency: 21.19 us(100%)
Max timerlat IRQ latency from idle: 2.02 us in cpu 0
Saving trace to timerlat_trace.txtlanguage-c复制代码
除此之外,当然还有很多扩展用法,可以参考https://bristot.me/linux-scheduling-latency-debug-and-analysis/
其他方法
当然,还有很多其他方法可以单独或者搭配上面的方法一起使用的,比如perf sched record查看调度延迟,比如/proc/[PID]/sched中的wait_max等字段,都可以辅助定位cpu抖动的原因。
常见原因
下面列举一下我自己目前遇到的可能造成cpu抖动的原因:
-
正常情况。也许抖动并不是出现了问题,比如客户侧网络流量激增、突增大量读写盘操作,这种情况可能导致cpu的抖动,但它是用户侧的行为,我们可以通过一些手段去优化,但不能说这是系统有问题 -
cgroup限制了进程的执行配额 -
THP透明大页的开启,在频繁分配/释放内存的情况下可能导致系统频繁进行回收、聚合透明大页的操作造成抖动 -
内存不足,无法分配指定order的页面触发kswapd回收内存或者触发kcompactd规整内存等 -
进程抢占,比如一些无关的进程/服务的运行抢占了cpu -
绑核错误,本不该在此cpu上执行的任务因为绑核错误跑到了本cpu导致抖动 -
numa_balancing的开启可能导致频繁进行内存迁移。如无必要,可以关掉。(另外,由此想到,irqbalance会进行自动修改中断绑核的操作,也许也会造成抖动呢,不过我还没遇到过这种情况) -
OS内的一些优化服务,比如tuned、ksmtuned等,这种服务一直在OS内暗地里进行一些”调优”策略,可能造成cpu抖动 -
中断抢占 -
硬件原因(硬件错误、bios版本问题、微码错误、过多的smi中断等)
……

