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)