バグレポートを読み取る

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

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

logcat

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

------ SYSTEM LOG (logcat -v threadtime -d *:v) ------
--------- beginning of system
Blah
Blah
Blah

--------- beginning of main
Blah 
Blah
Blah

イベントログを確認する

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

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

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

------ EVENT LOG (logcat -b events -v threadtime -d *:v) ------
09-28 13:47:34.179   785  5113 I am_proc_bound: [0,23054,com.google.android.gms.unstable]
09-28 13:47:34.777   785  1975 I am_proc_start: [0,23134,10032,com.android.chrome,broadcast,com.android.chrome/org.chromium.chrome.browser.precache.PrecacheServiceLauncher]
09-28 13:47:34.806   785  2764 I am_proc_bound: [0,23134,com.android.chrome]
...

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

ANR とデッドロック

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

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

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

grep "am_anr" bugreport-2015-10-01-18-13-48.txt
10-01 18:12:49.599  4600  4614 I am_anr  : [0,29761,com.google.android.youtube,953695941,executing service com.google.android.youtube/com.google.android.apps.youtube.app.offline.transfer.OfflineTransferService]
10-01 18:14:10.211  4600  4614 I am_anr  : [0,30363,com.google.android.apps.plus,953728580,executing service com.google.android.apps.plus/com.google.android.apps.photos.service.PhotosService]

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

grep "ANR in" bugreport-2015-10-01-18-13-48.txt
10-01 18:13:11.984  4600  4614 E ActivityManager: ANR in com.google.android.youtube
10-01 18:14:31.720  4600  4614 E ActivityManager: ANR in com.google.android.apps.plus
10-01 18:14:31.720  4600  4614 E ActivityManager: PID: 30363
10-01 18:14:31.720  4600  4614 E ActivityManager: Reason: executing service com.google.android.apps.plus/com.google.android.apps.photos.service.PhotosService
10-01 18:14:31.720  4600  4614 E ActivityManager: Load: 35.27 / 23.9 / 16.18
10-01 18:14:31.720  4600  4614 E ActivityManager: CPU usage from 16ms to 21868ms later:
10-01 18:14:31.720  4600  4614 E ActivityManager:   74% 3361/mm-qcamera-daemon: 62% user + 12% kernel / faults: 15276 minor 10 major
10-01 18:14:31.720  4600  4614 E ActivityManager:   41% 4600/system_server: 18% user + 23% kernel / faults: 18597 minor 309 major
10-01 18:14:31.720  4600  4614 E ActivityManager:   32% 27420/com.google.android.GoogleCamera: 24% user + 7.8% kernel / faults: 48374 minor 338 major
10-01 18:14:31.720  4600  4614 E ActivityManager:   16% 130/kswapd0: 0% user + 16% kernel
10-01 18:14:31.720  4600  4614 E ActivityManager:   15% 283/mmcqd/0: 0% user + 15% kernel
...
10-01 18:14:31.720  4600  4614 E ActivityManager:   0.1% 27248/irq/503-synapti: 0%
10-01 18:14:31.721  4600  4614 I ActivityManager: Killing 30363:com.google.android.apps.plus/u0a206 (adj 0): bg anr

スタック トレースを見つける

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

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

------ VM TRACES AT LAST ANR (/data/anr/traces.txt: 2015-10-01 18:14:41) ------

----- pid 30363 at 2015-10-01 18:14:11 -----
Cmd line: com.google.android.apps.plus
Build fingerprint: 'google/angler/angler:6.0/MDA89D/2294819:userdebug/dev-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=3978 post zygote classes=27
Intern table: 45068 strong; 21 weak
JNI: CheckJNI is off; globals=283 (plus 360 weak)
Libraries: /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libwebviewchromium_loader.so libjavacore.so (7)
Heap: 29% free, 21MB/30MB; 32251 objects
Dumping cumulative Gc timings
Total number of allocations 32251
Total bytes allocated 21MB
Total bytes freed 0B
Free memory 9MB
Free memory until GC 9MB
Free memory until OOME 490MB
Total memory 30MB
Max memory 512MB
Zygote space size 1260KB
Total mutator paused time: 0
Total time waiting for GC to complete: 0
Total GC count: 0
Total GC time: 0
Total blocking GC count: 0
Total blocking GC time: 0

suspend all histogram:  Sum: 119.728ms 99% C.I. 0.010ms-107.765ms Avg: 5.442ms Max: 119.562ms
DALVIK THREADS (12):
"Signal Catcher" daemon prio=5 tid=2 Runnable
  | group="system" sCount=0 dsCount=0 obj=0x12c400a0 self=0xef460000
  | sysTid=30368 nice=0 cgrp=default sched=0/0 handle=0xf4a69930
  | state=R schedstat=( 9021773 5500523 26 ) utm=0 stm=0 core=1 HZ=100
  | stack=0xf496d000-0xf496f000 stackSize=1014KB
  | held mutexes= "mutator lock"(shared held)
  native: #00 pc 0035a217  /system/lib/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, char const*, art::ArtMethod*, void*)+126)
  native: #01 pc 0033b03b  /system/lib/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&) const+138)
  native: #02 pc 00344701  /system/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+424)
  native: #03 pc 00345265  /system/lib/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+200)
  native: #04 pc 00345769  /system/lib/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+124)
  native: #05 pc 00345e51  /system/lib/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+312)
  native: #06 pc 0031f829  /system/lib/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+68)
  native: #07 pc 00326831  /system/lib/libart.so (art::SignalCatcher::HandleSigQuit()+896)
  native: #08 pc 003270a1  /system/lib/libart.so (art::SignalCatcher::Run(void*)+324)
  native: #09 pc 0003f813  /system/lib/libc.so (__pthread_start(void*)+30)
  native: #10 pc 00019f75  /system/lib/libc.so (__start_thread+6)
  (no managed stack frames)

