メインコンテンツへ移動
黯羽軽揚毎日少しずつ

Android GC ログの読み解き方

無料2016-03-11#Android#GC_CONCURRENT#GC_FOR_MALLOC#GC_HPROF_DUMP_HEAP#GC_EXPLICIT#GC_EXTERNAL_ALLOC#Concurrent#Alloc#Explicit#NativeAlloc#CollectorTransition#HomogeneousSpaceCompact#DisableMovingGc#HeapTrim

公式ドキュメントを翻訳し、GCログを読み解いてOOMから遠ざかる

はじめに

英語の原文リンクはこちら。この記事の翻訳に至らない点があれば、迅速に修正できるようご指摘ください。以下は翻訳文です。

Androidはモバイルデバイス向けに設計されているため、開発者は常にアプリが消費するRAM（Random-Access Memory）の量に注意を払う必要があります。DalvikやARTが定期的にガベージコレクション（GC）を行ってくれるからといって、開発者がアプリのメモリ使用状況（いつ、どこで、どれだけのメモリが割り当てられ、または解放されたか）を無視して良いわけではありません。安定したユーザー体験を確保し、システムが複数のアプリ間を迅速に切り替えられるようにするためには、ユーザーが操作していない時にアプリが不必要なメモリを消費しないことが重要です。

P.S. Dalvik（Android専用のJVM）とART（Android Runtime）。Android 4.4でARTが導入され、それ以前はDalvikが使用されていました。

開発中にアプリのメモリ管理に関するすべてのベストプラクティスに従っていたとしても（開発者はそうすべきですが）、オブジェクトのメモリリークやその他のメモリ関連のバグが発生する可能性はあります。アプリのメモリ使用量を最小限に抑える唯一の確実な方法は、ツールを使用してアプリのメモリ使用状況を分析することです。このガイドでは、その具体的な方法について詳しく説明します。

ログ情報の解説

アプリのメモリ使用状況を確認する最も簡単な方法は、実行時のログ情報を見ることです。GCが実行されると、logcatにメッセージが出力されます。logcatの出力はDevice Monitorで確認するか、Android StudioなどのIDEで直接確認できます。

Dalvik のログ情報

Dalvik（ARTではない）モードでは、GCが発生するたびにlogcatに以下のような情報が出力されます：

D/dalvikvm: <GC_Reason> <Amount_freed>, <Heap_stats>, <External_memory_stats>, <Pause_time>

例えば：

D/dalvikvm( 9050): GC_CONCURRENT freed 2049K, 65% free 3571K/9991K, external 4703K/5261K, paused 2ms+2ms

GC Reason

何がGCのトリガーとなったか、およびどのタイプのガベージコレクションであるかを示します。考えられる値は以下の通りです：

  • GC_CONCURRENT

ヒープが満杯に近づいたことによって引き起こされる並行GCです。

  • GC_FOR_MALLOC

ヒープがすでに満杯の状態でアプリがメモリを割り当てようとしたため、システムがアプリを停止させてメモリを回収せざるを得ず、結果としてメモリ割り当てに失敗した場合のGCです。

  • GC_HPROF_DUMP_HEAP

ヒープ分析用のHPROFファイル作成がリクエストされ、それによって引き起こされたGCです。

P.S. hprofファイルはヒープの使用状況を記述したもので、Chromeのheapsnapshotファイルに似ています。

  • GC_EXPLICIT

明示的なGC。例えば gc() の呼び出しによるものです（この方法は避けるべきであり、GCは必要な時に自動的に実行されると信じるべきです）。

  • GC_EXTERNAL_ALLOC

外部メモリの割り当て（ピクセルデータがネイティブメモリやNIO byte bufferに保存されるなど）によって引き起こされるGCで、API 10以下のバージョンでのみ表示されます（新しいバージョンではすべてDalvikヒープ内で割り当てられます）。

Amount freed

今回のGCで回収されたメモリの量です。

Heap stats

ヒープ内の空きメモリの割合、および [使用済みメモリ量]/[ヒープの総サイズ] です。

External memory stats

外部メモリの統計データです。

API 10以下のバージョンにおいて、外部に割り当てられたメモリ量、および [割り当て済みメモリ量]/[GC発生のしきい値] です。

P.S. GC発生のしきい値に達するとGCが実行されます。

Pause time

ヒープが大きいほど、より多くの停止時間（ポーズ）が必要になります。並行GC（GC ReasonがGC_CONCURRENT）の停止時間は2つの部分に分かれます。1つ目はGCの開始時、もう1つはGCの終了時です。

これらのログ情報を記録し、ヒープ統計（例では 3571K/9991K）に注目してください。この値が継続して増加している場合、メモリリークが発生している可能性があります。

ART のログ情報

Dalvikとは異なり、ARTは明示的でない（暗黙の）リクエストによるGCをログに記録しません。GCは非常に遅いと判断された場合にのみログを出力します。具体的には、GCの停止時間が5msを超えた場合、またはGCの実行時間が100msを超えた場合です。アプリがユーザーに気づかれるような停止状態（jank）でなければGCは遅いと判断されませんが、明示的なGCはログに記録されます。

