Boot time

BootEvent:

cat /proc/bootprof    /** M: Mtprof tool @{ */

LINUX/android/system/core/rootdir/init.rc
INIT: on init start

LINUX/android/device/mediatek/mt6795/init.mt6795.rc
INIT:Mount_START
INIT:Mount_END

LINUX/android/frameworks/base/core/java/com/android/internal/os/ZygoteInit.java
Zygote:Preload

frameworks/native/services/surfaceflinger/mediatek/SurfaceFlinger.cpp
frameworks/native/services/surfaceflinger/SurfaceFlinger.cpp
BOOT_Animation:START
BOOT_Animation:END

./services/java/com/android/server/SystemServer.java
Android:SysServerInit_START

frameworks/base/services/core/java/com/android/server/pm/PackageManagerService.java
Android:PackageManagerService_Start

frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
AP_Init:[]

Log:

Boot animation time:

frameworks/native/services/surfaceflinger/SurfaceFlinger.cpp
 316 void SurfaceFlinger::bootFinished()
 317 {
 318     const nsecs_t now = systemTime();
 319     const nsecs_t duration = now - mBootTime;
 320     ALOGI("Boot is finished (%ld ms)", long(ns2ms(duration)) );
 321     mBootFinished = true;
 322
 323     // wait patiently for the window manager death
 324     const String16 name("window");
 325     sp<IBinder> window(defaultServiceManager()->getService(name));
 326     if (window != 0) {
 327         window->linkToDeath(static_cast<IBinder::DeathRecipient*>(this));
 328     }
 329
 330     // stop boot animation
 331     // formerly we would just kill the process, but we now ask it to exit so it
 332     // can choose where to stop the animation.
 333     property_set("service.bootanim.exit", "1");
 334
 335 #ifdef MTK_AOSP_ENHANCEMENT
 336     // boot time profiling
 337     ALOG(LOG_INFO,"boot","BOOTPROF:BootAnimation:End:%ld", long(ns2ms(systemTime())));
 338     bootProf(0);
 339     SFWatchDog::getInstance()->setThreshold(500);
 340 #endif
 341 }

Scan package time:

frameworks/base/services/core/java/com/android/server/pm/PackageManagerService.java
            /** M: Add PMS scan package time log @{ */
            startScanTime = SystemClock.uptimeMillis();
            Slog.d(TAG, "scan package: " + file.toString() + " , start at: " + startScanTime + "ms.");
            /** M: Add PMS scan package time log @{ */
            endScanTime = SystemClock.uptimeMillis();
            Slog.d(TAG, "scan package: " + file.toString() + " , end at: " + endScanTime + "ms. elapsed time = " + (endScanTime - startScanTime) + "ms.");

            Slog.i(TAG, "Time to scan packages: "
                    + ((SystemClock.uptimeMillis()-startTime)/1000f)
                    + " seconds");

AP initialization time:

frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
            StringBuilder buf = mStringBuilder;
            buf.setLength(0);
            buf.append("Start proc ");
            buf.append(app.processName);
            if (!isActivityProcess) {
                buf.append(" [");
                buf.append(entryPoint);
                buf.append("]");
            }
            buf.append(" for ");
            buf.append(hostingType);
            if (hostingNameStr != null) {
                buf.append(" ");
                buf.append(hostingNameStr);
            }
            buf.append(": pid=");
            buf.append(startResult.pid);
            buf.append(" uid=");
            buf.append(uid);
            buf.append(" gids={");
            if (gids != null) {
                for (int gi=0; gi<gids.length; gi++) {
                    if (gi != 0) buf.append(", ");
                    buf.append(gids[gi]);
                }
            }
            buf.append("}");
            if (requiredAbi != null) {
                buf.append(" abi=");
                buf.append(requiredAbi);
            }
            Slog.i(TAG, buf.toString());

System server blocked and killed by WatchDag

 如何從各種 log找出造成 System server block的原因

event_log:

07-12 01:42:44.727   956  1520 I [2802]  : Blocked in handler on main thread (main)