"main" prio=5 tid=1 Suspended
  | group="main" sCount=1 dsCount=0 obj=0x747552a0 self=0xf5376500
  | sysTid=30363 nice=0 cgrp=default sched=0/0 handle=0xf74feb34
  | state=S schedstat=( 331107086 164153349 851 ) utm=6 stm=27 core=3 HZ=100
  | stack=0xff00f000-0xff011000 stackSize=8MB
  | held mutexes=
  kernel: __switch_to+0x7c/0x88
  kernel: futex_wait_queue_me+0xd4/0x130
  kernel: futex_wait+0xf0/0x1f4
  kernel: do_futex+0xcc/0x8f4
  kernel: compat_SyS_futex+0xd0/0x14c
  kernel: cpu_switch_to+0x48/0x4c
  native: #00 pc 000175e8  /system/lib/libc.so (syscall+28)
  native: #01 pc 000f5ced  /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+80)
  native: #02 pc 00335353  /system/lib/libart.so (art::Thread::FullSuspendCheck()+838)
  native: #03 pc 0011d3a7  /system/lib/libart.so (art::ClassLinker::LoadClassMembers(art::Thread*, art::DexFile const&, unsigned char const*, art::Handle<art::mirror::Class>, art::OatFile::OatClass const*)+746)
  native: #04 pc 0011d81d  /system/lib/libart.so (art::ClassLinker::LoadClass(art::Thread*, art::DexFile const&, art::DexFile::ClassDef const&, art::Handle<art::mirror::Class>)+88)
  native: #05 pc 00132059  /system/lib/libart.so (art::ClassLinker::DefineClass(art::Thread*, char const*, unsigned int, art::Handle<art::mirror::ClassLoader>, art::DexFile const&, art::DexFile::ClassDef const&)+320)
  native: #06 pc 001326c1  /system/lib/libart.so (art::ClassLinker::FindClassInPathClassLoader(art::ScopedObjectAccessAlreadyRunnable&, art::Thread*, char const*, unsigned int, art::Handle<art::mirror::ClassLoader>, art::mirror::Class**)+688)
  native: #07 pc 002cb1a1  /system/lib/libart.so (art::VMClassLoader_findLoadedClass(_JNIEnv*, _jclass*, _jobject*, _jstring*)+264)
  native: #08 pc 002847fd  /data/dalvik-cache/arm/system@framework@boot.oat (Java_java_lang_VMClassLoader_findLoadedClass__Ljava_lang_ClassLoader_2Ljava_lang_String_2+112)
  at java.lang.VMClassLoader.findLoadedClass!(Native method)
  at java.lang.ClassLoader.findLoadedClass(ClassLoader.java:362)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:499)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:469)
  at android.app.ActivityThread.installProvider(ActivityThread.java:5141)
  at android.app.ActivityThread.installContentProviders(ActivityThread.java:4748)
  at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4688)
  at android.app.ActivityThread.-wrap1(ActivityThread.java:-1)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1405)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:148)
  at android.app.ActivityThread.main(ActivityThread.java:5417)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)

  ...
  Stacks for other threads in this process follow
  ...

デッドロックを見つける

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

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

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

"Binder_B" prio=5 tid=73 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x13faa0a0 self=0x95e24800
  | sysTid=2016 nice=0 cgrp=default sched=0/0 handle=0x8b68d930
  | state=S schedstat=( 9351576559 4141431119 16920 ) utm=819 stm=116 core=1 HZ=100
  | stack=0x8b591000-0x8b593000 stackSize=1014KB
  | held mutexes=
  at com.android.server.pm.UserManagerService.exists(UserManagerService.java:387)
  - waiting to lock <0x025f9b02> (a android.util.ArrayMap) held by thread 20
  at com.android.server.pm.PackageManagerService.getApplicationInfo(PackageManagerService.java:2848)
  at com.android.server.AppOpsService.getOpsRawLocked(AppOpsService.java:881)
  at com.android.server.AppOpsService.getOpsLocked(AppOpsService.java:856)
  at com.android.server.AppOpsService.noteOperationUnchecked(AppOpsService.java:719)
  - locked <0x0231885a> (a com.android.server.AppOpsService)
  at com.android.server.AppOpsService.noteOperation(AppOpsService.java:713)
  at com.android.server.AppOpsService$2.getMountMode(AppOpsService.java:260)
  at com.android.server.MountService$MountServiceInternalImpl.getExternalStorageMountMode(MountService.java:3416)
  at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3228)
  at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3170)
  at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3059)
  at com.android.server.am.BroadcastQueue.processNextBroadcast(BroadcastQueue.java:1070)
  - locked <0x044d166f> (a com.android.server.am.ActivityManagerService)
  at com.android.server.am.ActivityManagerService.finishReceiver(ActivityManagerService.java:16950)
  at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:494)
  at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2432)
  at android.os.Binder.execTransact(Binder.java:453)
