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が不自然に遅いケースがあったため調べて次の最適化を行った。

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を統合しない選択肢についてはかなりあっさりとしか書かれていないので、もう少し追記する提案をしてみるつもりだ。

PythonのマルチスレッドWSGIサーバーの選定

今までuWSGIをシングルスレッド、マルチプロセスで使っていたのだけれども、昔に比べて外部のAPI呼び出しが増えているのでマルチスレッド化を検討している。

uWSGI

uWSGIでマルチスレッドを有効にした時は、各workerスレッドがacceptする形で動作する。スレッド数以上の接続をacceptすることがないので安心。

プロセス内のスレッド間ではmutexで排他されて、同時にacceptを実行するのは1スレッドのみに制限されている。つまりthendering herd問題はプロセス間でしか起こらない。マルチスレッド化でプロセス数はむしろCPUコア数まで減らせるので、thendering herd問題はむしろ今よりも軽減できる。(ちなみにプロセス間でもロックしてthendering herdを許さないオプションもあるけど、プロセス間同期は怖いので使っていなかった。)

ただしuWSGIのマルチスレッド対応は、graceful shutdownの動作に問題がある。終了時に pthread_cancel() を利用してworkerスレッドを止めようとしているために、うまく終了できずにハングすることがある。特にメモリ使用量が増えたときにworkerを再起動する reload-on-rss や、指定回数リクエスト処理したあとに再起動する max-requests オプションを使う場合にこの問題を踏んでしまう。先週から今週にかけてこの問題をデバッグしていて、 pthread_cancel() を使うのを止めない範囲で他スレッドの終了待ちをもっと丁寧にするプルリクエストと、pthread_cancel()を使うのを止めるプルリクエストを作った。

なお、uWSGIはメンテナンスモードに入っていて、一人のメンテナがアクティブに月に数件〜数十件のプルリクエストを処理してくれているものの、将来を考えると他の選択肢も考慮しておきたい。

Gunicorn/gthread

Pythonで一番使われているWebサーバーはGunicornだろう。あちこちのドキュメントでサーバーを立てる手段として紹介されている。

Gunicornはworkerを選択できて、gunicorn本体に同梱されているマルチスレッドのワーカーとしてgthreadがある。ちなみに後述するUvicornもGunicornのworker classを提供しているので、Gunicornのプロセス監視機能を利用できる。

gthreadの動作は、メインスレッドでaccept loopを回して接続を受け付けて、その接続をスレッドプールで処理するモデルになる。このモデルではワーカースレッド数以上の接続を受け付けないかが心配になるが、Gunicornには同時接続数を制限する worker_connections オプションがあり、gthreadは接続数の上限に到達した場合は新規のacceptを止めてくれる。acceptを止めている間は、他の余裕のあるworkerプロセスがacceptしてくれるか、リクエストが待たされることになる。gthreadを使う場合はこのオプションを設定しておくと良いだろう。

gthread workerはシングルスレッドのsync workerと同じく、HTTP parserが独自のpure Python実装になってしまっているので、性能面では uWSGI に劣る。非常に高いrequest/secを必要とする場合は慎重に性能を評価するべきだろう。

後で時間ができたときにこの部分の性能改善にも取り組んでみたい。

Uvicorn

別の人気のあるWebサーバーとして、FastAPIが推奨しているUvicornがある。

UvicornはHTTP parserとして httptools を使える。 httptools は実装として node.js と同じ llparse を使っているので、リクエストを受け付ける速度はGunicorn+gthreadよりも速いだろう。実際、FastAPIはUvicornを使うことで高いパフォーマンスを実現している。

しかし、UvicornはasyncioをベースにしたASGIサーバーだ。WSGIアプリケーションを動かすためには、a2wsgiというライブラリを使って、ASGIリクエストを受け取ってWSGIリクエストに変換し、スレッドプールの中でWSGIアプリケーションを動作させることになる。このオーバーヘッドがあるので、WSGIアプリケーションはUvicornの性能を最大限に活かすことはできないだろう。

