Android crash debugging

Android logging and debugging ● By: Ashish Agrawal 1

Android's boot up process Stage Steps Comments Boot-loader - Location: bootablebootloaderlegacyusbloader init.S Initializes stacks, zeros the BSS segment, call _main() in main.c main.c Initializes hardware (clocks, board, keypad, console), creates Linux tags Displays "USB FastBoot". Boot from flash, or loops while usb_poll() awaits host PC connection Linux kernel - Sets up the system, loads drivers, and starts running the first process init The init process Setup file system Create and mount directories like /dev, /proc, /sys Execute init.rc This is the boot-up script, commands are using Android-specific syntax Setup console Display "A N D R This is just a text msg written to /dev/tty0 O I D" Zygote Zygot process in init.rc brings up Dalvik Java VM and starts the system server bootanimation Shows the animation during boot-up 2 Framework …. ….

Overview of Android Logging system 3

* Main - the main application log This log contains output from android.util.Log class on Java side and LOGE(LOGV, LOGI, LOGW.) macro on the native side. * Events - for system event information Events log reflects system diagnostic events which outputs using android.util.EventLog class e.g: System diagnostic events are used to record certain system-level events (such as garbage collection, activity manager state, system watchdogs, and other low level activity) * Radio - for radio and phone-related information The logging system automatically routes messages with specific tags (“RIL”, “GSM” etc.) into the radio buffer. * System - a log for low-level system messages and debugging. Many classes in the Android framework utilize the system log to keep their messages separate from (possibly noisy) application log messages. 4 Slog.i(“Tag I want to see in the system log”, “Hello system log");

dumpsys/dumpstate Dumps huge amounts of information about the system, including status, counts and statistics • Dumpstate reproduces lots of stuff from /proc – Does a dumpsys as well • Dumpsys show status information from Android services – e.g. dumpsys alarm 5

Dumpsys Eg: adb shell dumpsys battery You will get output: Current Battery Service state: AC powered: false AC capacity: 500000 USB powered: true status: 5 health: 2 present: true level: 100 scale: 100 voltage:4201 temperature: 271 <---------- Battery temperature! %) technology: Li-poly <---------- Battery technology! %) 6

How to get kernel messages from Android? ● To invoke the "dmesg" from the control PC, one can simply run ● # adb shell dmesg ● However, because "syslogd" is possibly not included in Android, there is no such logs, and one may find that the directory "/var" is not even created.One can just run the following command to continuously dump the kernel messages. ● adb shell cat /proc/kmsg 7

Redirecting kernel messages ● If the phone doesn't even boot up to a stable state where the ADB commands can be used, one might be interested in redirecting the kernel messages to some places where they can be seen. This is to leverage the "console=" command for the kernel. ● For different devices, there may be different ports where the messages can be redirected to. USB SERIAL PORT, SERIAL PORT, UART port ● Eg: console=ttyMSM2,115200n8, console=ttyUSB0,9600n8 etc ● In order to be used as a console, a device driver has to register itself as a console provider by calling register_console in kernel/printk.c, and it has to provide some callbacks for printk to write kernel messages.

Java Application Crash When a Java application crashes, the Dalvik VM will receive a SIGQUIT, it dumps stack traces for all threads and parse to plain text typo. Developer could use this dump together with AndroidRuntime error level log to locate error. 9

Example ----- pid 182 at 2009-03-06 06:15:22 ----- Cmd line: com.android.settings DALVIK THREADS: "main" prio=5 tid=3 NATIVE | group="main" sCount=1 dsCount=0 s=0 obj=0x40018dd8 | sysTid=182 nice=0 sched=0/0 handle=-1096356708 at android.os.BinderProxy.transact(Native Method) at android.app.ActivityManagerProxy.handleApplicationError(ActivityMana gerNative.java:2044) at com.android.internal.os.RuntimeInit.crash(RuntimeInit.java:302) at com.android.internal.os.RuntimeInit$UncaughtHandler.uncaughtE xception(RuntimeInit.java:75) at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:887) at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:884) at dalvik.system.NativeStart.main(Native Method) 10

ANR In Android, the system guards against applications that are insufficiently responsive for a period of time by displaying a dialog to the user, called the “Application Not Responding” (ANR) dialog Note that system cannot show this dialog sometimes due to internal problems e.g. if ANR occurred in the Activity or Window Manager. 11