main_log:

06-13 15:55:55.725  9028  9028 I AEE/AED : $** *** *** *** *** *** *** *** Fatal *** *** *** *** *** *** *** **$
06-13 15:55:55.725  9028  9028 I AEE/AED : Build Info: 'L0.MP6:ALPS.L0.MP6.TC9SP.V1.38_FIH6795.LWT.S50.L_P43:MT6795:S01,alps/hollyds/hollyds:5.0/2.60.J.1.3_3_04/1434012189:userdebug/test-keys'
06-13 15:55:55.725  9028  9028 I AEE/AED : Flavor Info: 'None'
06-13 15:55:55.725  9028  9028 I AEE/AED : Exception Log Time:[Sat Jun 13 15:55:55 CST 2015] [91427.879630]
06-13 15:55:55.725  9028  9028 I AEE/AED :
06-13 15:55:55.725  9028  9028 V AEE/AED : Write: Req.AE_REQ_CLASS, seq:0
06-13 15:55:55.727  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_CLASS, seq:0, 0, 4
06-13 15:55:55.727  9028  9028 D AEE/AED :   Got data:SWT
06-13 15:55:55.727  9028  9028 I AEE/AED : SWT
06-13 15:55:55.727  9028  9028 V AEE/AED : Write: Req.AE_REQ_TYPE, seq:1
06-13 15:55:55.727  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_TYPE, seq:1, 0, 17
06-13 15:55:55.827  9028  9028 D AEE/AED :   Type:system_server_watchdog
06-13 15:55:55.828  9028  9028 I AEE/AED : system_server_watchdog
06-13 15:55:55.828  9028  9028 V AEE/AED : Write: Req.AE_REQ_PROCESS, seq:2
06-13 15:55:55.828   799  1367 D AEE/LIBAEE: shell: got the request (cmd:Req,AE_REQ_PROCESS)
06-13 15:55:55.829  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_PROCESS, seq:2, 0, e
06-13 15:55:55.829  9028  9028 D AEE/AED :   Process:system_server
06-13 15:55:55.829  9028  9028 I AEE/AED : system_server
06-13 15:55:55.830  9028  9028 V AEE/AED : Write: Req.AE_REQ_MODULE, seq:3
06-13 15:55:55.830  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_MODULE, seq:3, 0, 1
06-13 15:55:55.830  9028  9028 D AEE/AED :   Module:
06-13 15:55:55.830  9028  9028 V AEE/AED : Write: Req.AE_REQ_BACKTRACE, seq:4
06-13 15:55:55.831  9028  9028 V AEE/AED : Read: Rsp.AE_REQ_BACKTRACE, seq:4, 0, bd
06-13 15:55:55.831  9028  9028 D AEE/AED :   Backtrace:Process: system_server
06-13 15:55:55.831  9028  9028 D AEE/AED : Subject: Blocked in handler on main thread (main)
06-13 15:55:55.831  9028  9028 D AEE/AED : Build: alps/hollyds/hollyds:5.0/2.60.J.1.3_3_04/1434012189:userdebug/test-keys
06-13 15:55:55.831  9028  9028 D AEE/AED :
06-13 15:55:55.831  9028  9028 D AEE/AED :
06-13 15:55:55.831  9028  9028 D AEE/AED : Unable to open log device 'crash'
06-13 15:55:55.831  9028  9028 D AEE/AED :
06-13 15:55:55.831  9028  9028 I AEE/AED : Process: system_server
06-13 15:55:55.831  9028  9028 I AEE/AED : Subject: Blocked in handler on main thread (main)
..........
06-13 15:55:42.483   799  1367 I Process : Sending signal. PID: 799 SIG: 3

sys_log:

06-13 15:55:33.637   799  1367 E Watchdog: **SWT happen **Blocked in handler on main thread (main)
.......
06-13 15:56:00.575   799  1367 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in handler on main thread (main)
06-13 15:56:00.576   799  1367 W Watchdog: main thread stack trace:
06-13 15:56:00.593   799  1367 W Watchdog:     at android.media.ToneGenerator.native_setup(Native Method)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.media.ToneGenerator.<init>(ToneGenerator.java:746)
06-13 15:56:00.593   799  1367 W Watchdog:     at com.android.server.notification.NotificationManagerService$2.onReceive(NotificationManagerService.java:775)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:912)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.os.Handler.handleCallback(Handler.java:815)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:104)
06-13 15:56:00.593   799  1367 W Watchdog:     at android.os.Looper.loop(Looper.java:194)
06-13 15:56:00.593   799  1367 W Watchdog:     at com.android.server.SystemServer.run(SystemServer.java:359)
06-13 15:56:00.593   799  1367 W Watchdog:     at com.android.server.SystemServer.main(SystemServer.java:227)
06-13 15:56:00.593   799  1367 W Watchdog:     at java.lang.reflect.Method.invoke(Native Method)
06-13 15:56:00.593   799  1367 W Watchdog:     at java.lang.reflect.Method.invoke(Method.java:372)
06-13 15:56:00.596   799  1367 W Watchdog:     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:955)
06-13 15:56:00.597   799  1367 W Watchdog:     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:750)

如何從Backtrace中尋找block的原因：

1. 看 Process是 block在哪一個 thread
2. Trace block tread的 callstack，觀察 class name或 function name，尋找可能造成block的地方
    (不管是在 Java code或 native code)
3. 如果是 block在 main thread，從 call stack中又無法看出可能造成 block的地方，可以嘗試搜  
    尋同一個 process下的其他 tread的 call stack，觀察是否有和 main thread呼叫相同 method的地
    方

Backtrace:

----- pid 956 at 2015-07-12 09:42:08 -----
Cmd line: system_server
............
DALVIK THREADS (111):
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x747d7fa8 self=0x558db4b0e0
  | sysTid=956 nice=-2 cgrp=apps sched=0/0 handle=0x7f88880150
  | state=S schedstat=( 2873204364724 2124560498532 5319630 ) utm=153154 stm=134166 core=7 HZ=100
  | stack=0x7fcc017000-0x7fcc019000 stackSize=8MB
  | held mutexes=
  kernel: __switch_to+0x70/0x7c
  kernel: binder_thread_read+0x47c/0xec4
  kernel: binder_ioctl+0x3f8/0x828
  kernel: do_vfs_ioctl+0x4c4/0x598
  kernel: SyS_ioctl+0x5c/0x88
  kernel: cpu_switch_to+0x48/0x4c
  native: #00 pc 0005eeb4  /system/lib64/libc.so (__ioctl+4)
  native: #01 pc 0006882c  /system/lib64/libc.so (ioctl+100)
  native: #02 pc 00028544  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+164)
  native: #03 pc 00028fa4  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+112)
  native: #04 pc 00029218  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+176)
  native: #05 pc 0001ff18  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+64)
  native: #06 pc 0008aa10  /system/lib64/libmedia.so (???)
  native: #07 pc 00071c38  /system/lib64/libmedia.so (android::AudioSystem::getDevicesForStream(audio_stream_type_t)+40)
  native: #08 pc 000264b8  /system/framework/arm64/boot.oat (Java_android_media_AudioSystem_getDevicesForStream__I+144)
  at android.media.AudioSystem.getDevicesForStream(Native method)
  at android.media.AudioService.getDeviceForStream(AudioService.java:3399)
  at android.media.AudioService.getStreamVolume(AudioService.java:1698)
  at android.media.AudioManager.getStreamVolume(AudioManager.java:961)
  at com.android.server.notification.NotificationManagerService.buzzBeepBlinkLocked(NotificationManagerService.java:1966)
  at com.android.server.notification.NotificationManagerService.access$3600(NotificationManagerService.java:128)
  at com.android.server.notification.NotificationManagerService$7.run(NotificationManagerService.java:1880)
  - locked <0x3d78bf02> (a java.util.ArrayList)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:135)
  at com.android.server.SystemServer.run(SystemServer.java:295)
  at com.android.server.SystemServer.main(SystemServer.java:183)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1016)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:811)
