uvicornのワーカーが「Child process died」で1日10回落ちる原因 ─ スワップで数秒止まったワーカーを、健全性確認の5秒がkillしていた話

2026年10月26日

当ページのリンクには広告が含まれています。

この記事の結論

本番のuvicornワーカーが1日10回前後入れ替わっていた原因は、クラッシュではありませんでした。メモリ不足でスワップから読み戻している数秒の間にワーカーが止まり、親プロセスが既定5秒の健全性確認で強制終了していたのです。止まった瞬間のスタックを先に記録できるようにしたことで、推測ではなくログで原因を確かめられました。猶予を30秒に延ばすと入れ替えは減りましたが、30秒を超えて止まるワーカーはまだ残っています。

お疲れ様です！IT業界で働くアライグマです！

個人開発している開発関連ニュースのキュレーションサービス「DevPick」のバックエンドは、FastAPIをuvicornで動かしています。あるとき本番のログを見ると、デプロイとは関係ない時刻に、uvicornがワーカーを入れ替えた記録が1日に10回前後も残っていました。この記事では、その原因を突き止めるまでの順番と、対策した後にまだ残っていることを書きます。

1日10回ワーカーが入れ替わっていた

親プロセスが子のワーカーを作り直した記録が残っていた

DevPickの本番では、uvicornを--workers 2で起動しています。この場合、uvicornの親プロセスが1つあり、その下で実際にリクエストを処理する子プロセス（ワーカー）が2つ動きます。親はワーカーを見張っていて、ワーカーがいなくなると新しいものを起動し直します。

その作り直しの記録が、systemdのログ（journal）に次のように残っていました。

04:06:45 Waiting for child process [2583736]
04:06:45 Child process [2583736] died
04:06:49 Started server process [2589502]

10月23日の17時から翌24日の13時までの約23時間で、この記録は11回ありました。どれもデプロイによる再起動とは別の時刻です。このときのログは、journalをディスクに残す設定を入れた直後のものです。それまではメモリ上にしか持っておらず、約8時間分しか残らないうえ、サーバーの再起動で消えていました。

ワーカーが消えた瞬間のリクエストは502になっていた

DevPickでは、Apacheが受けたリクエストをuvicornへ転送しています。ワーカーが消えた同じ秒に、Apache側には転送先から応答を読めなかったという記録が残っていました。消えたワーカーが処理していたリクエストは、利用者からは502エラーに見えていたことになります。

困ったのは、この入れ替えがどこにも通知されていなかったことです。外部からの死活監視は/healthというURLに定期的にアクセスしていますが、片方のワーカーが消えても、もう片方が/healthに答えるため、監視は正常のままでした。/healthが正常でも実際の処理は壊れていた件は、以前「/healthが200を返しているのに、保存系APIは全滅していた話」にも書きましたが、今回も同じ形で見逃していました。

「died」という記録だけでは、落ちたのか殺されたのか分からなかった

Child process [...] diedという文言は、ワーカーが自分でクラッシュした場合にも、親が強制終了した場合にも、同じように出ます。実際、OSのログにはPythonのプロセスが暗号ライブラリ（OpenSSL 1.1.1g）の中でセグメンテーション違反、つまり不正なメモリ参照で落ちた記録も数日に1回ありました。

一方で、uvicornの親は定期的にワーカーへ合図を送り、既定で5秒以内に返事が無ければそのワーカーを強制終了して作り直します。直近の11回にはセグメンテーション違反の記録が無く、こちらの強制終了の可能性が高いと見ていました。ただ、どちらにしてもワーカーが何をしていたかの記録は残っていません。

IT女子アラ美

監視は正常なのに、裏で1日10回も入れ替わってたのね。気づけないのが一番怖いわ。

ITアライグマ

はい。片方のワーカーが答えてしまうので、外からの監視では見えませんでした。

落ちる瞬間のスタックを残す仕組みを先に入れた

原因を決め打ちせず、まず次の1回を記録することにした

