何年も前から気になっていたのに、数週間前までちゃんと理解できていなかった、ちょっとマニアックなターミナルの問題があります。たとえば、ログファイルから特定の出力を監視するためにこんなコマンドを実行しているとします。

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関数を使ってチェックする
  • 端末なら行バッファリングを使う（行が揃い次第すぐに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 -uやPYTHONUNBUFFERED=1、あるいはsys.stdout.reconfigure(line_buffering=False)、またはprint(x, flush=True)で無効にする)
• Ruby ( STDOUT.sync = trueで無効にする)
• Perl ( $| = 1で無効にする)

これらの言語がこう設計されているのは、バッチ処理をするときにデフォルトの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がバッファをフラッシュし、grepがexample.comを検索して、見逃していた出力をすべて見られることです。

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

この問題はおそらく避けられないと思います――straceで少し調べてみたところ、grepの方がtcpdumpより先に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によるHow stdbuf worksという素晴らしい記事があります。

解決策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による2つのブログ記事から得ました。NO_COLORのようにNO_BUFFERとかどうでしょう？

設計をうまくやるのは難しそうです。Markは、NetBSDには環境変数STDBUFやSTDBUF1などと呼ばれるものがあってバッファリングを細かく制御できると指摘していますが、比較的些細なエッジケースのために多くの異なる環境変数を実装したいと思う開発者はあまりいないでしょう。

また、一定時間（たとえば1秒）経ったら自動的に出力バッファをフラッシュするようなプログラムがあるのかどうかも気になっています。理論上は良さそうに思えますが、そういう動きをするプログラムを思いつかないので、何かデメリットがあるのだろうと想像しています。

省略したこと

最近この手の記事がかなり長くなってきているので、この記事では触れなかったこともいくつかあります。正直、バッファリングについて3000語も読みたい人なんて本当にいるのでしょうか？

• 行バッファリングと完全にバッファリングしない出力の違い
• stderrへのバッファリングがstdoutへのバッファリングとどう違うか
• この記事で扱っているのはプログラム内部で起きるバッファリングだけで、OSのTTYドライバもときどき少しバッファリングを行うこと
• 「パイプに書き込んでいる」以外に出力をフラッシュする必要があるその他の理由