私の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」と表示されると予想されていますが、主に2つの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/Oと同じ方法です。この答えはそれを非常によく説明しますhttps://stackoverflow.com/questions/6338812/printing-to-the-console-vs-writing-to-a-file-speed。
また、stdoutの代わりにファイルにログを送信する方が高速ですが、コマンドによって増加するのではなく、syカーネルスペースの時間が長くなります。これは、sys呼び出しがディスク上のファイルに直接書き込むのではなく、ファイルシステムのバッファに送信することで、可能な限り最善の方法でディスクへの書き込みを処理するためであることがわかりました。wa%Topwrite
その後、sys呼び出しを使用してすべてのログを印刷してsyncバッファを消去し、すべてのデータをすぐにファイルにコミットし始めました。ここでは、wa%IOジョブのデータが予想よりはるかに高く、CPUが大部分がスリープモードであることを確認しました。
結論として：
- 端末はディスクI / Oと同じではなく、遅いです。
- システムコールを介して作成されたI / O関数は、ファイル
writeシステムバッファによってディスク書き込みオーバーヘッドを必ずしも増やすわけではありませんが、コンテキスト切り替えを増やし、カーネルスペースでCPUサイクルを消費します。