............

"NetworkPolicy" prio=5 tid=42 Native

  | group="main" sCount=1 dsCount=0 obj=0x139b2860 self=0x557590bc50

  | sysTid=1191 nice=0 cgrp=apps sched=0/0 handle=0x557523dcb0

  | state=S schedstat=( 66132269378 123944333623 433825 ) utm=3755 stm=2858 core=5 HZ=100

  | stack=0x7f6d87d000-0x7f6d87f000 stackSize=1036KB

  | held mutexes=

  kernel: __switch_to+0x70/0x7c

  kernel: binder_thread_read+0x47c/0xec4

  kernel: binder_ioctl+0x3f8/0x828

  kernel: do_vfs_ioctl+0x4c4/0x598

  kernel: SyS_ioctl+0x5c/0x88

  kernel: cpu_switch_to+0x48/0x4c

  native: #00 pc 0005eeb4  /system/lib64/libc.so (__ioctl+4)

  native: #01 pc 0006882c  /system/lib64/libc.so (ioctl+100)

  native: #02 pc 00028544  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+164)

  native: #03 pc 00028fa4  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+112)

  native: #04 pc 00029218  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+176)

  native: #05 pc 0001ff18  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+64)

  native: #06 pc 000d99dc  /system/lib64/libandroid_runtime.so (???)

  native: #07 pc 010e0fec  /system/framework/arm64/boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+212)

  at android.os.BinderProxy.transactNative(Native method)

  at android.os.BinderProxy.transact(Binder.java:501)

  at com.android.internal.telephony.ISub$Stub$Proxy.getDefaultDataSubId(ISub.java:845)

  at android.telephony.SubscriptionManager.getDefaultDataSubId(SubscriptionManager.java:887)

  at com.android.server.net.NetworkPolicyManagerService.isDdsSimStateReady(NetworkPolicyManagerService.java:2269)

  at com.android.server.net.NetworkPolicyManagerService.setNetworkTemplateEnabled(NetworkPolicyManagerService.java:1019)

  at com.android.server.net.NetworkPolicyManagerService.updateNetworkEnabledLocked(NetworkPolicyManagerService.java:989)

  at com.android.server.net.NetworkPolicyManagerService$7.onReceive(NetworkPolicyManagerService.java:563)

  - locked <0x3532129f> (a java.lang.Object)

  at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:869)

  at android.os.Handler.handleCallback(Handler.java:739)

  at android.os.Handler.dispatchMessage(Handler.java:95)

  at android.os.Looper.loop(Looper.java:135)

  at android.os.HandlerThread.run(HandlerThread.java:61)

Debug abnormal appearence of (Back, Home, Recent) key

說明

大寫：顯示
小寫：消失
*      ：變更狀態

Ex:
06-16 23:26:01.708  1300  1300 D PhoneStatusBar: disable: < expand icons alerts system_info back HOME* RECENT* clock SEARCH* >
Back key -> 維持顯示狀態
Home key -> 變為消失狀態
Recent app key -> 變為消失狀態

Source code:

frameworks/base/packages/SystemUI/src/com/android/systemui/statusbar/phone/PhoneStatusBar.java
public void disable(int state, boolean animate) {
............
StringBuilder flagdbg = new StringBuilder();
        flagdbg.append("disable: < ");
        flagdbg.append(((state & StatusBarManager.DISABLE_EXPAND) != 0) ? "EXPAND" : "expand");
        flagdbg.append(((diff  & StatusBarManager.DISABLE_EXPAND) != 0) ? "* " : " ");
        flagdbg.append(((state & StatusBarManager.DISABLE_NOTIFICATION_ICONS) != 0) ? "ICONS" : "icons");
        flagdbg.append(((diff  & StatusBarManager.DISABLE_NOTIFICATION_ICONS) != 0) ? "* " : " ");
        flagdbg.append(((state & StatusBarManager.DISABLE_NOTIFICATION_ALERTS) != 0) ? "ALERTS" : "alerts");
        flagdbg.append(((diff  & StatusBarManager.DISABLE_NOTIFICATION_ALERTS) != 0) ? "* " : " ");
        flagdbg.append(((state & StatusBarManager.DISABLE_SYSTEM_INFO) != 0) ? "SYSTEM_INFO" : "system_info");
        flagdbg.append(((diff  & StatusBarManager.DISABLE_SYSTEM_INFO) != 0) ? "* " : " ");
        flagdbg.append(((state & StatusBarManager.DISABLE_BACK) != 0) ? "BACK" : "back");
        flagdbg.append(((diff  & StatusBarManager.DISABLE_BACK) != 0) ? "* " : " ");
        flagdbg.append(((state & StatusBarManager.DISABLE_HOME) != 0) ? "HOME" : "home");
        flagdbg.append(((diff  & StatusBarManager.DISABLE_HOME) != 0) ? "* " : " ");
        flagdbg.append(((state & StatusBarManager.DISABLE_RECENT) != 0) ? "RECENT" : "recent");
        flagdbg.append(((diff  & StatusBarManager.DISABLE_RECENT) != 0) ? "* " : " ");
        flagdbg.append(((state & StatusBarManager.DISABLE_CLOCK) != 0) ? "CLOCK" : "clock");
        flagdbg.append(((diff  & StatusBarManager.DISABLE_CLOCK) != 0) ? "* " : " ");
        flagdbg.append(((state & StatusBarManager.DISABLE_SEARCH) != 0) ? "SEARCH" : "search");
        flagdbg.append(((diff  & StatusBarManager.DISABLE_SEARCH) != 0) ? "* " : " ");
        flagdbg.append(">");
        Log.d(TAG, flagdbg.toString());
.............
}

Boot log

想要看有關開機異常的issue時，可利用以下的key word確認開機的時間點

event log:
06-09 16:24:06.995   334   334 I boot_progress_start: 13204

system log:
SystemServer: Entered the Android system server!

main log:
06-09 16:24:06.995   334   334 D AndroidRuntime: >>>>>> AndroidRuntime START com.android.internal.os.ZygoteInit <<<<<<

Debug native crash

工具：

1. addr2line - 透過objdump將address轉換成行數

${project}/LINUX/android/prebuilts/tools/gcc-sdk/addr2line

$ addr2line -iCfe <XXXX.so> <address>
Ex: addr2line -iCfe libart-compiler.so 001e84f7
 
2. objdump - 可得知運行過程中暫存器內所存的值的變化
$ source build/envsetup.sh
$ choosecombo
$ arm-linux-androideabi-objdump -S -g <XXXX.so> > <XXXX.asm>
Ex: arm-linux-androideabi-objdump -S -g libart-compiler.so  > libart-compiler.asm
 
3. symbol file
手機上燒錄的版本和電腦上要分析的版本要一致，經過轉換後的行數才會正確
${project}\out\target\product\${production}\symbols\system\lib\XXXX.so
Ex: l-chambalplus-holly-release\LINUX\android\out\target\product\hollyds\symbols\system\lib\libc.so 

分析log：

