何年も前から気になっていたのに、数週間前まで本当の原因がわからなかったニッチなターミナルの問題があります。ログファイルから特定の出力を監視するために次のようなコマンドを実行しているとしましょう:

tail -f /some/log/file | grep thing1 | grep thing2

ログ行が比較的ゆっくりとファイルに追加されている場合、表示される結果は…何もありません! ログファイルに一致する行があったかどうかは関係なく、出力は何も表示されません。

私はこれを「うーん、パイプは時々詰まって出力を表示しなくなるんだ、変だな」と理解し、代わりに grep thing1 /some/log/file | grep thing2 を実行するようにしていました。こちらは正常に動作します。

ここ数ヶ月ターミナルについて深掘りしてきた中で、ようやくこの現象の正確な理由を理解できて本当にうれしかったです。

なぜこうなるのか:バッファリング

「パイプが詰まる」理由は、プログラムがパイプやファイルに書き込む前に出力をバッファするのが非常に一般的だからです。つまりパイプ自体は正常に動作しており、問題はプログラムがそもそもデータをパイプに書き込んでいないことにあります!

これはパフォーマンス上の理由です。出力可能なデータをすべて即座に書き込むとシステムコールの回数が増えるため、8KB程度のデータが溜まるまで(またはプログラムが終了するまで)データを溜めてからパイプに書き込む方が効率的です。

この例では:

tail -f /some/log/file | grep thing1 | grep thing2

問題は grep thing1 がマッチした結果をすべて、8KBのデータが溜まるまで保存していることで、これは文字通り起こらない可能性もあります。

プログラムはターミナルへ書き込むときはバッファしない

混乱を招いた理由のひとつは、tail -f file | grep thing は完全に正常に動作するのに、2つ目の grep を追加すると動作しなくなることです。これは grep のバッファリングの扱いが、ターミナルへ書き込んでいるかどうかによって変わるためです。

grep(および多くの他のプログラム)がどのように出力のバッファリングを決定しているかを見てみましょう:

  • isatty 関数を使って stdout がターミナルかどうかを確認する
    • ターミナルであれば行バッファリングを使用(1行分のデータが揃ったら即座に出力)
    • そうでなければ「ブロックバッファリング」を使用 – 少なくとも8KB程度のデータが揃うまで出力しない

つまり grep が直接ターミナルへ書き込んでいる場合は行が出力された瞬間に表示されますが、パイプへ書き込んでいる場合は表示されません。

もちろんバッファサイズが常にすべてのプログラムで8KBというわけではなく、実装によって異なります。grep の場合、バッファリングは libc が扱っており、libc のバッファサイズは BUFSIZ 変数で定義されています。glibc での定義はこちら

(補足:「プログラムはターミナルへ書き込むときは8KBの出力バッファを使わない」というのはターミナルの物理法則のようなものではなく、プログラムが意図的にターミナル出力時に8KBバッファを使うことも可能です。ただそのような振る舞いをするプログラムは極端に珍しく、思い浮かびません)

バッファするコマンドとしないコマンド

このバッファリングの振る舞いで困るのは、どのコマンドがパイプへ書き込むときにバッファするかを覚えておく必要がある点です。

バッファしないコマンドの例:

  • tail
  • cat
  • tee

他はほぼすべてバッファすると思われます。特にバッチ処理で使われやすいコマンドではそうです。以下はパイプへ書き込むときにバッファする一般的なコマンドと、ブロックバッファリングを無効にするフラグのリストです。

  • grep (--line-buffered)
  • sed (-u)
  • awk(fflush() 関数がある)
  • tcpdump (-l)
  • jq (-u)
  • tr (-u)
  • cut(バッファリングを無効にできない)

思いつく限りこれだけです。unix コマンドの多く(sort など)は出力のバッファリングの有無が関係ない場合もあります。なぜなら sort は入力の受信が完了するまで何もできないからです。

また Mac OS 版と GNU 版の両方をできる限りテストしましたが、さまざまなバリエーションがあり、誤りがあるかもしれません。

デフォルトの「print」文がバッファするプログラミング言語

また、デフォルトの print 文がパイプへ書き込むときにバッファするプログラミング言語と、バッファリングを無効にする方法をいくつか挙げます:

  • C(setvbuf で無効化)
  • Python(python -uPYTHONUNBUFFERED=1sys.stdout.reconfigure(line_buffering=False)、または print(x, flush=True) で無効化)
  • Ruby(STDOUT.sync = true で無効化)
  • Perl($| = 1 で無効化)

これらの言語がこのように設計されているのは、バッチ処理を行うときにデフォルトの print 関数を高速にするためだと考えられます。

また、出力がバッファされるかどうかは print の方法によっても変わる場合があります。たとえば C++ では cout << "hello\n" はパイプへ書き込むときにバッファしますが、cout << "hello" << endl は出力をフラッシュします。

パイプ上で Ctrl-C を押すとバッファの内容は失われる

example.com への DNS リクエストを監視するハック的な方法として次のコマンドを実行していて、tcpdump に -l を渡し忘れたとしましょう:

sudo tcpdump -ni any port 53 | grep example.com

Ctrl-C を押すとどうなるでしょうか? 魔法のような完璧な世界であれば、tcpdump がバッファをフラッシュし、grepexample.com を検索して、見逃した出力がすべて表示されることを望むでしょう。

しかし現実の世界では、すべてのプログラムが終了させられ、tcpdump のバッファにあった出力は失われます。

この問題はおそらく避けられないと思います。strace で動作を確認したところ、greptcpdump より先に SIGINT を受け取るため、たとえ tcpdump がバッファをフラッシュしようとしても grep はすでに終了しているからです。

