バグレポートを読む

どのようなタイプの開発であっても、バグを避けることはできません。そのため、問題の特定と解決のためにバグレポートが不可欠です。Android のすべてのバージョンで、Android Debug Bridge(adb)を使用したバグレポートの取得がサポートされています。Android バージョン 4.2 以降の場合、バグレポートを取得してメールやドライブなどを通じて共有するための開発者向けオプションがサポートされています。

Android バグレポートには、dumpsysdumpstatelogcat のデータがテキスト(.txt)形式で含まれており、個々のコンテンツを簡単に検索できます。以下のセクションでは、バグレポートのコンポーネント、よくある問題、バグに関連するログを見つけるためのヒントと grep コマンドについて説明します。また、ほとんどのセクションで、grep コマンドとその出力の例や、dumpsys 出力の例を記載しています。

logcat

logcat ログは、すべての logcat 情報の文字列ベースのダンプです。[system] の部分は、フレームワーク自体のログであり、他のすべてのログが格納される [main] よりも長い期間の履歴が記録されます。各行は、timestamp PID TID log-level で始まります。

イベントログの表示

このログには、バイナリ形式のログメッセージの文字列表現が格納されます。logcat ログよりもノイズは少ないものの、読みやすくはありません。イベントログを確認する際、このセクションを対象として特定のプロセス ID(PID)を検索すると、プロセスが何を行っているのか確認できます。基本的な書式は timestamp PID TID log-level log-tag tag-values です。

ログレベルには以下のものがあります。

  • V: 詳細
  • D: デバッグ
  • I: 情報
  • W: 警告
  • E: エラー

 

他の有用なイベントログのタグについては、/services/core/java/com/android/server/EventLogTags.logtags をご覧ください。

ANR とデッドロック

バグレポートは、ANR(アプリケーション応答なし)エラーやデッドロック イベントの原因の特定に役立ちます。

応答しないアプリを特定する

アプリが一定時間内に応答しない場合(多くの場合、メインスレッドがブロックされているかビジー状態のため)、システムはプロセスを強制終了して、スタックを /data/anr にダンプします。ANR の背後にある原因を見つけるためには、バイナリ イベントログ内で am_anr を grep します。

また、logcat ログ内で ANR in を grep する方法もあります。このログには、ANR の発生時に CPU が何に使用されていたのかに関する詳細情報が記載されています。

スタック トレースの検索

多くの場合、ANR に対応するスタック トレースを見つけることができます。VM トレースのタイムスタンプと PID が、調査対象の ANR と合致していることを確認したら、プロセスのメインスレッドをチェックします。次の点に注意してください。

  • メインスレッドが示すのは、「ANR 時にスレッドが何を行っていたのか」ということだけです。そのため、ANR の真の原因に対応していない可能性があります。バグレポート内のスタックが原因ではなく、他に長期間(ただし、ANR と見なすには不十分な時間)停止していたものがある可能性があります。
  • スタック トレースのセット(VM TRACES JUST NOWVM TRACES AT LAST ANR)が複数存在することがあります。正しいセクションが表示されているか確認してください。

デッドロックの検索

多くの場合、デッドロックは最初 ANR として表示されます。これはスレッドが停止するためです。デッドロックがシステム サーバーに達すると、ウォッチドッグが最終的にそのプロセスを強制終了し、WATCHDOG KILLING SYSTEM PROCESS のようなエントリをログに記録します。ユーザーにはデバイスがリブートしたように見えますが、実際にはデバイスのリブートではなくランタイムの再起動です。

  • ランタイムの再起動の場合、システム サーバーが終了して再起動し、デバイスにはブート アニメーションが再び表示されます。
  • リブートの場合、カーネルがクラッシュしており、デバイスには Google ブートロゴが再び表示されます。

デッドロックを見つけるには、VM トレース セクション内で、スレッド B が保持するものをスレッド A が待ち、スレッド A が保持するものをスレッド B が待っているというパターンを探します。

アクティビティ