main log:
05-20 20:45:27.503 V/ESTA ( 4241): Build fingerprint: 'alps/hollyss/hollyss:5.0/2.59.J.0.31_3_05/1431922950:userdebug/test-keys'
05-20 20:45:27.503 V/ESTA ( 4241): Revision: '0'
05-20 20:45:27.503 V/ESTA ( 4241): ABI: 'arm'
05-20 20:45:27.503 V/ESTA ( 4241): pid: 3205, tid: 3205, name: le.android.talk >>> com.google.android.talk <<<
05-20 20:45:27.503 V/ESTA ( 4241): signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr --------
05-20 20:45:27.503 V/ESTA ( 4241): Abort message: 'art/runtime/quick_exception_handler.cc:417] Check failed: handler_quick_frame_pc_ != 0u (handler_quick_frame_pc_=0, 0u=0) '
05-20 20:45:27.503 V/ESTA ( 4241): r0 00000000 r1 00000c85 r2 00000006 r3 00000000
05-20 20:45:27.503 V/ESTA ( 4241): r4 f7052118 r5 00000006 r6 0000000b r7 0000010c
05-20 20:45:27.503 V/ESTA ( 4241): r8 00000001 r9 f4c4f550 sl f4c07800 fp e1be1510
05-20 20:45:27.503 V/ESTA ( 4241): ip 00000c85 sp ffa4d590 lr f6fdde15 pc f7000f18 cpsr 60070010
05-20 20:45:27.503 V/ESTA ( 4241):
05-20 20:45:27.503 V/ESTA ( 4241): backtrace:
05-20 20:45:27.503 V/ESTA ( 4241): #00 pc 00039f18 /system/lib/libc.so (tgkill+12)
05-20 20:45:27.503 V/ESTA ( 4241): #01 pc 00016e11 /system/lib/libc.so (pthread_kill+52)
05-20 20:45:27.503 V/ESTA ( 4241): #02 pc 00017a13 /system/lib/libc.so (raise+10)
05-20 20:45:27.503 V/ESTA ( 4241): #03 pc 00014357 /system/lib/libc.so (__libc_android_abort+34)
05-20 20:45:27.503 V/ESTA ( 4241): #04 pc 00012a84 /system/lib/libc.so (abort+4)
05-20 20:45:27.503 V/ESTA ( 4241): #05 pc 000a7753 /system/lib/libart.so (art::LogMessage::~LogMessage()+1410)
05-20 20:45:27.503 V/ESTA ( 4241): #06 pc 0020aaf7 /system/lib/libart.so (art::QuickExceptionHandler::DoLongJump()+210)
05-20 20:45:27.503 V/ESTA ( 4241): #07 pc 00223ad3 /system/lib/libart.so (art::Thread::QuickDeliverException()+118)
05-20 20:45:27.503 V/ESTA ( 4241): #08 pc 0027c125 /system/lib/libart.so (artDeliverExceptionFromCode+60)
05-20 20:45:27.503 V/ESTA ( 4241): #09 pc 0005f9cb /data/dalvik-cache/arm/system@framework@boot.oat
 
1. 使用addr2line將backtrace每一個address做轉換
backtrace:
#00 pc 00039f18 /system/lib/libc.so (tgkill+12)
tgkill
/home/user/Holly_SS_Formal/ex_host_sync/LINUX/android/bionic/libc/arch-arm/syscalls/tgkill.S:9
#01 pc 00016e11 /system/lib/libc.so (pthread_kill+52)pthread_kill
/home/user/tt/holly/LINUX/android/bionic/libc/bionic/pthread_kill.cpp:49
#02 pc 00017a13 /system/lib/libc.so (raise+10)
raise
/home/user/Holly_SS_Daily/ex_host_sync/LINUX/android/bionic/libc/bionic/raise.cpp:32
....................
#06 pc 0020aaf7 /system/lib/libart.so (art::QuickExceptionHandler::DoLongJump()+210)
art::QuickExceptionHandler::DoLongJump()
/home/user/tt/holly/LINUX/android/art/runtime/quick_exception_handler.cc:417 
 
2. 使用objdump顯示目的檔的檔頭、區段、內容、符號表等資訊
利用backtrace的address找出正確的位置

