-
Linux性能优化实践(1): 进程长时间不被调度执行案例
1. 前言
限于作者能力水平，本文可能存在谬误，因此而给读者带来的损失，作者不做任何承诺。
2. 分析环境
1. SoC: T507, Cortex-A53, 4核, 1.5GHz(最高频) 2. 系统: Linux 4.9/Ubuntu 18.04- 1
3. 问题描述
有一个简单的按键驱动，
采样 GPIO 上升或下降沿中断信号。按键信号通过PLC设备以25Hz的固定频率触发；然后用户空间读取按键事件，测试发现，3万次左右就漏掉了接近 190 次按键事件。4. 问题分析
4.1 代码分析
内核按键驱动非常简单，核心逻辑概要如下：
static irqreturn_t xxx_gpio_key_isr(int irq, void *dev_id) { ... input_event(input, EV_KEY, code, state); input_sync(input); // 唤醒可能的睡眠等待读者进程 ... return IRQ_HANDLED; }- 1
- 2
- 3
- 4
- 5
- 6
- 7
用户空间读取按键事件的代码，核心逻辑概要如下：
int fd; fd_set fds; struct input_event event; int down_count = 0; fd = open("/dev/input/event1", O_RDWR); for (;;) { FD_ZERO(&fds); FD_SET(fd, &fds); if (select(fd + 1, &fds, NULL, NULL, NULL) < 0) { // 有事件数据立即返回，否则睡眠等待直到有事件数据到来 perror("select"); break; } memset(&event, 0, sizeof(event)); if (read(fd, &event, sizeof(event)) < 0) { perror("read"); break; } if (event.type == EV_KEY) { if (event.code == KEY_DOWN) { // 驱动上报的是 Down 键 if (event.value) { // 下降沿事件上报: 理解为按键按下 ++down_count; LOGI("event.value: %d, count = %d/%d\n", event.value, down_count, trigger_count()); } else { // 上升沿事件上报: 理解为按键松开 LOGI("event.value = %d\n", event.value); } } } } close(fd);- 1
- 2
- 3
- 4
- 5
- 6
- 7
- 8
- 9
- 10
- 11
- 12
- 13
- 14
- 15
- 16
- 17
- 18
- 19
- 20
- 21
- 22
- 23
- 24
- 25
- 26
- 27
- 28
- 29
- 30
- 31
其中，
LOGI()是封装的一个日志接口，其输出在日志内容前加上了时间戳、线程名和线程PID，后面从日志中可以看到；trigger_count()返回PLC设备实际触发的按键事件次数(至于怎么做的，读者不用纠结，了解这点就可以了)。另外，上面的按键事件代码用在一个比较复杂的应用程序中，但分析的时候，为排除其它代码的影响，已经将该段代码独立到一个测试程序中，该测试程序仅包含上述代码。
分析下了驱动和测试代码，没发现什么问题，这代码毕竟是一目了然。4.2 程序日志分析
由于程序日志加入了
时间戳、线程名和线程PID，所以很容易发现线程每两次被调度执行之间的大概时间间隔，从程序日志里，发现如下异常日志：[809.934931608] <I> <test.2867> event.value: 1, count = 18156/18156 [811.244779323] <I> <test.2867> event.value: 0 [809.246744615] <I> <test.2867> event.value: 1, count = 18157/18188- 1
- 2
日志中的时间戳，格式为
秒.纳秒，上面 第1行 和 第2行 日志的时间戳，相差为1309.847715 毫秒，按每秒 25 次按键计算，每两次按键相隔 1000 / 25 = 40ms，所以1309.847715 毫秒约有1309.847715 / 40 = 32次按键事件，和日志里面的count = 18157/18188统计是对应的：18188 - 18157 = 31。不要为不是 32 而奇怪，日志的打印也是会存在一点消耗的，这没有问题。看到这里，首先考虑是不是按键事件上报的源头，中断处理不及时，但通过cat /proc/interrupts查看，所有的按键中断都被捕捉上报了：# cat /proc/interrupts 120: 36376 0 0 0 sunxi_pio_edge 103 Edge gpio_key_drv- 1
可以看到，处理了
36376次中断(包括上升沿和下降沿)，36376 / 2 = 18188和程序日志里的实际按键事件次数是对应的。既然没有漏掉按键中断，就意味着按键事件都上报了，按理每次都会唤醒应用读取事件才对，但为什么应用日志里面会有1,309.847715 毫秒的间隙，这可是1秒多，进程的唤醒调度延迟，再怎么也不应该造成这么久的延迟，简直太不可思议了！4.2.1 CPU 频率变换引发的抖动？
查看了下
Ubuntu 18.04配置的CPU 频率策略：# cat /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor interactive interactive interactive interactive- 1
- 2
- 3
- 4
嗯，可能会产生 CPU 频率的切换，于是打开了内核
cpufreq的相关日志，再次进行测试，发现如下内核日志：[ 586.352163] cpufreq: notification 1 of frequency transition to 792000 kHz [ 586.352170] cpufreq: FREQ: 792000 - CPU: 1 [ 586.352180] cpufreq: notification 1 of frequency transition to 792000 kHz [ 586.352188] cpufreq: FREQ: 792000 - CPU: 2 [ 586.352198] cpufreq: notification 1 of frequency transition to 792000 kHz [ 586.352205] cpufreq: FREQ: 792000 - CPU: 3 [ 586.371136] cpufreq: target for CPU 0: 1008000 kHz, relation 1, requested 1008000 kHz [ 586.371147] cpufreq: __target_index: cpu: 0, oldfreq: 792000, new freq: 1008000 [ 586.371158] cpufreq: cpus 0-3 cur freq/max freq 1008000/1512000 kHz freq scale 682 [ 586.371168] cpufreq: notification 0 of frequency transition to 1008000 kHz [ 586.371176] cpufreq: notification 0 of frequency transition to 1008000 kHz [ 586.371185] cpufreq: notification 0 of frequency transition to 1008000 kHz [ 586.371193] cpufreq: notification 0 of frequency transition to 1008000 kHz [ 586.373613] cpufreq: notification 1 of frequency transition to 1008000 kHz [ 586.373620] cpufreq: FREQ: 1008000 - CPU: 0 [ 586.373629] cpufreq: notification 1 of frequency transition to 1008000 kHz [ 586.373635] cpufreq: FREQ: 1008000 - CPU: 1 [ 586.373643] cpufreq: notification 1 of frequency transition to 1008000 kHz [ 586.373649] cpufreq: FREQ: 1008000 - CPU: 2 [ 586.373657] cpufreq: notification 1 of frequency transition to 1008000 kHz [ 586.373662] cpufreq: FREQ: 1008000 - CPU: 3 [ 586.474473] cpufreq: target for CPU 0: 480000 kHz, relation 1, requested 480000 kHz [ 586.474482] cpufreq: __target_index: cpu: 0, oldfreq: 1008000, new freq: 480000 [ 586.474491] cpufreq: cpus 0-3 cur freq/max freq 480000/1512000 kHz freq scale 325 [ 586.474498] cpufreq: notification 0 of frequency transition to 480000 kHz [ 586.474505] cpufreq: notification 0 of frequency transition to 480000 kHz [ 586.474511] cpufreq: notification 0 of frequency transition to 480000 kHz [ 586.474518] cpufreq: notification 0 of frequency transition to 480000 kHz [ 586.477606] cpufreq: notification 1 of frequency transition to 480000 kHz [ 586.477621] cpufreq: FREQ: 480000 - CPU: 0 [ 586.477640] cpufreq: notification 1 of frequency transition to 480000 kHz [ 586.477653] cpufreq: FREQ: 480000 - CPU: 1 [ 586.477669] cpufreq: notification 1 of frequency transition to 480000 kHz [ 586.477682] cpufreq: FREQ: 480000 - CPU: 2 [ 586.477697] cpufreq: notification 1 of frequency transition to 480000 kHz [ 586.477709] cpufreq: FREQ: 480000 - CPU: 3 [ 610.431310] cpufreq: target for CPU 0: 600000 kHz, relation 1, requested 600000 kHz [ 610.431333] cpufreq: __target_index: cpu: 0, oldfreq: 480000, new freq: 600000- 1
- 2
- 3
- 4
- 5
- 6
- 7
- 8
- 9
- 10
- 11
- 12
- 13
- 14
- 15
- 16
- 17
- 18
- 19
- 20
- 21
- 22
- 23
- 24
- 25
- 26
- 27
- 28
- 29
- 30
- 31
- 32
- 33
- 34
- 35
- 36
- 37
呵呵，这频率简直在跳舞，最低都降到了
480000 Hz，鉴于此，于是将 CPU 频率策略调整为 performance ，以最高频率 1.5 GHz 来跑，同时将 PLC设备 的按键触发频率提高到了 60Hz(毕竟4核，1.5GHz)，看情况会变成怎样。# echo performance > /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor # echo performance > /sys/devices/system/cpu/cpu1/cpufreq/scaling_governor # echo performance > /sys/devices/system/cpu/cpu2/cpufreq/scaling_governor # echo performance > /sys/devices/system/cpu/cpu3/cpufreq/scaling_governor # cat /sys/devices/system/cpu/cpu*/cpufreq/scaling_cur_freq 1512000 1512000 1512000 1512000- 1
- 2
- 3
- 4
- 5
- 6
- 7
- 8
- 9
测试结果发现，情况得到了很大的改善，但还是会偶尔漏掉按键事件，看程序日志：
[3122.791343360] <I> <test.2867> event.value: 1, count = 113659/113659 [3122.972479211] <I> <test.2867> event.value: 0- 1
两个时间戳，相差了
181.135851 毫秒！查看内核日志，没有发现 CPU 频率变化的日志信息。读到这里，有的童鞋可能有疑问了，既然都调整成了performance模式，为什么还要观察内核日志中 CPU 频率变化信息，怎么还可能降频？事实上，在带有温控监测模块的情形下，即使是 CPU 运行于performance模式，也有可能出现因温度过高导致的降频，但这里的情形显然不是。4.2.2 中断导致的调度延迟？
因为是偶发的漏掉按键事件，那可能是一些不规律的事件的引起的，中断是一个首先要考察的对象，查看了下系统的中断发生状况：
CPU0 CPU1 CPU2 CPU3 3: 105999 206753 224680 246969 wakeupgen 48 Level sun4i_timer0 6: 8103107 5279139 8122634 4230346 GIC-0 27 Level arch_timer 8: 0 0 0 0 wakeupgen 61 Level 30f0000.iommu 120: 285180 0 0 0 sunxi_pio_edge 103 Edge gpio_key_drv 273: 0 0 0 0 wakeupgen 42 Level 3002000.dma-controller 276: 0 0 0 0 wakeupgen 104 Level rtc 278: 0 0 0 0 wakeupgen 93 Level cedar_dev 279: 0 0 0 0 wakeupgen 90 Level 1480000.g2d 280: 472 0 0 0 wakeupgen 0 Level uart0 284: 6278 0 0 0 wakeupgen 105 Level twi5 285: 3421998 0 0 0 wakeupgen 7 Level twi1 286: 4 0 0 0 wakeupgen 9 Level twi3 290: 0 0 0 0 wakeupgen 28 Level ehci_hcd:usb1 291: 0 0 0 0 wakeupgen 29 Level ohci_hcd:usb4 292: 0 0 0 0 wakeupgen 30 Level ehci_hcd:usb2 293: 0 0 0 0 wakeupgen 31 Level ohci_hcd:usb5 294: 0 0 0 0 wakeupgen 32 Level ehci_hcd:usb3 295: 0 0 0 0 wakeupgen 33 Level ohci_hcd:usb6 296: 0 0 0 0 wakeupgen 13 Level spi1 299: 22759 0 0 0 wakeupgen 37 Level sunxi-mmc2 300: 7 0 0 0 wakeupgen 36 Level sunxi-mmc1 304: 0 0 0 0 wakeupgen 66 Level dispaly 308: 240 0 0 0 wakeupgen 75 Level vin_cci 311: 0 0 0 0 wakeupgen 69 Level vinc0 312: 0 0 0 0 wakeupgen 70 Level vinc1 313: 0 0 0 0 wakeupgen 71 Level vinc2 314: 0 0 0 0 wakeupgen 72 Level vinc3 315: 0 0 0 0 wakeupgen 79 Level vinc4 316: 0 0 0 0 wakeupgen 80 Level vinc5 319: 0 0 0 0 wakeupgen 89 Level 1420000.deinterlace 323: 201292 0 0 0 wakeupgen 14 Level gmac0 330: 0 0 0 0 sunxi-8i-nmi 0 Level axp858_irq_chip 342: 0 0 0 0 axp858_irq_chip 11 Edge axp20x-pek-dbf 343: 0 0 0 0 axp858_irq_chip 12 Edge axp20x-pek-dbr IPI0: 155361 229366 208753 236313 Rescheduling interrupts IPI1: 69 520 585 539 Function call interrupts IPI2: 0 0 0 0 CPU stop interrupts IPI3: 4622 9795 13988 15958 Timer broadcast interrupts IPI4: 12449 11302 10855 12823 IRQ work interrupts IPI5: 0 0 0 0 CPU wake-up interrupts Err: 0- 1
- 2
- 3
- 4
- 5
- 6
- 7
- 8
- 9
- 10
- 11
- 12
- 13
- 14
- 15
- 16
- 17
- 18
- 19
- 20
- 21
- 22
- 23
- 24
- 25
- 26
- 27
- 28
- 29
- 30
- 31
- 32
- 33
- 34
- 35
- 36
- 37
- 38
- 39
- 40
- 41
发现了吧，
SPI 中断基本都集中在 CPU 核 0上。鉴于此，有了这样的一个猜想：某段时间内，我们的测试程序被调度到 CPU 0 上执行，但由于此段时间中断频发，导致程序始终无法被调度去执行读取按键事件的代码；等到再被调度去读取按键事件时，Input 子系统缓冲里、前面的按键事件数据已经被新事件数据覆盖了，再也无法读取到。此段期间，测试程序一直在 CPU 0 上接受调度。有了想法，就去验证，于是通过taskset命令对测试程序进行绑核操作，不让测试程序在中断压力大的 CPU 0 上运行：# taskset -p 0xe 2867 # taskset -cp 2867 pid 2867's current affinity list: 1-3- 1
- 2
重新测试500万次，没有再发现漏掉按键事件的情况，看样子优化方向应该是对的。
5. 结语
小结一下，导致问题的原因，包括两点:
1. CPU 频率变换导致的调度延迟 2. CPU 中断引发的调度延迟- 1
如果经过前面的优化，仍然有丢失按键事件的问题，继续优化的方向包括：
1. 调整进程优先级 2. 调整为实时进程 3. 通过 cgroup 分配独立的核给程序使用- 1
- 2
本文分析没有使用诸如
ftrace, perf, eBPF之类的工具，事实上，笔者认为，在有源码的情形下，分析源码本身，就是最有效的分析方法，带上时间戳、线程名和其PID，简单朴素的printf()调试插桩，在大多数情形下，都是很好的调试工具。像ftrace, perf, eBPF之类的工具，都是一种逆向的分析方法，是不得已的选择，而且这些工具，在分析性能的时候，都是计算被关注代码段前后时间消耗，和本文使用的方法并无本质的差别，即使是调试程序流程，printf()仍然也是很好的选择。当然，printf()也有它不适用的场合。
另外，上面的观察中，发现SPI 中断总是集中在 CPU 0 上，具体原因可参考博文：Linux: ARM GIC仅中断CPU 0问题分析 。
本文涉及到中断相关内容，可参考博文：Linux: 中断实现简析
涉及到的输入子系统相关内容，可参考博文：Linux输入子系统简析 -
相关阅读:
【XInput】游戏手柄模拟鼠标动作
数值分析复习：误差
Victor CMS SQL注入漏洞（ CVE-2022-26201）
css的三种引入方式
SpringMVC
北京多域名通配符SSL证书能保护几个域名
AI改写-AI改写可以迅速生成新的文章有什么弊端吗？
php判断是否是email格式
信息量与信息熵
自己动手从零写桌面操作系统GrapeOS系列教程——6.电脑启动过程介绍
- 原文地址：https://blog.csdn.net/JiMoKuangXiangQu/article/details/131085260
