GC の一時停止と漏れる行を数字で見つける

目標

このPodのGC設定を出力し、循環参照を作るハンドラーが残すゴミを数えたあと、weakrefで循環を断ち切ります。gc.callbacksでGCの一時停止を測って、リクエストの遅延のp99につなげ、gc.freezeの効果を見ます。sys.getsizeofの落とし穴と__slots__をtracemallocで確認し、リークしているサービスで増えた行(ファイル:行)を見つけて、上限付きのキャッシュで直したあと、増加が消えたかを測ります。

なぜ重要なのか

CPythonは、ほとんどのオブジェクトを参照カウントですぐに片付けますが、循環は、世代別コレクターが割り当て数に応じてまとめて片付けます。その収集がリクエストの1%超に当たると、平均は変わらないのにp99が跳ね上がります。メモリの問題は、「もっとも大きい行」ではなく「もっとも多く増えた行」から探す必要があり、getsizeofは、指しているオブジェクトを数えないので、サイズを小さく言います。採点ツールは、書いた数字だけを見るのではなく、あなたの関数を、新しいインタープリターで、用意された素材ではない入力に対して再実行し、基準と突き合わせます。

用意するもの

/opt/fixtures/svccs/memory/の下にあります。読み取り専用で使ってください。Pythonでは、sys.path.insert(0, "/opt/fixtures/svccs/memory")のあとにimport svcで呼び出します。

svc.py          가짜 주문 서비스
                CATALOG         불러올 때 한 번 만드는 상품 2만 개(자라지 않는 큰 정적 데이터)
                load_requests() requests.jsonl 의 요청 목록
                handle_cyclic   요청마다 부모↔자식이 서로 가리키는 트리를 만든다 → {"id", "items", "path"}
                render(req)     요청을 문자열로 렌더링
                handle_leaky    렌더링 결과를 전역 사전에 넣고 지우지 않는다 → {"id", "bytes"}
requests.jsonl  요청 3,000줄 {"id", "user", "items"} — id 는 다시 오지 않는다
sessions.json   세션 400개 {세션 id: {"user", "roles", "cart", "flags"}}

このコードブロックの韓国語の説明は、順に、svc.pyは偽の注文サービスで、CATALOGは読み込み時に1回作る商品2万個(増えない大きな静的データ)、load_requests()はrequests.jsonlのリクエストのリスト、handle_cyclicはリクエストごとに親と子が互いを指す木を作ること、render(req)はリクエストを文字列にレンダリングすること、handle_leakyはレンダリング結果をグローバルな辞書に入れて消さないこと、requests.jsonlはリクエスト3,000行で、idは二度と来ないこと、sessions.jsonはセッション400個で、セッションidごとのuser・roles・cart・flagsを持つこと、を述べています。

ステップ

