写入小文件会阻塞 20 毫秒
Cap*_*man 15 c++ linux performance
我发现在我的 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，几乎不运行其他任何东西，也没有其他用户。
uname -a请参阅随附的屏幕截图，显示和的结果dpkg --list | grep -E "libc6?-(dev|bin)"
Jér*_*ard 13
此答案旨在提供有关观察到的行为的信息并检查正在发生的情况。
TL;DR：问题显然来自NVMe 设备的活动电源状态，可以对其进行调整，这样就不必支付巨大的唤醒开销。由于异步 IO 操作和Linux 内核中完成的延迟等待，此开销会被延迟。请阅读“ NVMe 设备电源管理”部分（最后）来解决此问题。
底层：基本分析
首先，在某些情况下，我可以在我的机器（Debian Linux 内核 5.15.0-2，带有 6 核 Intel i5-9600KF 和 NVMe“Samsung 970 Evo Plus”SSD）上部分重现效果。2: C Write, time =更具体地说，只有在第二次 C 测试 ( ) 期间，当我没有在此之前调用 GCC 来生成二进制文件时，才可以看到约 6 毫秒的延迟。否则所有计时均小于 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运行。
Perf 可以提供一些有关内核调用的信息。您可以通过将选项添加--kernel-callchains --call-graph dwarf到 来做到这一点sched record。不幸的是，结果在这种情况下不是很有用。唯一有用的信息是当io_schedule <- folio_wait_bit_common <- folio_wait_writeback <- truncate_inode_partial_folio程序在尖峰期间被中断时调用内核函数。这证明程序因IO操作而中断。您还可以添加该--wakeups标志，以便查看唤醒事件并查看可疑的慢速内核线程是否被目标程序唤醒（而前一个线程被其他任务唤醒（通常为gmain或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
[...]
根据收集到的信息，我们可以清楚地说，系统调用 likeopenat或closedo 并不总是导致程序：1. 被中断，2. 启动内核线程在 SSD 上执行实际操作。相反，IO 调用似乎以某种方式聚合/缓存在 RAM 中，并且 SSD 上的完成/同步仅在特定时刻完成。仅当内核线程完成工作并且任务被中断时，才会出现延迟峰值。我的猜测是，IO 操作是在 RAM 中完成的（当然是异步的），内核有时会将 RAM 中的数据刷新/同步到 SSD，这需要几毫秒的时间。这种延迟的原因尚不清楚。无论如何，这意味着该操作可能会受到延迟限制。
在深渊中：内核分析
为了了解到底发生了什么，不幸的是需要跟踪内核线程，甚至可能是 SSD 驱动程序堆栈，这有点棘手。最简单的方法似乎是使用Linux Function Tracer（又名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
[...]
内核跟踪证明上下文切换发生在 a 期间__x64_sys_openat（即由调用完成的系统调用fopen），并且延迟峰值也发生在此时。
更深入的跟踪显示了负责等待的函数：
__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调用，所以没有任务中断，也没有内核线程完成任务。事实上，对“hellow.txt”的所有调用都会导致被调用，但在对 的 5 次首次调用中只进行了两次调用。该函数在实际中总是会调用，但只有第一个函数比较慢（后续调用需要 20-700 us，平均时间为 30 us）。该函数倾向于确认是否存在缓存，但这并不能解释为什么后续调用速度更快。truncate_inode_pages_rangetruncate_inode_partial_folioopenattruncate_inode_pages_rangetruncate_inode_partial_foliofopenscheduletruncate_pagecacheschedule
当跟踪内核线程时，我最终得到如下跟踪：
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设备在较长时间没有发送请求时进入睡眠模式，需要时间才能唤醒。
NVMe设备电源管理
睡眠模式状态称为活动功率状态。可以使用以下命令查看它们smartctl -a /dev/nvme0（在smartmontools包中）：
__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
[...]
S3和S4模式的延迟相当大，但消耗也远小于其他模式。这可以使用nvme命令（在nvme-cli包中）进行控制。更具体地说，是get-feature和set-feature子命令。您可以在此处获取有关此内容的更多信息。就我而言，我只是在文件中写入了 1000 /sys/class/nvme/nvme0/power/pm_qos_latency_tolerance_us，因此延迟不会大于 1 毫秒（需要 root 权限）。请注意，当机器重新启动时，该文件将被重置。
警告：请注意，阻止 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 不会导致延迟峰值。