もう少し調査したところ、回避策があります。tcpdump の PID を調べて kill -TERM $PID を実行すると、tcpdump はバッファをフラッシュして出力を見ることができます。ちょっと手間ですが、テストしたところ動作するようです。

ファイルへのリダイレクトもバッファする

これはパイプに限った話ではなく、次のような場合もバッファします:

sudo tcpdump -ni any port 53 > output.txt

ただしファイルへのリダイレクトには「Ctrl-C でバッファの内容が完全に失われる」という問題はありません。私の経験では、プログラムが終了する前にバッファの内容がファイルに書き込まれるという、望ましい動作になることが多いです。これが常に当てはまるかどうかは100%確信が持てません。

バッファリングを避けるためのさまざまな方法

では解決策について話しましょう。次のコマンドを実行したとします:

tail -f /some/log/file | grep thing1 | grep thing2

Mastodon で人々にこの問題をどう解決しているか聞いたところ、基本的に5つのアプローチがありました。以下に示します:

解決策1:すぐに終了するプログラムを実行する

これまで私が取っていた解決策は、「コマンドがゆっくりとパイプにデータを書き込む」状況を完全に避け、以下のようにすぐに終了するプログラムを実行することでした:

cat /some/log/file | grep thing1 | grep thing2 | tail

これは元のコマンドと同じ動作ではありませんが、この奇妙なバッファリングの問題を考えなくて済むという利点があります。

grep thing1 /some/log/file とすることもできますが、私はしばしば「不要な」cat を使うことを好みます)

解決策2:grep の「行バッファ」フラグを覚えておく

grep にバッファリングを避けるフラグがあることを覚えておき、以下のように指定する方法です:

tail -f /some/log/file | grep --line-buffered thing1 | grep thing2

解決策3:awk を使う

複数の grep を扱う場合、以下のように単一の awk に書き換えると答えた人もいました:

tail -f /some/log/file |  awk '/thing1/ && /thing2/'

または以下のように、より複雑な grep を書くこともできます:

tail -f /some/log/file |  grep -E 'thing1.*thing2'

awk もバッファするので、これを動作させるには awk をパイプラインの最後のコマンドにする必要があります)

解決策4:stdbuf を使う

stdbuf は LD_PRELOAD を使って libc のバッファリングを無効にします。以下のようにして出力バッファリングを無効にできます:

tail -f /some/log/file | stdbuf -o0 grep thing1 | grep thing2

どんな LD_PRELOAD ソリューションにも言えることですが、少し信頼性が低く、静的リンクされたバイナリでは動作せず、プログラムが libc のバッファリングを使っていない場合は動作しない可能性があり、Mac OS でも常に動作するわけではありません。Harry Marr 氏が stdbuf の仕組みを詳しく説明した優れた記事を書いています。

解決策5:unbuffer を使う

unbuffer program はプログラムの出力を TTY であるかのように強制します。これにより、通常 TTY 上で動作するような振る舞い(バッファリングの低減、カラー出力など)になります。この例では以下のように使えます:

tail -f /some/log/file | unbuffer grep thing1 | grep thing2

stdbuf とは異なり、常に動作しますが、意図しない副作用がある場合があります。たとえば grep thing1 のマッチ部分も色付けされてしまいます。

unbuffer をインストールしたい場合は expect パッケージに含まれています。

私が知っている解決策は以上です!

どれが「最善」かは判断しにくいですが、私自身は unbuffer を使う可能性が最も高いと思います。なぜなら常に動作することがわかっているからです。

さらに解決策が見つかったら、この記事に追加してみようと思います。

この問題がどれくらい頻繁に起こるのかはよくわかりません

私にとって、プログラムがゆっくりとデータをパイプに流し込むような状況はあまり一般的ではありません。通常パイプを使うときは大量のデータが素早く書き込まれ、パイプライン内のすべてで処理され、その後すべてが終了します。今のところ思いつく例は以下のとおりです:

  • tcpdump
  • tail -f
  • kubectl logs などでログファイルを別の方法で監視する
  • 遅い計算処理の出力

バッファリングを無効にする環境変数があったらどうでしょう

Python の PYTHONUNBUFFERED のように、バッファリングを無効にする標準的な環境変数があったら便利だと思います。このアイデアは 2018 年に Mark Dominus 氏が書いた一連のブログ記事から得ました。 NO_COLOR のように NO_BUFFER という名前はどうでしょうか?

設計を正しく行うのは難しいようです。Mark 氏は NETBSD に STDBUFSTDBUF1 などの環境変数があり、バッファリングを細かく制御できると指摘していますが、多くの開発者が比較的マイナーなエッジケースのために多くの異なる環境変数を実装したがらないだろうと想像できます。

また、一定時間(1秒など)後に自動的に出力バッファをフラッシュするプログラムがあるかどうかも気になります。理論的には魅力的ですが、そのような動作をするプログラムは思い浮かばず、何らかの欠点があるのだろうと思います。

省略した内容

最近の記事がかなり長くなっていることや、本当に3000語ものバッファリングに関する記事を読みたい人がいるのかという理由で、この記事で触れなかったいくつかのトピックがあります:

  • 行バッファリングと完全な非バッファリング出力の違い
  • stderr へのバッファリングと stdout へのバッファリングの違い
  • この記事はプログラム内部で発生するバッファリングについてのみ扱っており、オペレーティングシステムの TTY ドライバも時々少しバッファリングを行う
  • 「パイプへ書き込んでいる」以外の理由で出力をフラッシュする必要がある場合