...
  "PackageManager" prio=5 tid=20 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x1304f4a0 self=0xa7f43900
  | sysTid=1300 nice=10 cgrp=bg_non_interactive sched=0/0 handle=0x9fcf9930
  | state=S schedstat=( 26190141996 13612154802 44357 ) utm=2410 stm=209 core=2 HZ=100
  | stack=0x9fbf7000-0x9fbf9000 stackSize=1038KB
  | held mutexes=
  at com.android.server.AppOpsService.noteOperationUnchecked(AppOpsService.java:718)
  - waiting to lock <0x0231885a> (a com.android.server.AppOpsService) held by thread 73
  at com.android.server.AppOpsService.noteOperation(AppOpsService.java:713)
  at com.android.server.AppOpsService$2.getMountMode(AppOpsService.java:260)
  at com.android.server.AppOpsService$2.hasExternalStorage(AppOpsService.java:273)
  at com.android.server.MountService$MountServiceInternalImpl.hasExternalStorage(MountService.java:3431)
  at com.android.server.MountService.getVolumeList(MountService.java:2609)
  at android.os.storage.StorageManager.getVolumeList(StorageManager.java:880)
  at android.os.Environment$UserEnvironment.getExternalDirs(Environment.java:83)
  at android.os.Environment.isExternalStorageEmulated(Environment.java:708)
  at com.android.server.pm.PackageManagerService.isExternalMediaAvailable(PackageManagerService.java:9327)
  at com.android.server.pm.PackageManagerService.startCleaningPackages(PackageManagerService.java:9367)
  - locked <0x025f9b02> (a android.util.ArrayMap)
  at com.android.server.pm.PackageManagerService$PackageHandler.doHandleMessage(PackageManagerService.java:1320)
  at com.android.server.pm.PackageManagerService$PackageHandler.handleMessage(PackageManagerService.java:1122)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:148)
  at android.os.HandlerThread.run(HandlerThread.java:61)
  at com.android.server.ServiceThread.run(ServiceThread.java:46)

アクティビティ

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

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

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

grep "am_focused_activity" bugreport-2015-10-01-18-13-48.txt
10-01 18:10:41.409  4600 14112 I am_focused_activity: [0,com.google.android.GoogleCamera/com.android.camera.CameraActivity]
10-01 18:11:17.313  4600  5687 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]
10-01 18:11:52.747  4600 14113 I am_focused_activity: [0,com.google.android.GoogleCamera/com.android.camera.CameraActivity]
10-01 18:14:07.762  4600  5687 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]

プロセスの開始履歴を表示する

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

grep "Start proc" bugreport-2015-10-01-18-13-48.txt
10-01 18:09:15.309  4600  4612 I ActivityManager: Start proc 24533:com.metago.astro/u0a240 for broadcast com.metago.astro/com.inmobi.commons.analytics.androidsdk.IMAdTrackerReceiver
10-01 18:09:15.687  4600 14112 I ActivityManager: Start proc 24548:com.google.android.apps.fitness/u0a173 for service com.google.android.apps.fitness/.api.services.ActivityUpsamplingService
10-01 18:09:15.777  4600  6604 I ActivityManager: Start proc 24563:cloudtv.hdwidgets/u0a145 for broadcast cloudtv.hdwidgets/cloudtv.switches.SwitchSystemUpdateReceiver
10-01 18:09:20.574  4600  6604 I ActivityManager: Start proc 24617:com.wageworks.ezreceipts/u0a111 for broadcast com.wageworks.ezreceipts/.ui.managers.IntentReceiver
...

デバイスがスラッシングしているかどうかを判断する

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

grep -e "am_proc_died" -e "am_proc_start" bugreport-2015-10-01-18-13-48.txt
10-01 18:07:06.494  4600  9696 I am_proc_died: [0,20074,com.android.musicfx]
10-01 18:07:06.555  4600  6606 I am_proc_died: [0,31166,com.concur.breeze]
10-01 18:07:06.566  4600 14112 I am_proc_died: [0,18812,com.google.android.apps.fitness]
10-01 18:07:07.018  4600  7513 I am_proc_start: [0,20361,10113,com.sony.playmemories.mobile,broadcast,com.sony.playmemories.mobile/.service.StartupReceiver]
10-01 18:07:07.357  4600  4614 I am_proc_start: [0,20381,10056,com.google.android.talk,service,com.google.android.talk/com.google.android.libraries.hangouts.video.CallService]
10-01 18:07:07.784  4600  4612 I am_proc_start: [0,20402,10190,com.andcreate.app.trafficmonitor:loopback_measure_serivce,service,com.andcreate.app.trafficmonitor/.loopback.LoopbackMeasureService]
10-01 18:07:10.753  4600  5997 I am_proc_start: [0,20450,10097,com.amazon.mShop.android.shopping,broadcast,com.amazon.mShop.android.shopping/com.amazon.identity.auth.device.storage.LambortishClock$ChangeTimestampsBroadcastReceiver]
10-01 18:07:15.267  4600  6605 I am_proc_start: [0,20539,10173,com.google.android.apps.fitness,service,com.google.android.apps.fitness/.api.services.ActivityUpsamplingService]
10-01 18:07:15.985  4600  4612 I am_proc_start: [0,20568,10022,com.android.musicfx,broadcast,com.android.musicfx/.ControlPanelReceiver]
10-01 18:07:16.315  4600  7512 I am_proc_died: [0,20096,com.google.android.GoogleCamera]

メモリ

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

メモリ不足を識別する

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

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

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

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

grep "am_low_memory" bugreport-2015-10-01-18-13-48.txt
10-01 18:11:02.219  4600  7513 I am_low_memory: 41
10-01 18:12:18.526  4600 14112 I am_low_memory: 39
10-01 18:12:18.874  4600  7514 I am_low_memory: 38
10-01 18:12:22.570  4600 14112 I am_low_memory: 40
10-01 18:12:34.811  4600 20319 I am_low_memory: 43
10-01 18:12:37.945  4600  6521 I am_low_memory: 43
10-01 18:12:47.804  4600 14110 I am_low_memory: 43

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

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

