KDOC 254: ジョブプロセスがSleepしていた理由

この文書のステータス

  • 作成
    • 2024-10-17 貴島
  • レビュー
    • 2024-10-28 貴島

概要

数時間かかる機械学習の推論処理をブラウザからキック + 進捗ログを確認できるようにする、ということをした。ジョブワーカーを起動して非同期処理をできるようにしたのだが、そこで不可解な事象にあたって悩んだので書いていく。ちゃんとわかっている人であれば秒で解決できただろう。

前提。

  • タスクのステータス(Running, Success, Failed, …)はFlowerで確認できる
  • ワーカーはDockerコンテナ上で動いている

事象。

  • タスクが永遠にRunningのままで、 終了ステータスにならない。ログを見ると同じ箇所で進まなくなっている
    • 調べると、タスクプロセスがスリープステータスになっていた。終了はしていない
    • スリープだけあって、CPU使用率はほぼ0%に近い。いっぽうメモリは率が高いままになっている
    • スリープになったプロセスを再開させても、すぐスリープに戻る
    • システムログにめぼしいメッセージは出ていない
    • マシンリソースには余裕がある
  • 特定の入力データだけで起こる。データサイズに違いはない
  • 直にシェルから実行すると成功する。ジョブワーカー経由で実行すると失敗する
  • straceで該当プロセスのシステムコールをトレースしてみると、最後に実行されているのは write(2, "Warning: ...") であった。プロセスを再開させて(すぐ終了する)トレースしても、最後に write(2, "Warning: ...") が実行されていた。

原因。

結論としては、タスク内で実行しているサブプロセスで標準エラー出力を取り出せておらず、標準エラー出力が詰まっていた1ためだった。詰まった結果、プロセスがスリープしていた。

  • うまくいかない入力データでは、実行の過程でWarningが大量に出ており、このWarningは標準エラー出力に出されていた
  • うまくいく入力データでは、Warningはあまり出ていない

Warningは実行終了時に、まとめてログに書き込まれていた。標準エラー出力に書き込まれたそのタイミングでログに記録されるのではなく、終了時に標準エラー出力がまとめて書き込まれていた。推論コードはあまり見ていないので、標準エラー出力が最後にまとめて出ているのがおかしいことに気づかなかった。

シェルで実行するときは標準エラー出力が即時に取り出される。そのためエラーが起きない。ジョブワーカー経由では、エラー出力を取り出せていなかったために、貯まってしまうようになっていた。

関連

なし。

Backlinks

Footnotes:

1

ざっくりした表現なのはわかっていないためだ。文書やコードから挙動を理解したわけではなく、動作から推理したもので、確かではない。