”私の環境で”大きなテキストファイルをawkで処理するときにcatで投げ込むと速い理由

大きなテキストファイルをawkで処理するときにcatで投げ込むと速い理由 - ablog を書きましたが、awk file > file より cat file|awk > file が速い環境は稀なようなので、私の環境でなぜ cat file|awk > file のほうが速いのか調べてみました。プロセススケジューラが関係しているようです。

↑はPerf + Flame Graphs で、awk file > file 実行時のコールスタックと所要時間を可視化したものです。

結論(たぶん)

• SSDの暗号化・復号をカーネルスレッドで行なっているのと、プロセススケジューラが awk とカーネルスレッドを同じ CPU にスケジューリングしていた(他に空いている CPU があるのに)。
• awk file > file では暗号化データを復号するカーネルスレッドと awk のプロセスをプロセススケジューラがなぜか同じ CPU にスケジューリングし、並列処理ができていない。
• cat file|awk > file では cat、awk、復号するカーネルスレッドが別々の CPU にスケジューリングされ、並列処理できている。
• Linux カーネルのプロセススケジューラのスケジューリングの話なので、カーネルのバージョンやカーネルパラメータの設定次第で変わります。

分析結果

awk file > file

awk file > file では暗号化データを復号するカーネルスレッドと awk のプロセスをプロセススケジューラがなぜか同じ CPU にスケジューリングし、並列処理できていない。

• awk file > file を実行する

$ time awk '$5 ~ /00$/ {print}' sample.txt > result1.txt
real	1m12.940s
user	0m59.059s
sys	0m1.477s

• top で見ると、awk と復号するカーネルスレッド（kworker/0:*）が同じ CPU0 を使い、合計すると約 100% になっている。つまり、awk はカーネルスレッドと同じ CPU を使おうとしているため、CPU0 で直列化し、マルチプロセッサを有効活用できていない。

$ top -c 
# f を押して、j(Last used cpu (SMP))、l(CPU Time)、y(Sleeping in Function) を押して、return
top - 01:34:00 up  2:06,  8 users,  load average: 1.17, 0.90, 0.74
Tasks: 227 total,   3 running, 224 sleeping,   0 stopped,   0 zombie
Cpu(s): 20.6%us,  4.2%sy,  0.0%ni, 75.1%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:  16158544k total,  2895472k used, 13263072k free,     3176k buffers
Swap:  8085500k total,        0k used,  8085500k free,  2148524k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P★CPU番号   TIME WCHAN     COMMAND
 9577 yazekats  20   0  103m  780  644 R 83.4  0.0   0:37.65 0   0:37 -         awk $5 ~ /00$/ {print} sample.txt ★カーネルスレッドと同じ CPU0 を使っている
 6230 root      20   0     0    0    0 S  8.6  0.0   0:09.30 0   0:09 worker_th [kworker/0:2] ★カーネルスレッドは CPU0 を使用
 9349 root      20   0     0    0    0 S  7.3  0.0   0:03.82 0   0:03 worker_th [kworker/0:1] ★カーネルスレッドは CPU0 を使用
 9303 yazekats  20   0 15204 1248  860 R  0.7  0.0   0:00.83 1   0:00 -         top -c
 6240 root      20   0     0    0    0 R  0.3  0.0   0:00.93 1   0:00 ?         [kworker/1:0]

top で表示されるCPU番号は正確には最後に使ったCPU番号です。

cat file|awk > file

cat file|awk > file では cat、awk、復号するカーネルスレッドが別々のCPUにスケジューリングされ、並列処理できている。

• cat file|awk > file を実行する。

