理由
びっくりした。対話シェルで実行してパフォーマンス測定すると何故かめちゃくちゃ時間がかかる。これではデータにならない。
追記 よくよく考えたらパフォーマンス測定だけの問題ではなく実際に遅くなるのだから、対話シェルから「このようなコード」を実行してはいけないということを意味しています。「このようなコード」がどのようなコードなのか発生条件はまだ特定できていませんが、少なくともシェルスクリプトにしていれば問題は発生しません。また bash 以外のシェルでも問題は発生しません。
検証結果が気になった方は、ぜひ試してみて、この話を広めてください。
証拠
実行環境: Ubuntu 22.04.3 LTS、bash 5.1.16
$ time { seq 100000 | while read i; do cp /dev/null /tmp/null; done; }
real 6m50.453s
user 7m7.769s
sys 2m10.563s
[追記] .bash_profile や .bashrc を読み込まず環境変数なし状態でも大差なし
$ env -i bash --noprofile --norc
bash-5.1$ typeset -f
bash-5.1$ env
PWD=/home/koichi
SHLVL=1
_=/usr/bin/env
bash-5.1$ time { seq 100000 | while read i; do cp /dev/null /tmp/null; done; }
real 6m13.752s
user 6m48.380s
sys 1m31.793s
環境変数 PATH がないのにコマンドが実行できるの？と思った人へ
→ PATH が未定義のときはシステムデフォルトのパス扱いです。
$ /bin/bash -c 'time { seq 100000 | while read i; do cp /dev/null /tmp/null; done; }'
real 1m45.884s
user 1m22.641s
sys 0m26.101s
$ # 補足 これでも計測結果はほぼ同じ
$ time /bin/bash -c 'seq 100000 | while read i; do cp /dev/null /tmp/null; done'
$ time { seq 100000 | xargs -I{} cp /dev/null /tmp/null; }
real 1m43.350s
user 1m20.950s
sys 0m23.727s
念のためですが、確かに bash から実行しているという証拠です。
$ echo $SHELL
/bin/bash
$ ps $$
PID TTY STAT TIME COMMAND
4031866 pts/26 Ss 0:00 -bash
$ echo $BASH_VERSION
5.1.16(1)-release
その他の環境での結果
仮想マシン上の Debian 12.0。bash のバージョンは 5.2.15。テスト用の環境なのでシェルの設定はほとんどデフォルトのまま。それが理由かは知らないが差は減っている。ただし誤差とは言えない差がある。
$ time { seq 100000 | while read i; do cp /dev/null /tmp/null; done; }
real 2m29.249s
user 1m48.251s
sys 0m39.456s
$ /bin/bash -c 'time { seq 100000 | while read i; do cp /dev/null /tmp/null; done; }'
real 1m58.144s
user 1m24.425s
sys 0m32.407s
$ # 参考 xargs との比較
$ time { seq 100000 | xargs -I{} cp /dev/null /tmp/null; }
real 1m53.947s
user 1m23.199s
sys 0m29.350s
なんでこうなるの？
わからない。一応 set コマンドや shopt コマンドで対話シェルとシェルスクリプトの違いを可能な限りなくしたり、対話シェルで定義される関数を全て削除したり、--noprofile、--norc オプション付きで起動した bash で実行したりしたが、このような違いが発生する。bash のバグなのかわからないし、環境によるものなのかもわからない。対話シェルとシェルスクリプトでの違いはありそうな話だが、それにしても差が大きすぎる。
私は普段さまざまなシェルでパフォーマンス測定を行う関係上、time bash -c "..." や time dash -c "..." のような形で計測していたのでこの問題に今まで気づいていなかった。xargs と bash の while ループに大きなパフォーマンスの差があるはずがないという出発点から検証していて気づいた。
結論
本当にびっくりしたのでひとまず速報です。おそらく対話シェルで計測しても問題ない例もあると思います。追加の検証が必要ですがこのような違いがあることが判明した以上、対話シェルで実行して計測しても無意味（シェルスクリプトのパフォーマンス測定の結果として信用できない）ということになります。確かにいろんな機能が有効化されている対話モードと非対話モードでは環境が全く違うわけで、言われてみればそりゃそうだと言った感じですね。この事実により過去に対話シェルから行われたさまざまなパフォーマンスの検証結果に影響が発生する可能性があります。
とりあえず、bashスクリプトを対話シェル上で直接実行してパフォーマンス測定をやってはいけないということを伝えておきます。シェルコードのパフォーマンス測定は、計測対象のコードを -c の引数で書くかシェルスクリプトを作成して計測しましょう。
この件に関する情報（言及している記事等）を知っている方がいましたら教えてくださいm(_ _)m
記事公開後の更新
追加実験 - sleep や /bin/true での実験
記事を書いたあとに行った追加実験です。
$ env -i bash --noprofile --norc --noediting
【sleep の場合（同様の結果）】
bash-5.1$ time { seq 100000 | while read i; do sleep 0; done; }
real 6m39.411s
user 6m58.340s
sys 1m0.540s
bash-5.1$ bash -c 'time { seq 100000 | while read i; do sleep 0; done; }'
real 0m57.407s
user 0m41.748s
sys 0m12.548s
【/bin/true の場合（同様の結果）】
bash-5.1$ time { seq 100000 | while read i; do /bin/true; done; }
real 5m47.896s
user 6m15.922s
sys 1m8.270s
bash-5.1$ bash -c 'time { seq 100000 | while read i; do /bin/true; done; }'
real 0m43.628s
user 0m35.113s
sys 0m10.774s
【true の場合（シェルビルトインの場合は問題が発生しない。速いのでループ回数を10倍している）】
bash-5.1$ time { seq 1000000 | while read i; do true; done; }
real 0m8.529s
user 0m5.168s
sys 0m6.066s
bash-5.1$ bash -c 'time { seq 1000000 | while read i; do true; done; }'
real 0m8.703s
user 0m5.340s
sys 0m6.164s
【パイプからの読み取りがない場合は問題が発生しない】
bash-5.1$ time { for((i=1; i<=100000; i++)) do /bin/true; done; }
real 0m46.610s
user 0m37.586s
sys 0m11.389s
bash-5.1$ bash -c 'time { for((i=1; i<=100000; i++)) do /bin/true; done; }'
real 0m44.162s
user 0m35.871s
sys 0m10.349s
ここまで判明した条件
- パイプからの読み取りを行っている
- ループの中で外部コマンドを呼び出している
この条件で対話シェルで実行すると大幅に遅くなる。シェルスクリプトで実行していれば遅くならない。
以前から私はシェル自体は（問題になるほど）遅くはないと言っているのだが、この現象は対話シェルからパフォーマンス測定を行うと while ループは遅いという間違った検証結果が出てしまう事例になっている。
追加実験２ - strace 結果
strace の実行結果です。次のようなコマンドを実行して計測。計測が終了したら手動で strace をフォアグラウンドにして CTRL-C しています。時間がかかりそうなのでループ回数は1/10にしました。（ちゃんと検証できているか不安ですが）大きな違いがあるのは rt_sigaction 関数だけに思えます。ブコメ にも同様のコメントがありますね。
$ sudo strace -f -c -o strace.txt -S name -p $$ >/dev/null 2>/dev/null &
time { seq 10000 | while read i; do /bin/true; done; } の結果
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
0.08 0.003245 0 10005 10001 access
0.08 0.003018 0 20002 10001 arch_prctl
0.03 0.001354 0 10015 brk
9.42 0.376820 37 10002 clone
0.08 0.003080 0 20034 2 close
0.00 0.000000 0 2 dup2
2.17 0.086624 8 10001 execve
0.00 0.000000 0 1 fcntl
0.00 0.000003 3 1 futex
0.00 0.000003 0 4 getegid
0.00 0.000017 4 4 geteuid
0.00 0.000003 0 4 getgid
0.00 0.000182 0 10002 getpid
0.00 0.000004 4 1 getrandom
0.00 0.000003 0 4 getrusage
0.00 0.000005 1 4 getuid
0.33 0.013303 1 10023 10001 ioctl
0.27 0.010995 1 10001 10001 lseek
0.74 0.029434 0 80021 mmap
0.35 0.013807 0 30003 mprotect
0.25 0.009903 0 10002 munmap
0.11 0.004559 0 20030 5 newfstatat
0.17 0.006813 0 20030 13 openat
0.00 0.000012 4 3 pipe2
0.17 0.006871 0 40004 pread64
0.05 0.002192 0 10001 prlimit64
0.00 0.000178 1 114 pselect6
1.61 0.064239 1 58957 read
0.04 0.001611 0 10001 rseq
1.28 0.051294 0 110076 rt_sigaction
3.97 0.158795 1 105940 rt_sigprocmask
0.33 0.013115 1 10001 rt_sigreturn
0.05 0.001860 0 20003 set_robust_list
0.04 0.001622 0 10001 set_tid_address
0.00 0.000004 1 4 setpgid
78.37 3.133938 156 20003 10000 wait4
0.00 0.000082 3 23 write
------ ----------- ----------- --------- --------- ----------------
100.00 3.998988 6 665327 50024 total
bash -c 'time { seq 10000 | while read i; do /bin/true; done; }'の結果
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
0.05 0.002566 0 10012 10003 access
0.04 0.002330 0 20004 10002 arch_prctl
0.02 0.000938 0 10007 brk
7.51 0.408186 40 10003 clone
0.05 0.002672 0 20050 2 close
0.00 0.000000 0 2 dup2
0.90 0.048835 4 10002 execve
0.00 0.000001 1 1 fcntl
0.00 0.000002 1 2 futex
0.00 0.000018 1 11 getegid
0.00 0.000015 1 11 geteuid
0.00 0.000014 1 11 getgid
0.00 0.000003 3 1 getpgrp
0.01 0.000331 0 10006 getpid
0.00 0.000007 2 3 getppid
0.00 0.000003 1 2 getrandom
0.00 0.000009 2 4 getrusage
0.00 0.000022 2 11 getuid
0.34 0.018691 1 10033 10002 ioctl
0.29 0.015982 1 10001 10001 lseek
0.43 0.023180 0 80046 mmap
0.20 0.011028 0 30007 mprotect
0.15 0.008087 0 10002 munmap
0.07 0.003674 0 20070 11 newfstatat
0.10 0.005514 0 20063 26 openat
0.00 0.000015 7 2 pipe2
0.10 0.005413 0 40008 pread64
0.03 0.001764 0 10003 prlimit64
0.00 0.000230 1 134 pselect6
1.72 0.093416 1 58973 read
0.02 0.001343 0 10002 rseq
0.65 0.035229 0 80080 rt_sigaction
3.15 0.171252 1 100050 rt_sigprocmask
0.36 0.019289 1 10002 rt_sigreturn
0.03 0.001503 0 20005 set_robust_list
0.02 0.001323 0 10002 set_tid_address
0.00 0.000002 1 2 setpgid
0.00 0.000007 7 1 sysinfo
0.00 0.000003 3 1 uname
83.75 4.550034 227 20005 10001 wait4
0.00 0.000078 3 25 write
------ ----------- ----------- --------- --------- ----------------
100.00 5.433009 8 629660 50048 total
ちなみに標準入出力のバッファリングに関しては、今回のケースでは「どちらもターミナルに入出力していない」ので関係ないはずだとして、最初の段階から考慮していませんでしたが、strace をしたのでついでに書くと read/write の数に大きな差は見られないことがわかります。
補足 --login を付けても遅くならないことが判明しました。
$ bash -c 'time { seq 100000 | while read i; do /bin/true; done; }'
real 0m46.166s
user 0m36.711s
sys 0m12.110s
$ bash --login -c 'time { seq 100000 | while read i; do /bin/true; done; }'
real 0m47.276s
user 0m37.716s
sys 0m13.012s
検証結果の更新
2023年9月末までのコメントの反映
対話シェルかつ、サブシェルの中で大量に外部コマンドを呼び出すと遅くなる。おそらくループ回数が少ない時はあまり差が出ない。
$ time ( for((i=0; i<100000; i++)); do /bin/true; done )
real 5m55.102s
user 6m19.980s
sys 1m16.081s
$ time bash -c '( for((i=0; i<100000; i++)); do /bin/true; done )'
real 0m45.142s
user 0m36.386s
sys 0m10.922s
シェルスクリプトにしていれば遅くならない
$ time ./script.bash
real 0m44.758s
user 0m36.269s
sys 0m10.779s
#!/bin/bash
( for((i=0; i<100000; i++)); do /bin/true; done )