------ CPU INFO (top -n 1 -d 1 -m 30 -t) ------

User 15%, System 54%, IOW 28%, IRQ 0%
User 82 + Nice 2 + Sys 287 + Idle 1 + IOW 152 + IRQ 0 + SIRQ 5 = 529

  PID   TID PR CPU% S     VSS     RSS PCY UID      Thread          Proc
15229 15229  0  19% R      0K      0K  fg root     kworker/0:2
29512 29517  1   7% D 1173524K 101188K  bg u0_a27   Signal Catcher  com.google.android.talk
24565 24570  3   6% D 2090920K 145168K  fg u0_a22   Signal Catcher  com.google.android.googlequicksearchbox:search
19525 19525  2   6% R   3476K   1644K  fg shell    top             top
24957 24962  2   5% R 1706928K 125716K  bg u0_a47   Signal Catcher  com.google.android.GoogleCamera
19519 19519  3   4% S      0K      0K  fg root     kworker/3:1
  120   120  0   3% S      0K      0K  fg root     mmcqd/1
18233 18233  1   3% S      0K      0K  fg root     kworker/1:1
25589 25594  1   2% D 1270476K  75776K  fg u0_a8    Signal Catcher  com.google.android.gms
19399 19399  2   1% S      0K      0K  fg root     kworker/2:2
 1963  1978  1   0% S 1819100K 125136K  fg system   android.fg      system_server
 1963  1981  3   0% S 1819100K 125136K  fg system   android.display system_server

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

10-03 17:19:59.959  1963  1976 E ActivityManager: ANR in com.google.android.apps.magazines
10-03 17:19:59.959  1963  1976 E ActivityManager: PID: 18819
10-03 17:19:59.959  1963  1976 E ActivityManager: Reason: Broadcast of Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.google.android.apps.magazines/com.google.apps.dots.android.newsstand.appwidget.NewsWidgetProvider (has extras) }
10-03 17:19:59.959  1963  1976 E ActivityManager: Load: 19.19 / 14.76 / 12.03
10-03 17:19:59.959  1963  1976 E ActivityManager: CPU usage from 0ms to 11463ms later:
10-03 17:19:59.959  1963  1976 E ActivityManager:   54% 15229/kworker/0:2: 0% user + 54% kernel
10-03 17:19:59.959  1963  1976 E ActivityManager:   38% 1963/system_server: 14% user + 23% kernel / faults: 17152 minor 1073 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   11% 120/mmcqd/1: 0% user + 11% kernel
10-03 17:19:59.959  1963  1976 E ActivityManager:   10% 2737/com.android.systemui: 4.7% user + 5.6% kernel / faults: 7211 minor 149 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   0.2% 1451/debuggerd: 0% user + 0.2% kernel / faults: 15211 minor 147 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   8.7% 6162/com.twofortyfouram.locale: 4% user + 4.7% kernel / faults: 4924 minor 260 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   6.1% 24565/com.google.android.googlequicksearchbox:search: 2.4% user + 3.7% kernel / faults: 2902 minor 129 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   6% 55/kswapd0: 0% user + 6% kernel
10-03 17:19:59.959  1963  1976 E ActivityManager:   4.9% 18819/com.google.android.apps.magazines: 1.5% user + 3.3% kernel / faults: 10129 minor 986 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   2.8% 18233/kworker/1:1: 0% user + 2.8% kernel
10-03 17:19:59.959  1963  1976 E ActivityManager:   4.2% 3145/com.android.phone: 2% user + 2.2% kernel / faults: 3005 minor 43 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   4.2% 8084/com.android.chrome: 2% user + 2.1% kernel / faults: 4798 minor 380 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   3.4% 182/surfaceflinger: 1.1% user + 2.3% kernel / faults: 842 minor 13 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   3% 18236/kworker/1:2: 0% user + 3% kernel
10-03 17:19:59.959  1963  1976 E ActivityManager:   2.9% 19231/com.android.systemui:screenshot: 0.8% user + 2.1% kernel / faults: 6119 minor 348 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   2.3% 15350/kworker/0:4: 0% user + 2.3% kernel
10-03 17:19:59.959  1963  1976 E ActivityManager:   2.2% 1454/mediaserver: 0% user + 2.2% kernel / faults: 479 minor 6 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   2% 16496/com.android.chrome:sandboxed_process10: 0.1% user + 1.8% kernel / faults: 3610 minor 234 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   1% 3119/com.android.nfc: 0.4% user + 0.5% kernel / faults: 1789 minor 17 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   1.7% 19337/com.jarettmillard.localeconnectiontype:background: 0.1% user + 1.5% kernel / faults: 7854 minor 439 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   0.7% 3066/com.google.android.inputmethod.latin: 0.3% user + 0.3% kernel / faults: 1336 minor 7 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   1% 25589/com.google.android.gms: 0.3% user + 0.6% kernel / faults: 2867 minor 237 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   0.9% 1460/sensors.qcom: 0.5% user + 0.4% kernel / faults: 262 minor 5 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   0.8% 3650/mpdecision: 0% user + 0.8% kernel / faults: 160 minor 1 major
10-03 17:19:59.959  1963  1976 E ActivityManager:   0.1% 3132/com.redbend.vdmc: 0% user + 0% kernel / faults: 1746 minor 5 major

メモリ スナップショットを取得する

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

• プロセスの実行時間については、プロセス ランタイムをご覧ください。
• 現在実行中のプロセスが実行されている理由については、プロセスが実行されている理由をご覧ください。

