系统诊断小技巧(11):如何解决“问题复现了,但是捕捉数据进程因为CPU打满没有运行”?

引子

曾经搞过一个尴尬的案例。排查过一个CPU打满的问题。因为问题是在凌晨出现,而且非常随机。所以我们就准备了一个脚本,用来捕获占用CPU高的线程。但尴尬的是,问题复现了,我们的脚本偏偏在问题复现时,没有记录。推断是因为CPU打满,脚本没有机会执行导致的。

那么,CPU打满导致捕捉数据的进程没有运行的问题,能够解决吗?我们尝试回答这个问题。

亦步亦趋:了解Linux内核线程watchdog是怎么保证及时运行的

watchdog内核线程是检测Linux内核softlock机制的一部分,必须及时运行,除非是内核死锁了。如果我们把目光聚焦在用户空间,那么watchdog内核线程的运行设定是个合适的模仿对象。

理解watchdog的运行特点,需要稍微了解下Linux的调度策略和chrt(1)工具。

Linux支持多个调度策略,在“实时”的调度策略上又有调度优先级的区分。这部分话题,以后有机会我们再细聊。现在只要知道这一点,并且知道我们可以使用chrt(1)检查和设置即可。

那么,watchdog内核线程有什么特殊呢?比较下

# 1. 检查watchdog的pid
root@pusf:~# ps -ef | egrep watchdog | egrep -v egrep
root        11     2  0 09:15 ?        00:00:00 [watchdog/0]
root        14     2  0 09:15 ?        00:00:00 [watchdog/1]
... ....
# 2. 检测watchdog的调度策略和优先级
root@pusf:~# chrt -p 11
pid 11's current scheduling policy: SCHED_FIFO
pid 11's current scheduling priority: 99
# 3. 检测当前交互shell的调度策略和优先级
root@pusf:~# chrt -p $$
pid 10389's current scheduling policy: SCHED_OTHER
pid 10389's current scheduling priority: 0
root@pusf:~#

简单比较,让我们了解了两种调度策略(sched-fifo vs. sched-other)和两种优先级(99 vs. 0)。

下面我们用简单例子测试下这两种调度策略的差别。

两种调度策略的比较

测试脚本和压力产生器

我们的测试脚本每隔1秒打印下时间戳,一共取10次。具体内容如下(下文以demo指代这个脚本):

#!/bin/bash

export LANG=C

for ((i=0;i<10;i++));do
    sleep 1
    date
done

既然是比较在CPU打满情况下的调度策略,自然也需要一个压力产生器,用来把CPU打满。我们偷偷懒,直接使用perf(1)工具。

基线数据

我们给出CPU没有打满情况下的测试数据,作为基线数据。测试命令如下

root@pusf:~# ./demo > baseline-data-1 & ./demo > baseline-data-2 &

让我们看看测试结果

# baseline-data-1
Fri Aug 24 06:17:59 EDT 2018
Fri Aug 24 06:18:00 EDT 2018
Fri Aug 24 06:18:01 EDT 2018
Fri Aug 24 06:18:02 EDT 2018
Fri Aug 24 06:18:04 EDT 2018
Fri Aug 24 06:18:05 EDT 2018
Fri Aug 24 06:18:06 EDT 2018
Fri Aug 24 06:18:07 EDT 2018
Fri Aug 24 06:18:08 EDT 2018
Fri Aug 24 06:18:09 EDT 2018

# baseline-data-2
Fri Aug 24 06:17:59 EDT 2018
Fri Aug 24 06:18:00 EDT 2018
Fri Aug 24 06:18:01 EDT 2018
Fri Aug 24 06:18:02 EDT 2018
Fri Aug 24 06:18:04 EDT 2018
Fri Aug 24 06:18:05 EDT 2018
Fri Aug 24 06:18:06 EDT 2018
Fri Aug 24 06:18:07 EDT 2018
Fri Aug 24 06:18:08 EDT 2018
Fri Aug 24 06:18:09 EDT 2018

难以置信, 两份数据没有什么差异。好吧,测试机确实是非常的空闲。

CPU打满情况下的测试结果

我们再采样前,先运行压力产生器把CPU打满。具体运行命令如下

root@pusf:~# perf bench sched messaging -l 10000 & \ # 启动压力产生器
sleep 1; \ # 等待压力产生器驱动CPU
./demo > sched-other.log & \ # 以默认/正常的调度策略采样
chrt -f 99 ./demo > sched-fifo.log & # 以watchdog的调度策略和优先级运行采样

让我们看看结果。

# sched-other.log
Fri Aug 24 06:06:43 EDT 2018
Fri Aug 24 06:06:49 EDT 2018
Fri Aug 24 06:06:55 EDT 2018
Fri Aug 24 06:07:00 EDT 2018
Fri Aug 24 06:07:02 EDT 2018
Fri Aug 24 06:07:04 EDT 2018
Fri Aug 24 06:07:06 EDT 2018
Fri Aug 24 06:07:08 EDT 2018
Fri Aug 24 06:07:09 EDT 2018
Fri Aug 24 06:07:10 EDT 2018

# sched-fifo.log
Fri Aug 24 06:06:39 EDT 2018
Fri Aug 24 06:06:40 EDT 2018
Fri Aug 24 06:06:41 EDT 2018
Fri Aug 24 06:06:42 EDT 2018
Fri Aug 24 06:06:43 EDT 2018
Fri Aug 24 06:06:44 EDT 2018
Fri Aug 24 06:06:45 EDT 2018
Fri Aug 24 06:06:46 EDT 2018
Fri Aug 24 06:06:47 EDT 2018
Fri Aug 24 06:06:48 EDT 2018

调度策略在CPU打满情况下的差异太明显了。第一份数据前后间隔没有是1秒的情况,而第二份数据估计完美主义者都会树大拇指。

步骤

如何解决我们开头提出的问题,现在已经很明确了。我们不再饶舌。

探索愉快!

上一篇:iOS新手引导页的实现,源码。


下一篇:有内核造成的nginx启动异常