ワーカーが消える直前の記録を見ると、記事画像を中継する処理へのアクセスが続いていました。画像の取得には暗号化通信を使い、取得した画像の縮小も行っています。怪しい処理はいくつも挙げられましたが、どれも推測です。そこで、直す前に「次に消えたとき、ワーカーの中で何が動いていたか」をログに残す仕組みだけを先に入れ、本番に出しました。直す変更は、記録が取れてから別に入れています。

使ったのは、Python標準ライブラリのfaulthandlerです。プログラムが異常な状態になったときに、その時点で各スレッドがどの関数のどの行を実行していたか（スタック）を出力してくれます。

クラッシュ用と、止まったとき用の2つを有効にした

1つ目はfaulthandler.enableです。セグメンテーション違反のような致命的なエラーで落ちるときに、全スレッドのスタックを出します。

2つ目は、止まったことの検知です。強制終了の場合、ワーカーは落ちる前に何も書けずに殺されます。そこで「殺される前に、止まっていることに気づいて書き出す」仕組みを作りました。ワーカーの中で1秒ごとに目覚まし時計を3秒後へかけ直し続け、かけ直しが3秒途絶えたら、そのときのスタックを出すという作りです。単純化すると次のようになります。

import asyncio
import faulthandler
import sys

STALL_TIMEOUT_SECONDS = 3.0      # uvicornが殺すまでの5秒より短くする
HEARTBEAT_INTERVAL_SECONDS = 1.0

async def run_loop_stall_watchdog():
    try:
        while True:
            # 3秒後にスタックを出す予約を、1秒ごとにかけ直す
            faulthandler.dump_traceback_later(
                STALL_TIMEOUT_SECONDS, repeat=False, file=sys.stderr
            )
            await asyncio.sleep(HEARTBEAT_INTERVAL_SECONDS)
    finally:
        faulthandler.cancel_dump_traceback_later()

アプリの起動時に、この処理をイベントループ上のタスクとして動かします。イベントループが正常に回っていれば1秒ごとに予約がかけ直されるので、何も出ません。イベントループが3秒以上止まると予約が実行され、スタックがjournalに出ます。

止まった状態でも書き出せる仕組みを選んだ

この方法を選んだのは、dump_traceback_laterの予約を実行するのが、Pythonのコードとは別に動く監視用のスレッドだからです。Pythonには、同時に1つのスレッドしかPythonのコードを実行できないようにする仕組み（GIL）があります。普通のPythonのスレッドで見張っていると、止まっている原因がGILを握ったままのスレッドだった場合、見張り役も一緒に止まってしまいます。faulthandlerの予約はGILを取らずに動くので、こうした状態でも書き出せます。

3秒という値は、uvicornが強制終了するまでの5秒より短くし、殺される前に記録が残るようにしました。repeat=Falseにしたのは、止まり続けたときに同じスタックでログを埋めないためです。

IT女子アラ美

怪しい所がいくつもあるなら、つい片っ端から直したくなるけどね。

ITアライグマ

当て推量で直すと、効いたのかどうかも分かりません。まず次の1回を記録しました。

10件すべてが「止まってからkill」だった

どの入れ替えも、直前に停止の記録があった

記録の仕組みを本番に出したあと、10月24日の18時から翌25日の8時半までに、ワーカーの入れ替えは10回ありました。journalを見ると、10回すべてで、入れ替えの2〜6秒前に止まったことを示すTimeout (0:00:03)!とスタックが出ていました。一方、セグメンテーション違反のときに出るFatal Python errorは1件もありませんでした。

停止を検知した時刻	ワーカーが入れ替わった時刻
10/24 18:22:08	18:22:12
10/24 18:23:32	18:23:37
10/24 18:23:44	18:23:49
10/24 22:59:13	22:59:17
10/25 01:50:00	01:50:02
10/25 02:04:43	02:04:48
10/25 04:37:27	04:37:31
10/25 08:05:43	08:05:49
10/25 08:24:49	08:24:51
10/25 08:30:11	08:30:14

停止の検知は、止まってから3秒後に出ます。そこから数秒で入れ替わっているので、止まってから5秒前後で親に殺された、という順番と合います。この期間のワーカーの入れ替えは、どれもクラッシュではなく強制終了でした。