Total PSS by OOM adjustment:
    86752 kB: Native
               22645 kB: surfaceflinger (pid 197)
               18597 kB: mediaserver (pid 204)
               ...
   136959 kB: System
              136959 kB: system (pid 785)
   220218 kB: Persistent
              138859 kB: com.android.systemui (pid 947 / activities)
               39178 kB: com.android.nfc (pid 1636)
               28313 kB: com.android.phone (pid 1659)
               13868 kB: com.redbend.vdmc (pid 1646)
     9534 kB: Persistent Service
                9534 kB: com.android.bluetooth (pid 23807)
   178604 kB: Foreground
              168620 kB: com.google.android.googlequicksearchbox (pid 1675 / activities)
                9984 kB: com.google.android.apps.maps (pid 13952)
   188286 kB: Visible
               85326 kB: com.google.android.wearable.app (pid 1535)
               38978 kB: com.google.process.gapps (pid 1510)
               31936 kB: com.google.android.gms.persistent (pid 2072)
               27950 kB: com.google.android.gms.wearable (pid 1601)
                4096 kB: com.google.android.googlequicksearchbox:interactor (pid 1550)
    52948 kB: Perceptible
               52948 kB: com.google.android.inputmethod.latin (pid 1566)
   150851 kB: A Services
               81121 kB: com.google.android.gms (pid 1814)
               37586 kB: com.google.android.talk (pid 9584)
               10949 kB: com.google.android.music:main (pid 4019)
               10727 kB: com.motorola.targetnotif (pid 31071)
               10468 kB: com.google.android.GoogleCamera (pid 9984)
    33298 kB: Previous
               33298 kB: com.android.settings (pid 9673 / activities)
   165188 kB: B Services
               49490 kB: com.facebook.katana (pid 15035)
               22483 kB: com.whatsapp (pid 28694)
               21308 kB: com.iPass.OpenMobile (pid 5325)
               19788 kB: com.google.android.apps.googlevoice (pid 23934)
               17399 kB: com.google.android.googlequicksearchbox:search (pid 30359)
                9073 kB: com.google.android.apps.youtube.unplugged (pid 21194)
                7660 kB: com.iPass.OpenMobile:remote (pid 23754)
                7291 kB: com.pujie.wristwear.pujieblack (pid 24240)
                7157 kB: com.instagram.android:mqtt (pid 9530)
                3539 kB: com.qualcomm.qcrilmsgtunnel (pid 16186)
   204324 kB: Cached
               43424 kB: com.amazon.mShop.android (pid 13558)
               22563 kB: com.google.android.apps.magazines (pid 13844)
               ...
                4298 kB: com.google.android.apps.enterprise.dmagent (pid 13826)

ブロードキャスト

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

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

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

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

 Historical broadcasts summary [foreground]:
 #0: act=android.intent.action.SCREEN_ON flg=0x50000010
    +1ms dispatch +90ms finish
    enq=2015-10-29 17:10:51 disp=2015-10-29 17:10:51 fin=2015-10-29 17:10:51
  #1: act=android.intent.action.SCREEN_OFF flg=0x50000010
    0 dispatch +60ms finish
    enq=2015-10-29 17:10:05 disp=2015-10-29 17:10:05 fin=2015-10-29 17:10:05
 ...
 Historical broadcasts summary [background]:
 ...

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

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

