【衝撃の罠】bashスクリプトのパフォーマンス測定は、対話シェルでやっても無意味だ！

## 理由

びっくりした。対話シェルで実行してパフォーマンス測定すると何故かめちゃくちゃ時間がかかる。これではデータにならない。

**追記** よくよく考えたらパフォーマンス測定だけの問題ではなく実際に遅くなるのだから、対話シェルから「このようなコード」を実行してはいけないということを意味しています。「このようなコード」がどのようなコードなのか発生条件はまだ特定できていませんが、少なくともシェルスクリプトにしていれば問題は発生しません。また bash 以外のシェルでも問題は発生しません。

検証結果が気になった方は、ぜひ試してみて、この話を広めてください。

## 証拠

実行環境: Ubuntu 22.04.3 LTS、bash 5.1.16

```console:対話シェルで実行した場合
$ time { seq 100000 | while read i; do cp /dev/null /tmp/null; done; }

real	6m50.453s
user	7m7.769s
sys	    2m10.563s
```

<details><summary>[追記] .bash_profile や .bashrc を読み込まず環境変数なし状態でも大差なし</summary>

```console
$ 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` が未定義のときはシステムデフォルトのパス扱いです。
</details>

```console:シェルスクリプト（相当）で実行した場合
$ /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'
```

```console:参考 xargs と bash の while ループの速度に大きな差はない
$ time { seq 100000 | xargs -I{} cp /dev/null /tmp/null; }

real	1m43.350s
user	1m20.950s
sys	    0m23.727s
```

念のためですが、確かに bash から実行しているという証拠です。

```console
$ 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。テスト用の環境なのでシェルの設定はほとんどデフォルトのまま。それが理由かは知らないが差は減っている。ただし誤差とは言えない差がある。

```console
$ 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 での実験

記事を書いたあとに行った追加実験です。

```console
$ 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` 関数だけに思えます。[ブコメ](https://b.hatena.ne.jp/entry/4742887642876690223/comment/gaudere) にも同様のコメントがありますね。

```console
$ sudo strace -f -c -o strace.txt -S name -p $$ >/dev/null 2>/dev/null &
```

<details><summary>time { seq 10000 | while read i; do /bin/true; done; } の結果</summary>

```
% 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
```
</details>

<details><summary>bash -c 'time { seq 10000 | while read i; do /bin/true; done; }'の結果</summary>

```txt:
% 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
```
</details>

ちなみに標準入出力のバッファリングに関しては、今回のケースでは「どちらもターミナルに入出力していない」ので関係ないはずだとして、最初の段階から考慮していませんでしたが、`strace` をしたのでついでに書くと read/write の数に大きな差は見られないことがわかります。


**補足** `--login` を付けても遅くならないことが判明しました。

```console:
$ 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月末までのコメントの反映

対話シェルかつ、サブシェルの中で大量に外部コマンドを呼び出すと遅くなる。おそらくループ回数が少ない時はあまり差が出ない。

```console
$ 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
```

シェルスクリプトにしていれば遅くならない

```console
$ time ./script.bash

real    0m44.758s
user    0m36.269s
sys     0m10.779s
```

```bash:script.bash
#!/bin/bash
( for((i=0; i<100000; i++)); do /bin/true; done )
```