관련링크

WhaTap収集サーバーアプリケーションはJavaで実装されています。

UIを担当するFront、データ保存を担当するYard、データ受信を担当するProxyなど、それぞれ役割別に名前をつけました。

そのうち、いくつかのモジュールが理解できないほどメモリ使用量が高く、追跡を開始することにしました。

Javaプロセスメモリが増加する理由

Java Heapサイズは1Gbなのに、なぜプロセスメモリは2.6Gbです。WhaTapサービスのいくつかのモジュールのうち、顧客アカウント情報を管理するアカウントモジュールがあります。他のモジュールに比べて特に多くのことをせず、CPU使用量も低いのに有毒メモリ使用量だけ高いです。同様の症状を示すNotihubモジュールもあります。Notihubは発生したイベントをSMS、Email、Slackなどで知らせる役割をしています。かなり長い間縛られている認知している問題ですが、今でも原因追跡をすることにしました。

Java Heap = -Xms1g -Xmx1g

Springbootで実装された AccountのHeap Sizeは 1Gbに設定されています。

1Gb Heapを使用しますが、プロセスメモリ使用量は2.65Gbです。

ヒープ使用パターンは特に問題ありません。

vmにAccountだけが浮いているのに、メモリ使用量がなぜこんなに高いのでしょうか。

Nativeエリアには何が起こっていますか？

2.65Gbのフルメモリ使用量のうち、Java Heap 1Gbを除く残りの1.65GbはNativeメモリ領域です。

それでは、負荷も少ない時間帯に複雑な処理なしに認証/権限情報だけを提供するアカウント管理モジュールでヒープより1.5倍大きいメモリはなぜ使用されているのでしょうか？

ヒープ問題はJavaのヒープダンプを覗くだけですが、ネイティブゾーンはどのようにチェックして追跡する必要がありますか？

ステップ1 - Native Memory Tracking

Native Memoryトレースの開始は、オプションを適用してデータを覗くことです。

このプロセスの詳細は、Oracle Trouble Shootガイドで親切に説明されています。

https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr007.html(https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr007.html

運用環境に上記のオプションを適用するのは難しいので、同じ症状を示すテスト環境で試してみます。動作環境との違いはヒープサイズであり、症状は同じです。

| 2環境 | Heap | Process Memory | | --- | ----------------- | ------------------ | | 運用 | -Xms1g -Xmx1g | 2.65g | | テスト | -Xms512m -Xmx512m | 2g |

なんと2Gbを超えて使っています。

NativeMemoryTrackingオプションを適用した状態でjcmdコマンドを使用して確認してみました。

800Mb committed!

reservedは利用可能なメモリ領域、committedは実際に使用されている領域を意味します。きっと私の目で2Gbを確認しましたが、javaではHeapを合わせて800Mb余りだけ使うことだけを知っています。

残りの1.2Gbを超えるメモリは、jvmも知らない道に迷った友達です。

ステップ2 - pmap と smaps で OS 時刻で確認する

jcmdコマンドで確認した使用量は800Mbです。JVM は 800Mb だけを使うと知っているのでしょう。それでは、失われた1.2Gbは何で追跡する必要がありますか？

JVMは知りません。だから、OSの時点でプロセスメモリ情報を見る必要があります。pmapコマンドを使用すると、プロセスのメモリマップを確認できます。https://www.howtoforge.com/linux-pmap-command/

目によく入らないです。 RSSでソートしてもう一度確認してみました。

Total 2152720、2Gb以上書いていると出てきます。

00000000e0000000 アドレスは 512Mb に設定した Java Heap、残りは最大 64Mb 単位に分かれた Native 領域です。 /proc//smaps でアドレス別にじっくり確認してみましょう。

pmapの結果よりも少し詳細な情報を提供するsmapからメモリアドレス範囲を取得します。

pmapアドレスの先頭0から4を除く値は、smapsの開始アドレスと同じです。

プロセスが占めるメモリを表す指標としてpssを確認します。開始アドレス00000000e0000000 のヒープは除外します。

実際の履歴を確認するために、64Mbサイズに分割されたpss値の高いメモリアドレスを複数確保してください。

ステップ3 - gdbでメモリをダンプする

メモリの内容を覗くためにgdbでメモリダンプを確保します。https://www.gnu.org/software/gdb/

ステップ2 pmapの結果から出た64Mb単位のメモリアドレスを5個程度確保してメモ帳によく書き留めました。

gdb を使って attach します。

取得したアドレスにダンプします。 16進数ラの前に0x付けます。

取得したgdpメモリダンプ解析に特別なツールはないので、stringsコマンドでdumpから文字列を抽出して目で確認します。

https://www.howtoforge.com/linux-strings-command/

こんなのも見えて。

こんなのも見えます。

非常に変です。明らかにJVMが見逃した区間のメモリ情報を確認しましたが、Java Class、pom.xmlの内容だらけです。

ステップ4 - 推論と検証

メモリダンプ履歴をもとに仮説を立てました。

仮説：この情報はjarモジュールを解凍した内容である。

仮説検証のためにjarファイルを1つ選んで解凍し、それを合計してstringsで文字列を抽出してみました。

確認してみました。

同じように見えました!!

jarを解凍して組み合わせた後、文字列だけを抽出した内容とメモリダンプの内容は同じようになりました。つまり、アプリケーションの実行中に使用された情報ではなく、解凍されたjarの内容がメモリに残り道を失っていたのです。

メモリはアプリケーションの起動時に増加したので、jarの圧縮が解放される時間帯のStack情報を確認してみました。

ビンゴ!!! 「ZipInflaterInputStream」オーレ！ 「hibernate」

冒頭では、いくつかのモジュールだけがこの現象を見せたと言っていましたが、hibernateが見えます。 ぴったりです。 メモリ使用量で問題を引き起こすモジュールの共通点は hibernate を使用していることでした。

InflaterInputStream関連のバグを確認しました。 現象と正確に一致します。

https://github.com/spring-projects/spring-boot/pull/14001

ステップ5 - 結論

SpringbootのBugでZipInflaterInputStream.close()がNative Memoryを解放できず、これにより不必要にGb単位でメモリを占有していました。これを解決するには、coreモジュールである、org.springframework.boot.loader.JarFileEntries.classを更新する必要があります。

Java Native Memory Tracking

それほど複雑ではないにもかかわらず、Native Memory領域を覗くのが難しいと思う人が多いです。過去にHeap領域に存在していたものがJava8以降からネイティブメモリ領域に大挙引っ越しました。だからか最近では、Heap DumpだけでなくNative Memory領域を覗き続けることができています。基本的な知識があれば、必ず開発者でなくても上記のようにsmapsとgdbを使ってNative Memory 領域を分析できると思います。

結果

テストのためにSpringBootアップグレード後に起動したとき、メモリ使用量が2Gbから800Mb(Heap 512Mb)に低下したことを確認しました。開発部門担当者に分析内容とバグを共有しました。ただし、SpringBootアップグレード後に検証すべき部分が多すぎて次期Major課題に進む予定です