Historical broadcasts [foreground]:
 ...
 Historical broadcasts [background]:
 Historical Broadcast background #0:
 ...
 Historical Broadcast background #5:
    BroadcastRecord{18dbb16 u0 android.intent.action.USER_PRESENT} to user 0
    Intent { act=android.intent.action.USER_PRESENT flg=0x24000010 }
    caller=com.android.systemui 2925:com.android.systemui/u0a27 pid=2925 uid=10027
    enqueueClockTime=2015-10-29 17:10:55 dispatchClockTime=2015-10-29 17:10:55
    dispatchTime=-2s321ms (0 since enq) finishTime=-2s320ms (+1ms since disp)
    Receiver #0: BroadcastFilter{8181cc1 u-1 ReceiverList{5d929a8 902 system/1000/u-1 local:eca4dcb}}
    Receiver #1: BroadcastFilter{6371c97 u-1 ReceiverList{2938b16 902 system/1000/u-1 local:840b831}}
    ...
    Receiver #19: BroadcastFilter{93f16b u0 ReceiverList{5c61eba 17016 com.google.android.gm/10079/u0 remote:24083e5}}
 ...
 Historical Broadcast background #37:
    BroadcastRecord{7f6dd6 u0 android.hardware.action.NEW_PICTURE} to user 0
    Intent { act=android.hardware.action.NEW_PICTURE dat=content://media/external/images/media/6345 flg=0x10 }
    caller=com.google.android.GoogleCamera 32734:com.google.android.GoogleCamera/u0a53 pid=32734 uid=10053
    enqueueClockTime=2015-10-29 17:09:48 dispatchClockTime=2015-10-29 17:09:49
    dispatchTime=-45s720ms (+399ms since enq) finishTime=-45s701ms (+19ms since disp)
    resultTo=null resultCode=0 resultData=null
    nextReceiver=4 receiver=null
    Receiver #0: ResolveInfo{33d2857 com.google.android.gms/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000}
      priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false
      ActivityInfo:
        name=com.google.android.libraries.social.mediamonitor.MediaMonitor
        packageName=com.google.android.gms
        enabled=true exported=true processName=com.google.android.gms
        ...
    Receiver #1: ResolveInfo{d9edf44 com.google.android.apps.maps/com.google.android.apps.gmm.ugc.clientnotification.StartPhotoTakenNotifierServiceReceiver m=0x608000}
      priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false
      ActivityInfo:
        name=com.google.android.apps.gmm.ugc.clientnotification.StartPhotoTakenNotifierServiceReceiver
        packageName=com.google.android.apps.maps
        enabled=true exported=true processName=com.google.android.apps.maps
        ...
    Receiver #2: ResolveInfo{743f82d com.google.android.apps.photos/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000}
      priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false
      ActivityInfo:
        name=com.google.android.libraries.social.mediamonitor.MediaMonitor
        packageName=com.google.android.apps.photos
        enabled=true exported=true processName=com.google.android.apps.photos
        ...
    Receiver #3: ResolveInfo{d5c9162 com.google.android.apps.plus/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000}
      priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false
      ActivityInfo:
        name=com.google.android.libraries.social.mediamonitor.MediaMonitor
        packageName=com.google.android.apps.plus
        enabled=true exported=true processName=com.google.android.apps.plus
        ...

アクティブ ブロードキャストを確認する

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

 Active ordered broadcasts [background]:
 Active Ordered Broadcast background #133: // size of queue
 ...

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

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

-------------------------------------------------------------------------------
ACTIVITY MANAGER BROADCAST STATE (dumpsys activity broadcasts)
..
  Receiver Resolver Table:
    Full MIME Types:
    ..
    Wild MIME Types:
    ..
    Schemes:
    ..
    Non-Data Actions:
    ..
        android.intent.action.USER_PRESENT:
          BroadcastFilter{8181cc1 u-1 ReceiverList{5d929a8 902 system/1000/u-1 local:eca4dcb}}
          BroadcastFilter{6371c97 u-1 ReceiverList{2938b16 902 system/1000/u-1 local:840b831}}
          BroadcastFilter{320c00 u0 ReceiverList{d3a6283 902 system/1000/u0 local:799c532}}
          BroadcastFilter{e486048 u0 ReceiverList{36fbaeb 902 system/1000/u0 local:5f51e3a}}
          BroadcastFilter{22b02 u-1 ReceiverList{b3f744d 902 system/1000/u-1 local:de837e4}}
          BroadcastFilter{3e989ab u0 ReceiverList{f8deffa 2981 com.google.process.gapps/10012/u0 remote:26bd225}}
          BroadcastFilter{fb56150 u0 ReceiverList{22b7b13 2925 com.android.systemui/10027/u0 remote:c54a602}}
          BroadcastFilter{63bbb6 u-1 ReceiverList{ba6c751 3484 com.android.nfc/1027/u-1 remote:5c4a478}}
          BroadcastFilter{95ad20d u0 ReceiverList{d8374a4 3586 com.google.android.googlequicksearchbox/10029/u0 remote:feb3737}}
          BroadcastFilter{fdef551 u0 ReceiverList{28ca78 3745 com.google.android.gms.persistent/10012/u0 remote:f23afdb}}
          BroadcastFilter{9830707 u0 ReceiverList{aabd946 3745 com.google.android.gms.persistent/10012/u0 remote:a4da121}}
          BroadcastFilter{83c43d2 u0 ReceiverList{d422e5d 3745 com.google.android.gms.persistent/10012/u0 remote:f585034}}
          BroadcastFilter{8890378 u0 ReceiverList{26d2cdb 3745 com.google.android.gms.persistent/10012/u0 remote:dfa61ea}}
          BroadcastFilter{7bbb7 u0 ReceiverList{214b2b6 3745 com.google.android.gms.persistent/10012/u0 remote:8353a51}}
          BroadcastFilter{38d3566 u0 ReceiverList{de859c1 3745 com.google.android.gms.persistent/10012/u0 remote:e003aa8}}
          BroadcastFilter{3435d9f u0 ReceiverList{6e38b3e 3745 com.google.android.gms.persistent/10012/u0 remote:8dd7ff9}}
          BroadcastFilter{d0a34bb u0 ReceiverList{5091d4a 3745 com.google.android.gms.persistent/10012/u0 remote:d6d22b5}}
          BroadcastFilter{d43c416 u0 ReceiverList{51a3531 3745 com.google.android.gms.persistent/10012/u0 remote:d0b9dd8}}
          BroadcastFilter{aabf36d u0 ReceiverList{a88bf84 3745 com.google.android.gms.persistent/10012/u0 remote:a9d6197}}
          BroadcastFilter{93f16b u0 ReceiverList{5c61eba 17016 com.google.android.gm/10079/u0 remote:24083e5}}
          BroadcastFilter{68f794e u0 ReceiverList{4cb1c49 947 com.google.android.googlequicksearchbox:search/10029/u0 remote:251d250}}
      ..
    MIME Typed Actions:

モニター競合

モニター競合のロギングは、実際のモニター競合を示す場合もありますが、ほとんどの場合、システムに大きな負荷がかかり、すべての処理が遅くなっていることを示します。長時間のモニター イベントが 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]

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

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

09-14 06:27:05.670  2508  2587 E ActivityManager: CPU usage from 0ms to 5857ms later:
09-14 06:27:05.670  2508  2587 E ActivityManager:   84% 5708/dex2oat: 81% user + 2.3% kernel / faults: 3731 minor 1 major
09-14 06:27:05.670  2508  2587 E ActivityManager:   73% 2508/system_server: 21% user + 51% kernel / faults: 10019 minor 28 major
09-14 06:27:05.670  2508  2587 E ActivityManager:   1% 3935/com.android.phone: 0.3% user + 0.6% kernel / faults: 2684 minor 2 major

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

