“tail -f”でログファイルを監視しながら”grep”すると出力が遅延する問題への対応

Bash

はじめに

稼働中の Web サーバーのアクセスログを tail -f で監視しながら、特定のログのみを探したことはあるでしょうか？

アクセス数の多いサービスの場合、tail -f access.log といった単純なコマンドではとても注視したい情報を見つけることはできません。
そのため tail -f access.log | grep xxx | awk {...} のような形で監視対象のログレコードを減らしながら、任意のカラム情報のみ切り出し監視を行います。

しかし、この際に遭遇する問題があります。それは grep で絞り込むと出力が遅延する、という現象です。

問題の原因と対処法を紹介します。

検証環境

$ uname -moi
aarch64 aarch64 GNU/Linux

$ head -n 3 /etc/os-release
PRETTY_NAME="Ubuntu Kinetic Kudu (development branch)"
NAME="Ubuntu"
VERSION_ID="22.10"

$ bash -version | head -n 1
GNU bash, バージョン 5.2.0(1)-release (aarch64-unknown-linux-gnu)

$ grep --version | head -n 2
grep (GNU grep) 3.7
Copyright (C) 2021 Free Software Foundation, Inc.

$ tail --version | head -n 2
tail (GNU coreutils) 8.32
Copyright (C) 2020 Free Software Foundation, Inc.

「grep で絞り込むと出力が遅延する」とは？

「grep で絞り込むと出力が遅延する」とはどのような現象でしょうか？

再現させてみましょう。

簡単なお題をあげます。

  1. access.log というファイルを tail-F で監視
  2. ( 1 ) の結果をパイプで受け取り、末尾が 0 の行だけを出力
  3. ( 2 ) の結果をパイプで受け取り、1 文字目だけを出力
$ tail -F access.log | grep '0$' | cut -c1

一方で、 access.log に書き込みを行います。
1 からカウントアップした数値を 0.1 秒ごとに追記してみます。

$ for ((i=0; i < 100; i++)) do echo $i >> access.log; sleep 0.1; done

access.log の書き込みが終わっても tail の監視コマンドには何も出力されません。

原因 : grep のバッファリング機構

grep は処理結果をすぐには出力せず、内部的に一定のデータをバッファリングします。
これにより、出力が連続的に行われる ( 例えば、大量のログが流れ続ける ) 場合には効率的に処理できるようになっています。
しかし中断的な場合には出力が行われるまでに遅延が生じます。

ちなみに、 grep の実行結果を次のコマンドにパイプで引き渡さない場合には、この問題は起きず直ちにターミナルに出力されます。

先ほどとは異なり、 grep の後に cut を行いません。

$ tail -F access.log | grep '0$'

この状態で access.log にデータを追記した場合は、 grep 実行結果が直ちに確認できます。

$ for ((i=0; i < 100; i++)) do echo $i >> access.log; sleep 0.1; done
# ほぼ 1秒おきに出力される
$ tail -F access.log | grep '0$'
tail: 'access.log' を 読み込み用に開くことが出来ません: そのようなファイルやディレクトリはありません
tail: 'access.log' has appeared;  following new file
0
10
20
30
40
50

対処法 : grep の --line-buffered オプションを使用する

grep コマンドには --line-buffered オプションがあります。
このオプションを付けることでバッファリングを行わず、行単位で出力を行います。
そのため、 tail -F と一緒に使用することで遅延のないリアルタイムな監視が可能になります。

改めて上記の例を --line-buffered オプションを付けて実行してみましょう。

$ tail -F access.log | grep --line-buffered '0$' | cut -c1

再度 access.log に書き込みを行うと、リアルタイムで追加されたログが出力されます。

ひとこと

tail -f と grep を組合せた監視は非常に有用ですが、 grep 出力結果を更にフィルタリングする場合には注意が必要です。
その際に出力遅延が発生します。
この問題に対する対処法を学び、適切なコマンドのオプションを理解することで、より効率的な監視ができます。

特に tails -F access.log | grep AAA | grep BBB といったように、 grep を多段につなげて絞り込みを行った場合、 tails -F access.log | grep AAA だと問題がなかったんだけどなぁ、と頭を抱えることがあるかもしれません。

その際には --line-buffered オプションを使用することで、遅延を解消できます。

Bash