アクティビティは、電話番号のダイヤル、写真の撮影、メールの送信などを行うための操作画面を提供するアプリ コンポーネントです。バグレポートの観点では、アクティビティとは、フォーカスされていた単一のユーザー操作を示します。そのため、クラッシュ時にフォーカスされていたアクティビティの特定が非常に重要になります。アクティビティ(ActivityManager 経由)はプロセスを実行するため、対象アクティビティのすべてのプロセス停止およびプロセス開始の位置を特定できると、トラブルシューティングに役立ちます。

フォーカスされていたアクティビティを確認する

フォーカスされていたアクティビティの履歴を確認するには、am_focused_activity を検索します。

プロセスの開始の表示

プロセスの開始履歴を表示するには、Start proc を検索します。

デバイスのスラッシングの確認

デバイスがスラッシングしているかどうかを判断するには、am_proc_diedam_proc_start の周辺でアクティビティが短時間で異常に増加していないかチェックします。

メモリ

多くの Android デバイスでは物理メモリに制約があるため、ランダム アクセス メモリ(RAM)の管理が不可欠です。バグレポートには、メモリ不足を示すさまざまなインジケーターや、メモリ スナップショットを提供する dumpstate が含まれています。

メモリ不足を識別する

メモリが不足すると、システムがスラッシングを行い、一部のプロセスを強制終了してメモリを解放しつつ、引き続き他のプロセスを開始する場合があります。メモリ不足の証拠を確認するには、バイナリ イベントログ内で am_proc_died エントリと am_proc_start エントリが集中していないかチェックします。

また、メモリ不足の場合、タスクの切り替えが遅くなったり、前に戻る操作ができなくなったりする可能性があります(ユーザーが戻ろうとしているタスクが強制終了しているため)。ランチャーが強制終了した場合、ユーザーがホームボタンに触れるとランチャーが再起動し、ランチャーによってコンテンツがリロードされたことがログに記録されます。

履歴インジケーターを確認する

バイナリ イベントログ内の am_low_memory エントリは、最後のキャッシュ プロセスが終了したことを示します。この後、システムはサービスの強制終了を開始します。

スラッシング インジケーターを確認する

システム スラッシング(ページング、直接回収など)の他のインジケーターとしては、kswapdkworkermmcqd の消費サイクルなどがあります。なお、バグレポートの収集自体が、スラッシング インジケーターに影響を与える場合があります。

ANR ログで、同様のメモリ スナップショットを取得できます。

メモリ スナップショットの取得

メモリ スナップショットは、実行中の Java プロセスやネイティブ プロセスをリスト表示する dumpstate です(詳細については、メモリ割り当て全体を確認するをご覧ください)。スナップショットが示すのは、特定の時点の状態だけに限られます。実際のシステムの状態は、スナップショット前よりも良くなっている(または悪くなっている)場合があります。

ブロードキャスト

アプリはブロードキャストを生成して、現在のアプリ内や別のアプリに対してイベントを送信します。ブロードキャスト レシーバは、フィルタ経由で特定のメッセージをサブスクライブすることで、ブロードキャストのリッスンと応答を行うことができます。バグレポートには、送信済みブロードキャストと未送信ブロードキャストに関する情報や、特定のブロードキャストをリッスンするすべてのレシーバの dumpsys が含まれています。

ブロードキャスト履歴を確認する

ブロードキャスト履歴とは、すでに送信済みのブロードキャストの履歴を意味し、新しい順でリスト表示されます。

[summary] セクションには、直近 300 件のフォアグラウンド ブロードキャストと直近 300 件のバックグラウンド ブロードキャストの概要が記録されています。

[detail] セクションには、直近 50 件のフォアグラウンド ブロードキャストと直近 50 件のバックグラウンド ブロードキャストの詳細情報と、各ブロードキャストのレシーバが記載されています。レシーバは以下のように登録されます。

  • BroadcastFilter エントリを持つレシーバは実行時に登録され、すでに実行中のプロセスに対してのみ送信されます。
  • ResolveInfo エントリを持つレシーバは、マニフェスト エントリを通じて登録されます。ActivityManager は、各 ResolveInfo のプロセスがまだ実行中でない場合に、プロセスを開始します。