/root/svccs/memory/gcinfo.jsonに、python(platform.python_version())、threshold(gc.get_threshold()をリストにしたもの)、gc_enabled(gc.isenabled())を書きます。
svc.load_requests()の最初の200件を、gc.collect() → gc.disable() → svc.handle_cyclicを200回 → gc.collect()(返された値が、回収した到達不能オブジェクトの数) → gc.enable()の順序で実行し、/root/svccs/memory/cycles.jsonに、requests・unreachable・per_request(unreachable÷requests、小数第2位)を書きます。
/root/svccs/memory/mem.pyにhandle_acyclic(req)を作成します。svc.handle_cyclic(req)と同じ値を返しますが、循環を作りません(子 → 親をweakrefで)。採点ツールは、GCを無効にしたまま何回も呼び出し、gc.collect()が0かどうかを確認します。
同じファイルにmeasure(handler, reqs)を、下の「測定のルール」のとおりに作成します。リクエストのリストを、[base[i % len(base)] for i in range(20000)](base = svc.load_requests())で延ばして、/root/svccs/memory/pause.jsonに、{"cyclic": measure(svc.handle_cyclic, …), "acyclic": measure(mem.handle_acyclic, …)}を書きます。
svcを読み込んだプロセスで、gc.collect()を3回実行した中でもっとも短い時間(ms)、gc.freeze()の直後のgc.get_freeze_count()、再びgc.collect()を3回実行した中でもっとも短い時間を測り、gc.unfreeze()します。/root/svccs/memory/freeze.jsonに、collect_ms_before・freeze_count・collect_ms_afterとして書きます。
同じファイルに、deep_size(obj)(dictのキー・値と、list・tuple・set・frozensetの要素をたどりながら、異なるオブジェクト(idを基準)ごとにsys.getsizeofを足した値)、属性a・b・c・dの4つを持つPlainPoint(a, b, c, d)と、同じ属性を__slots__で定義したSlotPoint(a, b, c, d)、per_object_bytes(cls, n=100000)(tracemallocを有効にし、cls(0, 0, 0, 0)をn個のリストにした前後のget_traced_memory()[0]の差÷n、小数第1位)を作成します。json.loadで読んだsessions.jsonについて、/root/svccs/memory/sizes.jsonに、shallow(getsizeof)・deep・plain_getsizeof・slots_getsizeof(それぞれ(0, 0, 0, 0)のインスタンス1つのgetsizeof)・plain_per_object・slots_per_objectを書きます。
svcを読み込む前にtracemalloc.start()を実行し、handle_leakyでリクエストの最初の500件を流したあとでスナップショット、次の2,000件(インデックス500–2,499)を流したあとでスナップショットを撮ります。compare_to(앞 스냅숏, "lineno")の最初の項目を、/root/svccs/memory/leak.jsonに、file(ファイル名のみ)・line・size_diff_kb(size_diff÷1024、小数第1位)・count_diffとして書きます(コード内の韓国語は「前のスナップショット」を意味する語です)。
同じファイルにhandle_fixed(req)を作成します。svc.handle_leakyと同じ値を返しますが、キャッシュは最大1,000個に制限します(あふれたら古いものから捨てる)。tracemallocを有効にし、2つのハンドラーそれぞれについて、リクエストの最初の1,500件でウォームアップしたあと、次の1,500件の間にget_traced_memory()[0]が増えた量(KB、小数第1位)を測り、/root/svccs/memory/fix.jsonに、requests_measured(1500)・leaky_growth_kb・fixed_growth_kb・leak_line(ステップ7の「ファイル:行」)を書きます。

測定のルール

시작 전에 gc.collect() 한 번. gc.callbacks 에 콜백을 넣어 phase "start" 에서 시각을 적고
"stop" 에서 그 차이를 일시정지 하나로 기록한다. 요청마다 handler(req) 앞뒤를 perf_counter 로 잰다.
끝나면 콜백을 뺀다(예외가 나도 — try/finally).
돌려줄 것: requests · collections(일시정지 개수) · gc_pause_ms_total · gc_pause_ms_max(소수 셋째 자리)
          total_ms(요청 지연의 합, 소수 셋째 자리)
          p50_ms · p99_ms(지연을 정렬한 목록의 [int(n×0.5)] · [int(n×0.99)] 번째, 소수 넷째 자리)

このコードブロックの韓国語の説明は、順に、開始前にgc.collect()を1回行い、gc.callbacksにコールバックを入れて、phaseがstartのときに時刻を記録し、stopのときにその差を一時停止1件として記録すること、リクエストごとにhandler(req)の前後をperf_counterで測ること、終わったらコールバックを外すこと(例外が出てもtry/finallyで)、返す値はrequests・collections(一時停止の件数)・gc_pause_ms_total・gc_pause_ms_max(小数第3位)、total_ms(リクエスト遅延の合計、小数第3位)、p50_msとp99_ms(遅延をソートしたリストの[int(n×0.5)]と[int(n×0.99)]の位置の値、小数第4位)であること、を述べています。

参考

採点ツールはmem.pyを読み込みます。結果のJSONを作るコードは、if __name__ == "__main__":の下か、別のスクリプトに置いてください。
GCとtracemallocの数字は、そのプロセスがすでに何を読み込んでいるかによって変わります。ステップごとに、新しいpython3プロセスで、指示した順序で測ってください。
よくある間違い: getsizeof 1つでコンテナ全体のサイズを書くこと、スナップショット1つのもっとも大きい行を犯人に指名すること、リクエスト全体の時間をGCの一時停止として書くこと、上限を大きく取りすぎて、直したあとも増加が残ること。
出力物はセッションが終わると消えます。必要なら別に保管してください。

このPodのGC設定を出力する

/root/svccs/memory/gcinfo.jsonに、python・threshold・gc_enabledを、このPodのpython3で出力して書いてください。

gc.get_threshold()はタプルを返すので、リストに変えて書きます。しきい値はバージョンごとに異なるので、ドキュメントの数字ではなく、このインタープリターで出力した値が基準です。

参照カウントでは消えないゴミを数える