止まった場所は、特定の処理ではなかった

次に、止まった瞬間にどこを実行していたかを見ました。イベントループのスレッドはPythonのコードを実行しておらず、別のスレッドで動いている同期処理が走っている形でした。その場所は、話題の集計、画像キャッシュの掃除、検索エンジンへ更新を知らせる対象の選定、サイトマップの組み立てなどに散らばっていました。特定の処理が重いのではなく、どの処理でもたまたま止まっていたことになります。

サーバーはメモリが足りず、スワップから読み戻し続けていた

そこでサーバー自体を見ると、メモリが足りていませんでした。DevPickを動かしているVPSは2コア・メモリ971MBで、スワップ（メモリに入りきらないデータを一時的にディスクへ追い出す領域）を約1.3GB使っていました。vmstatで見ると、ディスクからメモリへの読み戻しが毎秒2〜3MB続いていました。

free -m; vmstat 1 5          # si/so（スワップの読み書き）が続いていないか
grep -H VmSwap /proc/[0-9]*/status | sort -k2 -rn | head   # 追い出された量の多いプロセス

プロセスごとに見ると、uvicornのワーカーは実際にメモリへ載っている量が50〜65MBなのに対して、約100MBがスワップへ追い出されていました。ほかにMySQLが373MB、使っていないとみられるAIのコマンドラインツールのセッションが合計約320MB、スワップに追い出されていました。

止まったスレッドに、ワーカー全体が引きずられていた

ここまでを合わせると、次の流れになります。

あるスレッドが、スワップへ追い出されていたメモリに触る
ディスクから読み戻すまで、そのスレッドは数秒止まる。GILを握ったまま止まるので、ほかのスレッドもPythonのコードを実行できない
イベントループも、親からの合図に返事をする処理も止まる
親は5秒返事が無いので、ワーカーを強制終了して作り直す

作り直されたワーカーは、アプリを一から読み込みます。メモリが足りない中でこれを行うと、さらにほかのデータがスワップへ追い出されます。止まりやすい状態を、作り直しがさらに悪くしていた形です。

IT女子アラ美

コードのどこかが悪いんじゃなくて、サーバーのメモリが足りてなかったのね。

ITアライグマ

はい。止まった場所がばらばらだったことが、特定の処理のせいではないという手がかりになりました。

猶予を30秒に延ばし、本番に届いていなかったユニットも直した

ここからの対策は、この節の2つと次の節の通知を、1つの修正としてまとめて本番に出しています。

止まっただけのワーカーは殺さず、本当に固まったものだけ入れ替える

数秒止まっただけのワーカーは、読み戻しが終われば処理を再開できます。それを5秒で殺して作り直すと、処理中のリクエストが502になるうえ、作り直しでさらにメモリを使います。そこで、uvicornの親がワーカーの返事を待つ時間を、--timeout-worker-healthcheckで5秒から30秒に延ばしました。

# 親が子ワーカーの応答を待つ秒数（uvicornの既定は5秒）。
# メモリの小さいVPSではスワップからの読み戻しでワーカーが数秒止まることがあり、
# 5秒では止まっただけのワーカーをkillして入れ替え続けていた
ExecStart=.../venv/bin/uvicorn app.main:app --host 127.0.0.1 --port 8000 --workers 2 --timeout-worker-healthcheck 30 --proxy-headers --forwarded-allow-ips 127.0.0.1

30秒にしても、本当に固まって戻ってこないワーカーは、これまでどおり作り直されます。止まったことを記録する仕組みのほうは3秒のまま残しました。殺されるところまでいかない応答の遅れも、記録しておきたいからです。

リポジトリのユニットを直しても、本番には反映されていなかった

この修正では、起動オプションとあわせて、設定の届け方も直しました。systemdのユニットファイル（サービスの起動方法を書いた設定）は、リポジトリにも置いてあります。ところが本番のユニットは、サーバーを最初に用意したときに一度書かれたきりで、その後リポジトリ側を変えても本番には届かない作りでした。実際、本番のユニットはリポジトリと食い違ったまま動いていました。

