我的 HTTP 应用程序突然开始需要额外的时间来启动。在此阶段，它将数据从磁盘加载到内存中的数据结构。
我怀疑这是由于上次更改中循环内的大量日志记录所致，但我需要一些证据来确定瓶颈是 IO。
我所做的strace显示了太多的系统write调用，如预期的那样，在这里打印了它的前几行。
ubuntu@hemu-mcahine:~$ sudo strace -p 109374
[sudo] password for ubuntu:
strace: Process 109374 attached
write(1, "s1 size:, %!i(int=338632)\n", 26) = 26
futex(0x93a7d8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00003c948, FUTEX_WAKE_PRIVATE, 1) = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=109374, si_uid=1001} ---
rt_sigreturn({mask=[]}) = 1
write(1, "s1 size:, %!i(int=338633)\n", 26) = 26
write(1, "s1 size:, %!i(int=338634)\n", 26) = 26
write(1, "s1 size:, %!i(int=338635)\n", 26) = 26
write(1, "s1 size:, %!i(int=338636)\n", 26) = 26
write(1, "s1 size:, %!i(int=338637)\n", 26) = 26
write(1, "s1 size:, %!i(int=338638)\n", 26) = 26
write(1, "s1 size:, %!i(int=338639)\n", 26) = 26
write(1, "s1 size:, %!i(int=338640)\n", 26) = 26
write(1, "s1 size:, %!i(int=338641)\n", 26) = 26
write(1, "s1 size:, %!i(int=338642)\n", 26) = 26
write(1, "s1 size:, %!i(int=338643)\n", 26) = 26
write(1, "s1 size:, %!i(int=338644)\n", 26) = 26
write(1, "s1 size:, %!i(int=338645)\n", 26) = 26
write(1, "s1 size:, %!i(int=338646)\n", 26) = 26
write(1, "s1 size:, %!i(int=338647)\n", 26) = 26
write(1, "s1 size:, %!i(int=338648)\n", 26) = 26
write(1, "s1 size:, %!i(int=338649)\n", 26) = 26
...
我原本希望看到“top”的输出为高“%wa”，但它主要显示两个 CPU 都处于空闲状态，没有任何显着的等待或计算时间，为什么会这样？
这是顶部的输出，第一个进程表示我的应用程序
top - 08:21:58 up 5 days, 21:32, 2 users, load average: 0.00, 0.00, 0.00
Tasks: 140 total, 1 running, 138 sleeping, 0 stopped, 1 zombie
%Cpu0 : 0.3 us, 1.3 sy, 0.0 ni, 98.0 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st
%Cpu1 : 0.7 us, 1.0 sy, 0.0 ni, 98.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
MiB Mem : 3925.3 total, 2310.1 free, 831.4 used, 783.9 buff/cache
MiB Swap: 0.0 total, 0.0 free, 0.0 used. 2861.2 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
109374 ubuntu 20 0 1084416 118780 5392 S 1.7 3.0 0:01.77 server
108671 ubuntu 20 0 14836 7020 4304 S 0.7 0.2 0:06.71 sshd
841 root 20 0 402468 30328 8916 S 0.3 0.8 6:07.89 python3
86001 root 20 0 0 0 0 I 0.3 0.0 0:06.41 kworker/0:3-events
88908 ubuntu 20 0 1029916 77444 33692 S 0.3 1.9 0:39.35 node
109196 root 20 0 0 0 0 I 0.3 0.0 0:00.74 kworker/u4:0-events_unbound
109280 root 20 0 0 0 0 I 0.3 0.0 0:00.44 kworker/u4:1-events_power_efficient
109398 ubuntu 20 0 11276 4224 3548 R 0.3 0.1 0:00.01 top
1 root 20 0 168972 13052 8312 S 0.0 0.3 0:15.16 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.04 kthreadd
3 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_gp
4 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_par_gp
5 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 netns
7 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/0:0H-events_highpri
9 root 0 -20 0 0 0 I 0.0 0.0 0:08.76 kworker/0:1H-events_highpri
10 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 mm_percpu_wq
11 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_tasks_rude_
12 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_tasks_trace
13 root 20 0 0 0 0 S 0.0 0.0 0:00.77 ksoftirqd/0
14 root 20 0 0 0 0 I 0.0 0.0 0:33.30 rcu_sched
15 root rt 0 0 0 0 S 0.0 0.0 0:02.53 migration/0
当我的代码不断记录日志并使服务器变慢时，如何知道高空闲时间背后的原因以及为什么“%wa”不是太多？
答案1
我在一些场景上进行了一些实验，我想现在我有了答案 -
后@索托的评论和一些谷歌搜索，我发现打印到终端与写入磁盘不同，因为前者需要额外的处理，线程需要等待数据打印到终端，并且终端的缓冲工作方式与磁盘 I/奥。这个答案很好地解释了这一点https://stackoverflow.com/questions/6338812/printing-to-the-console-vs-writing-to-a-file-speed。
此外，将日志定向到文件而不是 stdout 速度更快，但会导致内核空间时间增加，sy而不是wa%按照Top命令增加。我发现这是因为writesys 调用不会直接写入磁盘中的文件，而是将其发送到文件系统的缓冲区，该缓冲区进一步注意以最佳方式写入磁盘。
后来我开始使用 sys 调用来打印所有日志以sync清除缓冲区，并立即将所有数据提交到文件，在这里我看到wa%IO 操作中的数据显着高于预期，并且 CPU 大部分都处于睡眠状态。
结论：
- 终端与磁盘 I/O 不同，它甚至更慢。
- 由于文件系统的缓冲区，通过系统调用编写的 I/O 函数
write不一定会增加磁盘写入开销，但它们确实会增加上下文切换并消耗内核空间中的 CPU 周期