1 <html devsite> 2 <head> 3 <title>Reading Bug Reports</title> 4 <meta name="project_path" value="/_project.yaml" /> 5 <meta name="book_path" value="/_book.yaml" /> 6 </head> 7 <body> 8 <!-- 9 Copyright 2017 The Android Open Source Project 10 11 Licensed under the Apache License, Version 2.0 (the "License"); 12 you may not use this file except in compliance with the License. 13 You may obtain a copy of the License at 14 15 http://www.apache.org/licenses/LICENSE-2.0 16 17 Unless required by applicable law or agreed to in writing, software 18 distributed under the License is distributed on an "AS IS" BASIS, 19 WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 20 See the License for the specific language governing permissions and 21 limitations under the License. 22 --> 23 24 25 26 <p>Bugs are a reality in any type of development—and bug reports are 27 critical to identifying and solving problems. All versions of Android support 28 capturing bug reports with <a href="http://developer.android.com/tools/help/adb.html">Android 29 Debug Bridge (adb)</a>; Android versions 4.2 and higher support a 30 <a href="http://developer.android.com/tools/device.html#developer-device-options">Developer 31 Option</a> for taking bug reports and sharing via email, Drive, etc.</p> 32 33 <p>Android bug reports contain <code>dumpsys</code>, <code>dumpstate</code>, and 34 <code>logcat</code> data in text (.txt) format, enabling you to easily search 35 for specific content. The following sections detail bug report components, 36 describe common problems, and give helpful tips and <code>grep</code> commands 37 for finding logs associated with those bugs. Most sections also include examples 38 for <code>grep</code> command and output and/or <code>dumpsys</code> output.</p> 39 40 <h2 id="logcat">Logcat</h2> 41 <p>The <code>logcat</code> log is a string-based dump of all <code>logcat</code> 42 information. The <strong>system</strong> part is reserved for the framework and 43 has a longer history than <strong>main</strong> which contains everything else. 44 Each line starts with <code>timestamp PID TID log-level</code>.</p> 45 46 <section class="expandable"> 47 <h4 class="showalways">Show example</h4> 48 <p><pre>------ SYSTEM LOG (logcat -v threadtime -d *:v) ------ 49 --------- beginning of system 50 <i>Blah</i> 51 <i>Blah</i> 52 <i>Blah</i> 53 54 --------- beginning of main 55 <i>Blah </i> 56 <i>Blah</i> 57 <i>Blah</i></pre></p> 58 </section> 59 60 <h3 id="event-log">Viewing the event log</h3> 61 <p>This log contains string representations of binary-formatted log messages. It 62 is less noisy than the <code>logcat</code> log but also a little harder to read. 63 When viewing event logs, you can search this section for specific process ID 64 (PID) to see what a process has been doing. The basic format is: 65 <code>timestamp PID TID log-level log-tag tag-values</code>.</p> 66 67 <p>Log levels include the following:</p> 68 <ul> 69 <li>V: verbose</li> 70 <li>D: debug</li> 71 <li>I: information</li> 72 <li>W: warning</li> 73 <li>E: error</li> 74 </ul> 75 76 <section class="expandable"> 77 <h4 class="showalways">Show example</h4> 78 <p><pre>------ EVENT LOG (logcat -b events -v threadtime -d *:v) ------ 79 09-28 13:47:34.179 785 5113 I am_proc_bound: [0,23054,com.google.android.gms.unstable] 80 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] 81 09-28 13:47:34.806 785 2764 I am_proc_bound: [0,23134,com.android.chrome] 82 ...</pre></p> 83 </section> 84 <p> </p> 85 <p>For other useful event log tags, refer to 86 <a href="https://android.googlesource.com/platform/frameworks/base/+/master/services/core/java/com/android/server/EventLogTags.logtags">/services/core/java/com/android/server/EventLogTags.logtags</a>.</p> 87 88 <h2 id="anrs-deadlocks">ANRs and deadlocks</h2> 89 <p>Bugreports can help you identify what's causing 90 <a href="http://developer.android.com/training/articles/perf-anr.html">Application 91 Not Responding (ANR)</a> errors and deadlock events.</p> 92 93 <h3 id="determine-anr-app">Identifying unresponsive apps</h3> 94 <p>When an application does not respond within a certain time, usually due to a 95 blocked or busy main thread, the system kills the process and dumps the stack to 96 <code>/data/anr</code>. To discover the culprit behind an ANR, grep for 97 <code>am_anr</code> in the binary event log.</p> 98 99 <section class="expandable"> 100 <h4 class="showalways">Show example</h4> 101 <p><pre>grep "am_anr" bugreport-2015-10-01-18-13-48.txt 102 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] 103 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]</pre></p> 104 </section> 105 106 <p></p> 107 <p>You can also grep for <code>ANR in</code> in the <code>logcat</code> log, 108 which contains more information about what was using CPU at the time of the ANR. 109 </p> 110 111 <section class="expandable"> 112 <h4 class="showalways">Show example</h4> 113 <p><pre>grep "ANR in" bugreport-2015-10-01-18-13-48.txt 114 10-01 18:13:11.984 4600 4614 E ActivityManager: ANR in com.google.android.youtube 115 10-01 18:14:31.720 4600 4614 E ActivityManager: ANR in com.google.android.apps.plus 116 10-01 18:14:31.720 4600 4614 E ActivityManager: PID: 30363 117 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 118 10-01 18:14:31.720 4600 4614 E ActivityManager: Load: 35.27 / 23.9 / 16.18 119 10-01 18:14:31.720 4600 4614 E ActivityManager: CPU usage from 16ms to 21868ms later: 120 10-01 18:14:31.720 4600 4614 E ActivityManager: 74% 3361/mm-qcamera-daemon: 62% user + 12% kernel / faults: 15276 minor 10 major 121 10-01 18:14:31.720 4600 4614 E ActivityManager: 41% 4600/system_server: 18% user + 23% kernel / faults: 18597 minor 309 major 122 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 123 10-01 18:14:31.720 4600 4614 E ActivityManager: 16% 130/kswapd0: 0% user + 16% kernel 124 10-01 18:14:31.720 4600 4614 E ActivityManager: 15% 283/mmcqd/0: 0% user + 15% kernel 125 ... 126 10-01 18:14:31.720 4600 4614 E ActivityManager: 0.1% 27248/irq/503-synapti: 0% 127 10-01 18:14:31.721 4600 4614 I ActivityManager: Killing 30363:com.google.android.apps.plus/u0a206 (adj 0): bg anr</pre></p> 128 </section> 129 130 <h3 id="find-stack-traces">Finding stack traces</h3> 131 <p>You can often find stack traces that correspond to an ANR. Make sure the 132 timestamp and PID on the VM traces match the ANR you are investigating, then 133 check the main thread of the process. Keep in mind:</p> 134 <ul> 135 <li>The main thread tells you only what the thread was doing at the time of the 136 ANR, which may or may not correspond to the true cause of the ANR. (The stack in 137 the bug report may be innocent; something else may have been stuck for a long 138 time—but not quite long enough to ANR—before becoming unstuck.) 139 </li> 140 <li>More than one set of stack traces (<code>VM TRACES JUST NOW</code> and 141 <code>VM TRACES AT LAST ANR</code>) might exist. Make sure you are viewing the 142 correct section.</li> 143 </ul> 144 145 <section class="expandable"> 146 <h4 class="showalways">Show example</h4> 147 <p><pre>------ VM TRACES AT LAST ANR (/data/anr/traces.txt: 2015-10-01 18:14:41) ------ 148 149 ----- pid 30363 at 2015-10-01 18:14:11 ----- 150 Cmd line: com.google.android.apps.plus 151 Build fingerprint: 'google/angler/angler:6.0/MDA89D/2294819:userdebug/dev-keys' 152 ABI: 'arm' 153 Build type: optimized 154 Zygote loaded classes=3978 post zygote classes=27 155 Intern table: 45068 strong; 21 weak 156 JNI: CheckJNI is off; globals=283 (plus 360 weak) 157 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) 158 Heap: 29% free, 21MB/30MB; 32251 objects 159 Dumping cumulative Gc timings 160 Total number of allocations 32251 161 Total bytes allocated 21MB 162 Total bytes freed 0B 163 Free memory 9MB 164 Free memory until GC 9MB 165 Free memory until OOME 490MB 166 Total memory 30MB 167 Max memory 512MB 168 Zygote space size 1260KB 169 Total mutator paused time: 0 170 Total time waiting for GC to complete: 0 171 Total GC count: 0 172 Total GC time: 0 173 Total blocking GC count: 0 174 Total blocking GC time: 0 175 176 suspend all histogram: Sum: 119.728ms 99% C.I. 0.010ms-107.765ms Avg: 5.442ms Max: 119.562ms 177 DALVIK THREADS (12): 178 "Signal Catcher" daemon prio=5 tid=2 Runnable 179 | group="system" sCount=0 dsCount=0 obj=0x12c400a0 self=0xef460000 180 | sysTid=30368 nice=0 cgrp=default sched=0/0 handle=0xf4a69930 181 | state=R schedstat=( 9021773 5500523 26 ) utm=0 stm=0 core=1 HZ=100 182 | stack=0xf496d000-0xf496f000 stackSize=1014KB 183 | held mutexes= "mutator lock"(shared held) 184 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) 185 native: #01 pc 0033b03b /system/lib/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&) const+138) 186 native: #02 pc 00344701 /system/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+424) 187 native: #03 pc 00345265 /system/lib/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+200) 188 native: #04 pc 00345769 /system/lib/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+124) 189 native: #05 pc 00345e51 /system/lib/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+312) 190 native: #06 pc 0031f829 /system/lib/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+68) 191 native: #07 pc 00326831 /system/lib/libart.so (art::SignalCatcher::HandleSigQuit()+896) 192 native: #08 pc 003270a1 /system/lib/libart.so (art::SignalCatcher::Run(void*)+324) 193 native: #09 pc 0003f813 /system/lib/libc.so (__pthread_start(void*)+30) 194 native: #10 pc 00019f75 /system/lib/libc.so (__start_thread+6) 195 (no managed stack frames) 196 197 "main" prio=5 tid=1 Suspended 198 | group="main" sCount=1 dsCount=0 obj=0x747552a0 self=0xf5376500 199 | sysTid=30363 nice=0 cgrp=default sched=0/0 handle=0xf74feb34 200 | state=S schedstat=( 331107086 164153349 851 ) utm=6 stm=27 core=3 HZ=100 201 | stack=0xff00f000-0xff011000 stackSize=8MB 202 | held mutexes= 203 kernel: __switch_to+0x7c/0x88 204 kernel: futex_wait_queue_me+0xd4/0x130 205 kernel: futex_wait+0xf0/0x1f4 206 kernel: do_futex+0xcc/0x8f4 207 kernel: compat_SyS_futex+0xd0/0x14c 208 kernel: cpu_switch_to+0x48/0x4c 209 native: #00 pc 000175e8 /system/lib/libc.so (syscall+28) 210 native: #01 pc 000f5ced /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+80) 211 native: #02 pc 00335353 /system/lib/libart.so (art::Thread::FullSuspendCheck()+838) 212 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) 213 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) 214 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) 215 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) 216 native: #07 pc 002cb1a1 /system/lib/libart.so (art::VMClassLoader_findLoadedClass(_JNIEnv*, _jclass*, _jobject*, _jstring*)+264) 217 native: #08 pc 002847fd /data/dalvik-cache/arm/system@framework (a] boot.oat (Java_java_lang_VMClassLoader_findLoadedClass__Ljava_lang_ClassLoader_2Ljava_lang_String_2+112) 218 at java.lang.VMClassLoader.findLoadedClass!(Native method) 219 at java.lang.ClassLoader.findLoadedClass(ClassLoader.java:362) 220 at java.lang.ClassLoader.loadClass(ClassLoader.java:499) 221 at java.lang.ClassLoader.loadClass(ClassLoader.java:469) 222 at android.app.ActivityThread.installProvider(ActivityThread.java:5141) 223 at android.app.ActivityThread.installContentProviders(ActivityThread.java:4748) 224 at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4688) 225 at android.app.ActivityThread.-wrap1(ActivityThread.java:-1) 226 at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1405) 227 at android.os.Handler.dispatchMessage(Handler.java:102) 228 at android.os.Looper.loop(Looper.java:148) 229 at android.app.ActivityThread.main(ActivityThread.java:5417) 230 at java.lang.reflect.Method.invoke!(Native method) 231 at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726) 232 at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616) 233 234 ... 235 <i> Stacks for other threads in this process follow</i> 236 ...</pre></p> 237 </section> 238 239 <h3 id="deadlocks">Finding deadlocks</h3> 240 <p>Deadlocks often first appear as ANRs because threads are getting stuck. If 241 the deadlock hits the system server, the watchdog will eventually kill it, 242 leading to an entry in the log similar to: 243 <code>WATCHDOG KILLING SYSTEM PROCESS</code>. From the user perspective, the 244 device reboots, although technically this is a runtime restart rather than a 245 true reboot.</p> 246 247 <ul> 248 <li>In a <strong>runtime</strong> restart, the system server dies and is 249 restarted; the user sees the device return to the boot animation.</li> 250 <li>In a <strong>reboot</strong>, the kernel has crashed; the user sees the 251 device return to the Google boot logo.</li> 252 </ul> 253 254 <p>To find deadlocks, check the VM traces sections for a pattern of thread A 255 waiting on something held by thread B, which in turn is waiting on something 256 held by thread A.</p> 257 258 <section class="expandable"> 259 <h4 class="showalways">Show example</h4> 260 <p><pre>"Binder_B" prio=5 tid=73 Blocked 261 | group="main" sCount=1 dsCount=0 obj=0x13faa0a0 self=0x95e24800 262 | sysTid=2016 nice=0 cgrp=default sched=0/0 handle=0x8b68d930 263 | state=S schedstat=( 9351576559 4141431119 16920 ) utm=819 stm=116 core=1 HZ=100 264 | stack=0x8b591000-0x8b593000 stackSize=1014KB 265 | held mutexes= 266 at com.android.server.pm.UserManagerService.exists(UserManagerService.java:387) 267 - waiting to lock <0x025f9b02> (a android.util.ArrayMap) held by thread 20 268 at com.android.server.pm.PackageManagerService.getApplicationInfo(PackageManagerService.java:2848) 269 at com.android.server.AppOpsService.getOpsRawLocked(AppOpsService.java:881) 270 at com.android.server.AppOpsService.getOpsLocked(AppOpsService.java:856) 271 at com.android.server.AppOpsService.noteOperationUnchecked(AppOpsService.java:719) 272 - locked <0x0231885a> (a com.android.server.AppOpsService) 273 at com.android.server.AppOpsService.noteOperation(AppOpsService.java:713) 274 at com.android.server.AppOpsService$2.getMountMode(AppOpsService.java:260) 275 at com.android.server.MountService$MountServiceInternalImpl.getExternalStorageMountMode(MountService.java:3416) 276 at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3228) 277 at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3170) 278 at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3059) 279 at com.android.server.am.BroadcastQueue.processNextBroadcast(BroadcastQueue.java:1070) 280 - locked <0x044d166f> (a com.android.server.am.ActivityManagerService) 281 at com.android.server.am.ActivityManagerService.finishReceiver(ActivityManagerService.java:16950) 282 at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:494) 283 at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2432) 284 at android.os.Binder.execTransact(Binder.java:453) 285 ... 286 "PackageManager" prio=5 tid=20 Blocked 287 | group="main" sCount=1 dsCount=0 obj=0x1304f4a0 self=0xa7f43900 288 | sysTid=1300 nice=10 cgrp=bg_non_interactive sched=0/0 handle=0x9fcf9930 289 | state=S schedstat=( 26190141996 13612154802 44357 ) utm=2410 stm=209 core=2 HZ=100 290 | stack=0x9fbf7000-0x9fbf9000 stackSize=1038KB 291 | held mutexes= 292 at com.android.server.AppOpsService.noteOperationUnchecked(AppOpsService.java:718) 293 - waiting to lock <0x0231885a> (a com.android.server.AppOpsService) held by thread 73 294 at com.android.server.AppOpsService.noteOperation(AppOpsService.java:713) 295 at com.android.server.AppOpsService$2.getMountMode(AppOpsService.java:260) 296 at com.android.server.AppOpsService$2.hasExternalStorage(AppOpsService.java:273) 297 at com.android.server.MountService$MountServiceInternalImpl.hasExternalStorage(MountService.java:3431) 298 at com.android.server.MountService.getVolumeList(MountService.java:2609) 299 at android.os.storage.StorageManager.getVolumeList(StorageManager.java:880) 300 at android.os.Environment$UserEnvironment.getExternalDirs(Environment.java:83) 301 at android.os.Environment.isExternalStorageEmulated(Environment.java:708) 302 at com.android.server.pm.PackageManagerService.isExternalMediaAvailable(PackageManagerService.java:9327) 303 at com.android.server.pm.PackageManagerService.startCleaningPackages(PackageManagerService.java:9367) 304 - locked <0x025f9b02> (a android.util.ArrayMap) 305 at com.android.server.pm.PackageManagerService$PackageHandler.doHandleMessage(PackageManagerService.java:1320) 306 at com.android.server.pm.PackageManagerService$PackageHandler.handleMessage(PackageManagerService.java:1122) 307 at android.os.Handler.dispatchMessage(Handler.java:102) 308 at android.os.Looper.loop(Looper.java:148) 309 at android.os.HandlerThread.run(HandlerThread.java:61) 310 at com.android.server.ServiceThread.run(ServiceThread.java:46)</pre></p> 311 </section> 312 313 314 <h2 id="activities">Activities</h2> 315 <p>An <a href="http://developer.android.com/guide/components/activities.html">Activity</a> 316 is an application component that provides a screen users interact with to do 317 something such as dial a number, take a photo, send an email, etc. From a bug 318 report perspective, an 319 <a href="http://developer.android.com/reference/android/app/Activity.html">activity</a> 320 is a single, focused thing a user can do, which makes locating the activity that 321 was in focus during a crash very important. Activities (via ActivityManager) 322 run processes, so locating all process stops and starts for a given activity can 323 also aid troubleshooting.</p> 324 325 <h3 id="history-focused-activities">Viewing focused activities</h3> 326 <p>To view a history of focused activities, search for 327 <code>am_focused_activity</code>.</p> 328 329 <section class="expandable"> 330 <h4 class="showalways">Show example</h4> 331 <p><pre>grep "am_focused_activity" bugreport-2015-10-01-18-13-48.txt 332 10-01 18:10:41.409 4600 14112 I am_focused_activity: [0,com.google.android.GoogleCamera/com.android.camera.CameraActivity] 333 10-01 18:11:17.313 4600 5687 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL] 334 10-01 18:11:52.747 4600 14113 I am_focused_activity: [0,com.google.android.GoogleCamera/com.android.camera.CameraActivity] 335 10-01 18:14:07.762 4600 5687 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]</pre></p> 336 </section> 337 338 <h3 id="history-process-starts">Viewing process starts</h3> 339 <p>To view a history of process starts, search for <code>Start proc</code>.</p> 340 341 <section class="expandable"> 342 <h4 class="showalways">Show example</h4> 343 <p><pre>grep "Start proc" bugreport-2015-10-01-18-13-48.txt 344 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 345 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 346 10-01 18:09:15.777 4600 6604 I ActivityManager: Start proc 24563:cloudtv.hdwidgets/u0a145 for broadcast cloudtv.hdwidgets/cloudtv.switches.SwitchSystemUpdateReceiver 347 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 348 ...</pre></p> 349 </section> 350 351 <h3 id="device-thrashing">Is the device thrashing?</h3> 352 <p>To determine if the device is 353 <a href="https://en.wikipedia.org/wiki/Thrashing_(computer_science)">thrashing</a>, 354 check for an abnormal increase in activity around <code>am_proc_died</code> and 355 <code>am_proc_start</code> in a short amount of time.</p> 356 357 <section class="expandable"> 358 <h4 class="showalways">Show example</h4> 359 <p><pre>grep -e "am_proc_died" -e "am_proc_start" bugreport-2015-10-01-18-13-48.txt 360 10-01 18:07:06.494 4600 9696 I am_proc_died: [0,20074,com.android.musicfx] 361 10-01 18:07:06.555 4600 6606 I am_proc_died: [0,31166,com.concur.breeze] 362 10-01 18:07:06.566 4600 14112 I am_proc_died: [0,18812,com.google.android.apps.fitness] 363 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] 364 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] 365 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] 366 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] 367 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] 368 10-01 18:07:15.985 4600 4612 I am_proc_start: [0,20568,10022,com.android.musicfx,broadcast,com.android.musicfx/.ControlPanelReceiver] 369 10-01 18:07:16.315 4600 7512 I am_proc_died: [0,20096,com.google.android.GoogleCamera]</pre></p> 370 </section> 371 372 <h2 id="memory">Memory</h2> 373 <p>Because Android devices often have constrained physical memory, managing 374 random-access memory (RAM) is critical. Bug reports contain several indicators 375 of low memory as well as a dumpstate that provides a memory snapshot.</p> 376 377 <h3 id="low-memory">Identifying low memory</h3> 378 <p>Low memory can cause the system to thrash as it kills some processes to free 379 memory but continues to start other processes. To view corroborating evidence of 380 low memory, check for concentrations of <code>am_proc_died</code> and 381 <code>am_proc_start</code> entries in the binary event log.</p> 382 383 <p>Low memory can also slow task switching and thwart return attempts (because 384 the task the user was trying to return to was killed). If the launcher was 385 killed, it restarts when the user touches the home button and logs show the 386 launcher reload its content.</p> 387 388 <h4 id="historical-low-memory">Viewing historical indicators</h4> 389 <p>The <code>am_low_memory</code> entry in the binary event log indicates the 390 last cached process has died. After this, the system starts killing services. 391 392 <section class="expandable"> 393 <h4 class="showalways">Show example</h4> 394 <p><pre>grep "am_low_memory" bugreport-2015-10-01-18-13-48.txt 395 10-01 18:11:02.219 4600 7513 I am_low_memory: 41 396 10-01 18:12:18.526 4600 14112 I am_low_memory: 39 397 10-01 18:12:18.874 4600 7514 I am_low_memory: 38 398 10-01 18:12:22.570 4600 14112 I am_low_memory: 40 399 10-01 18:12:34.811 4600 20319 I am_low_memory: 43 400 10-01 18:12:37.945 4600 6521 I am_low_memory: 43 401 10-01 18:12:47.804 4600 14110 I am_low_memory: 43</pre></p> 402 </section> 403 404 <h4 id="thrashing-indicators">Viewing thrashing indicators</h4> 405 <p>Other indicators of system thrashing (paging, direct reclaim, etc.) include 406 <code>kswapd</code>, <code>kworker</code>, and <code>mmcqd</code> consuming 407 cycles. (Keep in mind the bugreport being gathered can influence thrashing 408 indicators.)</p> 409 410 <section class="expandable"> 411 <h4 class="showalways">Show example</h4> 412 <p><pre>------ CPU INFO (top -n 1 -d 1 -m 30 -t) ------ 413 414 User 15%, System 54%, IOW 28%, IRQ 0% 415 User 82 + Nice 2 + Sys 287 + Idle 1 + IOW 152 + IRQ 0 + SIRQ 5 = 529 416 417 PID TID PR CPU% S VSS RSS PCY UID Thread Proc 418 15229 15229 0 19% R 0K 0K fg root kworker/0:2 419 29512 29517 1 7% D 1173524K 101188K bg u0_a27 Signal Catcher com.google.android.talk 420 24565 24570 3 6% D 2090920K 145168K fg u0_a22 Signal Catcher com.google.android.googlequicksearchbox:search 421 19525 19525 2 6% R 3476K 1644K fg shell top top 422 24957 24962 2 5% R 1706928K 125716K bg u0_a47 Signal Catcher com.google.android.GoogleCamera 423 19519 19519 3 4% S 0K 0K fg root kworker/3:1 424 120 120 0 3% S 0K 0K fg root mmcqd/1 425 18233 18233 1 3% S 0K 0K fg root kworker/1:1 426 25589 25594 1 2% D 1270476K 75776K fg u0_a8 Signal Catcher com.google.android.gms 427 19399 19399 2 1% S 0K 0K fg root kworker/2:2 428 1963 1978 1 0% S 1819100K 125136K fg system android.fg system_server 429 1963 1981 3 0% S 1819100K 125136K fg system android.display system_server</pre></p> 430 </section> 431 <p></p> 432 433 <p>ANR logs can provide a similar memory snapshot.</p> 434 435 <section class="expandable"> 436 <h4 class="showalways">Show example</h4> 437 <p><pre>10-03 17:19:59.959 1963 1976 E ActivityManager: ANR in com.google.android.apps.magazines 438 10-03 17:19:59.959 1963 1976 E ActivityManager: PID: 18819 439 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) } 440 10-03 17:19:59.959 1963 1976 E ActivityManager: Load: 19.19 / 14.76 / 12.03 441 10-03 17:19:59.959 1963 1976 E ActivityManager: CPU usage from 0ms to 11463ms later: 442 10-03 17:19:59.959 1963 1976 E ActivityManager: 54% 15229/kworker/0:2: 0% user + 54% kernel 443 10-03 17:19:59.959 1963 1976 E ActivityManager: 38% 1963/system_server: 14% user + 23% kernel / faults: 17152 minor 1073 major 444 10-03 17:19:59.959 1963 1976 E ActivityManager: 11% 120/mmcqd/1: 0% user + 11% kernel 445 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 446 10-03 17:19:59.959 1963 1976 E ActivityManager: 0.2% 1451/debuggerd: 0% user + 0.2% kernel / faults: 15211 minor 147 major 447 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 448 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 449 10-03 17:19:59.959 1963 1976 E ActivityManager: 6% 55/kswapd0: 0% user + 6% kernel 450 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 451 10-03 17:19:59.959 1963 1976 E ActivityManager: 2.8% 18233/kworker/1:1: 0% user + 2.8% kernel 452 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 453 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 454 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 455 10-03 17:19:59.959 1963 1976 E ActivityManager: 3% 18236/kworker/1:2: 0% user + 3% kernel 456 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 457 10-03 17:19:59.959 1963 1976 E ActivityManager: 2.3% 15350/kworker/0:4: 0% user + 2.3% kernel 458 10-03 17:19:59.959 1963 1976 E ActivityManager: 2.2% 1454/mediaserver: 0% user + 2.2% kernel / faults: 479 minor 6 major 459 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 460 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 461 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 462 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 463 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 464 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 465 10-03 17:19:59.959 1963 1976 E ActivityManager: 0.8% 3650/mpdecision: 0% user + 0.8% kernel / faults: 160 minor 1 major 466 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</pre></p> 467 </section> 468 469 <h3 id="memory-snapshot">Getting a memory snapshot</h3> 470 <p>The memory snapshot is a dumpstate that lists running Java and native 471 processes (for details, refer to 472 <a href="https://developer.android.com/tools/debugging/debugging-memory.html#ViewingAllocations">Viewing 473 Overall Memory Allocations</a>). Keep in mind the snapshot gives only the state 474 at a specific moment in time; the system might have been in better (or worse) 475 shape before the snapshot.</p> 476 <ul> 477 <li>To understand how long a process runs, see 478 <a href="#process-runtime">Process runtime</a>.</li> 479 <li>To understand why something is currently running, see 480 <a href="#why-is-process-running">Why is a process running?</a></li> 481 </ul> 482 483 <section class="expandable"> 484 <h4 class="showalways">Show example</h4> 485 <p><pre>Total PSS by OOM adjustment: 486 86752 kB: Native 487 22645 kB: surfaceflinger (pid 197) 488 18597 kB: mediaserver (pid 204) 489 ... 490 136959 kB: System 491 136959 kB: system (pid 785) 492 220218 kB: Persistent 493 138859 kB: com.android.systemui (pid 947 / activities) 494 39178 kB: com.android.nfc (pid 1636) 495 28313 kB: com.android.phone (pid 1659) 496 13868 kB: com.redbend.vdmc (pid 1646) 497 9534 kB: Persistent Service 498 9534 kB: com.android.bluetooth (pid 23807) 499 178604 kB: Foreground 500 168620 kB: com.google.android.googlequicksearchbox (pid 1675 / activities) 501 9984 kB: com.google.android.apps.maps (pid 13952) 502 188286 kB: Visible 503 85326 kB: com.google.android.wearable.app (pid 1535) 504 38978 kB: com.google.process.gapps (pid 1510) 505 31936 kB: com.google.android.gms.persistent (pid 2072) 506 27950 kB: com.google.android.gms.wearable (pid 1601) 507 4096 kB: com.google.android.googlequicksearchbox:interactor (pid 1550) 508 52948 kB: Perceptible 509 52948 kB: com.google.android.inputmethod.latin (pid 1566) 510 150851 kB: A Services 511 81121 kB: com.google.android.gms (pid 1814) 512 37586 kB: com.google.android.talk (pid 9584) 513 10949 kB: com.google.android.music:main (pid 4019) 514 10727 kB: com.motorola.targetnotif (pid 31071) 515 10468 kB: com.google.android.GoogleCamera (pid 9984) 516 33298 kB: Previous 517 33298 kB: com.android.settings (pid 9673 / activities) 518 165188 kB: B Services 519 49490 kB: com.facebook.katana (pid 15035) 520 22483 kB: com.whatsapp (pid 28694) 521 21308 kB: com.iPass.OpenMobile (pid 5325) 522 19788 kB: com.google.android.apps.googlevoice (pid 23934) 523 17399 kB: com.google.android.googlequicksearchbox:search (pid 30359) 524 9073 kB: com.google.android.apps.youtube.unplugged (pid 21194) 525 7660 kB: com.iPass.OpenMobile:remote (pid 23754) 526 7291 kB: com.pujie.wristwear.pujieblack (pid 24240) 527 7157 kB: com.instagram.android:mqtt (pid 9530) 528 3539 kB: com.qualcomm.qcrilmsgtunnel (pid 16186) 529 204324 kB: Cached 530 43424 kB: com.amazon.mShop.android (pid 13558) 531 22563 kB: com.google.android.apps.magazines (pid 13844) 532 ... 533 4298 kB: com.google.android.apps.enterprise.dmagent (pid 13826)</pre></p> 534 </section> 535 536 <h2 id="broadcasts">Broadcasts</h2> 537 <p>Applications generate broadcasts to send events within the current 538 application or to another application. Broadcast receivers subscribe to specific 539 messages (via filters), enabling them to both listen and respond to a broadcast. 540 Bug reports contain information about sent broadcasts and unsent broadcasts, as 541 well as a dumpsys of all receivers listening to a specific broadcast.</p> 542 543 <h3 id="historical-broadcasts">Viewing historical broadcasts</h3> 544 <p>Historical broadcasts are those that have already been sent, listed in 545 reverse chronological order.</p> 546 547 <p>The <strong>summary</strong> section is an overview of the last 300 548 foreground broadcasts and the last 300 background broadcasts.</p> 549 550 <section class="expandable"> 551 <h4 class="showalways">Show example</h4> 552 <p><pre> Historical broadcasts summary [foreground]: 553 #0: act=android.intent.action.SCREEN_ON flg=0x50000010 554 +1ms dispatch +90ms finish 555 enq=2015-10-29 17:10:51 disp=2015-10-29 17:10:51 fin=2015-10-29 17:10:51 556 #1: act=android.intent.action.SCREEN_OFF flg=0x50000010 557 0 dispatch +60ms finish 558 enq=2015-10-29 17:10:05 disp=2015-10-29 17:10:05 fin=2015-10-29 17:10:05 559 ... 560 Historical broadcasts summary [background]: 561 ...</pre></p> 562 </section> 563 <p></p> 564 565 <p>The <strong>detail</strong> section contains complete information for the 566 last 50 foreground broadcasts and the last 50 background broadcasts, as well as 567 the receivers for each broadcast. Receivers that have a:</p> 568 <ul> 569 <li><code>BroadcastRecord</code> entry are registered at runtime and are sent 570 only to already running processes.</li> 571 <li><code>ResolveInfo</code> entry are registered through manifest entries. The 572 ActivityManager starts the process for each <code>ResolveInfo</code> if it is 573 not already running.</li> 574 </ul> 575 576 <section class="expandable"> 577 <h4 class="showalways">Show example</h4> 578 <p><pre>Historical broadcasts [foreground]: 579 ... 580 Historical broadcasts [background]: 581 Historical Broadcast background #0: 582 ... 583 Historical Broadcast background #5: 584 BroadcastRecord{18dbb16 u0 android.intent.action.USER_PRESENT} to user 0 585 Intent { act=android.intent.action.USER_PRESENT flg=0x24000010 } 586 caller=com.android.systemui 2925:com.android.systemui/u0a27 pid=2925 uid=10027 587 enqueueClockTime=2015-10-29 17:10:55 dispatchClockTime=2015-10-29 17:10:55 588 dispatchTime=-2s321ms (0 since enq) finishTime=-2s320ms (+1ms since disp) 589 Receiver #0: BroadcastFilter{8181cc1 u-1 ReceiverList{5d929a8 902 system/1000/u-1 local:eca4dcb}} 590 Receiver #1: BroadcastFilter{6371c97 u-1 ReceiverList{2938b16 902 system/1000/u-1 local:840b831}} 591 ... 592 Receiver #19: BroadcastFilter{93f16b u0 ReceiverList{5c61eba 17016 com.google.android.gm/10079/u0 remote:24083e5}} 593 ... 594 Historical Broadcast background #37: 595 BroadcastRecord{7f6dd6 u0 android.hardware.action.NEW_PICTURE} to user 0 596 Intent { act=android.hardware.action.NEW_PICTURE dat=content://media/external/images/media/6345 flg=0x10 } 597 caller=com.google.android.GoogleCamera 32734:com.google.android.GoogleCamera/u0a53 pid=32734 uid=10053 598 enqueueClockTime=2015-10-29 17:09:48 dispatchClockTime=2015-10-29 17:09:49 599 dispatchTime=-45s720ms (+399ms since enq) finishTime=-45s701ms (+19ms since disp) 600 resultTo=null resultCode=0 resultData=null 601 nextReceiver=4 receiver=null 602 Receiver #0: ResolveInfo{33d2857 com.google.android.gms/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000} 603 priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false 604 ActivityInfo: 605 name=com.google.android.libraries.social.mediamonitor.MediaMonitor 606 packageName=com.google.android.gms 607 enabled=true exported=true processName=com.google.android.gms 608 ... 609 Receiver #1: ResolveInfo{d9edf44 com.google.android.apps.maps/com.google.android.apps.gmm.ugc.clientnotification.StartPhotoTakenNotifierServiceReceiver m=0x608000} 610 priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false 611 ActivityInfo: 612 name=com.google.android.apps.gmm.ugc.clientnotification.StartPhotoTakenNotifierServiceReceiver 613 packageName=com.google.android.apps.maps 614 enabled=true exported=true processName=com.google.android.apps.maps 615 ... 616 Receiver #2: ResolveInfo{743f82d com.google.android.apps.photos/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000} 617 priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false 618 ActivityInfo: 619 name=com.google.android.libraries.social.mediamonitor.MediaMonitor 620 packageName=com.google.android.apps.photos 621 enabled=true exported=true processName=com.google.android.apps.photos 622 ... 623 Receiver #3: ResolveInfo{d5c9162 com.google.android.apps.plus/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000} 624 priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false 625 ActivityInfo: 626 name=com.google.android.libraries.social.mediamonitor.MediaMonitor 627 packageName=com.google.android.apps.plus 628 enabled=true exported=true processName=com.google.android.apps.plus 629 ...</pre></p> 630 </section> 631 632 <h3 id="active-broadcasts">Viewing active broadcasts</h3> 633 <p>Active broadcasts are those that have yet to be sent. A large number in the 634 queue means the system can't dispatch the broadcasts fast enough to keep up.</p> 635 636 <section class="expandable"> 637 <h4 class="showalways">Show example</h4> 638 <p><pre> Active ordered broadcasts [background]: 639 Active Ordered Broadcast background #133: <i>// size of queue</i> 640 ...</pre></p> 641 </section> 642 643 <h3 id="broadcast-listeners">Viewing broadcast listeners</h3> 644 <p>To view a list of receivers listening for a broadcast, check the Receiver 645 Resolver Table in the <code>dumpsys activity broadcasts</code>. The following 646 example displays all receivers listening for <code>USER_PRESENT</code>.</p> 647 648 <section class="expandable"> 649 <h4 class="showalways">Show example</h4> 650 <p><pre>------------------------------------------------------------------------------- 651 ACTIVITY MANAGER BROADCAST STATE (dumpsys activity broadcasts) 652 .. 653 Receiver Resolver Table: 654 Full MIME Types: 655 .. 656 Wild MIME Types: 657 .. 658 Schemes: 659 .. 660 Non-Data Actions: 661 .. 662 android.intent.action.USER_PRESENT: 663 BroadcastFilter{8181cc1 u-1 ReceiverList{5d929a8 902 system/1000/u-1 local:eca4dcb}} 664 BroadcastFilter{6371c97 u-1 ReceiverList{2938b16 902 system/1000/u-1 local:840b831}} 665 BroadcastFilter{320c00 u0 ReceiverList{d3a6283 902 system/1000/u0 local:799c532}} 666 BroadcastFilter{e486048 u0 ReceiverList{36fbaeb 902 system/1000/u0 local:5f51e3a}} 667 BroadcastFilter{22b02 u-1 ReceiverList{b3f744d 902 system/1000/u-1 local:de837e4}} 668 BroadcastFilter{3e989ab u0 ReceiverList{f8deffa 2981 com.google.process.gapps/10012/u0 remote:26bd225}} 669 BroadcastFilter{fb56150 u0 ReceiverList{22b7b13 2925 com.android.systemui/10027/u0 remote:c54a602}} 670 BroadcastFilter{63bbb6 u-1 ReceiverList{ba6c751 3484 com.android.nfc/1027/u-1 remote:5c4a478}} 671 BroadcastFilter{95ad20d u0 ReceiverList{d8374a4 3586 com.google.android.googlequicksearchbox/10029/u0 remote:feb3737}} 672 BroadcastFilter{fdef551 u0 ReceiverList{28ca78 3745 com.google.android.gms.persistent/10012/u0 remote:f23afdb}} 673 BroadcastFilter{9830707 u0 ReceiverList{aabd946 3745 com.google.android.gms.persistent/10012/u0 remote:a4da121}} 674 BroadcastFilter{83c43d2 u0 ReceiverList{d422e5d 3745 com.google.android.gms.persistent/10012/u0 remote:f585034}} 675 BroadcastFilter{8890378 u0 ReceiverList{26d2cdb 3745 com.google.android.gms.persistent/10012/u0 remote:dfa61ea}} 676 BroadcastFilter{7bbb7 u0 ReceiverList{214b2b6 3745 com.google.android.gms.persistent/10012/u0 remote:8353a51}} 677 BroadcastFilter{38d3566 u0 ReceiverList{de859c1 3745 com.google.android.gms.persistent/10012/u0 remote:e003aa8}} 678 BroadcastFilter{3435d9f u0 ReceiverList{6e38b3e 3745 com.google.android.gms.persistent/10012/u0 remote:8dd7ff9}} 679 BroadcastFilter{d0a34bb u0 ReceiverList{5091d4a 3745 com.google.android.gms.persistent/10012/u0 remote:d6d22b5}} 680 BroadcastFilter{d43c416 u0 ReceiverList{51a3531 3745 com.google.android.gms.persistent/10012/u0 remote:d0b9dd8}} 681 BroadcastFilter{aabf36d u0 ReceiverList{a88bf84 3745 com.google.android.gms.persistent/10012/u0 remote:a9d6197}} 682 BroadcastFilter{93f16b u0 ReceiverList{5c61eba 17016 com.google.android.gm/10079/u0 remote:24083e5}} 683 BroadcastFilter{68f794e u0 ReceiverList{4cb1c49 947 com.google.android.googlequicksearchbox:search/10029/u0 remote:251d250}} 684 .. 685 MIME Typed Actions:</pre></p> 686 </section> 687 688 <h2 id="monitor contention">Monitor contention</h2> 689 <p>Monitor contention logging can sometimes indicate actual monitor contention, 690 but most often indicates the system is so loaded that everything has slowed down. 691 You might see long monitor events logged by ART in system or event log.</p> 692 693 <p>In the system log:</p> 694 <p><pre>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</pre></p> 695 696 <p>In the event log:</p> 697 <p><pre>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]</pre></p> 698 699 <h2 id="background-compilation">Background compilation</h2> 700 <p>Compilation can be expensive and load the device.</p> 701 702 <section class="expandable"> 703 <h4 class="showalways">Show example</h4> 704 <p><pre>09-14 06:27:05.670 2508 2587 E ActivityManager: CPU usage from 0ms to 5857ms later: 705 09-14 06:27:05.670 2508 2587 E ActivityManager: 84% 5708/dex2oat: 81% user + 2.3% kernel / faults: 3731 minor 1 major 706 09-14 06:27:05.670 2508 2587 E ActivityManager: 73% 2508/system_server: 21% user + 51% kernel / faults: 10019 minor 28 major 707 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</pre></p> 708 </section> 709 <p></p> 710 711 <p>Compilation might occur in the background when Google Play store updates are 712 downloading. In this case, messages from the Google Play store app 713 (<code>finsky</code>) and <code>installd</code> appear prior to 714 <code>dex2oat</code> messages.</p> 715 716 <section class="expandable"> 717 <h4 class="showalways">Show example</h4> 718 <p><pre>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 719 10-07 08:42:33.752 495 495 I installd: free_cache(48637657) avail 15111192576 720 721 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 722 </pre></p> 723 </section> 724 <p></p> 725 726 <p>Compilation might also occur in the background when an application is loading 727 a dex file that has not yet been compiled. In this case, you won't see 728 <code>finsky</code> or <code>installd</code> logging.</p> 729 730 <section class="expandable"> 731 <h4 class="showalways">Show example</h4> 732 <p><pre>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 733 ... 734 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</pre></p> 735 </section> 736 737 <h2 id="narrative">Narrative</h2> 738 <p>Establishing the narrative of a problem (how it started, what happened, how 739 the system reacted) requires a solid timeline of events. You can use the 740 information in the bug report to sync timelines across multiple logs and 741 determine the exact timestamp of the bug report.</p> 742 743 <h3 id="timelines">Syncing timelines</h3> 744 <p>A bugreport reflects multiple parallel timelines: system log, event log, 745 kernel log, and multiple specialized timelines for broadcasts, battery stats, 746 etc. Unfortunately, timelines are often reported using different time bases.</p> 747 748 <p>The system and event log timestamps are in the same timezone as the user (as 749 are most other timestamps). For example, when user taps the home button, the 750 system log reports:</p> 751 <p><pre>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</pre></p> 752 753 <p>For the same action, the event log reports:</p> 754 <p><pre>10-03 17:19:54.279 1963 2071 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]</pre></p> 755 756 <p>Kernel (<code>dmesg</code>) logs use a different time base, tagging log items 757 with seconds since bootloader completes. To register this timescale to other 758 timescales, search for <em>suspend exit</em> and <em>suspend entry</em> messages:</p> 759 <p><pre><6>[201640.779997] PM: suspend exit 2015-10-03 19:11:06.646094058 UTC 760 761 <6>[201644.854315] PM: suspend entry 2015-10-03 19:11:10.720416452 UTC</pre></p> 762 763 <p>Because kernel logs might not include time while in suspend, you should 764 piecewise register the log between the suspend entry and exit messages. 765 Additionally, kernel logs use UTC timezone and must be adjusted to the user 766 timezone.</p> 767 768 <h3 id="time-of-bugreport">Identifying bugreport time</h3> 769 <p>To determine when a bugreport was taken, first check the system log (Logcat) 770 for the <code>dumpstate: begin</code>:</p> 771 <p><pre>10-03 17:19:54.322 19398 19398 I dumpstate: begin</pre></p> 772 773 <p>Next, check the kernel log (<code>dmesg</code>) timestamps for the <code>Starting service 774 'bugreport'</code> message:</p> 775 <p><pre><5>[207064.285315] init: Starting service 'bugreport'...</pre></p> 776 777 <p>Work backwards to correlate the two events, keeping in mind the caveats 778 mentioned in <a href="#timelines">Syncing timelines</a>. While there's a lot 779 happening after the bugreport is initiated, most activity isn't very useful as 780 the act of taking the bugreport loads the system substantially.</p> 781 782 <h2 id="power">Power</h2> 783 784 <p>The event log contains screen power status, where 0 is screen off, 1 is 785 screen on, and 2 is for keyguard done.</p> 786 787 <section class="expandable"> 788 <h4 class="showalways">Show example</h4> 789 <p><pre>grep screen_toggled bugreport-2015-10-18-16-52-22.txt 790 10-18 15:05:04.383 992 992 I screen_toggled: 1 791 10-18 15:05:07.010 992 992 I screen_toggled: 0 792 10-18 15:23:15.063 992 992 I screen_toggled: 1 793 10-18 15:23:25.684 992 992 I screen_toggled: 0 794 10-18 15:36:31.623 992 992 I screen_toggled: 1 795 10-18 15:36:37.660 3283 3283 I screen_toggled: 2</pre></p> 796 </section> 797 798 <p></p> 799 <p>Bug reports also contain statistics about wake locks, a mechanism used by 800 application developers to indicate their application needs to have the device 801 stay on. (For details on wake locks, refer to 802 <a href="https://developer.android.com/reference/android/os/PowerManager.WakeLock.html">PowerManager.WakeLock</a> 803 and <a href="https://developer.android.com/training/scheduling/wakelock.html#cpu">Keep 804 the CPU on</a>.) 805 806 <p>The aggregated wake lock duration statistics track <strong>only</strong> the 807 time a wake lock is actually responsible for keeping the device awake and 808 <strong>do not</strong> include time with the screen on. In addition, if 809 multiple wake locks are held simultaneously, the wake lock duration time is 810 distributed across those wake locks.</p> 811 812 <p>For more help visualizing power status, use 813 <a href="https://github.com/google/battery-historian">Battery Historian</a>, a 814 Google open source tool to analyze battery consumers using Android bugreport 815 files.</p> 816 817 <h2 id="packages">Packages</h2> 818 <p>The DUMP OF SERVICE package contains application versions (and other useful 819 info).</p> 820 821 <section class="expandable"> 822 <h4 class="showalways">Show example</h4> 823 <p><pre>... 824 Packages: 825 ... 826 Package [com.google.android.gms] (3cf534b): 827 userId=10013 828 sharedUser=SharedUserSetting{98f3d28 com.google.uid.shared/10013} 829 pkg=Package{b8f6a41 com.google.android.gms} 830 codePath=/system/priv-app/PrebuiltGmsCore 831 resourcePath=/system/priv-app/PrebuiltGmsCore 832 legacyNativeLibraryDir=/system/priv-app/PrebuiltGmsCore/lib 833 primaryCpuAbi=arm64-v8a 834 secondaryCpuAbi=armeabi-v7a 835 versionCode=8186448 targetSdk=23 836 versionName=8.1.86 (2287566-448) 837 splits=[base] 838 applicationInfo=ApplicationInfo{5158507 com.google.android.gms} 839 flags=[ SYSTEM HAS_CODE ALLOW_CLEAR_USER_DATA ] 840 privateFlags=[ PRIVILEGED ] 841 dataDir=/data/user/0/com.google.android.gms 842 supportsScreens=[small, medium, large, xlarge, resizeable, anyDensity] 843 libraries: 844 com.google.android.gms 845 usesOptionalLibraries: 846 com.android.location.provider 847 com.google.android.ble 848 com.android.media.remotedisplay 849 usesLibraryFiles: 850 /system/framework/com.android.media.remotedisplay.jar 851 /system/framework/com.android.location.provider.jar 852 timeStamp=2015-10-14 15:17:56 853 firstInstallTime=2015-09-22 14:08:35 854 lastUpdateTime=2015-10-14 15:17:56 855 signatures=PackageSignatures{db63be6 [1af63d8]} 856 installPermissionsFixed=true installStatus=1 857 pkgFlags=[ SYSTEM HAS_CODE ALLOW_CLEAR_USER_DATA ] 858 declared permissions: 859 com.google.android.gms.permission.INTERNAL_BROADCAST: prot=signature, INSTALLED 860 ... 861 com.google.android.gms.permission.CAR_VENDOR_EXTENSION: prot=dangerous, INSTALLED 862 User 0: installed=true hidden=false stopped=false notLaunched=false enabled=0 863 disabledComponents: 864 com.google.android.gms.icing.service.PowerConnectedReceiver 865 ... 866 com.google.android.gms.icing.proxy.AppsMonitor 867 enabledComponents: 868 com.google.android.gms.mdm.receivers.GmsRegisteredReceiver 869 ... 870 com.google.android.gms.subscribedfeeds.SyncService</pre></p> 871 </section> 872 873 <h2 id="processes">Processes</h2> 874 <p>Bug reports contain a huge amount of data for processes, including start and 875 stop time, runtime length, associated services, <code>oom_adj</code> score, etc. 876 For details on how Android manages processes, refer to 877 <a href="http://developer.android.com/guide/components/processes-and-threads.html">Processes 878 and Threads</a>.</p> 879 880 <h3 id="process-runtime">Determining process runtime</h3> 881 <p>The <code>procstats</code> section contains complete statistics on how long 882 processes and associated services have been running. For a quick, human-readable 883 summary, search for <code>AGGREGATED OVER</code> to view data from either the 884 last three or 24 hours, then search for <code>Summary:</code> to view the list 885 of processes, how long those processes have run at various priorities, and their 886 RAM usage formatted as min-average-max PSS/min-average-max USS.</p> 887 888 <section class="expandable"> 889 <h4 class="showalways">Show example</h4> 890 <p><pre>------------------------------------------------------------------------------- 891 DUMP OF SERVICE processinfo: 892 ------------------------------------------------------------------------------- 893 DUMP OF SERVICE procstats: 894 COMMITTED STATS FROM 2015-10-19-23-54-56 (checked in): 895 ... 896 COMMITTED STATS FROM 2015-10-20-03-00-00 (checked in): 897 ... 898 CURRENT STATS: 899 ... 900 AGGREGATED OVER LAST 24 HOURS: 901 System memory usage: 902 ... 903 Per-Package Stats: 904 ... 905 Summary: 906 ... 907 * com.google.android.gms.persistent / u0a13 / v8186448: 908 TOTAL: 100% (21MB-27MB-40MB/20MB-24MB-38MB over 597) 909 Top: 51% (22MB-26MB-38MB/21MB-24MB-36MB over 383) 910 Imp Fg: 49% (21MB-27MB-40MB/20MB-25MB-38MB over 214) 911 912 Start time: 2015-10-19 09:14:37 913 Total elapsed time: +1d0h22m7s390ms (partial) libart.so 914 915 AGGREGATED OVER LAST 3 HOURS: 916 System memory usage: 917 ... 918 Per-Package Stats: 919 ... 920 Summary: 921 * com.google.android.gms.persistent / u0a13 / v8186448: 922 TOTAL: 100% (23MB-27MB-32MB/21MB-25MB-29MB over 111) 923 Top: 61% (23MB-26MB-31MB/21MB-24MB-28MB over 67) 924 Imp Fg: 39% (23MB-28MB-32MB/21MB-26MB-29MB over 44) 925 ... 926 Start time: 2015-10-20 06:49:24 927 Total elapsed time: +2h46m59s736ms (partial) libart.so</pre></p> 928 </section> 929 930 <h3 id="why-is-process-running">Why is a process running?</h3> 931 <p>The <code>dumpsys activity processes</code> section lists all currently 932 running processes ordered by <code>oom_adj</code> score (Android indicates 933 process importance by assigning the process an <code>oom_adj</code> value, which 934 can be dynamically updated by ActivityManager). The output is similar to that of 935 a <a href="#memory-snapshot">memory snapshot</a> but includes additional 936 information about what is causing the process to run. In the example below, 937 the bolded entries indicate the <code>gms.persistent</code> process is running 938 at <code>vis</code> (visible) priority because the system process is bound to 939 its <code>NetworkLocationService</code>.</p> 940 941 <section class="expandable"> 942 <h4 class="showalways">Show example</h4> 943 <p><pre>------------------------------------------------------------------------------- 944 ACTIVITY MANAGER RUNNING PROCESSES (dumpsys activity processes) 945 ... 946 Process LRU list (sorted by oom_adj, 34 total, non-act at 14, non-svc at 14): 947 PERS #33: sys F/ /P trm: 0 902:system/1000 (fixed) 948 PERS #32: pers F/ /P trm: 0 2925:com.android.systemui/u0a27 (fixed) 949 PERS #31: pers F/ /P trm: 0 3477:com.quicinc.cne.CNEService/1000 (fixed) 950 PERS #30: pers F/ /P trm: 0 3484:com.android.nfc/1027 (fixed) 951 PERS #29: pers F/ /P trm: 0 3502:com.qualcomm.qti.rcsbootstraputil/1001 (fixed) 952 PERS #28: pers F/ /P trm: 0 3534:com.qualcomm.qti.rcsimsbootstraputil/1001 (fixed) 953 PERS #27: pers F/ /P trm: 0 3553:com.android.phone/1001 (fixed) 954 Proc #25: psvc F/ /IF trm: 0 4951:com.android.bluetooth/1002 (service) 955 com.android.bluetooth/.hfp.HeadsetService<=Proc{902:system/1000} 956 Proc # 0: fore F/A/T trm: 0 3586:com.google.android.googlequicksearchbox/u0a29 (top-activity) 957 Proc #26: vis F/ /SB trm: 0 3374:com.google.android.googlequicksearchbox:interactor/u0a29 (service) 958 com.google.android.googlequicksearchbox/com.google.android.voiceinteraction.GsaVoiceInteractionService<=Proc{902:system/1000} 959 <b> Proc # 5: vis F/ /T trm: 0 3745:com.google.android.gms.persistent/u0a12 (service)</b> 960 <b> com.google.android.gms/com.google.android.location.network.NetworkLocationService<=Proc{902:system/1000}</b> 961 Proc # 3: vis F/ /SB trm: 0 3279:com.google.android.gms/u0a12 (service) 962 com.google.android.gms/.icing.service.IndexService<=Proc{947:com.google.android.googlequicksearchbox:search/u0a29} 963 Proc # 2: vis F/ /T trm: 0 947:com.google.android.googlequicksearchbox:search/u0a29 (service) 964 com.google.android.googlequicksearchbox/com.google.android.sidekick.main.remoteservice.GoogleNowRemoteService<=Proc{3586:com.google.android.googlequicksearchbox/u0a29} 965 Proc # 1: vis F/ /T trm: 0 2981:com.google.process.gapps/u0a12 (service) 966 com.google.android.gms/.tapandpay.hce.service.TpHceService<=Proc{3484:com.android.nfc/1027} 967 Proc #11: prcp B/ /IB trm: 0 3392:com.google.android.inputmethod.latin/u0a64 (service) 968 com.google.android.inputmethod.latin/com.android.inputmethod.latin.LatinIME<=Proc{902:system/1000} 969 Proc #24: svc B/ /S trm: 0 27071:com.google.android.music:main/u0a67 (started-services) 970 Proc #22: svc B/ /S trm: 0 853:com.qualcomm.qcrilmsgtunnel/1001 (started-services) 971 Proc # 4: prev B/ /LA trm: 0 32734:com.google.android.GoogleCamera/u0a53 (previous) 972 Proc #23: svcb B/ /S trm: 0 671:com.qualcomm.telephony/1000 (started-services) 973 Proc #20: cch B/ /CE trm: 0 27659:com.android.providers.calendar/u0a2 (provider) 974 com.android.providers.calendar/.CalendarProvider2<=Proc{27697:com.google.android.calendar/u0a40} 975 Proc #13: cch B/ /CE trm: 0 653:com.google.android.gms.wearable/u0a12 (cch-empty) 976 Proc #10: cch B/ /S trm: 0 4067:com.google.android.talk/u0a62 (cch-started-ui-services) 977 Proc # 7: cch B/ /S trm: 0 18868:com.google.corp.huddle.android/u0a95 (cch-started-ui-services) 978 Proc # 6: cch B/ /CA trm: 0 27697:com.google.android.calendar/u0a40 (cch-act) 979 Proc # 8: cch+1 B/ /CA trm: 0 25675:com.google.android.apps.genie.geniewidget/u0a81 (cch-act) 980 Proc #16: cch+2 B/ /CE trm: 0 1272:com.google.android.keep/u0a106 (cch-empty) 981 Proc #15: cch+2 B/ /CE trm: 0 885:android.process.media/u0a9 (cch-empty) 982 Proc #14: cch+2 B/ /CE trm: 0 15146:android.process.acore/u0a3 (cch-empty) 983 Proc # 9: cch+3 B/ /CA trm: 0 17016:com.google.android.gm/u0a79 (cch-act) 984 Proc #19: cch+4 B/ /CE trm: 0 973:com.google.android.apps.maps/u0a66 (cch-empty) 985 Proc #18: cch+4 B/ /CE trm: 0 1091:com.google.android.apps.photos/u0a71 (cch-empty) 986 Proc #17: cch+4 B/ /CE trm: 0 1141:com.google.android.apps.plus/u0a74 (cch-empty) 987 Proc #12: cch+5 B/ /CA trm: 0 22299:com.google.android.apps.dogfood/u0a105 (cch-act) 988 Proc #21: cch+6 B/ /CE trm: 0 995:com.google.android.partnersetup/u0a18 (cch-empty)></pre></p> 989 </section> 990 991 <h2 id=scans>Scans</h2> 992 <p>Use the following steps to identify applications performing excessive 993 Bluetooth Low Energy (BLE) scans:</p> 994 <ul> 995 <li>Find log messages for <code>BluetoothLeScanner</code>: 996 <pre> 997 $ grep 'BluetoothLeScanner' ~/downloads/bugreport.txt 998 07-28 15:55:19.090 24840 24851 D BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5 999 </pre></li> 1000 <li>Locate the PID in the log messages. In this example, "24840" and 1001 "24851" are PID (process ID) and TID (thread ID).</li> 1002 <li>Locate the application associated with the PID: 1003 <pre> 1004 PID #24840: ProcessRecord{4fe996a 24840:com.badapp/u0a105} 1005 </pre> 1006 <p>In this example, the package name is <code>com.badapp</code>.</li> 1007 <li>Look up the package name on Google Play to identify the responsible 1008 application: 1009 <strong>https://play.google.com/store/apps/details?id=com.badapp</strong>.</li> 1010 </ul> 1011 <p class=note><strong>Note</strong>: For devices running Android 7.0, the 1012 system collects data for BLE scans and associates these activities 1013 with the initiating application. For details, see 1014 <a href="/devices/tech/power/values.html#le-bt-scans">Low Energy (LE) 1015 and Bluetooth scans</a>.</p> 1016 1017 </body> 1018 </html> 1019