そこで、デプロイのたびにリポジトリのユニットと本番のユニットを比べ、違っていれば置き換えてsystemdに読み込み直させるようにしました。読み込みに失敗したときは元のユニットに戻し、壊れた設定を置いたままにしないようにしています。単純化すると次の流れです。

apply_backend_unit() {
    installed="/etc/systemd/system/devpick-backend.service"
    if [[ -f "$installed" && "$(cat "$installed")" == "$(cat "$APP_DIR/$BACKEND_UNIT")" ]]; then
        return 0   # 反映済み
    fi
    cp "$installed" "$backup"                 # 反映前のユニットを退避
    cp "$APP_DIR/$BACKEND_UNIT" "$installed"
    if systemctl daemon-reload; then
        BACKEND_UNIT_CHANGED=1                # この後の再起動で新しい起動行を効かせる
        return 0
    fi
    cp "$backup" "$installed"                 # 読み込めなければ元に戻す
    systemctl daemon-reload
    return 1
}

ユニットを変えた回は、必ずバックエンドを再起動する

ユニットは置き換えただけでは効かず、サービスを再起動して初めて新しい起動行で動きます。DevPickのデプロイは、デプロイスクリプト自体を変えた回だけ、同じコミットに対してもう一度スクリプトを走らせます。最初の1回は古いスクリプトで動くためです。そして2回目は、「すでに同じコミットで動いている」と判断してバックエンドの再起動を省く作りでした。

このままだと、2回目でユニットを置き換えても再起動されず、新しい設定が効きません。そのため、ユニットを置き換えた回は、コミットの比較より先に再起動を決めるようにしました。デプロイ時の再起動まわりでは、以前「デプロイ中に公開ページが500を返していた話」でも順番を直しています。

IT女子アラ美

設定ファイルを直したつもりでも、本番に届いてなかったら意味ないわね。

ITアライグマ

はい。オプションを足すだけで終えていたら、本番は5秒のまま動き続けていました。

入れ替えが続いたら通知する

ワーカー自身が、起動したことを書き残す

最初の節で書いたとおり、ワーカーの入れ替えは/healthの監視では見えません。そこで、入れ替えが続いたら運用者向けのDiscordへ通知する仕組みを、前の節の対策と同じ修正で足しました。

uvicornの親は、ワーカーを作り直したことをアプリに教えてくれません。そのため、ワーカーが起動するたびに、自分の親プロセスの識別子と起動時刻を、サーバー上の小さなJSONファイルに書き残すようにしました。2つのワーカーが同時に書くことがあるので、ファイルロックで順番に書かせています。書いている途中で殺されても壊れたファイルが残らないよう、一時ファイルに書いてから置き換えています。

デプロイでの再起動は数えない

入れ替えかどうかは、次のように見分けています。

親プロセスが前回の記録と違うなら、デプロイやsystemdによる再起動なので、新しい記録として始め直す
同じ親の下で、最初の起動から120秒以内に起動したワーカーは、起動直後の一群なので数えない
同じ親の下で、それより後に起動したワーカーを「入れ替え」として数える

親プロセスの識別には、プロセス番号（PID）に加えて、その親の起動時刻も使っています。PIDは使い回されることがあるので、PIDだけだと別の親を同じものと取り違える可能性があるためです。

10分ごとに数えて、直近60分で3回以上なら知らせる

数えるのは、アプリの定期ジョブです。10分ごとに記録を読み、直近60分の入れ替えが3回以上なら通知します。単純化すると次の判定です。

def count_recent_respawns(window_seconds, now, supervisor):
    state = read_state()
    if state is None or not is_same_supervisor(state, supervisor):
        return 0   # 記録が無い、またはデプロイで親が替わった後
    return sum(1 for t in state["respawns"] if 0 <= now - t <= window_seconds)

数える範囲（60分）は設定で変えられますが、10分から24時間の間に制限しました。記録は24時間で消すため、範囲をそれより長くすると数える前に記録が消えてしまいます。逆に、確認の間隔である10分より短くすると、確認と確認の間に起きた入れ替えを数え漏らします。同じ修正の中で、この制限も入れています。