10-07 08:42:33.725 11051 11051 D Finsky  : [1] InstallerTask.advanceState: Prepare to patch com.garmin.android.apps.virb (com.garmin.android.apps.virb) from content://downloads/my_downloads/3602 format 2
10-07 08:42:33.752   495   495 I installd: free_cache(48637657) avail 15111192576
…
10-07 08:42:39.998  2497  2567 I PackageManager.DexOptimizer: Running dexopt (dex2oat) on: /data/app/vmdl436577137.tmp/base.apk pkg=com.garmin.android.apps.virb isa=arm vmSafeMode=false debuggable=false oatDir = /data/app/vmdl436577137.tmp/oat bootComplete=true
…

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

09-14 07:29:20.433 15736 15736 I dex2oat : /system/bin/dex2oat -j4 --dex-file=/data/user/0/com.facebook.katana/app_secondary_program_dex/program-72cef82b591768306676e10161c886b58b34315a308602be.dex.jar --oat-file=/data/user/0/com.facebook.katana/app_secondary_program_dex_opt/program-72cef82b591768306676e10161c886b58b34315a308602be.dex.dex
...
09-14 07:29:25.102 15736 15736 I dex2oat : dex2oat took 4.669s (threads: 4) arena alloc=7MB java alloc=3MB native alloc=29MB free=4MB

ナラティブ

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

タイムラインを同期する

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

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

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 はキーガード完了を示します。

grep screen_toggled bugreport-2015-10-18-16-52-22.txt
10-18 15:05:04.383   992   992 I screen_toggled: 1
10-18 15:05:07.010   992   992 I screen_toggled: 0
10-18 15:23:15.063   992   992 I screen_toggled: 1
10-18 15:23:25.684   992   992 I screen_toggled: 0
10-18 15:36:31.623   992   992 I screen_toggled: 1
10-18 15:36:37.660  3283  3283 I screen_toggled: 2

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

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

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

パッケージ

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

...
DUMP OF SERVICE package:
...
Packages:
...
 Package [com.google.android.gms] (3cf534b):
   userId=10013
   sharedUser=SharedUserSetting{98f3d28 com.google.uid.shared/10013}
   pkg=Package{b8f6a41 com.google.android.gms}
   codePath=/system/priv-app/PrebuiltGmsCore
   resourcePath=/system/priv-app/PrebuiltGmsCore
   legacyNativeLibraryDir=/system/priv-app/PrebuiltGmsCore/lib
   primaryCpuAbi=arm64-v8a
   secondaryCpuAbi=armeabi-v7a
   versionCode=8186448 targetSdk=23
   versionName=8.1.86 (2287566-448)
   splits=[base]
   applicationInfo=ApplicationInfo{5158507 com.google.android.gms}
   flags=[ SYSTEM HAS_CODE ALLOW_CLEAR_USER_DATA ]
   privateFlags=[ PRIVILEGED ]
   dataDir=/data/user/0/com.google.android.gms
   supportsScreens=[small, medium, large, xlarge, resizeable, anyDensity]
   libraries:
     com.google.android.gms
   usesOptionalLibraries:
     com.android.location.provider
     com.google.android.ble
     com.android.media.remotedisplay
   usesLibraryFiles:
     /system/framework/com.android.media.remotedisplay.jar
     /system/framework/com.android.location.provider.jar
   timeStamp=2015-10-14 15:17:56
   firstInstallTime=2015-09-22 14:08:35
   lastUpdateTime=2015-10-14 15:17:56
   signatures=PackageSignatures{db63be6 [1af63d8]}
   installPermissionsFixed=true installStatus=1
   pkgFlags=[ SYSTEM HAS_CODE ALLOW_CLEAR_USER_DATA ]
   declared permissions:
     com.google.android.gms.permission.INTERNAL_BROADCAST: prot=signature, INSTALLED
     ...
     com.google.android.gms.permission.CAR_VENDOR_EXTENSION: prot=dangerous, INSTALLED
   User 0:  installed=true hidden=false stopped=false notLaunched=false enabled=0
     disabledComponents:
       com.google.android.gms.icing.service.PowerConnectedReceiver
       ...
       com.google.android.gms.icing.proxy.AppsMonitor
     enabledComponents:
       com.google.android.gms.mdm.receivers.GmsRegisteredReceiver
       ...
       com.google.android.gms.subscribedfeeds.SyncService

プロセス

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

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

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

-------------------------------------------------------------------------------
DUMP OF SERVICE processinfo:
-------------------------------------------------------------------------------
DUMP OF SERVICE procstats:
COMMITTED STATS FROM 2015-10-19-23-54-56 (checked in):
...
COMMITTED STATS FROM 2015-10-20-03-00-00 (checked in):
...
CURRENT STATS:
...
AGGREGATED OVER LAST 24 HOURS:
System memory usage:
...
Per-Package Stats:
...
Summary:
...
  * com.google.android.gms.persistent / u0a13 / v8186448:
           TOTAL: 100% (21MB-27MB-40MB/20MB-24MB-38MB over 597)
             Top: 51% (22MB-26MB-38MB/21MB-24MB-36MB over 383)
          Imp Fg: 49% (21MB-27MB-40MB/20MB-25MB-38MB over 214)
…
          Start time: 2015-10-19 09:14:37
  Total elapsed time: +1d0h22m7s390ms (partial) libart.so

AGGREGATED OVER LAST 3 HOURS:
System memory usage:
...
Per-Package Stats:
...
Summary:
  * com.google.android.gms.persistent / u0a13 / v8186448:
           TOTAL: 100% (23MB-27MB-32MB/21MB-25MB-29MB over 111)
             Top: 61% (23MB-26MB-31MB/21MB-24MB-28MB over 67)
          Imp Fg: 39% (23MB-28MB-32MB/21MB-26MB-29MB over 44)
