原文はこちら。
The original article was written by Poonam Parhar (Consulting Member of Technical Staff, Oracle).
https://blogs.oracle.com/poonam/troubleshooting-native-memory-leaks-in-java-applications
Javaアプリケーションと関わっていると、少なくとも一度は以下のようなエラーを見たことがあるはずです。
# A fatal error has been detected by the Java Runtime Environment:
#
# java.lang.OutOfMemoryError : unable to create new native Thread
# A fatal error has been detected by the Java Runtime Environment:
#
# java.lang.OutOfMemoryError: requested 32756 bytes for ChunkPool::allocate. Out of swap space?
#
# Internal Error (allocation.cpp:166), pid=2290, tid=27
# Error: ChunkPool::allocate
これらのエラーは何を意味するのでしょうか？Javaヒープがメモリを使い果たしたことに関係しているのでしょうか？
Native OutOfMemoryError
上記の2つのエラーは、JVMがネイティブメモリリソースを使い果たしたことを示しています。最初のケースでは、JVMは新しいネイティブスレッドの作成に失敗し、2番目のケースでは、内部のJVMクラスChunkPoolがメモリを割り当てることができなかったため、JVMはOutOfMemoryErrorで失敗しました。
JVMが管理していないネイティブメモリからの割り当てができない場合、JVMはネイティブのout-of-memoryエラーを報告します。これが発生する理由は、Javaアプリケーションやシステム上で実行されている他のアプリケーションがネイティブ・メモリ・リソースを使い果たしている可能性があるためです。これを回避するには、Javaヒープ、Metaspace、スレッド数とスタックサイズを減らし、システム上の他の不要なプロセスを終了させることで、ネイティブ割り当てのためのより多くのスペースを利用できる可能性がありますが、これらの対策のすべてがネイティブメモリ関連のエラーの解決に役に立たない場合、ネイティブメモリリークに直面している可能性があります。このエントリでは、ネイティブ・メモリ・リークと、それを検出してトラブルシューティングする方法について説明します。このエントリで使用する Javaサンプルコードは以下のリポジトリからご利用いただけます。
native_leaks
https://github.com/poonamparhar/native_leaks
Memory Pools
最初に、Javaアプリケーションがアクセスでき、割り当て可能な様々なメモリプールについて説明します。ご存知のように、JavaオブジェクトはJavaヒープに割り当てられます。Javaヒープの他にも、MetaspaceやCodecacheなどのJVMが管理するメモリ空間があります。さらに、JVMとアプリケーションのネイティブ・コードは、ネイティブ・メモリからメモリ割り当てできます。これらのネイティブメモリの割り当ては、JNIによる割り当て、JITコンパイラによる割り当て、またはJVMによる新しいスレッドの作成などに由来します。
上図は、Javaアプリケーションで利用可能な様々なメモリプールを表しています。一番上が、Javaオブジェクトが割り当てられているJavaヒープ。続いて、クラスとそのメタデータを格納するMetaspace、そして、JITコンパイラがコンパイルしたコードを保存するCodeCacheがあります。次のブロックは、JVMが実行できるさまざまな種類のネイティブ・メモリ割り当てを示しています。その中には、内部構造、ロードされたjarやネイティブ・ライブラリ、スレッド・スタックなどのためのメモリ割り当てが含まれています。その他、Javaアプリケーションは、ネイティブ・メモリからの割り当てを行うJNIまたはJVMTIコードを持つことができます。NIOとDirect ByteBufferでもネイティブメモリの割り当てを行います。ネイティブメモリの割り当てが様々なところで発生するという事実ゆえに、ネイティブメモリ関連の問題の検出、診断が非常に難しくなっています。
Confirm Native Memory Leak
メモリリークを検出する第一歩は、アプリケーションのメモリ使用量を監視して、全体的なメモリ使用量が増加していないかどうかを確認することです。UNIXベースのシステムでは、ps、top、pmapのようなツールを使ってメモリを監視できます。下のスクリーンショットは、監視しているプロセスのメモリ使用率（RSS – 青でマークされている7番目の列）が時間の経過とともに増加していることを示しています。
しかし、RSSはプロセスサイズを正確に測定する信頼できる方法ではない場合があります。プロセスがマルチマッピング（複数の仮想メモリ領域を物理メモリの同じ領域にマップすること）を使用している場合、RSSがプロセスのメモリサイズを正しくレポートしないという既知の問題があります。JVMのZGCはマルチマッピングを使用しているので、RSSはZGCを使っているプロセスの正しいメモリサイズを報告しないことに注意してください。代わりにPSSを使ってください。
PSSとはProportional Set Sizeを意味し、利用されている共有メモリおよびプライベートメモリのそれぞれから構成されています。を別々に計算します。プロセスのメモリフットプリントは以下の式に従って計算しています。
（プライベート物理メモリ） + （共有された物理メモリ） / （マッパーの個数）
プロセスのPSSの詳細を /proc/<pid>/smaps ファイルから取得できます。以下のスクリプトを使用すると、5秒ごとのプロセスのPSSの合計値を表示できます。
$ cat print_pss.sh
pid=$1
echo 'Monitoring PSS of the Process:' $pid
while true
do
cat /proc/$pid/smaps | grep -i 'Pss:' | awk '{Total+=$2} END {print "PSS: " Total}'
sleep 5
done
$ sh print_pss.sh 27890
Monitoring PSS of the Process: 27890
PSS: 46482
PSS: 47638
PSS: 48582
PSS: 50406
PSS: 51333
PSS: 52602
PSS: 53557
PSS: 54278
PSS: 55038
PSS: 55622
上記によると、プロセスの総物理メモリ使用量が時間の経過とともに増加しています。
次は、メモリ使用量の増加がJVMのヒープ領域または非ヒープ領域のいずれを由来としているかを判断する必要がありますが、これにはJConsoleやJMCのようなツールを利用できます。強制GCを実行してJVMがJavaヒープ内の到達不可能なJavaオブジェクトを収集し、確実に関連するネイティブメモリリソースを回収できるようにします。
上のスクリーンショットからわかるように、JVMが管理するメモリ領域でメモリ使用量の増加の証拠が見つからない場合、JVM外のメモリ割り当てがプロセスのメモリ使用量の増加の原因になっていることを意味します。このような場合、プロセスの成長しているメモリセクションの発見が有用であることが多々あります。そのためには、pmapのようなツールを使い、定期的に収集した出力を比較してどのメモリセクションのサイズが増えているのか、もしくがどのセクションが新たに割り当てられたのかを判断できます。
$ diff pmap.1 pmap.9
12a13,14
> 00007f4060000000 32276K rw--- [ anon ]
> 00007f4061f85000 33260K ----- [ anon ]
56,57c58
< 00007f40a4000000 18952K rw--- [ anon ]
---
> 00007f40a4000000 65536K rw--- [ anon ]
146c147
< total 3222140K
---
> total 3287676K
<strong>$ diff pmap.2 pmap.9</strong>
12a13,14
> 00007f4060000000 32276K rw--- [ anon ]
> 00007f4061f85000 33260K ----- [ anon ]
56,57c58
< 00007f40a4000000 25600K rw--- [ anon ]
---
> 00007f40a4000000 65536K rw--- [ anon ]
146c147
< total 3222140K
---
> total 3287676K
Windowsでも同様に、メモリ使用量を追跡するのにPerfMonやVMMapが役立ちます。
時間の経過でメモリ利用量の増加があり、その増加がJavaヒープに由来しないとわかれば、ネイティブメモリリークに直面している可能性が高いです。
Diagnose Native Memory Leaks
上述の通り、ネイティブメモリリークはJVMが内部で実施するネイティブメモリの割り当てに起因する場合と、JVM外に起因する場合があります。こうしたメモリリークの両方を診断する方法を見ていきましょう。
1. Native Memory Leaks Within the JVM （JVM内に由来）
JVMにはNative Memory Tracking (NMT)という強力なツールがあります。これを使うと、JVM内部で実施されているネイティブメモリの割り当てを追跡できます。ただしこのツールでは、JNIコードに由来するような、JVM外で割り当てられたネイティブメモリの追跡はできない点に注意が必要です。
以下はこのツールの使い方です。
NativeMemoryTrackingというJVMオプションを使って、NMTを有効化して監視対象にするJavaプロセスを起動します。NMTによる追跡の出力レベルを以下のように ‘summary’ もしくは ‘detail’ レベルに設定できます。
-XX:NativeMemoryTracking=summary
-XX:NativeMemoryTracking=detail
- NMTを有効化したプロセスに対して
jcmdツールを使い、ネイティブメモリの利用状況の詳細を取得できます。また、メモリ利用状況のベースラインを収集して、ベースラインとの利用状況の差を収集することもできます。
jcmd VM.native_memory
jcmd VM.native_memory baseline
jcmd VM.native_memory detail.diff/summary.diff
NMTを有効化すると、5〜10％ほどJVMのパフォーマンスが低下する場合があります。そのため、本番運用システムでの有効化は注意すべきです。また、NMTが利用するネイティブメモリもツール自身で追跡しています。
下図のJConsoleのスナップショットは、Compressed Class Spaceのメモリプールで時間経過とともに一定の割合で増加していることを示しています。
NMTを使ってこの増加状況を追跡できます。ベースラインとsummary.diffを収集すると、ロードされたクラスの個数が増加していることが原因で、クラスのメモリ領域利用量が激増していることがわかります。
bash-3.2$ jcmd 39057 VM.native_memory summary.diff
39057:
Native Memory Tracking:
Total: reserved=5761678KB +52943KB, committed=472350KB +104143KB
- Java Heap (reserved=4194304KB, committed=163328KB +7680KB)
(mmap: reserved=4194304KB, committed=163328KB +7680KB)
- Class (reserved=1118333KB +47579KB, committed=117949KB +89963KB)
(classes #68532 +58527)
(malloc=8317KB +2523KB #5461 +3371)
(mmap: reserved=1110016KB +45056KB, committed=109632KB +87440KB)
- Thread (reserved=21594KB -2057KB, committed=21594KB -2057KB)
(thread #22 -2)
(stack: reserved=21504KB -2048KB, committed=21504KB -2048KB)
(malloc=65KB -6KB #111 -10)
(arena=25KB -2 #42 -4)
- Code (reserved=250400KB +244KB, committed=5612KB +1348KB)
(malloc=800KB +244KB #1498 +234)
(mmap: reserved=249600KB, committed=4812KB +1104KB)
- GC (reserved=159039KB +18KB, committed=145859KB +50KB)
(malloc=5795KB +18KB #856 +590)
(mmap: reserved=153244KB, committed=140064KB +32KB)
- Compiler (reserved=153KB, committed=153KB)
(malloc=22KB #72 -2)
(arena=131KB #3)
- Internal (reserved=13537KB +6949KB, committed=13537KB +6949KB)
(malloc=13505KB +6949KB #70630 +59119)
(mmap: reserved=32KB, committed=32KB)
- Symbol (reserved=2715KB +9KB, committed=2715KB +9KB)
(malloc=1461KB +9KB #702 +29)
(arena=1255KB #1)
- Native Memory Tracking (reserved=1416KB +1031KB, committed=1416KB +1031KB)
(malloc=140KB +34KB #2197 +518)
(tracking overhead=1275KB +997KB)
- Arena Chunk (reserved=186KB -832KB, committed=186KB -832KB)
(malloc=186KB -832KB)
2. Native Memory Leaks from Outside the JVM（JVM外に由来）
JVM外からのネイティブメモリリークの場合、検出やトラブルシューティングのためにプラットフォームネイティブのツールや、3rdパーティーツールを利用できます。JVM外でなされたメモリ割り当てに由来するネイティブメモリリークをピンポイントで特定するのに有用なものをリストアップしてみました。
- jemalloc
- Valgrind
- dbx （Solaris）
- Purify （UNIXプラットフォーム、Windowsとも利用可能）
- User-Mode Dump Heap (UMDH) （Windows）
- コアファイル
これらのツールを見ていきましょう。
jemalloc
jemallocはメモリアロケータかつプロファイラです。これはmallocの独自実装で、mallocによる割り当てを追跡可能な組み込みのアロケーション・プロファイラを備えています。さらに、メモリ割り当てをサンプリングして追跡するため非常にパフォーマンスへの影響が小さく、本番運用システムでも安心して使用できます。パフォーマンスへの影響はmallocを非常に多用するアプリケーションでは約2%に制限できます。jemallocは以下のURLからダウンロードできます。
jemalloc
https://github.com/jemalloc/jemalloc
Build jemalloc
configure と make を使ってjemallocをビルドできます。生成されたバイナリでメモリプロファイリングを有効化するため、 –enable-prof を使うようにしてください。
$ configure --prefix=/usr/local --enable-prof<br>$ make
Create memory profiles
Javaアプリケーションのメモリプロファイルを生成するために、MALLOC_CONFという環境変数を設定する必要があります。これにより、割り当てのサンプリングとヒーププロファイルをディスクに保存する方法をツールに知らせます。以下の例では、jemallocをTestDeflaterというJavaアプリケーションで使う場合の例です。この構成を使うと、jemallocは2MB（2^21）の割り当て毎にメモリ割り当ての標本を収集し、1GB（2^30）の割り当てごとにプロファイルのダンプを作成します。
$ export JEMALLOC_PATH=/user/home/poonam/jemalloc-5.1.0
$ export MALLOC_CONF=prof:true,lg_prof_interval:30,lg_prof_sample:21
$ LD_PRELOAD=${JEMALLOC_PATH}/lib/libjemalloc.so.2 java -Xmx1024m -Xms1024m -XX:MaxNewSize=20m TestDeflater
以下のURLでこのツールで利用可能な全てのオプションの詳細情報を確認できます。
jemalloc
http://jemalloc.net/jemalloc.3.html
Display memory allocations using jeprof
前のステップでメモリプロファイル（jeprof*.heapという名前のファイル）をディスクに作成しました。jeprofツールというjemallocに含まれるツールでこれらのプロファイルの情報を表示できます。--show_bytesというオプションを使って、文字もしくはグラフィカル形式でメモリ割り当てを表示できます。
$ jeprof --show_bytes `which java` jeprof.23299.0.f.heap
(jeprof) top
Total: 341324080 B
325433344 95.3% 95.3% 325433344 95.3% deflateInit2_
15292392 4.5% 99.8% 15292392 4.5% os::malloc@926750
368704 0.1% 99.9% 368704 0.1% readCEN
116448 0.0% 100.0% 325549792 95.4% Java_java_util_zip_Deflater_init
81920 0.0% 100.0% 81920 0.0% std::__once_callable
12016 0.0% 100.0% 12016 0.0% _dl_new_object
3840 0.0% 100.0% 3840 0.0% allocate_dtv
3616 0.0% 100.0% 3616 0.0% _nl_intern_locale_data
2048 0.0% 100.0% 2208 0.0% __tzfile_read
1984 0.0% 100.0% 1984 0.0% _dl_check_map_versions
出力結果を見ると、最後の列に表示された関数が使用しているメモリの合計をバイト単位で最初の列に表示しています。4番目の列は、それぞれの関数とその呼び出し元で使用されているメモリです。第2列目と第5列目は、それぞれ第1列目と第4列目の数値のパーセンテージを表しています。そして、3番目の列は、2番目の列の累積和、すなわち、3番目の列のk番目のエントリは、2番目の列の最初のk個のエントリの和です。
上記の情報をグラフィカル形式で可視化することも可能です。その場合には、--gifオプションを使います。
$ jeprof --show_bytes --gif `which java` jeprof.23299.0.f.heap > leak.gif
Dbx
jemallocではメモリ割り当てのスタックトレース出力のためにlibunwindが必要ですが、これはSPARCプラットフォームでは利用できません。SPARCプラットフォームでは、Sun Studioのdbxを使ってネイティブメモリリークのデバッグが可能です。以下はその手順です。
$ export LD_AUDIT=<Path to Sun Studio>/lib/dbx/sparcv9/runtime/rtcaudit.so
$ export PATH=<Path to Sun Studio>/bin/sparcv9/:$PATH
$ java -Xmx1024m -Xms1024m -XX:MaxNewSize=20m TestDeflater &
$ dbx `which java`
> check -leaks
> showleaks
Actual leaks report (actual leaks: 891 total size: 15174608 bytes)
Total Num of Leaked Allocation call stack Size Blocks Block Address
=================================================================
3735552 57 - zcalloc < deflateInit2_ <Java_java_util_zip_Deflater_init < 0xffffffff6941191c< 0xffffffff694118c0<0xffffffff69407c28< 0xffffffff69408068< 0xffffffff69408068
3670016 56 - zcalloc < deflateInit2_
3670016 56 - zcalloc < deflateInit2_
3604480 55 - zcalloc < deflateInit2_
339264 57 - zcalloc < deflateInit2_
65536 2 - zcalloc < updatewindow < inflate
上記の内容からもわかるように、showleaksコマンドで最もリークしているブロックを表示し、Java_java_util_zip_Deflater_init()によるメモリ割り当てがリークしていることを正しく特定していることがわかります。
Valgrind
LinuxプラットフォームではTestDeflaterサンプルアプリケーションでVargrindも利用しました。
$ valgrind --leak-check=full --show-leak-kinds=all --suppressions=suppression_file --log-file=valgrind_full_suppression.log -v java TestDeflater
ご注意いただきたいのは、Valgrindに抑制ファイル（suppression file）を渡して、Javaヒープ割り当てなどのJVM内部割り当てを潜在的なメモリリークとして考慮しないようにしている点です。これをしないと、出力を解析してから手動でフィルタリングするのが非常に難しくなるためです。
抑制ファイル（suppression file）の内容は以下のようなものです。
{
name
Memcheck:Leak
fun:*alloc
...
obj:/home/poonam/Java/jdk1.8.0_181/jre/lib/amd64/server/libjvm.so
...
}
抑制ファイルを適用した場合、以下のスタック・トレースでいくつかのリークがわかりました。
==5200== 88 bytes in 1 blocks are still reachable in loss record 461 of 18,861
==5200== at 0x4C2FB55: calloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5200== by 0x7DCB156: Java_java_util_zip_Deflater_init (in /home/poonam/Java/jdk1.8.0_181/jre/lib/amd64/libzip.so)
==5200== by 0x80F54FC: ???
==5200== by 0x8105F87: ???
==5200== by 0xFFFFFFFE: ???
==5200== by 0xEC67F74F: ???
==5200== by 0xC241B03F: ???
==5200== by 0xEC67D767: ???
==5200== by 0x413F96F: ???
==5200== by 0x8101E7B: ???
==5200==
==5200== 88 bytes in 1 blocks are still reachable in loss record 462 of 18,861
==5200== at 0x4C2FB55: calloc (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5200== by 0x7DCB156: Java_java_util_zip_Deflater_init (in /home/poonam/Java/jdk1.8.0_181/jre/lib/amd64/libzip.so)
==5200== by 0x80F54FC: ???
==5200== by 0x8105F87: ???
==5200== by 0xFFFFFFFE: ???
==5200== by 0xEC67FF3F: ???
==5200== by 0xC241B03F: ???
==5200== by 0xEC630EB7: ???
==5200== by 0x413F96F: ???
==5200== by 0x8101E7B: ???
==5200== by 0x41: ???
==5200== by 0x19EAE47F: ???
このように、valgrindはサンプル・テスト・プログラムでメモリリークの原因を特定することに成功しました。しかし、valgrindの使用はアプリケーションのパフォーマンスに大きな影響（20倍から30倍くらい遅くなる）があることがわかりました。したがって，本番環境でvalgrindを効果的に使うことはできないかもしれません。
Core files
先ほど見たように、pmapによる出力は、時間の経過とともにサイズが変化するメモリブロックを識別するのに役立ちます。対してコアファイルを使うと、メモリブロックの内容を閲覧し、メモリブロック存在するものを認識し、その存在するものをコードに紐付けることが可能かどうかを確認できます。以下はサンプルアプリケーション JNINativeLeak の例です。
$ diff pmap.15767.1 pmap.15767.3
69,70c69,70
< 00007f6d68000000 17036K rw--- [ anon ]
< 00007f6d690a3000 48500K ----- [ anon ]
---
> 00007f6d68000000 63816K rw--- [ anon ]
> 00007f6d6be52000 1720K ----- [ anon ]
上記のpmap出力結果から、2個のスナップショット間で 00007f6d690a3000 のメモリブロックが変化し増大していることがわかります。プロセスから収集したコアファイルを使うと、このメモリブロックの内容を検査できます。
$ gdb `which java` core.15767
GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
Copyright (C) 2016 Free Software Foundation, Inc.
...
(gdb) x/100s 0x00007f6d690a3000
0x7f6d690a3000: "mory Leak "
0x7f6d690a300c: "Alert: JNI Memory Leak "
0x7f6d690a3025: "Alert: JNI Memory Leak "
0x7f6d690a303e: "Alert: JNI Memory Leak "
0x7f6d690a3057: "Alert: JNI Memory Leak "
0x7f6d690a3070: "Alert: JNI Memory Leak "
このメモリブロックに “Alert: JNI Memory Leak “という繰り返しの文字列が見つかりました。そして、ソースコードからこの文字列を探すことができました。これで犯人に到達しました。
JNIEXPORT void JNICALL Java_JNINativeLeak_allocateMemory
(JNIEnv *env, jobject obj, jint size) {
char* bytes = (char*) malloc(size);
printf("Allocated %d bytes at %p \n", size, (void*)bytes);
for (int i=0; i<40; i++) {
strcpy(bytes+i*25, "Alert: JNI Memory Leak ");
}
}
Summary
まとめると、以下の手順でネイティブメモリリークのトラブルシューティングが可能です。
ps、top、pmapなどのネイティブツールを使用して、プロセスの全体的なメモリ使用量を監視- メモリの増加がJVMの非ヒープ領域にあるか、JConsoleやJMCを使用してJVM外の領域にあるかを判断
- 強制GCで、ネイティブメモリリークがあることを確認
- JVM内部からのネイティブリークを特定するには、NMTを使用
- JVMの外部からのネイティブリークを識別するには、
jemalloc、valgrind、dbx、purify、UMDH、pmap、コアファイルを使用できる
ご興味があれば以下のブログエントリもどうぞ。
Running on a 64bit platform and still running out of memory
https://blogs.oracle.com/poonam/running-on-a-64bit-platform-and-still-running-out-of-memory
Logico Inside 