ARTのGCログには以下の情報が含まれています：

I/art: <GC_Reason> <GC_Name> <Objects_freed>(<Size_freed>) AllocSpace Objects, <Large_objects_freed>(<Large_object_size_freed>) <Heap_stats> LOS objects, <Pause_time(s)>

例えば：

I/art : Explicit concurrent mark sweep GC freed 104710(7MB) AllocSpace objects, 21(416KB) LOS objects, 33% free, 25MB/38MB, paused 1.230ms total 67.216ms

GC Reason

何がGCのトリガーとなったか、およびどのタイプのガベージコレクションであるかを示します。考えられる値は以下の通りです：

  • Concurrent

並行GCで、アプリのスレッドを一時停止させません。このGCはバックグラウンドスレッドで実行され、メモリ割り当てをブロックしません。

  • Alloc

ヒープが満杯の時にアプリがメモリ割り当てをリクエストしたため、GCが開始されました。この場合、GCは現在のスレッド（メモリ割り当てをリクエストしたスレッド）で実行されます。

  • Explicit

アプリによって明示的にGCがリクエストされました。例えば、System.gc() や runtime.gc() の呼び出しによるものです。Dalvikと同様に、ARTでもGCを信頼し、明示的なGCのリクエストはできるだけ避けることが推奨されます。現在のスレッドをブロックし、不必要なCPUサイクルを消費するため、明示的なGCは推奨されません。GCによって他のスレッドがプリエンプト（横取り）された場合、明示的なGCはjank（カクつき）を引き起こす可能性もあります。

P.S. jankとは、第nフレームが描画され���後、本来なら第n+1フレームを描画すべきなのに、CPUが横取りされてデータが準備できなかったため、もう一度第nフレームを表示し、次回の描画時に第n+1フレームを表示する現象を指します。

  • NativeAlloc

BitmapやRenderScriptオブジェクトなど、ネイティブによるネイティブメモリ割り当ての圧力によって引き起こされるGCです。

  • CollectorTransition

ヒープの移行によって引き起こされるGCです。実行時にガベージコレクタが動的に切り替わることで発生します。ガベージコレクタの移行プロセスには、すべてのオブジェクトをfree-list backed spaceからbump pointer spaceへコピーする（またはその逆）処理が含まれます。現在のガベージコレクタの移行は、低RAMデバイスでアプリの実行状態が変わる時（例えば、ユーザーが気づくような停止状態から気づかない状態へ移行する時など）にのみ発生します。

  • HomogeneousSpaceCompact

Homogeneous space compactionは、free-list space同士の統合であり、通常、アプリがユーザーに気づかれない状態になった時に発生します。これを行う主な理由は、RAMの使用量を減らし、ヒープの断片化を解消することです。

  • DisableMovingGc

本当のGCの理由ではありません。断片化を解消中のGCが GetPrimitiveArrayCritical によってブロックされている状態です。一般的に、 GetPrimitiveArrayCritical はガベージコレクタの移行を制限するため、使用しないことを強くお勧めします。

  • HeapTrim

これも本当のGCの理由ではありませんが、ヒープのトリム（整理）が終わるまでGCがブロックされている状態を示します。

GC Name

ARTにはいくつかの異なるGCがあります：

  • Concurrent mark sweep (CMS)

ヒープ全体のガベージコレクタで、image以外のすべての空間を回収して解放します。

  • Concurrent partial mark sweep

ヒープ全体のガベージコレクタに近いもので、imageとzygote以外のすべての空間を回収します。

  • Concurrent sticky mark sweep

世代別ガベージコレクタで、前回のGCから現在までに割り当てられたオブジェクトのみを解放します。このGCは、ヒープ全体や部分的なマークスイープ（mark sweep）よりも頻繁に実行されます。なぜなら、より速く、停止時間が短いからです。

  • Marksweep + semispace

非並行のGCで、ヒープの移行やhomogeneous space compaction（ヒープの断片化を解消するため）に使用されます。

Objects freed

今回のGCで、非大オブジェクト空間（non large object space）から回収されたオブジェクトの数です。

Size freed

今回のGCで、非大オブジェクト空間から回収されたバイト数です。

Large objects freed

今回のGCで、大オブジェクト空間から回収されたオブジェクトの数です。

Large object size freed

今回のGCで、大オブジェクト空間から回収されたバイト数です。

Heap stats

空き空間の割合と [使用済みメモリ量]/[ヒープの総サイズ] です。

Pause times

一般的に、GCの実行中、停止回数は変更されたオブジェクトの参照数に比例します。現在、ART CMS GCはGC終了時に1回だけ停止します。GCの移行時には長い停止時間があり、これがGCの実行時間の主な要因となります。

もしlogcatで大量のGCログを確認した場合、ヒープ統計（例では 25MB/38MB）に注目してください。この値が継続的に増加し、減少しない場合、メモリリークが存在する可能性があります。もしGCの理由が Alloc である場合、ヒープがすでに満杯に近づいており、OOM（Out Of Memory）になる寸前であることを示しています。

コメント

コメントはまだありません

コメントを書く