アクティブなブロードキャストの表示

アクティブ ブロードキャストとは、まだ送信されていないブロードキャストを意味します。キュー内に大量のブロードキャストがある場合、システムによるブロードキャストのディスパッチが追いついていないことになります。

ブロードキャスト リスナーを確認する

ブロードキャストをリッスンするレシーバのリストを確認するには、dumpsys activity broadcasts 内の [Receiver Resolver Table] をチェックします。次の例の場合、USER_PRESENT をリッスンするすべてのレシーバが表示されています。

モニター競合

モニター競合のロギングは、実際のモニター競合を示す場合もありますが、ほとんどの場合、システムに大きな負荷がかかり、すべての処理が遅くなっていることを示します。長時間のモニター イベントが ART によってロギングされ、システムログやイベントログに表示されることがあります。

システムログでは、以下のように表示されます。

10-01 18:12:44.343 29761 29914 W art     : Long monitor contention event with owner method=void android.database.sqlite.SQLiteClosable.acquireReference() from SQLiteClosable.java:52 waiters=0 for 3.914s

イベントログでは、以下のように表示されます。

10-01 18:12:44.364 29761 29914 I dvm_lock_sample: [com.google.android.youtube,0,pool-3-thread-9,3914,ScheduledTaskMaster.java,138,SQLiteClosable.java,52,100]

バックグラウンド コンパイル

コンパイルはコストがかさみ、デバイスにも負荷がかかる可能性があります。

Google Play ストアのアップデートのダウンロード中に、バックグラウンドでコンパイルが行われることがあります。この場合、Google Play ストア アプリからのメッセージ(finsky)と installd が、dex2oat メッセージより先に表示されます。

また、まだコンパイルされていない dex ファイルをアプリがロードしている間に、バックグラウンドでコンパイルが行われることもあります。この場合、finskyinstalld のロギングは表示されません。

ナラティブ

問題のナラティブ(どのように始まったのか、何が起こったか、システムはどのように反応したのか)を作成するには、イベントに関する確実なタイムラインが必要です。バグレポートの情報を利用することで、複数のログを横断してタイムラインを同期し、バグレポートの正確なタイムスタンプを特定することができます。

タイムラインを同期する

バグレポートには、システムログや、イベントログ、カーネルログ、ブロードキャスト用の複数の専用タイムライン、バッテリー統計情報など、複数の並列タイムラインが反映されています。残念ながら多くの場合、タイムラインはそれぞれ異なるタイムベースに基づいて報告されます。

システムログとイベントログのタイムスタンプは、他のほとんどのタイムスタンプと同様、ユーザー タイムゾーンと同じタイムゾーンを使用します。たとえば、ユーザーがホームボタンをタップすると、システムログは次のようにレポートします。

10-03 17:19:52.939  1963  2071 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10200000 cmp=com.google.android.googlequicksearchbox/com.google.android.launcher.GEL (has extras)} from uid 1000 on display 0

同じアクションに対して、イベントログは次のようにレポします。

10-03 17:19:54.279  1963  2071 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]

カーネル(dmesg)ログは別のタイムベースを使用しており、各ログ項目に対してブートローダー完了後の秒数をタグ付けします。このタイムスケールを他のタイムスケールに登録するには、[suspend exit] メッセージと [suspend entry] メッセージを検索します。

<6>[201640.779997] PM: suspend exit 2015-10-03 19:11:06.646094058 UTC
…
<6>[201644.854315] PM: suspend entry 2015-10-03 19:11:10.720416452 UTC

カーネルログにはサスペンド中の時間情報が含まれない場合があるため、[suspend entry] メッセージと [suspend exit] メッセージの間のログを区分的に登録する必要があります。また、カーネルログは UTC タイムゾーンを使用しているため、ユーザー タイムゾーンに合わせて調整する必要があります。

バグレポート時刻を識別する

バグレポートを取得したタイミングを識別するには、まず、システムログ(logcat)で dumpstate: begin をチェックします。

10-03 17:19:54.322 19398 19398 I dumpstate: begin

