尽きたのはこちらなのに、エラーはあちらで出る

一言でいうと

リソースが尽きると、リークさせたコードではなく、その後にリソースを必要としたコードが落ちます。そのため、トレースバックは無実のモジュールを指し、調査は計測でしか終わりません。

なぜ必要なのか

「午後3時ごろに落ちます」は、リソース枯渇の報告の典型的な文です。朝は問題なく、負荷とも正確には比例せず、再起動するとしばらくは大丈夫です。最後の条件が決定的な手がかりです。再起動で直るなら、溜まっていくものがあります。

ところが、ログを開くと、犯人ではなく被害者が見えます。ファイルディスクリプター(fd)をリークさせたのはセッションハンドラーなのに、エラーは、データベース接続で出たり、子プロセスの実行で出たり、ログファイルを開く場所で出たりします。ディスクリプターをリークさせたコードはすでに自分の分を取り終えていて、枯渇が表に出た瞬間に、その次にリソースを要求したコードが失敗するからです。

このずれのせいで、調査が見当違いの方向へ行きます。「sqliteがデータベースファイルを開けない」というメッセージを見て、ディスクと権限とパスを何時間も調べます。ファイルは無事で、権限も合っています。そのプロセスが、もうどのファイルも開けないだけです。

どう動くのか

リソース枯渇の調査の骨組みは、3つです。

1. 上限を知る。Linuxはプロセスごとにリソースの上限をかけ、Pythonではresourceモジュールで読み書きします。RLIMIT_NOFILEは同時に開けるディスクリプターの数、RLIMIT_ASはアドレス空間の大きさです。getrlimit(2)が定めるとおり、上限にはソフトとハードの2つの値があり、ソフトはハード以下の範囲で、プロセスが自分で下げられます。下げられるという点が、調査に使えます。10時間後に出会う枯渇を、今作れるのです。

2. 溜まるものを数える。Linuxはproc(5)に、プロセスごとに/proc/<pid>/fdディレクトリを置き、開いているディスクリプターごとにエントリを1つ置きます。そのエントリ数を数えれば、今いくつ持っているかがわかります。リクエスト数を変えながらこの値を測ると、点がいくつか出て、その点が直線の上にあれば、傾きがそのままリクエスト1つあたりのリーク数です。傾きが0ならリークしていません。これが、リークを「感覚」ではなくデータにする方法です。

3. 症状と原因を分けて書く。枯渇したあとのエラーメッセージは、リソースの種類を教えてくれるだけで、誰が使ったかは教えてくれません。そのため、報告書には2つを別々に書きます。観測された症状の一覧と、計測で明らかにした原因です。

한도                무엇을 막나                 바닥났을 때의 얼굴
RLIMIT_NOFILE      열린 파일·소켓 수           OSError errno 24 (EMFILE),
                                               그리고 자원을 쓰는 남의 코드의 오류
RLIMIT_AS          주소 공간 크기               MemoryError (트레이스백이 남는다)
커널 OOM 킬러      머신 전체의 메모리           SIGKILL (트레이스백이 남지 않는다)

メモリ側で特に重要な区別が、この表の最後の2行です。制限にかかった割り当ては例外として上がってきてトレースバックを残しますが、カーネルが殺す場合は、プロセスがSIGKILLで消えて、最後のログさえ残りません。「ログが途中で切れた」という報告は、それ自体が手がかりです。ただし、RLIMIT_ASはアドレス空間の上限であって、実際の使用量と同じではないことも一緒に書く必要があります。マッピングだけして触れていない領域も、アドレス空間は占有するからです。

現場での姿

1つ目は、エラーメッセージの単語を検索することです。「unable to open database file」で検索すると、権限とパスの話がたくさん出てきます。どれも正しい話ですが、この件とは関係ありません。リソース枯渇を疑うサインは、メッセージではなくパターンです。時間が経つほど悪くなり、再起動で直り、異なるモジュールが交互に失敗します。

2つ目は、1回の観測で結論を出すことです。「今ディスクリプターが900個あります」は、それだけでは何の意味もありません。元々いくつだったか、リクエストが増えるときにどう変わるかを一緒に測る必要があります。点が2つあれば、傾きが出ます。

3つ目は、上限を上げて覆い隠すことです。上限を上げると、落ちる時刻が午後3時から夜10時に移るだけです。リークしている側を直さなければ、いつか必ずまた出会います。ただし、上限を下げることは、調査の道具としてとても役に立ちます。10時間かかる再現を、数秒に縮められます。

4つ目は、ファイルだけを数えることです。ディスクリプターはファイルだけではありません。ソケット、パイプ、イベント通知、そして子プロセスを起動するときに一時的に使うものまで、同じ上限を分け合います。そのため、枯渇したプロセスは、ファイルを開けないのではなく、何もできません。

実務で本当に大切なこと

再起動で直るなら、溜まるものがあります。その一文を、調査の出発点にします。
リークは傾きで証明します。1回の観測はデータではありません。
上限を下げて、枯渇を前倒しで起こします。再現時間を、時間単位から秒単位に縮めます。
症状と原因を別々に書きます。トレースバックが指すモジュールは、たいてい無実です。

次のラボですること

セッションハンドラーを受け取って、開いているディスクリプターの数を数えるツールを作り、リクエスト数を変えながら測って、リクエスト1つあたりのリーク数を傾きとして求めます。上限を下げて枯渇を前倒しで再現し、枯渇したあとに異なる4つの処理がそれぞれどのような顔で失敗するかを記録します。メモリ側もアドレス空間の上限で安全に再現して、例外として受け取られる場合と殺される場合の違いを書き、最後に修正バージョンの傾きが0であることを、同じツールで証明します。