What triggers ANR In Android, application responsiveness is monitored by the Activity Manager and Window Manager system services. Android will display the ANR dialog for a particular application when it detects one of the following conditions: * No response to an input event (e.g. key press, screen touch) within 5 seconds * A BroadcastReceiver hasn't finished executing within 10 seconds 12

Click to11-28 12:30:56.258 489 505 W ActivityManager: Timeout executing service: ServiceRecord{41f9c338 com.google.android.apps.maps/com.google.android.location.internal.server.G oogleLocationService} 11-28 12:30:59.937 489 505 E ActivityManager: ANR in com.google.android.apps.maps:GoogleLocationService 11-28 12:30:59.937 489 505 E ActivityManager: Reason: Executing service com.google.android.apps.maps/com.google.android.location.internal.server.G oogleLocationService 11-28 12:30:59.937 489 505 E ActivityManager: Load: 96.68 / 22.15 / 7.49 11-28 12:30:59.937 489 505 E ActivityManager: CPU usage from 6970ms to 960ms ago: 11-28 12:30:59.937 489 505 E ActivityManager: 90% 9297/coredump: 82% user + 7.6% kernel R 11-28 12:31:00.875 489 505 W ActivityManager: Killing ProcessRecord{41b4af40 5361:com.google.android.apps.maps:GoogleLocationService/u0a35}: background ANR 11-28 12:31:01.203 489 794 I ActivityManager: Process com.google.android.apps.maps:GoogleLocationService (pid 5361) has died. 13

ANR hints * Look the “SIG: 9” line in the main thread and analyze nearby messages. Sometimes system output information why it decided that the thread is in ANR state. * In ANR log start your analysis from the “main” thread of the process since this is a thread where UI works. The ANR concept was specially invented with struggling “not responding” UI threads. * In ANR log check in which state is your main thread. If it is in MONITOR state it can be in “dead lock” state. TIMED_WAIT state can also point to the problems with locking of your thread by ‘sleep’ or ‘wait’ functions. * If the system itself (Activity or Window Managers) is in ANR condition and cannot raise ANR so you cannot differentiate which thread in which process is responsible for this analyze “Just Now”14 log.

Thread Status * ZOMBIE – terminated thread * RUNNABLE – runnable or running now * TIMED_WAIT – timed waiting in Object.wait() * MONITOR – blocked on a monitor * WAIT – waiting in Object.wait() * INITIALIZING - allocated, not yet running * STARTING - started, not yet on thread list * NATIVE - off in a JNI native method * VMWAIT - waiting on a VM resource * SUSPENDED - suspended, usually by GC or debugger * UNKNOWN – thread is in the undefined state 15

How to read Android native crash log and stack trace ● An Android crash in C/C++ code often generates some crash log which looks like the following. ● The first is the build information in the system property "ro.build.fingerprint" I/DEBUG ( 730): *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** I/DEBUG ( 730): Build fingerprint: 'generic/generic/generic/:1.5/...' 16 ●

How to read Android crash log and stack trace ● Then, it shows the process ID number (pid) and the thread id (tid). In this example, the PID and TID are the same. However, if the crash happens in a child thread, the thread ID tid will be different from pid. I/DEBUG ( 730): pid: 876, tid: 876 >>> /system/bin/mediaserver <<< 17 ●

How to read Android crash log and stack trace ● The following shows the signal which caused the process to abort, in this case, it's a segmentation fault. This is followed by the register values. I/DEBUG ( 730): signal 11 (SIGSEGV), fault addr 00000010 I/DEBUG ( 730): r0 00000000 r1 00016618 r2 80248f78 r3 00000000 I/DEBUG ( 730): r4 80248f78 r5 0000d330 r6 80248f78 r7 beaf9974 I/DEBUG ( 730): r8 00000000 r9 00000000 10 00000000 fp 00000000 I/DEBUG ( 730): ip afd020c8 sp beaf98d8 lr 8021edcd pc 8021c630 cpsr a0000030 ● 18 ●

How to read Android crash log and stack trace ● This is the call stack trace. #00 is the depth of the stack pointer. The "pc <addr>" is the PC address in the stack. Sometimes, the "lr" link register containing the return address is shown instead of PC. It is followed by the file containing the code. I/DEBUG ( 730): #00 pc 0001c630 /system/lib/libhelixplayer.so I/DEBUG ( 730): #01 pc 0001edca /system/lib/libhelixplayer.so I/DEBUG ( 730): #02 pc 0001ff0a /system/lib/libhelixplayer.so I/DEBUG ( 730): #03 pc 000214e0 /system/lib/libutils.so I/DEBUG ( 730): #04 pc 0000e322 /system/lib/libmediaplayerservice.so ... I/DEBUG ( 730): #15 pc b0001516 /system/bin/linker ● 19 ●

