GAミント至上主義

Web Monomaniacal Developer.

Pythonで作ったプロセスのメモリ肥大化の原因調査から解決まで

2017/9/25 追記変更

公式ライブラリの大幅アップデートがあり、0.28.3ではメモリリークがなくなったが別の問題が発生し、嫌になったので、Cloud Pub/Subでのsubscribe処理はあきらめRedis Pub/Subに戻した

pypi.python.org

uyamazak.hatenablog.com

元記事

Dockerで作っているoceanusでは、WEBサーバーだけでなく、Pythonで書いた常時稼働プロセスのコンテナが複数ある。

GitHub - uyamazak/oceanus: Send big data to Google BigQuery and redis pub/sub using HTTP beacons simply

r2bq

Redis to BigQueryの略。名前の通り、Redisのリストから取り出して、BigQueryに書き込む

table-manager

必要なBigQueryのテーブルがあるか確認して、無ければ作成する


どちらも、Dockerの1コンテナ1プロセスに乗っ取って分けたもので、コードも短くシンプルなのにメモリ使用量が肥大化してしまう問題があった。

起動直後は40~50MB、数日立つと100MBを超えてしまうこともあった。


GKE上で動かしているコンテナ(pod)ごとのメモリは下記コマンドで簡単に取得できる。

% kubectl top pod
NAME                             CPU(cores)   MEMORY(bytes)
r2bq-1477107478-n1eia            22m          61Mi
table-manager-1307035889-bco9o   13m          78Mi


最初はWhile無限ループの最後でdelだけしてみたけど変わらない。

その後、検索して見つけたgc.collect()を追加した。

gcは標準モジュールなのでインストールは必要ない。

import gc
while keep_processing:

    for site in OCEANUS_SITES:
        r2bq = redis2bqSerial(site)
        try:
            r2bq.main()
        except TimeoutError:
            logger.critical("timeout error exit")
            r2bq.clean_up()

        del site
        del r2bq
        gc.collect()
    sleep(SERIAL_INTERVAL_SECOND)

これを追加しただけで、劇的にメモリ使用量が減った。

% kc top pod  
NAME                             CPU(cores)   MEMORY(bytes)
r2bq-1043652369-7smpb            40m          16Mi
table-manager-1386334450-0x09y   55m          17Mi

どちらも40MB以上から17MB程度と半分以上の削減効果があった。まだ起動して時間が立ってないので持続的な効果はしばらく様子見だけど、これだけでも価値があると思う。

単純にメモリだけで考えれば、同じインスタンスで2倍のコンテナを起動できるようになる。実際はCPUの方が足りなくなる場合がほとんどだけど。

While Trueなどの無限ループを使ったプログラムは、Dockerを使う前はcronでなんとかしていたので書いたことがなく、まだまだ初心者。gc.collect()を使わずとも内部の書き方で減らせるところがあるかもしれない。

Debug Hacks -デバッグを極めるテクニック&ツール

Debug Hacks -デバッグを極めるテクニック&ツール

20時間後経過

上記コンテナを起動して20時間程度経ったので、様子を見てみる

% kc top pod
NAME                             CPU(cores)   MEMORY(bytes)
r2bq-1043652369-7smpb            41m          23Mi
table-manager-1466157299-a5h7p   51m          36Mi

起動時から1.5倍以上にメモリ仕様が増えてしまっていた。
やはりコード実行中に何かお漏らししているらしい。
作成したインスタンスごとdelしてるけど、それでも残ってしまうものがあるようだ。

pipでobjgraphをインストールし(Dockerを使っているのでDockerfileに追記して再build)

増加を表示してくれるobjgraph.show_growth()を追加し一旦ローカルのDockerでテストしてみることにした。

import gc
import objgraph
while True:
    for site in OCEANUS_SITES:
        # logger.debug("check:{}".format(site["site_name"]))
        tm = TableManager(site)
        tm.main()
        del tm
        del site
        gc.collect()
    objgraph.show_growth()
    sleep(INTERVAL_SECOND)

起動すると標準出力で下記のように出してくれる。

function                       4364     +4364
dict                           3960     +3960
tuple                          2865     +2865
weakref                        1502     +1502
wrapper_descriptor             1112     +1112
type                            922      +922
method_descriptor               845      +845
builtin_function_or_method      838      +838
getset_descriptor               729      +729
list                            689      +689

しばらくこれで動かしっぱなしにして、どのオブジェクトが増えてるかを確認してみる。

解決編

原因はGoogle公式のBigQueryのモジュールだった。

GitHub - tylertreat/BigQuery-Python: Simple Python client for interacting with Google BigQuery.

