何年も悩まされてきたものの、数週間前まで本当の意味では理解していなかった、ニッチな端末の問題があります。ログファイルに特定の出力が現れるのを監視するために、次のコマンドを実行しているとします。

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になるまでため込んでいることが問題です。しかも、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 -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を使う状況に特に対処している人の中には、代わりに1つの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が書いた2本のブログ記事から得ました。NO_COLORのようにNO_BUFFERでしょうか。

うまく設計するのは難しそうです。Markは、NETBSDにはSTDBUF、STDBUF1などの環境変数があると指摘しています。これを使うとバッファリングを非常に細かく制御できますが、比較的軽微な特殊ケースに対応するために、そこまで多くの環境変数を実装したい開発者はほとんどいないだろうと思います。

また、一定時間（1秒など）が経過したら出力バッファを自動的にフラッシュするプログラムがあるのかどうかも気になります。理論上は便利そうですが、そういう動作をするプログラムが思いつかないので、何かデメリットがあるのでしょう。

書かなかったこと

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

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