How to read Android crash log and stack trace ● The following is actually the current stack with the stack pointer address and code dump. Each line contains 4 bytes (one machine word), and the address is in ascending order. The words in the stack are mapped onto the memory region it belongs to. I/DEBUG ( 730): stack: I/DEBUG ( 730): beaf9898 00016618 [heap] I/DEBUG ( 730): beaf989c beaf98d0 [stack] I/DEBUG ( 730): beaf98a0 0000db28 [heap] I/DEBUG ( 730): beaf98a4 beaf98f8 [stack] I/DEBUG ( 730): beaf98b8 8021cf4d /system/lib/libhelixplayer.so I/DEBUG ( 730): beaf98bc 80248f78 I/DEBUG ( 730): #00 beaf98d8 0000d330 [heap] I/DEBUG ( 730): beaf98dc 00000000 I/DEBUG ( 730): beaf98e0 0000d330 [heap] I/DEBUG ( 730): beaf98e4 8021edcd /system/lib/libhelixplayer.so I/DEBUG ( 730): #01 beaf98e8 80248f78 ● 20 ●

Unix Signals SIGHUP 1 Exit Hangup SIGINT 2 Exit Interrupt SIGQUIT 3 Core Quit SIGILL 4 Core Illegal Instruction SIGTRAP 5 Core Trace/Breakpoint Trap SIGABRT 6 Core Abort SIGEMT 7 Core Emulation Trap SIGFPE 8 Core Arithmetic Exception SIGKILL 9 Exit Killed SIGBUS 10 Core Bus Error SIGSEGV 11 Core Segmentation Fault SIGSYS 12 Core Bad System Call SIGPIPE 13 Exit Broken Pipe 21

Android Watchdog Android framework's watchdog is meant to deal with cases when any of the following locks is held for more than a minute or when ServerThread is busy. ActivityManagerService.this PowerManagerService.mLocks WindowManagerService.mWindowMap WindowManagerService.mKeyguardTokenWatcher WindowManagerService.mKeyWaiter 22

Watchdog thread posts a message MONITOR to android.server.ServerThread. android.server.ServerThread's looper thread would read all pending messages including watchdog's MONITOR message and would invoke an appropriate handler. The handler of MONITOR message would simply check for availability of above mentioned locks. If all, locks are available variable mCompleted (Watchdog.java) would be set to true and watchdog would continue to post MONITOR messages once every minute. mCompleted stays false only when any of the above locks is held by any thread of system_server for more than a minute or if the23 MONITOR message isn't handled by ServerThread.

In this case, MONITOR is handled but can't be serviced due to unavailability of lock (ActivityManagerService) "android.server.ServerThread" prio=5 tid=8 MONITOR group="main" sCount=1 dsCount=0 s=N obj=0x4690be50 self=0x54e440 sysTid=206 nice=-2 sched=0/0 cgrp=unknown handle=5562400 at com.android.server.am.ActivityManagerService.monitor(ActivityMana gerService.java:~14726) - waiting to lock (0x4691a9b8) (a com.android.server.am.ActivityManagerService) held by threadid=41 (Binder Thread #7) at com.android.server.Watchdog$HeartbeatHandler.handleMessage(W atchdog.java:306) at android.os.Handler.dispatchMessage(Handler.java:99) at android.os.Looper.loop(Looper.java:123) at com.android.server.ServerThread.run(SystemServer.java:517) 24

When you are no longer wanted.. Android open source project supports a maximum of 15 hidden applications running at any point and any attempt to launch new apps kills the least recently used ones. This is done to reduce the load on RAM and has been the case since early version of Android. 02-19 13:43:55.194 I/ActivityManager( 1096): No longer want com.lge.omadmclient:remote (pid 23052): hidden #16 25

References: http://bootloader.wikidot.com/linux:boot:android http://softteco.blogspot.com/2011/04/android-playing-with-dumpsys.html http://bootloader.wikidot.com/linux:android:crashlog https://github.com/keesj/gomo/wiki http://elinux.org/Android_Portal 26

Android crash debugging

More Related Content

What's hot

Similar to Android crash debugging

More from Ashish Agrawal

Recently uploaded

In this document

Android crash debugging