IT女子アラ美

作り直されたことを親が教えてくれないなら、子が自分で書くしかないわね。

ITアライグマ

はい。デプロイを入れ替えと数えないよう、親が誰かも一緒に書かせました。

延ばした後も、30秒を超えて止まるワーカーは残った

メモリも空けたが、スワップはまた増えていた

猶予を延ばす修正は、10月25日の9時17分に本番へ出ました。同じ日の午前中には、メモリの空きも別の作業として増やしています。使っていないとみられるAIのコマンドラインツールのセッションを終了し、続けて10時19分にMySQLのメモリの使い方を見直して再起動しました。スワップの使用量は、作業前の約1.19GBから約0.55GBまで減りました。

ただ、この記事を書いている10月26日の7時46分にサーバーを見ると、スワップの使用量は911MBに戻っていました。

入れ替えは減ったが、5回残った

修正を出した10月25日9時17分から、26日7時46分まで（約22時間半）のjournalを数えると、ワーカーの入れ替えは5回ありました。修正前は約14時間で10回だったので、減ってはいます。ただ、間隔の形が修正前とはっきり変わっていました。

停止を検知した時刻	ワーカーが入れ替わった時刻	間隔
10/25 11:34:44	11:35:15	約31秒
10/25 18:35:33	18:36:03	約30秒
10/25 22:35:43	22:36:13	約31秒
10/26 02:04:44	02:05:14	約30秒
10/26 03:04:43	03:05:13	約30秒

修正前は止まってから数秒で殺されていましたが、今回はどれも停止を検知してからちょうど30秒前後で入れ替わっています。つまり、30秒の猶予を待っても戻ってこないほど長く止まったワーカーが、まだあるということです。止まったことの検知自体も、修正前の約15時間で108回、修正後の約22時間半で113回出ていて、止まることそのものは続いています。

30秒を超えて止まった原因は、まだ特定できていない

この5回について、止まったときに出たスタックを見ました。JSONの解析、要約の整形、暗号化通信の読み込みなど、場所はやはり散らばっていました。しかも、スタックの出力自体が途中で切れていて、どこで30秒以上止まっていたのかは特定できていません。

作った通知にも、数えられない入れ替えがあった

この期間、運用者への通知は1回も出ていません。60分の間に3回以上という条件に届かなかったためです。また、入れ替えとして記録されたのは5回のうち4回でした。18時36分の1回は、その約45秒前にsystemdからバックエンドが再起動されており、「最初の起動から120秒以内は数えない」という条件に入ったためです。デプロイの直後に起きた入れ替えは、今の作りでは数えられません。

止まること自体を減らすには、メモリの逼迫を解消するしかありません。今後もスワップの使用量と停止の回数を記録し、それでも続くようなら、ワーカーを2つから1つに減らすか、VPSのプランを上げることを検討します。

IT女子アラ美

30秒待っても戻ってこないなら、待つ時間を延ばしても限界があるわね。

ITアライグマ

はい。猶予の延長は入れ替えを減らす応急処置で、根本はメモリ不足の解消です。

まとめ

uvicornのChild process diedは、ワーカーがクラッシュしたときにも、親に殺されたときにも同じ文言で出ます。DevPickでは、怪しい処理を直す前に、faulthandlerで止まった瞬間とクラッシュした瞬間のスタックを残す仕組みを入れました。それで、入れ替えの10回すべてが「スワップからの読み戻しで数秒止まり、健全性確認の5秒で殺された」ものだと、ログで確かめられました。

対策として、健全性確認の猶予を30秒に延ばし、本番に届いていなかったユニットファイルをデプロイのたびに反映するようにしました。入れ替えが続いたときの通知も足しています。それでも、30秒を超えて止まるワーカーは残っていて、その原因はまだ特定できていません。今は、待つ時間を延ばすのは応急処置で、根本はメモリの足りなさを解消することだと考えています。

IT女子アラ美

直す前に記録を仕込んだから、5秒で殺されてたことまで分かったのね。

ITアライグマ

はい。記録があったので、延長後に30秒で殺されていることにも気づけました。