structlogとloggingの併用方法について

Pythonでアプリケーションのロギングライブラリとして標準ライブラリのlogging以外を使うときは、loggingを使ってる既存のコードをどうするかを考えないといけない。アプリケーション自体の中身を全部一気に書き換えるとしても、依存ライブラリがloggingを使ってるかもしれないからだ。

structlogのドキュメントにもそのためのページが用意されている。

www.structlog.org

最初に出ている選択肢として統合しない(Don't Integrate)と言うものがある。これについては一番最後に紹介する。

残りの3つの選択肢は、 structlog の Logger が logging.Logger の .info() 等のメソッドを呼び出す形をとり、その後の処理は logging のカスタマイズで対応する。

Rendering Within structlog

structlogでJSONにまでフォーマットしてしまい、それをmessageとしてloggingに渡すと言うもの。 logger.info(message) の message 部分にJSONがそのまま入る形だ。

これはloggingのフォーマットを "%(message)s" だけにしておかないとJSONの前後にログレベルとかタイムスタンプとかが付いて JSON lines ではなくなってしまう。だがこのフォーマットでは既存のloggingを使ったログをJSONにできない上に、情報が少なすぎる。

これはちょっと扱いにくいので、選択肢から外す。

Rendering Using logging-based Formatters

こちらは、 logger.info("hello", extra={"key":12}) のようにmessage以外のkey-valueをextraとして渡して、 loggingのFormatterでJSONにするという手順だ。

ここで紹介されているJSONにするためのFormatterが python-json-logger だ。 structlogは完全にloggingのフロントエンドとしてのみ利用するので、必要な設定も自動で追加する項目などにしぼり、フォーマットに関する設定はpython-json-logger側になる。

依存ライブラリが増えるのと、この構成を理解して設定するのが若干手間だけれども、非常にうまく統合されるのでこれは有力な選択肢だ。

ただし、せっかく structlog の使い方を調べて理解したのに、フォーマット関連の知識が全く使い物にならなくなってしまって新たに調べ直す必要があるのは残念な点ではある。

Rendering Using structlog-based Formatters Within logging

こちらは、構成としては先の "Rendering Using logging-based Formatters" と同じになる。ただしFormatterとしてstructlogが提供している structlog.stdlib.ProcessorFormatter を使うので、structlogのLoggerとProcessorFormatterがより高度に連携できる。

JSON化するときのフォーマットも、通常のstructlogを設定するときと同じようにprocessorsでできるから、依存ライブラリを増やさなくてもいい上にstructlogを調査したときに覚えた設定方法がそのまま使えるのも魅力だ。

一方で設定が複雑になる部分もあり、 structlogのBoundLoggerの中、logging.Loggerに渡す前に行う処理は structlog.configure() の processors= に、 ProcessorFormatter に来たログのうち、フロントエンドがstructlogではない通常のログに対して行う前処理は ProcessorFormatter() の foreign_pre_chain= に、最後に全てのログに対して行う処理は ProcessorFormatter() の processors= にと、考えを整理して正しい場所で処理する必要がある。

複雑になる分だけ、パフォーマンスも落ちやすい。パフォーマンスについては最後に簡単なベンチマーク結果を紹介する。

Don't Integrate

これは structlog から logging.Logger の .info() などのメソッドを呼び出すのではなく、両者がそれぞれにログをフォーマットして出力する、一番シンプルな方法だ。 別々とはいえ、 logging.StreamHandler と structlog.Write に同じオブジェクト（sys.stdoutかsys.stderr）を渡せば、最終的な出力は同じ場所にできる。

この場合、 ログが行の途中で混ざらないように、出力ファイルの .write() メソッドのアトミック性に依存する必要がある。そのために structlog.PrintLogger は使えないことに注意が必要だ。PrintLoggerは print(message, file=file, flush=True) をするのだけれど、このとき print の内部では file.write(message); file.write("\n"); file.flush() を行うので、マルチスレッドでログを書いたときにログ本体と改行の間に他のログが混ざってしまう可能性がある。マルチスレッドプログラムでprintを使っているとよく目にする壊れ方だ。

さて、別々に設定するとはいえ、最終的な出力をJSON linesに統一したいのであれば、結局 logging のフォーマットをJSONにしないといけない。そのためには上のpython-json-loggerか structlog.stdlib.ProcessorFormatter を使うことになる。

この場合だと、 structlog.stdlib.ProcessorFormatter を使った方が、structlog側のログとlogging側のログを同じ形に揃えやすいし、依存ライブラリも減らせるのでおすすめだ。

ベンチマーク

次の関数を、いろいろな構成のloggerを使って実行するだけのベンチマークをしてみた。

def hello(logger):
    logger.warning("hello")  # {"foo": "bar", "event": "hello"}
    logger.info("goodby %s", "world")  # {"arg": "world", "event": "goodby"}

なお、ベンチマーク中にstructlogが不自然に遅いケースがあったため調べて次の最適化を行った。

• optimize CallsiteParameterAdder by methane · Pull Request #606 · hynek/structlog · GitHub
• optimize `_find_first_app_frame_and_name` by methane · Pull Request #607 · hynek/structlog · GitHub

1つ目のPRはstructlogがログに呼び出し元のファイル名、行、関数名などを埋め込むCallsiteParameterAdderを高速化するもので、これを使うかどうかでstructlogの性能が大きく変わるので、構成の違いに加えてCallsiteParameterAdderの有無も変えて計測している。すでに取り込まれたので、次のリリースからは下のベンチマークと同じ速度まで速くなるはずだ。

2つ目のPRは、CallsiteParameterAdderやstdlib統合するときに使うfindCaller()というメソッドで使っている処理を高速化するもの。こちらは高速化効果が小さい上に、マルチスレッド＋何かの組み合わせの時によくわからないバグが発生する可能性があるだとかで、取り込まれなさそうだ。

まずはloggingと統合する方のベンチマークから。

ソース

結果:

CALLSITE=False N=100000
stdlib: 20145ns
stdlib+ProcessorFormatter: 35324ns
structlog+stdlib+ProcessorFormatter: 45063ns

CALLSITE=True N=100000
stdlib: 19964ns
stdlib+ProcessorFormatter: 52585ns
structlog+stdlib+ProcessorFormatter: 60687ns

• CALLSITEはCallsiteParameterAdderの有無
• stdlibは標準ライブラリのLoggerとFormatterのみ（JSONではない）
• stdlib+ProcessorFormatterはFormatterをProcessorFormatterに置き換えたもの（JSON）
• そしてstructlog+stdlib+ProcessorFormatterはstructlogのLogger経由でstdlib+ProcessorFormatterを呼び出すもの

structlog+stdlib+ProcessorFormatterはオーバーヘッドが大きく、またCallsiteParameterAdderも遅いのがわかるだろう。これでも上のPRで大分速くなったんだけどね…

次にloggingと分離したまま、同一ファイルに出力する方のベンチマーク

ソース

結果:

CALLSITE=False ORJSON=False N=100000
stdlib: 16008ns
stdlib+ProcessorFormatter: 30076ns
stdlib+json_formatter: 26234ns
structlog: 11394ns

CALLSITE=True ORJSON=False N=100000
stdlib: 16217ns
stdlib+ProcessorFormatter: 33315ns
stdlib+json_formatter: 25804ns
structlog: 19898ns

# ORJSONはstructlogにのみ関係するのでそれだけ掲載
CALLSITE=True ORJSON=True N=100000
structlog: 15110ns

CALLSITE=False ORJSON=True N=100000
structlog: 6830ns

• CALLSITE, stdlib, stdlib+ProcessorFormatter の意味はさっきの統合版と同じ
• stdlib+json_formatterはloggingのFormatterにpython-json-loggerを使ってカスタマイズしてなるべく出力を似せたもの
• structlogは、loggingと統合しないときのstructlogの性能。フォーマットはstdlib+ProcessorFormatterと同じ
• ORJSONはJSONのシリアライザにorjsonを使ったもの。高速だが、シリアライズ結果がbytesになるので、stdlib+ProcessorFormatterでは使いにくい。

まず目につくのは、stdlibの速度が統合版の20usから16usに速くなってることだ。これはstdlib統合版がloggingが使うLoggerクラスを置き換えて、呼び出し元を調べる findCaller() を置き換えたものだ。loggingのfindCaller()はlogging内のメソッドをスキップしてそれ以外の最初の呼び出し元を探すのだけれども、structlog版はlogging, structlog, その他設定でスキップすると指定されたprefixで始まるモジュールを飛ばすので遅くなっている。

ちなみにloggingはLoggerがLogRecordを作ってHandlerに渡すという処理になっていて、findCaller()はHandlerで呼び出し元が必要かどうかに関係なく呼ばれるので、CALLSITEがTrueでもFalseでも非統合版の方が速くなっている。

CALLSITE=Falseのときの速度は structlog < stdlib < stdlib+json_formatter < stdlib+ProcessorFormatter の順になっている。loggingを使う時はProcessorFormatterよりjson_formatterの方が速いが、一番多いログをstructlogで出力するのであればProcessorFormatterの遅さも許容範囲で、むしろ設定がstructlogと合わせやすいメリットが大きいだろう。

CALLSITE=Trueの場合はJSONでない素のloggingに負けるが、それでも統合版のloggingと同程度の速度は出ている。JSONシリアライザをorjsonにすることで素のloggingと同じ速度まで高速化できて、さらにCALLSITE=Falseと組み合わせれば素のloggingより倍くらい速くなる。

以上の結果から、構成の複雑さと性能、依存ライブラリ(python-json-logger)を増やさないことなどを天秤にかけると、loggingとstructlogを統合しないままloggingのFormatterにProcessorFormatterを使うのはかなり良い選択肢に思える。

structlogのドキュメントではloggingとstructlogを統合しない選択肢についてはかなりあっさりとしか書かれていないので、もう少し追記する提案をしてみるつもりだ。