我发现在我的 Ubuntu 22 服务器上，尝试写入文件通常会导致大约 20 毫秒的延迟，即使只写入几个字节也是如此。
这是一些演示该问题的基本代码：
#include <iostream>
#include <fstream>
#include <chrono>
#include <filesystem>
#include <thread>
using namespace std;
void go_c() {
FILE *out = fopen("hello.txt", "w");
fputs("hello", out);
fclose(out);
}
void go_cpp () {
ofstream out("hello.txt");
out<<"hello"<<endl;
}
double test(void (*f)()) {
typedef chrono::time_point <chrono::steady_clock> tp;
tp t0 = chrono::steady_clock::now();
f();
tp t1 = chrono::steady_clock::now();
return chrono::duration<double>(t1-t0).count() * 1000; //milliseconds
}
void bench(void (*f)(), const char *txt, int delay_ms) {
filesystem::remove("hello.txt");
for (int i=0;i<5;i++) {
double t = test(f);
cerr<<i<<": "<<txt<<", time = "<<t<<" ms"<<endl;
this_thread::sleep_for(std::chrono::milliseconds(delay_ms));
}
cerr<<endl;
}
int main () {
bench(go_c, "C Write", 0);
bench(go_cpp, "C++ Write", 0);
bench(go_c, "C Write with delay", 2500);
bench(go_cpp, "C++ Write with delay", 2500);
return 0;
}
这是输出：
ubuntu@captain:~/scratch$ g++ -o write3 write3.cpp -O2 -Wall
ubuntu@captain:~/scratch$ ./write3
0: C Write, time = 0.09978 ms
1: C Write, time = 21.9316 ms
2: C Write, time = 0.185957 ms
3: C Write, time = 0.140212 ms
4: C Write, time = 0.139051 ms
0: C++ Write, time = 0.145766 ms
1: C++ Write, time = 0.091845 ms
2: C++ Write, time = 0.139618 ms
3: C++ Write, time = 0.130834 ms
4: C++ Write, time = 0.132217 ms
0: C Write with delay, time = 0.048674 ms
1: C Write with delay, time = 0.23875 ms
2: C Write with delay, time = 20.8626 ms
3: C Write with delay, time = 8.4307 ms
4: C Write with delay, time = 19.4026 ms
0: C++ Write with delay, time = 17.1555 ms
1: C++ Write with delay, time = 17.5887 ms
2: C++ Write with delay, time = 18.9792 ms
3: C++ Write with delay, time = 25.8653 ms
4: C++ Write with delay, time = 20.7998 ms
如果尝试之间有一点延迟，则似乎更有可能发生这种情况，如果文件已经存在，则更有可能发生这种情况。
（似乎我可以通过在写入文件之前删除文件来提高服务器性能。这似乎不合逻辑。）
硬件是 6 核 Xeon 2386G，在软 Raid 上配备双 NVMe SSD，几乎不运行其他任何东西，也没有其他用户。
See attached screenshot showing the result of uname -a and dpkg --list | grep -E "libc6?-(dev|bin)"
此答案旨在提供有关观察到的行为的信息并检查正在发生的情况。
TL;DR:问题显然来自于有功功率状态可以调整的 NVMe 设备，因此无需支付巨额费用唤醒开销。此开销被延迟的原因是异步IO操作 and 延迟等待在Linux内核中完成。请阅读“NVMe设备电源管理“（最后）所以要解决这个问题。
首先，在某些情况下，我可以在我的机器（Debian Linux 内核 5.15.0-2，带有 6 核 Intel i5-9600KF 和 NVMe“Samsung 970 Evo Plus”SSD）上部分重现效果。更具体地说，仅在第二次 C 测试期间才可见约 6 毫秒的延迟（2: C Write, time =）当我之前没有调用 GCC 来生成二进制文件时。否则所有计时均小于 1 ms（通常在 0.1~0.4 ms 范围内）。将内核更新到版本 5.18.0-2 将延迟减少到 2.5 毫秒 (+/- 0.5 毫秒)。时间足够稳定和确定，因此可以报告此类信息。
使用出色的 Linux perf 工具进行的快速分析表明，当延迟峰值发生时，很大一部分时间花费在与内核调度相关的函数上（使用perf record）。希望我们也能分析调度程序对 perf 做了什么。命令perf sched record ./a.out可用于记录调度信息和perf sched timehist -Vg帮助您显示时间表（请注意，perf 命令有时会在某些系统上以版本为后缀，例如perf_5.4）。这是我机器上的一个例子：
time cpu 0123456 task name wait time sch delay run time
[tid/pid] (msec) (msec) (msec)
--------------- ------ ------- ------------------------------ --------- --------- ---------
95730.123845 [0005] i <idle> 0.000 0.000 0.000
95730.123845 [0002] s perf_5.4[55033] 0.000 0.000 0.000
95730.124721 [0000] i <idle> 0.000 0.000 0.000
95730.124725 [0000] s gmain[805/804] 0.000 0.025 0.004
95730.124761 [0000] i <idle> 0.004 0.000 0.036
95730.124765 [0000] s gmain[805/804] 0.036 0.025 0.003
95730.124789 [0003] i <idle> 0.000 0.000 0.000
95730.124795 [0003] s kworker/u12:2-e[45157] 0.000 0.023 0.006
95730.124822 [0002] i <idle> 0.000 0.000 0.976
95730.124833 [0000] i <idle> 0.003 0.000 0.068
95730.124834 [0005] s a.out[55040] 0.000 0.026 0.988
95730.124836 [0000] s | gmain[805/804] 0.068 0.038 0.003
95730.124838 [0002] s | sudo[54745] 0.000 0.028 0.015
95730.124849 [0003] i | <idle> 0.006 0.000 0.053
95730.124854 [0003] s | kworker/u12:2-e[45157] 0.053 0.027 0.004
95730.124886 [0002] i | <idle> 0.015 0.000 0.048
95730.124901 [0002] s | sudo[54745] 0.048 0.033 0.015
95730.124916 [0003] i | <idle> 0.004 0.000 0.062
95730.124922 [0003] s | kworker/u12:2-e[45157] 0.062 0.024 0.005
95730.124945 [0004] i| <idle> 0.000 0.000 0.000
95730.124987 [0004] s| gnome-terminal-[8464] 0.000 0.024 0.042
95730.127461 [0003] i | <idle> 0.005 0.000 2.539
95730.127474 [0005] i <idle> 0.988 0.000 2.639
95730.127475 [0003] s kworker/u12:2-e[45157] 2.539 0.023 0.013
95730.127516 [0000] i | <idle> 0.003 0.000 2.679
95730.127519 [0000] s | gmain[805/804] 2.679 0.027 0.003
95730.127530 [0005] | s a.out[55040] 2.639 0.001 0.056
95730.127537 [0003] i | <idle> 0.013 0.000 0.062
95730.127549 [0005] i <idle> 0.056 0.000 0.018
95730.127550 [0003] s kworker/u12:2-e[45157] 0.062 0.023 0.013
95730.127566 [0004] i <idle> 0.042 0.000 2.578
95730.127568 [0004] s kworker/u12:4-e[54041] 0.000 0.026 0.002
95730.127585 [0002] i <idle> 0.015 0.000 2.683
95730.127585 [0000] i <idle> 0.003 0.000 0.065
95730.127588 [0000] s gmain[805/804] 0.065 0.026 0.003
95730.127591 [0005] s a.out[55040] 0.018 0.001 0.042
95730.127595 [0002] s | sudo[54745] 2.683 0.043 0.009
95730.127605 [0004] i| <idle> 0.002 0.000 0.037
95730.127617 [0005] i <idle> 0.042 0.000 0.026
95730.127618 [0004] s kworker/u12:4-e[54041] 0.037 0.028 0.013
95730.127635 [0003] i <idle> 0.013 0.000 0.085
95730.127637 [0003] s kworker/u12:2-e[45157] 0.085 0.027 0.002
95730.127644 [0003] i <idle> 0.002 0.000 0.007
95730.127647 [0003] s kworker/u12:2-e[45157] 0.007 0.000 0.002
95730.127650 [0003] i <idle> 0.002 0.000 0.003
95730.127652 [0003] s kworker/u12:2-e[45157] 0.003 0.000 0.001
95730.127653 [0003] i <idle> 0.001 0.000 0.001
95730.127659 [0003] s kworker/u12:2-e[45157] 0.001 0.000 0.006
95730.127662 [0002] i <idle> 0.009 0.000 0.067
95730.127662 [0000] i <idle> 0.003 0.000 0.073
95730.127666 [0000] s gmain[805/804] 0.073 0.036 0.003
95730.127669 [0003] i <idle> 0.006 0.000 0.010
95730.127672 [0004] i <idle> 0.013 0.000 0.053
95730.127673 [0003] s kworker/u12:2-e[45157] 0.010 0.000 0.004
95730.127674 [0004] s kworker/u12:4-e[54041] 0.053 0.026 0.002
95730.127676 [0004] i <idle> 0.002 0.000 0.001
95730.127678 [0004] s kworker/u12:4-e[54041] 0.001 0.001 0.002
95730.127679 [0002] s sudo[54745] 0.067 0.052 0.016
95730.127692 [0001] i <idle> 0.000 0.000 0.000
95730.127717 [0001] s gnome-terminal-[8464] 2.704 0.019 0.024
95730.127725 [0005] s a.out[55040] 0.026 0.001 0.107
95730.127755 [0002] i | <idle> 0.016 0.000 0.075
时间和左边的单位是秒，0123456列显示核心上活动任务的计划。s意味着任务已安排并且i意味着它被中断。我添加了|符号以便更好地理解跟踪进程何时运行（a.out是执行您的代码的程序）。程序打印的执行时间为2.68278 ms所以我们基本上是在时间戳中搜索 0.0027 秒的间隙（但我发现空闲时间戳不可靠，因为它们似乎指示空闲时间的结束而不是空闲时间的开始——当任务挂起时）。
时间表显示进程运行了 0.988 毫秒，然后被中断 2.639 毫秒，然后再次运行 0.056 毫秒，然后再次被中断 0.018 毫秒并再次运行，依此类推（为了方便起见，其余的执行过程没有显示）明晰）。第一次中断与报告的峰值时间非常匹配（特别是因为我们应该包括进程再次预热的时间以及调度程序进行上下文切换的时间）。
在程序中断期间，有两个任务被唤醒：一个称为kworker/u12:2-e和一个名为gmain这肯定是 gnome-shell。内核线程在程序中断时启动，在程序恢复时中断（有 7 us 的延迟）。另请注意，内核线程需要2.539 to run.
Perf 可以提供一些有关内核调用的信息。您可以通过添加选项来做到这一点--kernel-callchains --call-graph dwarf to sched record。不幸的是，结果在这种情况下不是很有用。唯一有用的信息是核函数io_schedule <- folio_wait_bit_common <- folio_wait_writeback <- truncate_inode_partial_folio当程序在尖峰期间被中断时调用。这证明程序因IO操作而中断。您还可以添加--wakeups标记以便查看唤醒事件，并看到可疑的慢速内核线程被目标程序唤醒（而前一个被其他任务唤醒（通常是gmain or gnome-terminal).
strace -T ./a.out可以用来跟踪系统调用的时间，我们可以清楚地看到第三次调用openat我的机器上速度很慢。这是有趣的部分（为了清楚起见重新格式化）：
unlink: 0.000072 s
openat: 0.000047 s
newfstatat: 0.000007 s
write: 0.000044 s
close: 0.000006 s
[...] (write x 7)
openat: 0.000019 s
newfstatat: 0.000005 s
write: 0.000011 s
close: 0.000022 s
[...] (write x 7)
openat: 0.002334 s <----- latency spike
newfstatat: 0.000057 s
write: 0.000080 s
close: 0.000052 s
[...] (write x 7)
openat: 0.000021 s
newfstatat: 0.000005 s
write: 0.000029 s
close: 0.000014 s
[...]
根据收集到的信息，我们可以清楚地说系统调用如下openat or closedo 并不总是导致程序：1. 被中断，2. 启动一个内核线程，在 SSD 上执行实际操作。反而，IO 调用似乎以某种方式聚合/缓存在 RAM 中，SSD 上的完成/同步仅在特定时刻完成. 仅当内核线程完成工作并且任务被中断时才会出现延迟峰值。我的猜测是IO 操作在 RAM 中完成（当然是异步的），内核有时会将 RAM 中的数据刷新/同步到 SSD，这需要几毫秒的时间。这种延迟的原因尚不清楚。不管怎样，这意味着手术可能是延迟限制.
为了了解究竟发生了什么，不幸的是需要跟踪内核线程，甚至可能是 SSD 驱动程序堆栈，这有点棘手。最简单的方法似乎是使用Linux 函数跟踪器 (aka. ftrace）。请注意，跟踪所有内核函数的成本非常高，并且隐藏了昂贵函数的成本，因此应该调整粒度。内核跟踪很快就变得非常大，并且函数名称通常没有多大帮助。最重要的是，跟踪内核线程并不容易，因为在发出请求之前其 pid 是未知的，并且操作是在多线程上下文中完成的（并且由于上下文切换而在每个核心上同时进行）。
我在我的机器上尝试过，这里是程序的简化分析跟踪（为了清楚起见，仅调用 >=1us，没有 IRQ/故障内核调用）：
__x64_sys_unlink(); 92.569 us
__x64_sys_openat(); 48.103 us
__x64_sys_newfstatat(); 2.609 us
__x64_sys_write(); 33.606 us
exit_to_user_mode_prepare(); 12.517 us
__x64_sys_write(); 8.277 us
__x64_sys_write(); 2.482 us
__x64_sys_write(); 2.257 us
__x64_sys_write(); 2.240 us
__x64_sys_write(); 5.987 us
__x64_sys_write(); 5.090 us
__x64_sys_openat(); 77.006 us <------ Fast
__x64_sys_newfstatat(); 2.433 us
__x64_sys_write(); 43.509 us
exit_to_user_mode_prepare(); 83.260 us
__x64_sys_write(); 5.688 us
__x64_sys_write(); 6.339 us
__x64_sys_write(); 4.521 us
__x64_sys_write(); 3.006 us
__x64_sys_write(); 4.309 us
__x64_sys_write(); 3.472 us
__x64_sys_write(); 2.669 us
__x64_sys_openat() {
[CONTEXT SWITCH: a.out-73884 => <idle>-0]
[MISSING PART: KERNEL THREAD]
[CONTEXT SWITCH: <idle>-0 => a.out-73884]
} 2441.794 us <----- Latency spike
__x64_sys_newfstatat(); 3.007 us
__x64_sys_write(); 74.643 us
exit_to_user_mode_prepare(); 64.822 us
__x64_sys_write(); 24.032 us
__x64_sys_write(); 3.002 us
__x64_sys_write(); 2.408 us
__x64_sys_write(); 4.181 us
__x64_sys_write(); 3.662 us
__x64_sys_write(); 2.381 us
__x64_sys_write(); 23.284 us
__x64_sys_openat(); 79.258 us
__x64_sys_newfstatat(); 27.363 us
__x64_sys_write(); 45.040 us
[...]
内核跟踪证明上下文切换发生在__x64_sys_openat（即系统调用由fopencall）并且延迟峰值也发生在此时。
更深入的跟踪显示了负责等待的函数：
__x64_sys_openat
do_sys_openat2
do_filp_open
path_openat
do_truncate
notify_change
ext4_setattr
truncate_pagecache
truncate_inode_pages_range
truncate_inode_partial_folio
folio_wait_writeback
folio_wait_bit
io_schedule
schedule
[task interruption] <---- takes ~95% of the time
与此同时，第一个电话openat calls truncate_inode_pages_range但不是truncate_inode_partial_folio所以没有任务中断，也没有内核线程来完成任务。事实上，所有的调用openat关于“hellow.txt”原因truncate_inode_pages_range被呼叫但只有两次呼叫truncate_inode_partial_folio是在第 5 次调用中进行的fopen。该函数总是调用schedule在实践中，但只有第一个很慢（后续调用需要 20-700 us，平均时间为 30 us）。这truncate_pagecache函数倾向于确认存在缓存，但这并不能解释为什么后续调用schedule更快。
当跟踪内核线程时，我最终得到如下跟踪：
finish_task_switch.isra.0: 0.615 us
preempt_count_sub: 0.111 us
wq_worker_running: 0.246 us
_raw_spin_lock_irq: 0.189 us
process_one_work: 24.092 us <----- Actual kernel thread computation
这基本上表明最重要的部分 (>95%) 缺少分析跟踪。不幸的是，跟踪功能类似于上面（以及使用 EBPF 工具，如ext4slower-bpfcc）导致计时非常不一致，主要是因为时间的测量方式（缺少绝对时间）。我们需要跟踪基于 IO 的子系统才能进一步了解这一点。
较低级别 NVMe 堆栈的事件分析（使用基于 ftrace 的trace-cmd工具）显示第一个 NVMe 请求很慢，后续请求很快：
nvme_setup_cmd: 173732.202096 <----- First request started
nvme_sq: 173732.204539 <----- ~2.5 ms delay
nvme_complete_rq: 173732.204543
nvme_setup_cmd: 173732.204873 <----- Second request started
nvme_sq: 173732.204892 <----- No delay
nvme_complete_rq: 173732.204894
nvme_setup_cmd: 173732.205240
nvme_sq: 173732.205257 <----- Same here
nvme_complete_rq: 173732.205259
[...]
第二个快openat调用缓慢可能是由于同步（IO 调度程序等待前一个请求完成）造成的。最可能的原因是当较长时间没有发送请求并且需要时间唤醒时，NVME设备进入睡眠模式.
睡眠模式状态称为有功功率状态。可以使用命令查看它们smartctl -a /dev/nvme0（在里面smartmontools包裹）：
Supported Power States
St Op Max Active Idle RL RT WL WT Ent_Lat Ex_Lat
0 + 7.80W - - 0 0 0 0 0 0
1 + 6.00W - - 1 1 1 1 0 0
2 + 3.40W - - 2 2 2 2 0 0
3 - 0.0700W - - 3 3 3 3 210 1200
4 - 0.0100W - - 4 4 4 4 2000 8000
S3和S4模式的延迟相当大，但消耗也远小于其他模式。这可以使用以下命令进行控制nvme命令（在nvme-cli包裹）。更具体地说get-feature and set-feature子命令。您可以获得有关此的更多信息here。就我而言，我只是在文件中写入了 1000/sys/class/nvme/nvme0/power/pm_qos_latency_tolerance_us因此延迟不要大于 1 毫秒（需要 root 权限）。请注意，当机器重新启动时，该文件将被重置。
WARNING:请注意，阻止 SSD 切换到深度睡眠模式可能会缩短笔记本电脑的电池寿命并增加设备温度。在病理情况下（即不良的 NVMe 控制器），如果未正确冷却，可能会损坏设备。话虽这么说，大多数设备都使用节流策略来防止这种情况。
一旦修改了电源 QOS，延迟峰值就消失了！等等瞧！我得到以下程序输出：
0: C Write, time = 0.289867 ms
1: C Write, time = 0.285233 ms
2: C Write, time = 0.225163 ms
3: C Write, time = 0.222544 ms
4: C Write, time = 0.212254 ms
[...]
请注意，这解释了为什么一台机器到另一台机器的延迟不同（以及进入睡眠模式所需的等待时间），以及为什么之前运行 GCC 不会导致延迟峰值。