$  time { cat sample.txt|awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m52.097s
user	0m50.920s
sys	0m2.846s

• top で見ると、cat、awk、復号するカーネルスレッドが別々の CPU を使って並列処理している。

top - 01:45:59 up  2:18,  8 users,  load average: 1.37, 1.04, 0.83
Tasks: 228 total,   3 running, 225 sleeping,   0 stopped,   0 zombie
Cpu(s): 25.0%us,  6.2%sy,  0.0%ni, 68.7%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:  16158544k total,  2358376k used, 13800168k free,     5712k buffers
Swap:  8085500k total,        0k used,  8085500k free,  1604420k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P★CPU番号   TIME WCHAN     COMMAND
 9721 yazekats  20   0  103m  780  644 R 99.7  0.0   0:23.06 3★   0:23 -         awk $5 ~ /00$/ {print} ★1CPUをほぼ使い切っている
 9672 root      20   0     0    0    0 S 20.3  0.0   0:19.08 0★   0:19 worker_th [kworker/0:1]
 9720 yazekats  20   0 98.6m  484  416 S  4.0  0.0   0:00.91 2★   0:00 pipe_wait★ cat sample.txt ★cat はこの瞬間はパイプへの書込み待ちでスリープ

検証

• taskset コマンドで awk file > file 実行時に使うCPU番号を明示的に指定すると、awk と復号するカーネルスレッドが別のCPUを使って並列処理され、速くなりました。

$ time taskset -c 3 awk '$5 ~ /00$/ {print}' sample.txt > result1.txt
real	0m54.180s ★ cat file|awk > file に近い実行時間になっています
user	0m51.277s
sys	0m1.151s

• top で見ると、awk とカーネルスレッドが別のCPUを使って並列処理でき、awk のCPU使用率が 100% 近くなっています。

Tasks: 226 total,   2 running, 224 sleeping,   0 stopped,   0 zombie
Cpu(s): 24.0%us,  5.5%sy,  0.0%ni, 70.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  16158544k total,  3458788k used, 12699756k free,     6656k buffers
Swap:  8085500k total,        0k used,  8085500k free,  2698136k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P★CPU番号   TIME WCHAN     COMMAND
 9783 yazekats  20   0  103m  780  644 R 97.6★  0.0   0:43.60 3★   0:43 -         awk $5 ~ /00$/ {print} sample.txt
 9784 root      20   0     0    0    0 S 18.6  0.0   0:05.79 0★   0:05 worker_th [kworker/0:2]
 4431 yazekats  20   0 15196 1236  856 S  0.7  0.0   0:24.78 1   0:24 poll_sche top -c

補足

• 検証の前には都度ページキャッシュを解放しています。

# echo 3 > /proc/sys/vm/drop_caches

• ベースライン

$ time { awk '$5 ~ /00$/ {print}' sample.txt > result1.txt; }
real	1m9.755s
user	0m56.078s
sys	0m1.593s
$ time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m59.299s
user	0m56.994s
sys	0m4.005s

• "> file" しなくても実行時間はほぼ同じため、write はボトルネックになっていない。

$ time { awk '$5 ~ /00$/ {print}' sample.txt > /dev/null; }
real	1m11.339s
user	0m57.730s
sys	0m1.304s
$ time { awk '$5 ~ /00$/ {}' sample.txt; }
real	1m8.525s
user	0m55.022s
sys	0m1.420s
$ time { cat sample.txt|awk '$5 ~ /00$/ {print}' > /dev/null; }
real	0m55.854s
user	0m54.418s
sys	0m3.293s
$  time { cat sample.txt|awk '$5 ~ /00$/ {}'; }
real	0m58.242s
user	0m56.425s
sys	0m3.540s

• awk に posix_fadivse(SEQUENTIAL) を入れても速くならない。

$ pwd
/usr/src/gnu/gawk-3.1.7
$ diff io.c io.c.org 
27d26
< #include "fadvise.h"
1679d1677
< 	posix_fadvise(openfd, 0, 0, POSIX_FADV_SEQUENTIAL);
$ ./configure
$ make
$ strace /usr/src/gnu/gawk-3.1.7/gawk '{print}' sample.txt 2>&1|grep -C2 fadvise
open("sample.txt", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=2800000000, ...}) = 0
fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffa7cb3930) = -1 ENOTTY (Inappropriate ioctl for device)
fstat(3, {st_mode=S_IFREG|0664, st_size=2800000000, ...}) = 0
$ time { /usr/src/gnu/gawk-3.1.7/gawk '$5 ~ /00$/ {print}' sample.txt > result1.txt; }
real 1m9.574s
user 0m56.812s
sys 0m1.408s

参考

• wikipedia:プロセッサ親和性
• https://access.redhat.com/documentation/ja-JP/Red_Hat_Enterprise_MRG/2/html/Realtime_Reference_Guide/chap-Realtime_Reference_Guide-Affinity.html
• https://www.kernel.org/doc/ols/2012/ols2012-lim.pdf

関連

• top でプロセスが使っていたCPU番号を表示する - ablog
• top でプロセスがスリープしている原因を表示する - ablog
• perf + Flame Graphs で Linux カーネル内のボトルネックを特定する - ablog