この記事はZOZO Advent Calendar 2021 9日目の記事になります。
ZOZOでSREをしている @calorie です。よろしくお願いします。

昨日の記事は @matsumana07384 さんによる「GithubのPullRequest作成時のコメントで気をつけていること」でした。
僕もフロントの実装をしていた時は画像をのせるようにしていたのを思い出しました。こちらの記事もぜひご覧ください。

この記事について

メモリアロケータとして有名なjemallocに付属するメモリプロファイラのjeprofを使ってメモリリークを見つける様子を書きます。

jemalloc/jeprof

jemallocはFacebookやFirefoxなどで使われるメモリアロケータで、
フラグメンテーションに効くことが多いためRubyのメモリアロケータをjemallocに変更することでメモリ効率を改善する例がよく挙げられます。
下の記事ではglibc mallocに対してメモリ効率が2倍改善し、内部フラグメンテーションが小さいことが効いているのではないかという考察もあげられています。

jeprofはjemallocに付属するメモリプロファイラで、Google社のpprofと同様の形式でプロファイリングデータを視覚化することができます。下の画像はjeprofでヒーププロファイリングしたものです。

メモリリークの調査

実際にjeprofを使ってみます。
調査の対象として、過去に議論したembulkのissueがOpenのままだったので調べます。

issueの内容としては、embulkで大量のデータをoutputしようとした時に以下のようなエラーが発生しメモリリークが起きていそうだというものです。

[ERROR] (0022:task-0000): LEAK: ByteBuf.release() was not called before it's garbage-collected. Enable advanced leak reporting to find out where the leak occurred. To enable advanced leak reporting, specify t
he JVM option '-Dio.netty.leakDetection.level=advanced' or call ResourceLeakDetector.setLevel() See http://netty.io/wiki/reference-counted-objects.html for more information.

ということで、下のコメントの通り大量のjsonlをElasticsearchにoutputすることでメモリリークが再現できるので、この処理にjeprofを適用する様子を以下に書いていきます。

jemallocのインストール

以降に載せるコードはこちらで公開しています。また、実行はDocker上で行います。

jeprofを使うためにはjemallocをビルドする必要があり、 ./configure で --enable-prof をわたします。