623017   20aa8e:       4824            ldr     r0, [pc, #144]  ; (20ab20 <_ZN3art21QuickExceptionHandler10DoLongJumpEv+0xfc>)

  623018   20aa90:       447f            add     r7, pc

  623019   20aa92:       447e            add     r6, pc

 .................................

  623052   20aaf0:       f699 eb94       blx     a421c <_ZNSt3__1lsINS_11char_traitsIcEEEERNS_13basic_ostreamIcT_EES6_PKc>

  623053   20aaf4:       4628            mov     r0, r5

  623054   20aaf6:       f69c fb6b       bl      a71d0 <_ZN3art10LogMessageD1Ev>

  623055   20aafa:       f8dd c008       ldr.w   ip, [sp, #8]

  623056   20aafe:       e7cb            b.n     20aa98 <_ZN3art21QuickExceptionHandler10DoLongJumpEv+0x74>

Native Crash類型：

1. SIGABRT
signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr
Abort message: 'art/runtime/quick_exception_handler.cc:417] Check failed: handler_quick_frame_pc_ != 0u (handler_quick_frame_pc_=0, 0u=0)
重點：
觀察Abort message，確認backtrace發生crash的位置
觀察main log發生crash的時間點附近，是否有造成crash發生的異常
        
 
2. SIGSEGV
signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x10
重點：
根據addr2line轉換出的行數，trace source code找出發生問題的地方
配合objdump，找出暫存器的值為何發生異常  

 

Debug ANR issue

1. 利用 "InputDispatcher: Application is not responding" 做為關鍵字搜尋main log，找出發生anr的時間點、造成anr的兇手和ANR的類型

Ex: 05-20 13:08:48.863   819   944 I InputDispatcher: Application is not responding: AppWindowToken{eb23daa token=Token{33133f87 ActivityRecord{38efa3c6 u0 com.sony.nfx.app.sfrc/.npam.InitialActivity t405}}} - Window{38ae425f u0 com.sony.nfx.app.sfrc/com.sony.nfx.app.sfrc.npam.InitialActivity}.  It has been 15007.0ms since event, 15001.4ms since wait started.  Reason: Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 3.

2. 尋找ANR發生點附近的ActivityManager的資訊，可以得知ANR的類型和當時CPU的使用情況

如果CPU使用量接近100%，說明當前設備很忙，有可能是CPU飢餓導致了ANR
如果CPU使用量很少，說明主線程被BLOCK了
如果IOwait很高，說明ANR有可能是主線程在進行I/O操作造成的

04-0113:12:15.872 E/ActivityManager( 220): ANR in com.android.email(com.android.email/.activity.SplitScreenActivity)
04-0113:12:15.872 E/ActivityManager( 220): Reason:keyDispatchingTimedOut
04-0113:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.53
..............................
04-0113:12:15.872 E/ActivityManager( 220): 32%TOTAL: 28% user + 3.7% kernel

3. 分析 traces log

首先取得traces log檔案：
adb pull data/anr/traces.txt ./mytraces.txt

然後再分析traces log
使用關鍵字Cmdline: 搜尋，並找出發生ANR的兇手的traces log，並檢查 call stack，尋找造成ANR的原因

DALVIK THREADS:
(mutexes: tll=0tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)
"main" prio=5 tid=1NATIVE                    // 表示process 沒有被 block住

DALVIK THREADS:
(mutexes: tll=0tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)
"main" prio=5 tid=1BLOCK                     // 表示process 被block住

4. 常見ANR發生的原因

案例一：
CPU IOWait很高，說明當前系統在忙於I/O，因此資料庫操作被阻塞
atjava.lang.Thread.parkFor(Thread.java:1424)
atjava.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
atsun.misc.Unsafe.park(Unsafe.java:337)
atjava.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
atjava.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:808)
atjava.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:841)
atjava.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1171)
atjava.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:200)
atjava.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261)
atandroid.database.sqlite.SQLiteDatabase.lock(SQLiteDatabase.java:378)
atandroid.database.sqlite.SQLiteCursor.(SQLiteCursor.java:222)
atandroid.database.sqlite.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:53)

案例二：
在UI線程進行網路數據的讀寫
atorg.apache.harmony.luni.platform.OSNetworkSystem.receiveStreamImpl(NativeMethod)
atorg.apache.harmony.luni.platform.OSNetworkSystem.receiveStream(OSNetworkSystem.java:478)
atorg.apache.harmony.luni.net.PlainSocketImpl.read(PlainSocketImpl.java:565)
atorg.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:87)

案例三：
DMS06424182
Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.
此案例可以直接從main log和sys log找出root cause，不透過traces log

