CPython の GC チューニング

ISUCON は Go で参戦しているんだけど、複数のチームが Python で予選通過したらしいので、応援のために Tips を公開していこうと思う。

CPython の GC について
統計情報を出力する
第一世代GCの間隔を調整する
Out of Band GC
循環参照を見つけて対処する

CPython の GC について

CPython のGCは参照カウント＋循環参照コレクタだ。そして参照カウント方式は(幾つかの欠点はあるものの)Webアプリのボトルネックになったりはしにくい。なのでGCチューニングの基本は次のようになる。

循環参照を避ける
循環参照コレクタの呼び出しタイミングを制御する

循環参照コレクタは、生きているオブジェクトの数がある程度増えると第一世代が実行され、第一世代が一定回数実行されると第二世代が、第二世代が一定回数実行されると第三世代が実行される。

各世代を実行するしきい値は次のAPIで参照・設定が可能だ。

In [1]: import gc

In [2]: print(gc.get_threshold())
(700, 10, 10)

In [3]: gc.set_threshold(1000, 10, 10)

In [4]: print(gc.get_threshold())
(1000, 10, 10)

デフォルトでは、700個オブジェクトが増えた時点で第一世代GCが起動し、第二世代と第三世代は前世代GCが10回起動する度に実行される。

重要なのは、第一世代GCが起動する条件が「循環参照してるオブジェクト」ではなく「生きてるオブジェクト」が増えた時だということだ。*1

例えば複雑なJSONを処理するプログラムでは、JSONは循環する構造を持っていないにもかかわらず、JSONデコード中に何度も循環参照コレクタが起動してスピードを落としてしまう。

統計情報を出力する

プログラムのエントリーポイントなどで、GCが統計情報を出力するようにしておく。

import gc
gc.set_debug(gc.DEBUG_STATS)

これで標準エラー出力に、GCが実行される度に統計情報が出力される。

import gc
gc.set_debug(gc.DEBUG_STATS)

while True:
    d = {}
    d['key'] = d

...
gc: collecting generation 1...
gc: objects in each generation: 782 11 5083
gc: done, 791 unreachable, 0 uncollectable, 0.0001s elapsed
...

最初の行は、世代を0からカウントしているので1と表示されているので、第二世代のGCを開始していることを示している。

次の行は、GC実行前の各世代のオブジェクト数で、若いオブジェクトが782、第一世代GCを生き残ったオブジェクトが11、第二世代GCを生き残ったオブジェクトが5083あることを示している。

次の行で、 791 個のオブジェクトが unreachable (到達不能) で消されている。 0 uncollectable はすべての到達不能オブジェクトが回収できたことを示している。*2

第一世代GCの間隔を調整する

Web アプリのような場合、リクエストごとにたくさんのオブジェクトを作っては捨てる。 Python の場合その殆どがリクエストの処理の終了時に参照カウントで自動的に回収されるはずだが、第一世代GCのしきい値が低いとそれらのオブジェクトのために循環参照GCが実行されてしまう。

本物のWebアプリの代わりに次のような簡単なサンプルを見てみる。GCの動作が見やすいようにしきい値は調整している。

import gc
import sys
gc.set_debug(gc.DEBUG_STATS)
gc.set_threshold(500, 2, 2)


def app():
    x = []
    for i in range(2000):
        x.append([])


def main():
    for i in range(5):
        print('start:', i, file=sys.stderr)
        app()
        print('end', file=sys.stderr)


main()

...
start: 2
gc: collecting generation 0...
gc: objects in each generation: 583 0 4759
gc: done, 0.0000s elapsed
gc: collecting generation 1...
gc: objects in each generation: 504 581 4759
gc: done, 0.0001s elapsed
gc: collecting generation 2...
gc: objects in each generation: 504 0 5842
gc: done, 0.0013s elapsed
end
start: 3
gc: collecting generation 0...
gc: objects in each generation: 576 0 4750
gc: done, 0.0000s elapsed
...

このログを見ると、次の2つのことがわかる

循環参照コレクタが1つもオブジェクトを開放できていない (N unreachable, が表示されていない)
app() の呼び出しが終わるごとに 1000 個前後のオブジェクトが (参照カウンタによって) 消えてる

このことから、第一世代GCのしきい値を倍の2000程度にすれば、循環参照コレクタの起動を抑制できることがわかる。

import gc
import sys
gc.set_debug(gc.DEBUG_STATS)
gc.set_threshold(2000, 2, 2)
# ...以下同じ