svc.handle_cyclicをGCを無効にしたまま200回呼び出したあと、gc.collect()が回収した数を、/root/svccs/memory/cycles.jsonにrequests・unreachable・per_requestとして書いてください。

循環のないオブジェクトは、リクエストが終わった瞬間に参照カウントが0になって消えるので、GCを無効にしておけば、残るのは循環だけです。開始前にgc.collect()で以前のゴミを先に片付けておかないと、これらのリクエストが残したものだけを数えられません。GCを有効にしたまま実行すると、途中の自動収集が一部を持っていきます。

weakrefで循環を断ち切る

/root/svccs/memory/mem.pyにhandle_acyclic(req)を作成してください。svc.handle_cyclicと同じ値で、循環はありません。採点ツールは、別のリクエストで値を突き合わせ、GCを無効にしたまま実行したあと、gc.collect()が0かどうかを確認します。

親 → 子(childrenのリスト)は強い参照のままにして、子 → 親だけをweakref.ref(parent)で持てば、循環が消えます。経路をさかのぼるときは、弱い参照を呼び出して(ref())親を得ます。ルートは、関数が終わるまでローカル変数が握っているので、途中で消えません。

GCの一時停止がp99を作る

mem.pyに、測定のルールどおりmeasure(handler, reqs)を作成し、2万リクエストで2つのハンドラーを測って、/root/svccs/memory/pause.jsonにcyclic・acyclicを書いてください。採点ツールは、あなたのmeasureを、自分のハンドラー(収集のないもの・gc.collectを呼び出すもの)で再び呼び出します。

一時停止は、コールバックのstartとstopの間の時間であり、リクエスト全体の時間ではありません。収集は割り当て数で引き起こされるので、循環を作るほうだけが頻繁に動きます。収集がリクエストの1%超にかかると、p99がそのコストを引き受けます。

gc.freezeで長く生きるオブジェクトを除外しておく

svcを読み込んだプロセスで、freezeの前後の完全な収集の時間とfreeze_countを測り、/root/svccs/memory/freeze.jsonにcollect_ms_before・freeze_count・collect_ms_afterとして書いてください。

freezeは「今」追跡中のオブジェクトを永続世代に移します。そのため、大きな静的データ(svcのCATALOG)を作ったあとに呼び出さないと効果がありません。時間は揺らぐので、3回のうちもっとも短い値を使います。

getsizeofは浅い: 深いサイズと__slots__

mem.pyにdeep_size・PlainPoint・SlotPoint・per_object_bytesを作成し、/root/svccs/memory/sizes.jsonを書いてください。採点ツールは、共有と循環が混ざった別のオブジェクトで、deep_sizeを突き合わせます。

getsizeofは、辞書のキーと値を数えません。たどっていきながら、idですでに数えたオブジェクトを飛ばす必要があり、そうすれば、共有された文字列を2回数えず、自分自身を含むリストでも処理が終わります。__slots__のインスタンスは、getsizeofではより大きく見えることがあるので、tracemallocでオブジェクトを10万個作って測った値を信じてください。

もっとも大きい行ではなく、もっとも多く増えた行

svcを読み込む前にtracemallocを有効にし、handle_leakyで500件ウォームアップしたあとと、さらに2,000件流したあとのスナップショットの差から、最初の行を、/root/svccs/memory/leak.jsonにfile・line・size_diff_kb・count_diffとして書いてください。

スナップショット1つのstatisticsの一番上は「もっとも多く占めている」行なので、起動時に1回作った大きなデータが出てきます。リークは時間が経つにつれて「増えていく」ものなので、compare_toで2つのスナップショットの差を見ます。filenameはフルパスなので、os.path.basenameで名前だけを残します。

上限付きのキャッシュで直して、増加が消えたかを測る

mem.pyに、キャッシュを最大1,000個に制限したhandle_fixed(req)を作成し、2つのハンドラーの増加量を測って、/root/svccs/memory/fix.jsonにrequests_measured・leaky_growth_kb・fixed_growth_kb・leak_lineを書いてください。採点ツールは、新しいリクエストidで、あなたのhandle_fixedを新しいプロセスで測り直します。

二度と来ないキーで埋めるキャッシュは、上限がなければリークです。OrderedDictに入れ、長さが上限を超えたら、popitem(last=False)でもっとも古いものを捨てれば十分です。ウォームアップのリクエスト数が上限より少ないと、測定区間でキャッシュがまだ成長していて、増加が残っているように見えます。採点ツールは、新しいリクエストidで2,000件ウォームアップしたあと、4,000件を測ります。