Linux 性能优化实践(1): 进程长时间不被调度执行案例

JiMoKuangXiangQu

已于 2024-03-21 09:58:12 修改

阅读量1k

点赞数

分类专栏： # 追踪 & 调试 & 性能文章标签： linux 性能优化调度延迟

于 2023-06-07 16:43:30 首次发布

本文链接：https://blog.csdn.net/JiMoKuangXiangQu/article/details/131085260

版权

追踪 & 调试 & 性能专栏收录该内容

20 篇文章 4 订阅

订阅专栏

文章目录

1. 前言
2. 分析环境
3. 问题描述
4. 问题分析
5. 结语

1. 前言

限于作者能力水平，本文可能存在谬误，因此而给读者带来的损失，作者不做任何承诺。

2. 分析环境

1. SoC: T507, Cortex-A53, 4核, 1.5GHz(最高频)
2. 系统: Linux 4.9/Ubuntu 18.04

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;
}

用户空间读取按键事件的代码，核心逻辑概要如下：

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);

其中， 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行日志的时间戳，相差为 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

可以看到，处理了 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

嗯，可能会产生 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

呵呵，这频率简直在跳舞，最低都降到了 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

测试结果发现，情况得到了很大的改善，但还是会偶尔漏掉按键事件，看程序日志：

[3122.791343360] <I> <test.2867> event.value: 1, count = 113659/113659
[3122.972479211] <I> <test.2867> event.value: 0

两个时间戳，相差了 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

发现了吧，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

重新测试500万次，没有再发现漏掉按键事件的情况，看样子优化方向应该是对的。

5. 结语

小结一下，导致问题的原因，包括两点:

1. CPU 频率变换导致的调度延迟
2. CPU 中断引发的调度延迟

如果经过前面的优化，仍然有丢失按键事件的问题，继续优化的方向包括：

1. 调整进程优先级
2. 调整为实时进程
3. 通过 cgroup 分配独立的核给程序使用

本文分析没有使用诸如 ftrace, perf, eBPF 之类的工具，事实上，笔者认为，在有源码的情形下，分析源码本身，就是最有效的分析方法，带上时间戳、线程名和其PID，简单朴素的 printf() 调试插桩，在大多数情形下，都是很好的调试工具。像 ftrace, perf, eBPF 之类的工具，都是一种逆向的分析方法，是不得已的选择，而且这些工具，在分析性能的时候，都是计算被关注代码段前后时间消耗，和本文使用的方法并无本质的差别，即使是调试程序流程，printf() 仍然也是很好的选择。当然，printf() 也有它不适用的场合。
另外，上面的观察中，发现 SPI 中断总是集中在 CPU 0 上，具体原因可参考博文：Linux: ARM GIC仅中断CPU 0问题分析。
本文涉及到中断相关内容，可参考博文：Linux: 中断实现简析
涉及到的输入子系统相关内容，可参考博文：Linux输入子系统简析