jeprofでメモリリークを見つける

この記事は[ZOZO Advent Calendar 2021](https://qiita.com/advent-calendar/2021/zozo) 9日目の記事になります。
ZOZOでSREをしている @calorie です。よろしくお願いします。

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

https://qiita.com/matsumana07384/items/5aecbcd228a98394b3fe

# この記事について

メモリアロケータとして有名な[jemalloc](http://jemalloc.net/)に付属するメモリプロファイラの[jeprof](https://github.com/jemalloc/jemalloc/blob/5.2.1/bin/jeprof.in)を使ってメモリリークを見つける様子を書きます。

# jemalloc/jeprof

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

http://blog.matsumoto-r.jp/?p=3131

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

![jeprof.gif](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/8523/8619ec81-e4e9-d478-0278-a28a1c87e269.gif)

# メモリリークの調査

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

https://github.com/embulk/embulk/issues/1218

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を適用する様子を以下に書いていきます。

https://github.com/embulk/embulk/issues/1218#issuecomment-773142496

## jemallocのインストール

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

https://github.com/calorie/embulk-repro

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

```dockerfile
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` を設定します。

https://github.com/jemalloc/jemalloc/wiki/Use-Case%3A-Heap-Profiling

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

```sh
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でプロファイリングができます。

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

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

```sh
(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などで出力することもできます。

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

![jeprof.gif](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/8523/8619ec81-e4e9-d478-0278-a28a1c87e269.gif)

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

![jeprof2.gif](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/8523/376dc195-f53d-9ba4-3f8e-eec93f155c1d.gif)

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

```sh
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していることがわかります。

https://github.com/shun0102/embulk-parser-jsonl/blob/v0.2.0/src/main/java/org/embulk/parser/jsonl/JsonlParserPlugin.java#L172

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

https://github.com/embulk/embulk/blob/v0.9.24/embulk-core/src/main/java/org/embulk/spi/PageBuilder.java#L239-L247

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

https://github.com/embulk/embulk-input-jdbc/pull/225

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

![jeprof3.gif](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/8523/5691b02d-8277-f51f-4bbb-f2f068195704.gif)

めでたしめでたし。

# 最後に

めでたしと書きましたが、[こちらのコメント](https://github.com/embulk/embulk-input-jdbc/pull/225#issuecomment-906383443)で指摘されているように根本原因が正しいのか、俯瞰して見た時に正しく動くのか、などはもう少し考える必要があるでしょう。

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