固まった Python プロセスの消えたスレッドを py-spy で見つけてみた
はじめに
ある常駐プロセスが絡む処理が、CPU 0% のまま固まりました。プロセスは生きているのに何も進まず、ログにもわかりやすいエラーは出ていません。
本記事では、この Python プロセスを py-spy で覗いてみた体験を紹介します。先に結論を書いておくと、原因は「標準出力を読むはずのスレッドが 1 つ終了していて、誰も出力を読まなくなっていた」ことでした。その不在に気づき、起動ログの 1 行から終了の理由にたどり着くまでを順に追っていきます。
py-spy とは
py-spy とは、動作中の Python プロセスを止めずに、実行中のスタックを外から吸い出せるサンプリングプロファイラです。dump サブコマンドを使うと、その瞬間の全スレッドのスタックを一覧できます。
対象読者
- Python が絡むプロセスの固着調査で手が止まっている方
- デーモンや常駐サービスの中で何が起きているかを、プロセスを止めずに知りたい方
- py-spy を名前は知っているが、固着調査で使ったことはない方
参考
- py-spy (GitHub)
- Python codecs のエラーハンドラ (strict と replace)
- Python subprocess (encoding と errors)
- 匿名パイプの満杯とブロッキング
課題: 生きているのにアイドルなプロセスの中が見えない
固着した Python プロセスは、CPU 0% で止まっていました。プロセス自体は生きていて、ログにも派手なエラーは出ていません。生きているのに何も進まない、という状態です。
原因を知るには中のスレッドを見たいところですが、これが意外と難しいです。常駐プロセスを再起動すると、その瞬間の状態は消えてしまいます。通常のデバッガでブレークを張ると対象を止めてしまい、止めた影響で症状が変わることもあります。止めずに、生きたままスレッドの様子を見る手が必要でした。
調査: py-spy で消えたスレッドを見つける
そこで py-spy を使用しました。対象を止めずに、全スレッドのスタックを吸い出して見ていきます。
py-spy で全スレッドを吸い出す
次のように dump を実行します。--native を付けると、Python のフレームだけでなく、C 拡張などのネイティブフレームもあわせて見えます。読み取りが C 側で止まっている場合に効果的です。
py-spy dump --pid <pid> --native
出力には、生きている全スレッドが、それぞれ現在のスタックとともに並びます。
あるはずのスレッドが居ない
ダンプを眺めて気づいたのは、あるべきスレッドが無いことでした。このデーモンは、サブプロセスの標準出力を読み続けるスレッドを持っているはずなのに、それがどこにも見当たりません。一方で、標準エラーを読むスレッドは生きていて、読み取り待ちで止まっていました。
Thread (idle): "MainThread"
...
Thread (idle): "標準エラー読み取り"
readline (...)
# 「標準出力読み取り」スレッドが一覧に無い
出力読み取りスレッドがいないということは、誰もサブプロセスの標準出力を読んでいないということです。py-spy が役立つのは、こうした「あるはずのものが無い」ことに気づけるからです。
起動ログで終了の理由を確かめる
スレッドが消えた理由は、デーモンの起動ログに残っていました。
Exception in thread 標準出力読み取り:
Traceback (most recent call last):
...
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xc7 in position 2: invalid continuation byte
サブプロセスの標準出力を、厳格 (strict) な UTF-8 として読んでいたのが原因でした。想定外のバイト (ここでは 0xc7) が 1 つ来た時点で UnicodeDecodeError が投げられ、その例外が読み取りループのスレッドを巻き込んで終了させていました。
調査の結果と対応
標準出力を読むスレッドが例外で終了し、以降は誰も出力を読まなくなっていた、というのが原因だということがわかりました。
読み手が止まると、サブプロセスの標準出力のパイプ (既定で数十 KB) はやがて満杯になります。満杯になるとサブプロセスは書き込みでブロックし、その結果、さらに上流のプロセスの処理まで返らなくなります。表に出ていた固着は、この連鎖の末に起きていました。
外部プロセスの出力をテキストとして読むループは、デコードを寛容にしておくと安全です。不正なバイトを置換文字に変える (errors="replace") か、バイト列のまま受け取って明示的にデコードすれば、想定外の 1 バイトでスレッドごと落ちる事故を防げます。
デコードを寛容にしてスレッドが終了しないようにしたところ、パイプは常に読み出され、CPU 0% の固着は再現しなくなりました。
まとめ
py-spy を使うと、固着した Python プロセスを止めずに全スレッドのスタックを吸い出せます。今回の決め手は「あるはずのスレッドが無い」という不在に気づけたことでした。外部プロセスの出力を読むループはデコードを寛容にしておくと、1 バイトの想定外でスレッドごと落ちる事故を避けられます。固着調査で手が止まったとき、本記事が参考になれば幸いです。