Crash log DMS06424182_DS3 analysis(Another one is similar):
1. ESTA test app's sends back key event to camera app caused ANR, because camera window of CameraActivity has been set to null before CameraActivity receives the back key event. And due to time out, input event has been injected by ESTA app(pid: 3039).
[filter_log.txt]
05-16 02:07:22.968 V/ESTA    ( 3039): [Test Step] [d] pressKey KEYCODE_BACK
05-16 02:07:39.222 V/ESTA    ( 3039): [Test Step] [d] sleep 250
05-16 02:07:39.231 V/ESTA    ( 3039): appEarlyNotResponding com.sonyericsson.android.camera Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
05-16 02:07:39.232 V/ESTA    ( 3039): <<<<<<<<<<<< EarlyANR >>>>>>>>>>>>
05-16 02:07:39.236 V/ESTA    ( 3039): ProcessName: com.sonyericsson.android.camera
05-16 02:07:39.239 V/ESTA    ( 3039): PID: 19897
05-16 02:07:39.241 V/ESTA    ( 3039): annotation: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
[SYS_ANDROID_LOG]
05-16 02:07:23.202   809  1853 V WindowManager: Changing focus from Window{3f36f72d u0 com.sonyericsson.android.camera/com.sonyericsson.android.camera.CameraActivity} to null Callers=com.android.server.wm.WindowManagerService.relayoutWindow:3670 com.android.server.wm.Session.relayout:202 android.view.IWindowSession$Stub.onTransact:237 com.android.server.wm.Session.onTransact:136
05-16 02:07:39.220   809  1896 W InputManager: Input event injection from pid 3039 timed out.
05-16 02:07:39.229  3039  3300 V AcceptanceTest: appEarlyNotResponding com.sonyericsson.android.camera Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
05-16 02:07:39.231  3039  3300 V ESTA    : appEarlyNotResponding com.sonyericsson.android.camera Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
05-16 02:07:39.232  3039  3300 V ESTA    : <<<<<<<<<<<< EarlyANR >>>>>>>>>>>>
05-16 02:07:39.236  3039  3300 V ESTA    : ProcessName: com.sonyericsson.android.camera
05-16 02:07:39.239  3039  3300 V ESTA    : PID: 19897
05-16 02:07:39.241  3039  3300 V ESTA    : annotation: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)

2. In stability test like ESTA, too many input events are sent in short time(stress test). This ANR might be caused by time sequence problem.
InputDispatcher dispatches input event to wrong focused Activity. As we know, focused activity always be set before its task resumed, however, sometimes it doesn't set at all. Eg. task already exists in stack. That may make the focus info in InputDispatcher mismatched, and resulting input dispatcher timed out.

3. Proposal solution: update the focused activity in time with below codes.
BTW, please framework team double check it before delivering it.
/frameworks/base/services/core/java/com/android/server/am/ActivityStackSupervisor.java
1649    final int startActivityUncheckedLocked(ActivityRecord r, ActivityRecord sourceRecord,
1650            IVoiceInteractionSession voiceSession, IVoiceInteractor voiceInteractor, int startFlags,
1651            boolean doResume, Bundle options, TaskRecord inTask) {
......
......
2084                    if (!addingToTask && reuseTask == null) {
2085                        // We didn't do anything...  but it was needed (a.k.a., client
2086                        // don't use that intent!)  And for paranoia, make
2087                        // sure we have correctly resumed the top activity.
2088                        if (doResume) {
2089                            targetStack.resumeTopActivityLocked(null, options);
+                                   ActivityRecord top = topRunningActivityLocked();
+                                   if (top != null) {
+                                       mService.setFocusedActivityLocked(top);
+                                   }
2090                        } else {
2091                            ActivityOptions.abort(options);
2092                        }
2093                        /// M: Add debug task message @{
2094                        if (DEBUG_TASKS) {
2095                            Slog.i(TAG, "START_TASK_TO_FRONT, doResume = " + doResume);
2096                        }

5. 參考資料：

http://codex.wiki/post/186093-336/