MALLOC_ARENA_MAX=2を足すと、スレッド用のアリーナは15個から1個に減りました。ただ、修正後に記録できているのは起動から約20分までで、長時間たってもメモリが増えなくなったかはまだ確かめられていません。
お疲れ様です！IT業界で働くアライグマです！
個人開発している開発関連ニュースのキュレーションサービス「DevPick」のバックエンドは、FastAPIをuvicornで動かしています。前回、メモリ不足でワーカーが数秒止まり、親プロセスに強制終了されていた件を書き、根本はメモリの足りなさだと締めくくりました。この記事はその続きで、ワーカー自身のメモリがなぜ増え続けていたのかを突き止めるまでの順番と、まだ確かめられていないことを書きます。
起動後にワーカーのメモリが増え続け、頭打ちにならなかった
前回の対策の後も、スワップは増え続けていた
DevPickの本番は、メモリ971MBの小さなVPSで動いています。前回の「uvicornのワーカーが「Child process died」で1日10回落ちる原因」では、ワーカーが強制終了されるまでの猶予を5秒から30秒に延ばしました。同じ日に別の作業として、使っていないとみられるプロセスを止めるなどして、スワップ（メモリに入りきらないデータを一時的にディスクへ追い出す領域）の使用量を約0.55GBまで減らしています。
それでも、翌朝にはスワップの使用量が911MBまで戻っていました。サーバー全体のメモリが足りないのは確かでも、その中で何が増えているのかは分かっていませんでした。そこで、uvicornのワーカー自身のメモリが、起動してから増え続けるのか、ある量で止まるのかを確かめることにしました。
ワーカーのメモリを10分おきにログへ残すようにした
この確認には、時間を追った記録が必要でした。DevPickはデプロイのたびにワーカーが入れ替わるので、ある瞬間の値を1回見ただけでは、増え続けているのか、起動直後の一時的な山なのかを区別できないからです。
そこで、各ワーカーが起動直後と以後10分ごとに、自分のメモリの量をjournal（systemdのログ）へ1行書くようにしました。値はLinuxの/proc/self/statusから読んでいます。実際の行は次のような形です。
worker_memory pid=86858 uptime_s=600 VmRSS_kB=58992 VmSwap_kB=67496 VmHWM_kB=124220
worker_memory pid=86858 uptime_s=43800 VmRSS_kB=81704 VmSwap_kB=174652 VmHWM_kB=186084VmRSSは実際にメモリに載っている量、VmSwapはスワップへ追い出された量、VmHWMはVmRSSのこれまでの最大値です。メモリが足りないサーバーでは、使っている量が増えても、その分がスワップへ追い出されてVmRSSだけを見ると減って見えることがあります。そのため、判定にはVmRSSとVmSwapの合計を使いました。
7時間以上動いた6つのワーカーすべてで、最後の値が最大だった
記録を始めて約1日半たった時点で、それまでのログを集計すると、7時間以上動いた6つのワーカーすべてで、VmRSSとVmSwapの合計は、ワーカーが入れ替わる直前の値が最大でした（以下、MBはkBを1,000で割った値です）。
| ワーカー | 動いていた時間 | 起動直後 | 入れ替わる直前 |
|---|---|---|---|
| 1 | 12.7時間 | 118MB | 380MB |
| 2 | 12.7時間 | 115MB | 327MB |
| 3 | 11.2時間 | 118MB | 373MB |
| 4 | 11.2時間 | 115MB | 276MB |
| 5 | 7.7時間 | 120MB | 400MB |
| 6 | 7.7時間 | 115MB | 277MB |
1つ目のワーカーを3時間ごとに追うと、起動直後の約120MBから、3時間後に322MB、6時間後に364MB、9時間後に331MB、12.7時間後に380MBでした。最初の数時間で大きく増え、その後も途中で少し下がりながら増えています。入れ替わる直前は、実際にメモリに載っていたのが118MBで、スワップに追い出されていたのが262MBでした。増えた分の大半はスワップに回っていたことになります。
なお、24時間動き続けたワーカーは1つもありませんでした。デプロイで約12時間ごとに入れ替わっていたためで、入れ替えが無ければ、さらに増えていたと考えられます。
IT女子 アラ美
ITアライグマ疑っていたPython側のキャッシュには上限があった
長く動くPythonのプロセスで、まず疑うのは「上限の無い保持」
起動してからメモリが増え続けると聞くと、まず思い浮かぶのはメモリリーク、つまり使い終わったデータがどこかに残り続けることです。長く動くPythonのプロセスでよくあるのは、次のような「上限の無い保持」です。
- 結果を覚えておくキャッシュやメモ化（
functools.lru_cacheなど）に、件数の上限が無い - 定期ジョブの結果を、どこかの辞書やリストに追加し続けている
- HTTPクライアントを呼び出しのたびに作り、閉じずに捨てている
調べ始めた時点では、これらを候補に挙げていました。あわせて、Pythonのメモリ確保を追跡する標準ライブラリのtracemallocで、時間をおいたスナップショットを比べて裏付ける案もメモしていました。
コードを探すと、キャッシュは1件だけを持つ作りだった
最初に、キャッシュやメモ化をしている箇所をコードから洗い出しました。探し方は単純で、次のようなgrepです。
# キャッシュ用のデコレータやライブラリ、モジュール直下のキャッシュ変数を探す
grep -rnE "lru_cache|functools\.cache|cachetools|TTLCache" app
grep -rnE "^_[A-Za-z_]*(cache|CACHE|memo)[A-Za-z_]*\s*[:=]" app見つかったものを1つずつ読むと、どれも保持する量に上限がありました。
- サイトマップ、媒体ごとの統計、話題の集計に使うキャッシュは、最新の結果を1件だけ持ち、新しい結果で置き換える作り
- 同じ画像を同時に二重で取りに行かないよう画像ごとに作るロックは、使っている処理がいなくなったら捨てる作り
- フィードや画像を取りに行くHTTPクライアントは、
async withで使うたびに作って閉じる作り
件数が増えていくキャッシュは見当たらず、コードを読んだ範囲では、半日足らずで160〜280MB増える理由が見つかりませんでした。
Pythonの中だけを見ても、プロセスのメモリは説明しきれない
ここでtracemallocには進まず、プロセス全体のメモリが何に使われているかを、OSの側から見ることにしました。
OSの側から見る意味は、tracemallocが数える範囲にあります。tracemallocが数えるのは、Pythonが確保して使っているメモリです。一方、OSから見たプロセスのメモリには、Pythonがいったん解放したあとも、下の層のメモリ管理が手元に抱えたままの領域も含まれます。その差の部分で増えていると、Pythonの中をいくら調べても原因は出てきません。
IT女子 アラ美ITアライグマsmapsで内訳を見ると、スレッド用のアリーナが223MBを占めていた
smapsは、プロセスのメモリを領域ごとに並べた一覧
Linuxでは、/proc/<pid>/smapsというファイルに、プロセスが使っているメモリが領域ごとに並んでいます。領域ごとに、アドレスの範囲、読み書きの権限、何の領域か（共有ライブラリのファイル名や[heap]など）、そして実際にメモリに載っている量（Rss）とスワップへ追い出された量（Swap）が書かれています。
7f3a2c000000-7f3a2e9c1000 rw-p 00000000 00:00 0
Size: 42756 kB
Rss: 18204 kB
Swap: 23840 kB
...名前の欄が空の領域は、ファイルと結び付いていない「匿名」のメモリで、プログラムが自分で確保したデータはここに入ります。10月31日の朝、修正前の本番ワーカー2つについて、このsmapsを読み、種類ごとにRssとSwapを合計しました。
glibcは、スレッドごとにmallocのアリーナを作る
集計の話の前に、今回の主役を説明します。Pythonの大きめのオブジェクトや、C言語で書かれた拡張モジュールが使うメモリは、最終的にglibcのmallocから確保されます。
mallocは、複数のスレッドが同時にメモリを確保するとき、互いに待たなくて済むように、スレッドごとに別の置き場を用意します。この置き場をアリーナと呼びます。64ビットのLinuxでは、アリーナの数の上限は既定でCPUのコア数の8倍で、2コアのDevPickのVPSなら16個です。スレッド用のアリーナは、1つあたり64MBの範囲を先に予約し、使う分だけを読み書きできるようにします。
困るのは、アリーナの中で解放された部分が、OSへ返されにくいことです。大量に確保して解放しても、間に使用中の小さな領域が残っていると、空いた部分はアリーナが抱えたままになります。これが断片化で、プロセスのメモリとしては減りません。DevPickのワーカーは、同期処理を逃がすスレッドプールや定期ジョブ（APScheduler）のスレッドを使っているので、アリーナが作られる条件はそろっていました。
64MBちょうどの塊を探しても、使われているアリーナは見つからなかった
最初の集計では、アリーナは64MB単位だからと、名前の無い領域のうち大きさが64MB前後のものを数えました。すると、そうした領域は5個と8個見つかったものの、実際に使われている量は合計しても1MBに届きませんでした。
使われている量は、大きさが1MB以上の名前の無い領域にまとまっていました。定期ジョブも動かす側のワーカーでは、この種類の合計がメモリに79MB、スワップに251MBです。ただ、この分け方では、それがアリーナなのか、ほかの用途で確保された領域なのかを区別できませんでした。
使っている部分と予約だけの部分を合わせて数えると、15個・223MBだった
見つからなかった理由は、アリーナのsmapsでの見え方にありました。使用中のアリーナは、64MBの境目から始まる読み書きできる部分（rw-p）と、その直後に続く、まだ使っていない予約の部分（アクセス不可の---p）の2つの領域に分かれて見えます。どちらか片方だけを見ても64MBにはなりません。
そこで、この2つが並んでいて合計がちょうど64MBになる組を、スレッド用のアリーナとして数え直しました。
import re
import sys
ARENA = 64 * 1024 * 1024 # glibcがスレッド用アリーナ1つに予約する大きさ（64ビット環境）
rows = [] # [開始, 終了, 権限, 名前, Rss(kB), Swap(kB)]
for line in sys.stdin:
m = re.match(r"^([0-9a-f]+)-([0-9a-f]+) (\S+) \S+ \S+ \S+\s*(.*)$", line)
if m:
rows.append([int(m[1], 16), int(m[2], 16), m[3], m[4].strip(), 0, 0])
elif line.startswith("Rss:"):
rows[-1][4] = int(line.split()[1])
elif line.startswith("Swap:"):
rows[-1][5] = int(line.split()[1])
count = used_kb = 0
for cur, nxt in zip(rows, rows[1:]):
start, end, perm, name, rss, swap = cur
# 名前の無い読み書きできる領域が64MBの境目から始まり、
# 直後の---p（予約だけの領域）と合わせてちょうど64MBなら、スレッド用アリーナとみなす
if (not name and perm.startswith("rw") and start % ARENA == 0
and nxt[0] == end and nxt[2] == "---p" and not nxt[3]
and nxt[1] - start == ARENA):
count += 1
used_kb += rss + swap
print(f"スレッド用アリーナ: {count}個, Rss+Swap {used_kb // 1024}MB")sudo cat /proc/<pid>/smaps | python3 arena_count.pyのように、ワーカーのsmapsを標準入力から渡して使います。
どちらのワーカーにも、上限に近い15個のアリーナができていた
数え直した結果は次のとおりです（この表の内訳はkBを1,024で割った値です）。
| ワーカー | メモリ＋スワップの合計 | スレッド用アリーナ | その他の名前の無い領域 | [heap] |
|---|---|---|---|---|
| 定期ジョブも動かす（起動から約11時間） | 約400MB | 15個・223MB | 107MB | 50MB |
| リクエストだけを処理する（起動から約12時間） | 約257MB | 15個・98MB | 97MB | 45MB |
どちらのワーカーにも、上限16個に近い15個のアリーナができていました。定期ジョブも動かす側では、合計約400MBのうち223MBがアリーナに載っています。一方、Pythonのオブジェクトなどが入る「その他の名前の無い領域」は、2つのワーカーで107MBと97MBで、差は小さいままでした。増えた分の大半は、Pythonのキャッシュではなく、glibcのアリーナに溜まっていたことになります。
IT女子 アラ美ITアライグマMALLOC_ARENA_MAX=2をsystemdのユニットに足した
アリーナの数は、環境変数MALLOC_ARENA_MAXで制限できる
glibcのアリーナの数の上限は、環境変数MALLOC_ARENA_MAXで変えられます。アリーナが少なければ、スレッドは少ない置き場を共有して使うので、断片化した空きを抱えたアリーナが増えていくことを防げます。DevPickでは、この値を2にしました。
この環境変数は、glibcがプロセスの起動時に読むものです。DevPickでは、uvicornを起動しているsystemdのユニットに書きました。ユニットで設定すれば、親のuvicornから子のワーカーへ、環境変数ごと引き継がれます。
# MALLOC_ARENA_MAX: glibcはスレッドごとにmallocアリーナを作り（2コアで最大16個）、断片化した分を
# OSへ返さないため、ワーカーのRSS+Swapが起動後に増え続けていた
Environment=MALLOC_ARENA_MAX=2
ExecStart=.../venv/bin/uvicorn app.main:app --host 127.0.0.1 --port 8000 --workers 2 --timeout-worker-healthcheck 30 --proxy-headers --forwarded-allow-ips 127.0.0.1本番用と初回セットアップ用、2つのユニットに同じ1行を足した
DevPickには、ユニットを書く場所が2つあります。リポジトリに置いた本番用のユニットと、サーバーを最初に用意するときにデプロイスクリプトが書き出すユニットです。この2つは、起動の仕方が同じになるよう揃えて管理しています。
そこで、修正では両方に同じ1行を足し、あわせてテストを2つ用意しました。1つは本番用のユニットに設定があることを確かめるもの、もう1つは2つのユニットの環境変数の行が一致していることを確かめるものです。運用の手順書にも、メモリの内訳と、再び増えたときの切り分け方を書き足しています。ユニット・デプロイスクリプト・テスト・手順書は、1つの修正としてまとめて本番に出しました。
def test_backend_unit_limits_glibc_malloc_arenas():
"""スレッドごとのmallocアリーナの断片化でワーカーのメモリが増え続けないよう上限を付ける"""
assert "Environment=MALLOC_ARENA_MAX=2" in BACKEND_UNIT.read_text().splitlines()本番への届け方は、前回の記事で作った仕組みがそのまま使えました。デプロイのたびにリポジトリのユニットと本番のユニットを比べ、違っていれば置き換えてバックエンドを再起動する仕組みです。そのため、ユニットに1行足すだけで、マージ後のデプロイで本番のワーカーに設定が届きます。
マージ前に手元で試すと、162MBが121MBになった
マージする前に、手元でも効果を確かめました。16本のスレッドで、大きさの違うデータの確保と解放を繰り返し、一部だけを残して断片化を起こす小さなスクリプトです。
import os
import re
from concurrent.futures import ThreadPoolExecutor
keep = []
def work(i):
# 寿命の違うデータを確保・解放し、一部だけを残して断片化を起こす
for _ in range(30):
tmp = [("x" * (200 + j % 500)).encode() for j in range(20000)]
keep.append(tmp[::997])
del tmp
with ThreadPoolExecutor(16) as ex:
list(ex.map(work, range(64)))
rss = int(re.search(r"VmRSS:\s+(\d+)", open("/proc/self/status").read())[1])
print(f"MALLOC_ARENA_MAX={os.environ.get('MALLOC_ARENA_MAX', 'unset')} VmRSS={rss // 1024}MB")上限を付けずに動かすと、スレッド用のアリーナが約15個でき、VmRSSは162MBでした。MALLOC_ARENA_MAX=2を付けて同じものを動かすと、121MBでした。スレッドが多いとアリーナが増え、その分メモリが膨らむことを、手元でも確かめられました。
IT女子 アラ美ITアライグマアリーナは15個から1個になったが、長時間の推移は記録できていない
デプロイ後のワーカーでは、スレッド用のアリーナが1個になった
修正は10月31日の9時35分にマージされ、9時46分ごろに新しいワーカー2つが起動しました。起動から約15分後に、まず設定が本当にワーカーに届いているかを確かめています。
# ワーカーの環境変数にMALLOC_ARENA_MAXが入っているか
sudo cat /proc/<pid>/environ | tr '\0' '\n' | grep MALLOC2つのワーカーともMALLOC_ARENA_MAX=2が入っていました。同じ時点のsmapsを先ほどの方法で数えると、次のとおりです。
| 時点 | スレッド用アリーナ | メモリ＋スワップの合計 |
|---|---|---|
| 修正前（起動から11〜12時間） | 15個・223MB／15個・98MB | 約400MB／約257MB |
| 修正後（起動から約15分） | 1個・9MB／1個・19MB | 約133MB／約156MB |
| 修正後（起動から20分） | （数えていない） | 約133MB／約161MB |
MALLOC_ARENA_MAX=2は、プロセス全体でアリーナを2つまでにする設定です。そのうち1つは[heap]として見えている最初のアリーナなので、スレッド用は1個で頭打ちになります。
起動から20分の値だけでは、効いたとは言えない
ただ、この表の修正後の数字は、起動から15〜20分のものです。修正前のワーカーも、起動から10〜20分の時点では約126〜248MBとばらついていました。修正後の約133〜161MBはこの幅に収まっていて、起動直後の値を比べても、効果があったかどうかは判断できません。
確かめるべきなのは、修正前と同じように何時間も動かしたあとで、メモリが増え続けるのか、どこかで止まるのかです。調査のときは、次のデプロイで入れ替わる前、約12時間生きた時点の値を見て判定するつもりでした。しかし、この記事を書いている時点で、その値は記録できていません。アリーナが1個になったことは確かめられましたが、そのおかげでメモリが増えなくなったかは、まだ確かめられていない状態です。
アリーナを減らした影響も、まだ測っていない
アリーナを減らすと、複数のスレッドが同じアリーナを使うので、メモリを確保するときに互いを待つことが増えるとされています。DevPickの負荷試験は、systemdのユニットを通さずにバックエンドを起動しているため、この設定は負荷試験には入っていません。本番の応答速度への影響も、比べていません。
もしまたメモリが増えるようなら、手順書に書いたとおり、まずsmapsで「アリーナが増えたのか、それ以外が増えたのか」を切り分けます。今回、コードを読むだけでは手がかりが無かったのに、smapsで内訳を出した途端に向きが決まったので、次も最初にこれを見るつもりです。
IT女子 アラ美ITアライグマまとめ
DevPickのuvicornワーカーは、起動から半日足らずでメモリとスワップの合計が約2.4〜3.3倍に増え、頭打ちになっていませんでした。疑っていたPythonのキャッシュには、どれも上限がありました。/proc/<pid>/smapsで内訳を数えると、glibcがスレッドごとに作るmallocアリーナが15個でき、多い方のワーカーでは約400MBのうち223MBを占めていました。
アリーナは、使っている部分と予約だけの部分の2つの領域に分かれて見えるので、64MBの塊を探すだけでは見つかりません。両方を合わせて数え直して、初めて原因が見えました。
対策として、systemdのユニットにMALLOC_ARENA_MAX=2を足し、スレッド用のアリーナは15個から1個になりました。ただ、修正後に記録できているのは起動から約20分までで、何時間も動かしたあとにメモリが増えなくなったかは、まだ確かめられていません。アリーナを減らしたことによる速度への影響も測っていません。
Pythonのプロセスのメモリが増え続けるとき、原因はPythonのコードの中にあるとは限りません。今の自分は、コードを読む前に、まずOSから見たメモリの内訳を出すのが近道だと考えています。
IT女子 アラ美ITアライグマ