RUN apt-get update \
    && apt-get install --no-install-recommends -y wget build-essential autoconf libunwind-dev graphviz \
    && rm -rf /var/lib/apt/lists/*

RUN mkdir -p /jemalloc /tmp/jeprof && cd /jemalloc \
  && wget https://github.com/jemalloc/jemalloc/releases/download/5.2.1/jemalloc-5.2.1.tar.bz2 \
  && tar -xvf jemalloc-5.2.1.tar.bz2 && cd jemalloc-5.2.1 \
  && ./configure --enable-prof --enable-prof-libunwind \
  && make && make install \
  && cd / && rm -rf /jemalloc

プロファイリング

先程のembulkの問題に対してヒーププロファイリングします。
まず、embulkを実行するjavaがjemallocを使用するように環境変数の LD_PRELOAD で libjemalloc のパスを設定します。
コンテナのイメージなどで設定してしまうと関係のないプロセスもjemallocを使うようになるため、調査目的であればコマンド実行時に設定するのが良いでしょう。
また、公式の例に沿って MALLOC_CONF を設定します。

lg_prof_interval はメモリダンプ間の間隔で2^n byteごとにダンプが作られます。この例だと2^30 = 1GiBです。
lg_prof_sample はサンプリング間隔で2^n byteです。この例だと2^17 = 128 KiBです。
コマンドは以下のようになります。

LD_PRELOAD=/usr/local/lib/libjemalloc.so
MALLOC_CONF=prof:true,lg_prof_interval:30,lg_prof_sample:17,prof_prefix:/tmp/jeprof.out
java -jar /usr/local/bin/embulk run memory_leak.yml

実行すると prof_prefix のパスにプロファイリングデータが作成されます。作成されたデータをjeprofでプロファイリングができます。

jeprof `which java` /tmp/jeprof.out.45846.0.i0.heap

何もオプションをつけなければインタラクティブモードで立ち上がり、 top などでメモリを消費している上位の関数名などが見られます。

(jeprof) top
Total: 45.9 MB
    45.1  98.2%  98.2%     45.1  98.2% je_prof_backtrace
     0.7   1.5%  99.7%      0.7   1.5% readCEN
     0.1   0.3% 100.0%      0.8   1.8% ZIP_Put_In_Cache0
     0.0   0.0% 100.0%      8.6  18.8% 0x00007f13f1daa4e5
     0.0   0.0% 100.0%      1.6   3.4% 0x00007f13f1db17ce
     0.0   0.0% 100.0%      0.3   0.6% 0x00007f13f1db1813
     0.0   0.0% 100.0%      0.1   0.3% 0x00007f13f1db189e
     0.0   0.0% 100.0%      5.6  12.2% 0x00007f13f1db1a3e
     0.0   0.0% 100.0%      0.5   1.0% 0x00007f13f1db1b0e
     0.0   0.0% 100.0%      8.2  18.0% 0x00007f13f1db1d7e

以下のようにgifやpdfなどで出力することもできます。

jeprof --gif `which java` /tmp/jeprof.out.45846.0.i0.heap > jeprof.gif

この結果を見るとほとんど関数がmallocを経由して je_prof_backtrace に行き着いていることがわかります。これらがメモリリークを起こしているとは考えづらいです。
ただし、以下の赤枠の箇所は何度も呼び出されmallocも経由しておらずメモリ上に残っているように見えます。

どうやらparseを繰り返しているようなのでjsonlを処理している箇所が関係していそうですが、これだけでは原因のコードは特定できません。
次にエラーメッセージでも提示されているJVM optionをつけてトレースの情報を見てみます。

LD_PRELOAD=/usr/local/lib/libjemalloc.so
MALLOC_CONF=prof:true,lg_prof_interval:30,lg_prof_sample:17,prof_prefix:/tmp/jeprof.out
java -Dio.netty.leakDetection.level=advanced -jar /usr/local/bin/embulk run memory_leak.yml
...
[ERROR] (0022:task-0000): LEAK: ByteBuf.release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records: 0
Created at:
        io.netty.util.ResourceLeakDetector.track(ResourceLeakDetector.java:229)
        io.netty.buffer.PooledByteBufAllocator.newHeapBuffer(PooledByteBufAllocator.java:286)
        io.netty.buffer.AbstractByteBufAllocator.heapBuffer(AbstractByteBufAllocator.java:158)
        io.netty.buffer.AbstractByteBufAllocator.heapBuffer(AbstractByteBufAllocator.java:149)
        io.netty.buffer.AbstractByteBufAllocator.buffer(AbstractByteBufAllocator.java:107)
        org.embulk.deps.buffer.PooledBufferAllocatorImpl.allocate(PooledBufferAllocatorImpl.java:26)
        org.embulk.spi.PageBuilder.newBuffer(PageBuilder.java:46)
        org.embulk.spi.PageBuilder.flush(PageBuilder.java:221)
        org.embulk.spi.PageBuilder.addRecord(PageBuilder.java:198)
        org.embulk.parser.jsonl.JsonlParserPlugin.run(JsonlParserPlugin.java:172)
        org.embulk.spi.FileInputRunner.run(FileInputRunner.java:140)
        org.embulk.exec.LocalExecutorPlugin$ScatterExecutor.runInputTask(LocalExecutorPlugin.java:269)
        org.embulk.exec.LocalExecutorPlugin$ScatterExecutor.access$100(LocalExecutorPlugin.java:194)
        org.embulk.exec.LocalExecutorPlugin$ScatterExecutor$1.call(LocalExecutorPlugin.java:233)
        org.embulk.exec.LocalExecutorPlugin$ScatterExecutor$1.call(LocalExecutorPlugin.java:230)
        java.util.concurrent.FutureTask.run(FutureTask.java:266)
        java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        java.lang.Thread.run(Thread.java:748)

JsonlParserPlugin.java あたりが怪しいため確認します。
呼び出されている箇所の周りを見るとファイルを読み込んでループでparseしていることがわかります。

183行目で pageBuilder.finish() してページを解放しているように見えますがこれが正しくないのかもしれません。
PageBuilderを見に行くと finish の他に close メソッドがあり、こちらで内部のバッファを解放していることが読み取れます。

なので pageBuilder.finish() のところに pageBuilder.close() を追加すると解決できそうな気がします。実際に似たようなPull Requestが出されています。

同様の修正をしてプロファイリングした結果が以下になります。先程の関数が消えていることが確認できます。

めでたしめでたし。

最後に

めでたしと書きましたが、こちらのコメントで指摘されているように根本原因が正しいのか、俯瞰して見た時に正しく動くのか、などはもう少し考える必要があるでしょう。

明日は、 @f6wbl6 さんが公開予定です。そちらもぜひご覧下さい。