長い文字列をtrにパイプするとハングアップしCPUスパイクが発生する

長い文字列をtrにパイプするとハングアップしCPUスパイクが発生する

MacOS Yosemite (10.10.5)。これは Unix/Linux セクションであることは承知していますが、この質問は MacOS よりもこちらの方が適していると思われます。

ターミナルは起動時にプロンプ​​トが表示される前にハングし始めました...そして同時に CPU 使用率が急上昇しました。CTRL-C を押すとプロンプトが表示されます (おそらくハングまたは実行中の .bashrc/.profile などを終了していると思われます)。

すぐに、.bashrc 内の特定の行がハングの原因になっていることが分かりました。これは新しい現象です (つまり、.bashrc では何も変更しておらず、すべて正常に動作していました)。そのため、システムで何かが変更されました。

特定の長い文字列をパイプすると、ハングや CPU スパイクが発生するようです。

文字列をパイプしてハングするかどうかを確認することで、これを再現できますtr -d '\n'

macattack:~ $ openssl rand -base64 93  | tr -d '\n'
eDsz4JqFX/HAVjplNI6WDWwPRp9l9snp6UKp/pLn+GbBvJx0+ZMvSJFS/SuCwjMRRXVXfUvBdkaH1R0UgCr2UOf283MvHVTRusLFEVPcGCIz1t3sFMU/3foRzNWVmattp@macattack:~ $ openssl rand -base64 94 | tr -d '\n'
^C
mattp@macattack:~ $ openssl rand -base64 94 | tr -du '\n'
^C

93 文字は、tr がハングし始める魔法の数字のようです。openssl はハングしません (つまり、パイプを削除すればtrすべてが終了します)。ただし、元の問題行の長さが異なっていました。

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log;' | tr -d '\n'
^C-bash: echo: write error: Interrupted system call

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log' | tr -d '\n'

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log' | wc -c
     128
mattp@macattack:~ $

これはおそらく問題ではなくパイプの問題です。 (コマンドは意味をなさない...ハングを示すだけです)trで同じ問題を再現できます。sed

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log;'  | sed 's/\n/ /g'
^C-bash: echo: write error: Interrupted system call

mattp@macattack:~ $ echo 'echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log'  | sed 's/\n/ /g'
echo -e "$TS\t${TERM_SESSION_ID}\t$(pwd)\t$(history 1 | cut -c 8-)\n" >> $HOME/.history/history-$(date "+%Y-%m-%d")-${USER}.log
mattp@macattack:~

これをトラブルシューティングするアイデアが尽きました。
ハングしているコマンドは、ランダムな Centos Linux サーバーでは正常に実行されます。コマンドは最近まで Macos で正常に実行されていました。パイプのハングに遭遇したことは一度もありません。入力内の奇妙な文字が問題の原因かもしれないと思いましたが、openssl のランダム文字列はそうではないことを示しています。ulimits は、同じ問題が発生していない別の Mac と同じです。

mattp@macattack:~ $ ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
file size               (blocks, -f) unlimited
max locked memory       (kbytes, -l) unlimited
max memory size         (kbytes, -m) unlimited
open files                      (-n) 7168
pipe size            (512 bytes, -p) 1
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 709
virtual memory          (kbytes, -v) unlimited

dtrussこれを使用するとtr、read_nocancel 呼び出しでハングするようです。

アップデート

進展しています。ハングとパイプ バッファ サイズに関するコメントを見つけました。ここからテスト スクリプトを盗みました: パイプバッファの大きさはどれくらいですか?

問題が発生している間に実行すると、パイプ バッファが 128 バイトと表示されます。再起動すると (問題は一時的に解消されます)、パイプ バッファは 65536 バイトになります。以下のテスト出力を参照してください。

そこで疑問になるのは、「何か」がなぜ/どのようにしてシステム上のパイプ バッファー サイズを削減するのかということです。

問題あり

$ /bin/bash -c 'for p in {0..18}; do pipe-buffer-test.sh $((2 ** $p)) 0.5; done'
write size:          1; bytes successfully before error: 128
write size:          2; bytes successfully before error: 128
write size:          4; bytes successfully before error: 128
write size:          8; bytes successfully before error: 128
write size:         16; bytes successfully before error: 128
write size:         32; bytes successfully before error: 128
write size:         64; bytes successfully before error: 128
write size:        128; bytes successfully before error: 128
write size:        256; bytes successfully before error: 0
write size:        512; bytes successfully before error: 0
write size:       1024; bytes successfully before error: 0
write size:       2048; bytes successfully before error: 0
write size:       4096; bytes successfully before error: 0
write size:       8192; bytes successfully before error: 0
write size:      16384; bytes successfully before error: 0
write size:      32768; bytes successfully before error: 0
write size:      65536; bytes successfully before error: 0
write size:     131072; bytes successfully before error: 0
write size:     262144; bytes successfully before error: 0

再起動後(問題は一時的に解消)

$ /bin/bash -c 'for p in {0..18}; do pipe-buffer-test.sh $((2 ** $p)) 0.5; done'
write size:          1; bytes successfully before error: 65536
write size:          2; bytes successfully before error: 65536
write size:          4; bytes successfully before error: 65536
write size:          8; bytes successfully before error: 65536
write size:         16; bytes successfully before error: 65536
write size:         32; bytes successfully before error: 65536
write size:         64; bytes successfully before error: 65536
write size:        128; bytes successfully before error: 65536
write size:        256; bytes successfully before error: 65536
write size:        512; bytes successfully before error: 65536
write size:       1024; bytes successfully before error: 65536
write size:       2048; bytes successfully before error: 65536
write size:       4096; bytes successfully before error: 65536
write size:       8192; bytes successfully before error: 65536
write size:      16384; bytes successfully before error: 65536
write size:      32768; bytes successfully before error: 65536
write size:      65536; bytes successfully before error: 65536
write size:     131072; bytes successfully before error: 0
write size:     262144; bytes successfully before error: 0

答え1

@Barmar のカーネルバッファのリークに関するコメントに基づいて、現在の非 OS kext を調べてみました。最近インストールした BlockBlock から比較的新しいものがあることに気付きました (https://objective-see.com/products/blockblock.html)。

BlockBlock をアンインストールして再起動しましたが、問題は再発しませんでした。したがって、このケースでは BlockBlock が犯人であり、この問題を作者に報告しました。

しかし、原因を突き止めるために推測と確認のアプローチを主に採用したため、これは特に満足のいくものではありません。正直なところ、根本的な原因(OS の観点から)を本当に理解していないため、将来この種の問題をトラブルシューティングする際に何の助けにもなりません。

誰かがこれに遭遇し、何が起こっていたのかをより詳しく説明し、トラブルシューティングのアプローチを提供できる場合、それは「BlockBlock をアンインストールする」よりもはるかに良い答えになります。

関連情報