次に、カーネルログ(dmesg)で Starting service 'bugreport' メッセージのタイムスタンプをチェックします。

<5>[207064.285315] init: Starting service 'bugreport'...

タイムラインを同期するの注意事項を念頭に置きながら、上記 2 つのイベントを関連付けます。バグレポートが開始した後は多くのイベントが発生しますが、バグレポートの取得自体がシステムに大きな負荷をかけるため、ほとんどのアクティビティはあまり役に立ちません。

電源

イベントログには、画面の電源ステータスが記載されます。0 は画面オフ、1 は画面オン、2 はキーガード完了を示します。

また、バグレポートには、ウェイクロックに関する統計情報も記載されています。ウェイクロックとは、アプリが動作するうえでデバイスの電源をオンにしたままにする必要があることを示すために、アプリ デベロッパーが使用するメカニズムです(ウェイクロックの詳細については、PowerManager.WakeLockCPU をオンのままにするをご覧ください)。

総ウェイクロック持続時間の統計情報では、ウェイクロックによってデバイスがオンになっていた時間だけがトラッキングされ、画面がオンになっていた時間は含まれません。また、複数のウェイクロックが同時に実行された場合、ウェイクロック持続時間はその複数のウェイクロック間で分配されます。

電源の状態を詳細に可視化する必要がある場合は、Battery Historian をご利用ください。これは、Google のオープンソース ツールで、Android バグレポート ファイルを使用してバッテリー消費を分析できます。

パッケージ

DUMP OF SERVICE パッケージには、アプリ バージョンなど、有用な情報が記載されています。

プロセス

バグレポートには、開始時刻と終了時刻や、ランタイムの長さ、関連サービス、oom_adj スコアなど、プロセスに関する膨大な量のデータが記載されています。Android がプロセスを管理する仕組みについては、プロセスとスレッドをご覧ください。

プロセス ランタイムを判断する

procstats セクションには、プロセスおよび関連サービスが実行されている期間に関する詳細な統計情報が記載されています。人間が読める形式の簡潔なサマリーを確認するには、AGGREGATED OVER を検索して、過去 3 時間あるいは 24 時間のデータを表示します。そして、Summary: を検索して、プロセスのリストを表示し、各優先度のプロセスが実行された時間の長さを比較し、min-average-max PSS / min-average-max USS 形式で RAM の使用状況を確認します。

プロセスが実行されている理由

dumpsys activity processes セクションでは、現在実行中の全プロセスが oom_adj スコア順に表示されます(Android は、プロセスに oom_adj 値を割り当てることで、プロセスの重要性を示します。この値は ActivityManager によって動的に更新されます)。この出力は、メモリ スナップショットの出力と似ていますが、プロセスが実行されている理由に関する追加情報が含まれています。次の例の太字のエントリは、gms.persistent プロセスが vis(visible)優先度で実行されていることを示します。このシステム プロセスが実行されている理由として、NetworkLocationService にバインドされているためであることがわかります。

スキャン

Bluetooth Low Energy(BLE)スキャンを過剰に実行するアプリを特定する手順は次のとおりです。

  • 以下のコマンドで、BluetoothLeScanner のログメッセージを検索します。
    $ grep 'BluetoothLeScanner' ~/downloads/bugreport.txt
    07-28 15:55:19.090 24840 24851 D BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
    
  • ログメッセージ内で PID を見つけます。この例の場合、「24840」と「24851」が PID(プロセス ID)と TID(スレッド ID)を示します。
  • PID に関連付けられているアプリを見つけます。
    PID #24840: ProcessRecord{4fe996a 24840:com.badapp/u0a105}
    

    この例の場合、パッケージ名は com.badapp です。

  • Google Play(https://play.google.com/store/apps/details?id=com.badapp)でパッケージ名を検索して、該当するアプリを特定します。

注: Android 7.0 を搭載しているデバイスの場合、BLE スキャンのデータがシステムによって収集され、スキャンを開始したアプリにそのアクティビティが関連付けられます。詳細については、Low Energy(LE)と Bluetooth スキャンをご覧ください。