そして問題なのが、Uvicornにはgthreadのworker_connectionsオプションに相当するオプションがないことだ。

このため、nginxの後ろで1つのlisten socketをマルチプロセスで処理しようとすると、一部のプロセスに接続が集中して処理速度が悪化する可能性が出てくる。これを避けるためにはUvicornやGunicornのオプションで1つのインスタンスのワーカーをマルチプロセス化するのではなく、シングルプロセスのUvicornインスタンスを複数立てて前段で負荷分散するような構成が必要になってくる。

k8s等を使っていてすでにこういう構成になっているとか、簡単にその構成に対応できる場合を除いて、Gunicornの方が不安の少ない選択肢になると思う。または、非常に高いrequest/secを実現したくてUvicornを選定するのであれば、アプリケーションもASGIに移行するべきだろう。

Nginx Unit

まだあまりPython界で広まってなさそうに見えるが、uWSGIからの移行先としては有望かもしれない。今後時間があるときに調査してみる。

github.com

net.ConnのReadとWriteの振る舞いについて

Go-MySQL-DriverでカスタムのDialをサポートしていたり圧縮プロトコルサポートのコードをレビューしていたりして、利用している Write() の実装が多様化してきたので、「Write(p)って Read(p)みたいに n が len(p) より小さい場合にループで続きを書き込まなくてい良いのは決まりがあったっけ?」と気になって確認してみました。

まず、 net.Conn の定義ではReadとWriteは次のようになっています。

// https://pkg.go.dev/net#Conn