残念ながらobjgraphやtracemallocの結果ではわからず、他にもメモリリークしているプロセスがあり、それと共通して使っているライブラリが該当のモジュールだった。

DockerやKubernetes環境でのメモリの確認方法はこちら記事を参照。

get_clientを呼び出す度に、delや、gc.collect()で消せない領域を使ってしまっているのかも。

ループ内では呼び出さず、ループの前に一度だけ作成し、クラスに渡すことで、メモリの使用量の増加や増減がピタッと止まった。

再現できる最小のコードができたら、報告してみようと思う。

bq_client = get_client(json_key_file=JSON_KEY_FILE, readonly=False)
while True:
    for site in OCEANUS_SITES:
        # logger.debug("check:{}".format(site["site_name"]))
        tm = TableManager(site, bq_client)
        tm.main()
        tm = None
        site = None
        del tm
        del site
        gc.collect()
    sleep(INTERVAL_SECOND)

リトライ間隔の重要性

この記事を読んで、定期的な同期時や、エラーからの復帰時のリトライで負荷の増大や偏りが出てしまうことを知る。自業自得のDDosって文言にちょっと釣られたけど読んでみて納得。

googlecloudplatform-japan.blogspot.jp


早速リトライ時の以下の条件でスリープ時間を変えるのをpythonで書いて、oceanusでリトライする時に使ってみた。

  • リトライの回数によって、待機時間を倍増させる
  • 待機時間にジッター(ゆらぎ)を加える
import random
from sys import exit


def retry_wait(retry_num,
               base_seconds=3,
               jitter=0.1,
               wait_seconds_limit=30):
    """
    http://googlecloudplatform-japan.blogspot.jp/2016/11/ddos-cre.html
    """
    if retry_num <= 0:
        retry_num = 1
    jitter_rate = random.uniform(1 - jitter, 1 + jitter)
    wait_seconds = base_seconds * retry_num * jitter_rate
    if wait_seconds > wait_seconds_limit:
        wait_seconds = wait_seconds_limit

    sleep(wait_seconds)

プラスマイナスのゆらぎを持たせる処理はちょっと悩んだけど、random.uniformを使って書いてみた。

random.uniform(1 - jitter, 1 + jitter)

これでjitterが0.2だったら0.8から1.2の間の乱数が出てくるので、それをベースとなる時間にかけて使う。


今回はサーバー間(Redis、BigQuery)に繋げる処理で使い、同時に動くかもしれないプロセス数は最大で10程度を想定しているけど、クライアント数が多くなるスマホアプリの場合はこういった工夫が重要になると思う。

How Google Works (ハウ・グーグル・ワークス)  ―私たちの働き方とマネジメント

How Google Works (ハウ・グーグル・ワークス) ―私たちの働き方とマネジメント

GCPでログの内容によってアラートを送信する設定方法

oceanusでは、Google Cloud Platform(GCP)のGoogle Container Engine(GKE)を使っていますが、これらを使うとほぼ何も設定せずに、アプリ側で標準出力へのエラーを出すだけで、Google側でログを集めてくれます。

サーバーを増やすごとにそれぞれにfluentdを入れて設定するのは手間なので、非常に楽。内部的にはGoogle仕様のfluentdが動いてる模様。

しかもWEB画面でほぼリアルタイムに閲覧、検索ができるのも便利。

さらにメールなどでの通知も簡単に設定できました。

GCPの管理画面のメニューからログをクリック

f:id:uyamazak:20161117104109p:plain

アラートを出したい条件を設定して指標を作成

f:id:uyamazak:20161117104122p:plain
自分で出したものはすべてERROR扱いされてしまうようなので、Container Engineに絞り、テキスト検索で「CRITICAL」を絞り込んでます。

作成した指標からアラート作成

f:id:uyamazak:20161117104125p:plain
Stack Driverの画面に飛びます。

通知条件、通知先を指定。

f:id:uyamazak:20161117104128p:plain

何分に何回以上、以下などを指定できます。今回はCRITICALなものなので、5分間に1回でもあったらとしました。

通知先は、メールの他、SMSやSlack、WebHookもあるので、ほぼなんでも対応できそう。

これで、エラー以外でも普段頻繁に出してる正常なログ(書き込み成功など)が減った時なども指標に利用できそうです。




Stack Driverは有料化され今はお試し期間中だけど、無料枠で十分使えるかはこれから調べる必要がありそう。

クラウド開発徹底攻略 (WEB+DB PRESS plus)

クラウド開発徹底攻略 (WEB+DB PRESS plus)