start: 0
gc: collecting generation 1...
gc: objects in each generation: 2041 4417 0
gc: done, 0.0009s elapsed
end
start: 1
end
start: 2
end
start: 3
end
...

最初だけ、多分 Python 起動時に1000個以上のオブジェクトを確保していたためにGCが起動しているが、その後のリクエストの処理では一切循環参照コレクタが実行されていないことがわかる。

Out of Band GC

循環参照オブジェクトがあって完全には循環参照コレクタを抑止できない場合もある。

その場合、例えば GC を止める・Ruby ウェブアプリケーションの高速化にあるように、レスポンスを返したあと、次のリクエストを受け取る前に循環参照コレクタを実行することで、GCの実行時間がレスポンスタイムに与える影響を最小限にすることができる。 (=Out of Band GC, OOBGC)

純粋な wsgi アプリケーションは関数呼び出し=アプリケーションの実行であるため凝ったことをしないと OOBGC ができないが、アプリケーションサーバーによっては OOBGC を可能にする hook を提供している。

特に uWSGI の場合、 uwsgi プロトコルで keep-alive なしで nginx の配下に置くのが一般的なので、OOBGCが完了したプロセスが次のリクエストを accept() することができるので効果的だ。

# wsgi.py
import gc
import uwsgi
import myapp


application = myapp.get_app()

gc.set_threshold(10000, 10, 10)
uwsgi.after_req_hook = lambda: gc.collect(1)

循環参照を見つけて対処する

gc.DEBUG_STATS により、GCの実行時間が長く、また大量の unreachable が検出されている場合は、循環参照が原因だ。その場合は個別に循環参照を潰していく必要がある。

まずは循環参照を見つけるために、 gc.DEBUG_COLLECTABLE を使って、循環参照に入っていたオブジェクトの型を見る。

import gc
gc.set_debug(gc.DEBUG_STATS | gc.DEBUG_COLLECTABLE)

for _ in range(10000):
    d = {}
    d['key'] = d

...
gc: done, 780 unreachable, 0 uncollectable, 0.0617s elapsed
gc: collecting generation 2...
gc: objects in each generation: 365 11 4750
gc: collectable <dict 0x7fe7be594d08>
gc: collectable <dict 0x7fe7be58f048>
gc: collectable <dict 0x7fe7be58c9c8>
gc: collectable <dict 0x7fe7be589ac8>
gc: collectable <dict 0x7fe7be589a88>
gc: collectable <dict 0x7fe7be589a48>
gc: collectable <dict 0x7fe7be589a08>
gc: collectable <dict 0x7fe7be5899c8>
gc: collectable <dict 0x7fe7be589988>
gc: collectable <dict 0x7fe7be589948>
gc: collectable <dict 0x7fe7be589908>
...

型だけではわからない場合、 gc.DEBUG_SAVEALL を使う。このオプションを使うと本来回収されるオブジェクトを gc.garbage というリストに入れてくれるので、コールバックで gc.garbage の中の注目してる型のオブジェクトの情報を表示して、 gc.garbage をクリアしてやる。

import sys
import gc
gc.set_debug(gc.DEBUG_STATS | gc.DEBUG_SAVEALL)


@gc.callbacks.append
def after_gc(phase, info):
    if phase == "start":
        return
    for o in gc.garbage:
        if isinstance(o, dict):
            print("gc dict keys=", list(o), file=sys.stderr)
    gc.garbage.clear()


for _ in range(10000):
    d = {}
    d['key'] = d

...
gc dict: ['key']
gc dict: ['key']
gc dict: ['key']
gc dict: ['key']
gc dict: ['key']
...

これで、 'key' というキーを持つ dict が原因だとわかった。gc.garbage から見つけたオブジェクトがどうやって循環参照に加担しているかを調べるために、他にも gc.get_referrers() や gc.get_referents() がある。

さて、これで問題の dict が見つかった。循環参照を壊してやるには、使い終わった dict の .clear() メソッドを呼べばいい。

import sys
import gc
gc.set_debug(gc.DEBUG_STATS)


for _ in range(10000):
    d = {}
    d['key'] = d
    ...
    d.clear()

GC方式の違いから、Python は Ruby に比べてWebアプリケーションでGCの時間がパフォーマンスに影響することは少ないが、大きいXMLを扱うアプリケーションをチューニングする場合や、数msを気にするチューニングの場合はこのような手段でGCのチューニングができる。

*1:具体的には、文字列や整数のような循環参照を作らないオブジェクトは除く、循環参照を作り得るオブジェクトだけを管理している

*2:Python3.4までは __del__ メソッドがあるだけで回収できなかった