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()を使うのを止めるプルリクエストを作った。

• graceful stop worker when max_requests/realod_on_* by methane · Pull Request #2615 · unbit/uwsgi · GitHub
• stop using pthread_cancel() by methane · Pull Request #2619 · unbit/uwsgi · GitHub

なお、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.Reader と io.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) を返すのが一般的（待っても良い）。
  • len(p) バイトのデータを待ちたい場合は、 io.ReadFull() や io.ReadAtLeast() を使える。
• n > 0 かつ err != nil の場合があるので、 err をチェックする前に p[:n] までのデータを処理する必要がある。
  • 特に err == io.EOF の場合は正常系として頻出する。
• Readの実装は、 n にかかわらず、 p 全体を一時メモリとして利用可能。

Writeの場合

• n < len(p) の場合は err が nil でないことが保証されている。
  • つまり、呼び出し側は 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/mysql も MySQL 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したカラムの少ないログをデバッグレベルで出力するとか、トレーシングを使っているならトレースの属性やイベントとして記録するのが良いでしょう。ログを分けることで、保存期間を分けたり、異なるサンプリングをできます。たとえば構造化イベントは全てのログに対してとってアクセスログと同じ期間記録し、デバッグやパフォーマンス分析用のログはトレースと一緒にサンプリングしてより短い期間で破棄すると良いでしょう。

構造化ログのタイムスタンプ形式

みんなtai64nを使おう。と言いたいところだけれど、サポートしてるところが見当たらないのでナシだ。

個人的に好きなのはナノ秒単位のUnixタイムスタンプだ。 OpenTelemetryのOTLPでもナノ秒タイムスタンプを使っている。

  "logRecords": [
    {
      "timeUnixNano": "1544712660300000000",

(opentelemetry-protoのexample より)

しかし、これはスキーマが厳密に定義されているOTLPだからこそできる事であって、普通にJSON linesのログをあちこちで扱うには問題がある。

• レコード名が "time" や "timestamp" だとナノ秒なのかマイクロ秒なのかわかりにくい
• そもそも人間はUnixタイムスタンプを読めるようにできていない

整数の代わりに実数を使えば、精度はマイクロ秒に落ちてしまうものの、単位が秒だと自然に判断できるので前者の問題は解決できそうに思える。しかし、DataDogの場合はUnix epochからのミリ秒をタイムスタンプとして採用しているので、カスタマイズが必要になる。

https://docs.datadoghq.com/logs/log_configuration/pipelines/?tab=date#date-attribute

BigQueryの場合はフィールドをタイムスタンプ型だと指定すると秒単位の実数として扱うようだ。Unixミリ秒のサポートは見つからない。

Loading JSON data from Cloud Storage  |  BigQuery  |  Google Cloud

UnixタイムスタンプもあきらめてISO8601を使えば、サービスによる精度の解釈違いも起きないし、JSONを直接人間が読む時も読みやすくなる。日付と時間の区切りはTよりもスペースの方が読みやすいので "YYYY-MM-DD hh:mm:ss.ssssssZ" 形式にしても良いだろう。

ログ管理ツールは運用メンバーのタイムゾーンが多様である前提で作られていることが多いのでUIから表示するタイムゾーンを選べるし、BigQueryでも "+0900" をつけていてもUTCに変換して取り込まれるそうだ。それでも運用チームが日本ローカルでメンバーがJSONをそのまま読む機会が多いなら、ローカルタイムを使って末尾に"+0900"をつけるのでもいいだろう。

dev.classmethod.jp