...
          Start time: 2015-10-20 06:49:24
  Total elapsed time: +2h46m59s736ms (partial) libart.so

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

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

-------------------------------------------------------------------------------
ACTIVITY MANAGER RUNNING PROCESSES (dumpsys activity processes)
...
Process LRU list (sorted by oom_adj, 34 total, non-act at 14, non-svc at 14):
    PERS #33: sys   F/ /P  trm: 0 902:system/1000 (fixed)
    PERS #32: pers  F/ /P  trm: 0 2925:com.android.systemui/u0a27 (fixed)
    PERS #31: pers  F/ /P  trm: 0 3477:com.quicinc.cne.CNEService/1000 (fixed)
    PERS #30: pers  F/ /P  trm: 0 3484:com.android.nfc/1027 (fixed)
    PERS #29: pers  F/ /P  trm: 0 3502:com.qualcomm.qti.rcsbootstraputil/1001 (fixed)
    PERS #28: pers  F/ /P  trm: 0 3534:com.qualcomm.qti.rcsimsbootstraputil/1001 (fixed)
    PERS #27: pers  F/ /P  trm: 0 3553:com.android.phone/1001 (fixed)
    Proc #25: psvc  F/ /IF trm: 0 4951:com.android.bluetooth/1002 (service)
        com.android.bluetooth/.hfp.HeadsetService<=Proc{902:system/1000}
    Proc # 0: fore  F/A/T  trm: 0 3586:com.google.android.googlequicksearchbox/u0a29 (top-activity)
  Proc #26: vis   F/ /SB trm: 0 3374:com.google.android.googlequicksearchbox:interactor/u0a29 (service)
        com.google.android.googlequicksearchbox/com.google.android.voiceinteraction.GsaVoiceInteractionService<=Proc{902:system/1000}
    Proc # 5: vis   F/ /T  trm: 0 3745:com.google.android.gms.persistent/u0a12 (service)
        com.google.android.gms/com.google.android.location.network.NetworkLocationService<=Proc{902:system/1000}
    Proc # 3: vis   F/ /SB trm: 0 3279:com.google.android.gms/u0a12 (service)
        com.google.android.gms/.icing.service.IndexService<=Proc{947:com.google.android.googlequicksearchbox:search/u0a29}
    Proc # 2: vis   F/ /T  trm: 0 947:com.google.android.googlequicksearchbox:search/u0a29 (service)
        com.google.android.googlequicksearchbox/com.google.android.sidekick.main.remoteservice.GoogleNowRemoteService<=Proc{3586:com.google.android.googlequicksearchbox/u0a29}
    Proc # 1: vis   F/ /T  trm: 0 2981:com.google.process.gapps/u0a12 (service)
        com.google.android.gms/.tapandpay.hce.service.TpHceService<=Proc{3484:com.android.nfc/1027}
    Proc #11: prcp  B/ /IB trm: 0 3392:com.google.android.inputmethod.latin/u0a64 (service)
        com.google.android.inputmethod.latin/com.android.inputmethod.latin.LatinIME<=Proc{902:system/1000}
    Proc #24: svc   B/ /S  trm: 0 27071:com.google.android.music:main/u0a67 (started-services)
    Proc #22: svc   B/ /S  trm: 0 853:com.qualcomm.qcrilmsgtunnel/1001 (started-services)
    Proc # 4: prev  B/ /LA trm: 0 32734:com.google.android.GoogleCamera/u0a53 (previous)
    Proc #23: svcb  B/ /S  trm: 0 671:com.qualcomm.telephony/1000 (started-services)
    Proc #20: cch   B/ /CE trm: 0 27659:com.android.providers.calendar/u0a2 (provider)
        com.android.providers.calendar/.CalendarProvider2<=Proc{27697:com.google.android.calendar/u0a40}
    Proc #13: cch   B/ /CE trm: 0 653:com.google.android.gms.wearable/u0a12 (cch-empty)
    Proc #10: cch   B/ /S  trm: 0 4067:com.google.android.talk/u0a62 (cch-started-ui-services)
    Proc # 6: cch   B/ /CA trm: 0 27697:com.google.android.calendar/u0a40 (cch-act)
    Proc # 8: cch+1 B/ /CA trm: 0 25675:com.google.android.apps.genie.geniewidget/u0a81 (cch-act)
    Proc #16: cch+2 B/ /CE trm: 0 1272:com.google.android.keep/u0a106 (cch-empty)
    Proc #15: cch+2 B/ /CE trm: 0 885:android.process.media/u0a9 (cch-empty)
    Proc #14: cch+2 B/ /CE trm: 0 15146:android.process.acore/u0a3 (cch-empty)
    Proc # 9: cch+3 B/ /CA trm: 0 17016:com.google.android.gm/u0a79 (cch-act)
    Proc #19: cch+4 B/ /CE trm: 0 973:com.google.android.apps.maps/u0a66 (cch-empty)
    Proc #18: cch+4 B/ /CE trm: 0 1091:com.google.android.apps.photos/u0a71 (cch-empty)
    Proc #17: cch+4 B/ /CE trm: 0 1141:com.google.android.apps.plus/u0a74 (cch-empty)
    Proc #12: cch+5 B/ /CA trm: 0 22299:com.google.android.apps.dogfood/u0a105 (cch-act)
    Proc #21: cch+6 B/ /CE trm: 0 995:com.google.android.partnersetup/u0a18 (cch-empty)>

スキャン

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 スキャンをご覧ください。