type Conn interface {
    // Read reads data from the connection.
    // Read can be made to time out and return an error after a fixed
    // time limit; see SetDeadline and SetReadDeadline.
    Read(b []byte) (n int, err error)

    // Write writes data to the connection.
    // Write can be made to time out and return an error after a fixed
    // time limit; see SetDeadline and SetWriteDeadline.
    Write(b []byte) (n int, err error)

ここには n と err の関係どころか n の意味自体書かれていません。実際には net.Conn のReadとWriteは io.Readerio.Writer を満たしているので、そちらのドキュメントを見る必要があります。

https://pkg.go.dev/io#Reader

Reader is the interface that wraps the basic Read method.

Read reads up to len(p) bytes into p. It returns the number of bytes read (0 <= n <= len(p)) and any error encountered. Even if Read returns n < len(p), it may use all of p as scratch space during the call. If some data is available but not len(p) bytes, Read conventionally returns what is available instead of waiting for more.

(略)

https://pkg.go.dev/io#Writer

Writer is the interface that wraps the basic Write method.

Write writes len(p) bytes from p to the underlying data stream. It returns the number of bytes written from p (0 <= n <= len(p)) and any error encountered that caused the write to stop early. Write must return a non-nil error if it returns n < len(p). Write must not modify the slice data, even temporarily.

まとめると次のようになります。

Readの場合

  • 現時点で得られたデータが len(p) よりも少ない場合は、後続のデータを待たずに n < len(p) を返すのが一般的(待っても良い)。
  • n > 0 かつ err != nil の場合があるので、 err をチェックする前に p[:n] までのデータを処理する必要がある。
    • 特に err == io.EOF の場合は正常系として頻出する。
  • Readの実装は、 n にかかわらず、 p 全体を一時メモリとして利用可能。

Writeの場合

  • n < len(p) の場合は errnil でないことが保証されている。
    • つまり、呼び出し側は err == nil の時に改めて p[n:] を書き込む必要はない。
    • そのため、 io.WriteFull() などは存在しない。
  • n > 0 かつ err != nil の場合があるのはReadと同じ。
    • ただしReadと違って正常系の err == io.EOF が無いので、途中までデータが書き込めたことに対して何か処理が必要で無い限りは無視していい。
  • Writeは p に対して一切書き込みを行わない。

ということで、Writeの方が使う側にとってはかなりシンプルですね。

Go-MySQL-Driver v1.8.0 をリリースしました

github.com/go-sql-driver/mysql (a.k.a. Go-MySQL-Driver)のv1.8.0をリリースしました。

個人的に重要だと思う点を紹介していきます。

charset/collationの扱い

ちょうどGREEさんのBlogで話題になっていた件です。

go-sql-driver/mysqlMySQL 8.0 もデフォルトのままだと、collation_connectionはutf8mb4_general_ci、collation_serverはutf8mb4_0900_ai_ciになります。いずれも character set としてはutf8mb4ですが、utf8mb4_general_ciとutf8mb4_0900_ai_ciは振る舞いが大きく異なるので、Goでutf8mb4を使うなら、意図したcollationが適用されているか注意が必要です。

v1.7まではREADMEに次のように書かれていました。

Version 1.0 of the driver recommended adding &charset=utf8 (alias for SET NAMES utf8) to the DSN to enable proper UTF-8 support. This is not necessary anymore. The collation parameter should be preferred to set another collation / charset than the default.

DSNで charset を指定するのは非推奨で collation を書け、ということですね。ハンドシェイクではそのcollationに対応したcollation idを使います。 charset を指定した場合はそのcharsetに対するデフォルトのcollationを選びますし、両方を指定した場合は collation が優先されました。

これには、 collation を理解して正しく設定しないといけないという問題と、ドライバー側でサーバーと一致したcollationの名前とidのマッピングを持っていないといけないという問題がありました。MySQL 8がどんどん進化する中、MySQLプロトコルを利用する他の製品も多様化していくので、問題は徐々に悪化してきました。

v1.8では charset を指定したときの動作が変わります。ハンドシェイクでデフォルトのcollation_idを送るのはそのままですが、接続後に SET NAMES <charset> を実行するので、そのcharsetに対するサーバー側のデフォルトのcollationが利用されます。 skip-character-set-client-handshake や、指定したcollation_idをサーバーが知らなかったなどの理由で暗黙のうちに完全に無視されることはありません。そのcharsetをサーバーが知らないならちゃんとエラーになります。

ということで、サーバー側のデフォルトのcollationをそのまま使えばいいほとんどのケースで、 charset のみを指定する設定を推奨します。 collation も指定したい場合は、charsetとcollationの両方を指定してやれば、 SET NAMES <charset> COLLATE <collation> というクエリを実行するので、確実にそのcollationを使えます。

より詳しい解説を去年Zennで MySQL接続のcollation不整合の原因と対策 という記事を書いたので読んでみてください。

Scan()にanyを渡した時の挙動を改善しました。

v1.7では次のように、内部でテキストプロトコルが使われているかバイナリプロトコルが使われているかでanyにScan()した時の結果が異なりました。

// db の接続設定で interpolateParams が false の場合
var v any
db.QueryRow("SELECT 123 WHERE ? = 1", 1).Scan(&v)
fmt.Printf("%T %v\n", v, v)  // int64 123

db.QueryRow("SELECT 123 WHERE 1 = 1").Scan(&v)
fmt.Printf("%T %v\n", v, v)  // []uint8 [49 50 51]

整数やfloatなど、変換してもアロケーションが増えない型に限定して、テキストプロトコルでもバイナリプロトコルと同じ結果になるようにしました。

これも詳細は去年Zennに書いたので、Go-MySQL-DriverでScan()にanyを渡した時の挙動を改善しました を読んでみてください。

構造化ログから構造化イベントへ

オブザーバビリティ・エンジニアリングの5章のタイトルは「構造化イベントはオブザーバビリティの構成要素である」です。構造化イベントの定義は5.1節にあります。

イベント とは、本番環境のサービスへの影響を理解するために、ある特定のリクエストがそのサービスとやりとりしている間に発生したすべての記録です。

そこからさらにイベントの記録について説明が続きます。

空のマップを初期化することから始めます。このマップには、そのリクエストの有効期間中に発生したものに関する興味深い詳細、 たとえばユニークID、変数の値、ヘッダー、リクエストで渡されたすべてのパラメーター、実行時間、リモートサービスへのコール、それらのリモートコールの実行時間など、後にデバッグに役立つであろうあらゆるコンテキストが追加されます。 そして、リクエストが終了したりエラーが発生したりすると、そのマップ全体はリッチな情報として取得されます。

つまり、ログを1リクエストあたり1行まで減らす代わりに、ログのカラムを大幅に増やすのです。

構造化イベントという用語はオブザーバビリティ・エンジニアリングの著者が所属している honeycomb.io が利用している用語のようですが、広く定着しているわけでは無さそうです。同じプラクティスにStripeはCanonical Log Linesという名前を使っているようです。

brandur.org

structlogのドキュメントのBest PracticesでもCanonical Log Linesが紹介されています。

www.structlog.org

さて、ここを見るとCanonical Log Linesを実現するためにbindが使えそうに書いてあります。

structlog’s ability to bind data to loggers incrementally (snip) can help you to minimize the output to a single log entry.

しかし、 log.bind() の動作は(GoのContextのような)スタック型になっていて、リクエストの処理の最後にまとめて書き出すために属性を追記していくのには向きません。

import structlog
from structlog.processors import JSONRenderer

structlog.configure(processors=[JSONRenderer()])
logger = structlog.get_logger()

def hello():
    log = logger.bind(foo="bar")
    log.info("hello") # {"foo": "bar", "event": "hello"}

hello()
logger.info("goodby", arg="world") # {"arg": "world", "event": "goodby"}

このサンプルでは foo="bar" が最後のログに反映されていません。これでは hello() の中でログを書くのをやめられません。

このスタック型にkey-valueを積み重ねていく設計は、immutableで一般的にはセンスの良いものですが、構造化イベントを実現するのに向いているとは思えません。

structlogのドキュメントではあまり言及されていない structlog.get_context() というAPIを使えば、loggerが持っているbind()済み変数が保存されたdict(=Context)を直接編集できるので、追記型の振る舞いも実現できます。

import structlog
from structlog.processors import JSONRenderer

structlog.configure(processors=[JSONRenderer()])
logger = structlog.get_logger()

def hello():
    lg = structlog.get_context(logger)
    lg["foo"] = "bar"
    logger.info("hello") # {"foo": "bar", "event": "hello"}

hello()
logger.info("goodby", arg="world") # {"foo": "bar", "arg": "world", "event": "goodby"}

このサンプルで最後に "foo": "bar" が出力されているので、hello()の中のログを消せるようになりました。 このとき、 lg["foo"] = "bar" の部分は lg["hello.foo"] = "bar"lg["hello"] = {"foo": "bar"} と書き換えると良いと思います。

構造化イベントのサポートが弱いのは、structlogだけではなく多くの構造化ログライブラリに共通する点だと思います。しかし、リクエストスコープのコンテキストを持つ仕組みは一般的なので、構造化イベントの実装は難しくありません。

例えばFlaskであれば flask.g.log_event = {} みたいな辞書を用意して、そこにイベントを足していけば良いでしょう。この仕組みなら、Goでもリクエストの先頭でContext にイベント追記用の map か sync.Map を格納すれば良いでしょう。

ここまで構造化イベントをベストプラクティスとして紹介してきましたが、私は全てのログを構造化イベントにまとめるべきだとは思っていません。メトリクスを抽出したり、ユーザーの行動分析に役立つ要素なら構造化イベントが適していると思いますが、デバッグに役立つ中間値や分岐を残すログであったり、パフォーマンス分析のためにタイミングを記録するログまで構造化イベントにする必要はないでしょう。

そのようなログは、リクエストIDと限られた属性だけをbindしたカラムの少ないログをデバッグレベルで出力するとか、トレーシングを使っているならトレースの属性やイベントとして記録するのが良いでしょう。ログを分けることで、保存期間を分けたり、異なるサンプリングをできます。たとえば構造化イベントは全てのログに対してとってアクセスログと同じ期間記録し、デバッグやパフォーマンス分析用のログはトレースと一緒にサンプリングしてより短い期間で破棄すると良いでしょう。

このブログに乗せているコードは引用を除き CC0 1.0 で提供します。