Introduction
Android 重启或者说是system server重启,常见的case有以下几种:
- system server process crash
- system server watchdog timeout
- critical process crash
不论system server重启的原因是什么,system server重启后,logcat里,可以看到类似下面的打印。可以查找“system server.*terminated”关键字,来确认system server是否重启了。
01-01 15:48:23.955 E/Zygote ( 4211): Exit zygote because system server (4525) has terminated
system server process crash
目前随着project treble 的推进,frameworks基本上都是原生的AOSP代码,system server自身出现逻辑错误crash的情况越来越少见了。
system server进程自身crash,logcat里可以看到关键字:FATAL EXCEPTION IN SYSTEM PROCESS,之后是相应的callstack。比如下面这个例子,是TIF里的空指针:
01-01 12:45:11.950 E/AndroidRuntime( 4429): *** FATAL EXCEPTION IN SYSTEM PROCESS: main
01-01 12:45:11.950 E/AndroidRuntime( 4429): java.lang.NullPointerException: Attempt to read from field 'android.media.tv.TvInputInfo com.android.server.tv.TvInputManagerService$TvInputState.info' on a null object reference
01-01 12:45:11.950 E/AndroidRuntime( 4429): at com.android.server.tv.TvInputManagerService$TvInputState.-get0(TvInputManagerService.java)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at com.android.server.tv.TvInputManagerService.setStateLocked(TvInputManagerService.java:866)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at com.android.server.tv.TvInputManagerService.-wrap19(TvInputManagerService.java)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at com.android.server.tv.TvInputManagerService$HardwareListener.onStateChanged(TvInputManagerService.java:2757)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at com.android.server.tv.TvInputHardwareManager$ListenerHandler.handleMessage(TvInputHardwareManager.java:1152)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at android.os.Handler.dispatchMessage(Handler.java:102)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at android.os.Looper.loop(Looper.java:154)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at com.android.server.SystemServer.run(SystemServer.java:355)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at com.android.server.SystemServer.main(SystemServer.java:222)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at java.lang.reflect.Method.invoke(Native Method)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:889)
01-01 12:45:11.950 E/AndroidRuntime( 4429): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:779)
可以根据logcat里的callstack找到出问题的函数调用,进而分析原因。
system server watchdog timeout
Android watchdog 用来实时监测系统服务是否正常运行,实时监测SystemServer进程,防止系统死锁。Watchdog本身继承Thread,是一个线程类,监测任务运行在独立的线程中。需要加入Watchdog监控的服务必须实现Monitor接口。默认的timeout是60s,分成两个waited_half。如果两个waited_half,monitor还没有返回。则认为系统hang住了,watchdog会dump 信息,kill system server。
Watchdog timeout的case大概有以下几种:
- system server自身死锁
- 其它进程block住system server
- system server 进程得不到调度
Watchdog timout通常都伴随着ANR,分析时除了需要logcat之外,还需要trace文件。
Other process block system server
System server自身存在死锁,目前基本上没有。其它进程block住system serve,下面的这个例子,logcat里可以看到block的thread 和 callstack
01-01 15:48:23.144 W/Watchdog( 4525): *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg), Blocked in handler on ui thread (android.ui), Blocked in handler on display thread (android.display), Blocked in handler on ActivityManager (ActivityManager)
01-01 15:48:23.144 D/WindowManager( 4525): interceptKeyTq keycode=82 interactive=true keyguardActive=false policyFlags=2b000000
01-01 15:48:23.144 W/Watchdog( 4525): foreground thread stack trace:
01-01 15:48:23.145 W/Watchdog( 4525): at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:21685)
01-01 15:48:23.146 W/Watchdog( 4525): at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:182)
01-01 15:48:23.146 W/Watchdog( 4525): at android.os.Handler.handleCallback(Handler.java:751)
01-01 15:48:23.146 W/Watchdog( 4525): at android.os.Handler.dispatchMessage(Handler.java:95)
01-01 15:48:23.146 W/Watchdog( 4525): at android.os.Looper.loop(Looper.java:154)
01-01 15:48:23.146 W/Watchdog( 4525): at android.os.HandlerThread.run(HandlerThread.java:61)
01-01 15:48:23.146 W/Watchdog( 4525): at com.android.server.ServiceThread.run(ServiceThread.java:46)
01-01 15:48:23.146 W/Watchdog( 4525): ui thread stack trace:
01-01 15:48:23.147 W/Watchdog( 4525): at com.android.server.am.ActivityManagerService.dispatchUidsChanged(ActivityManagerService.java:4227)
01-01 15:48:23.147 W/Watchdog( 4525): at com.android.server.am.ActivityManagerService.-wrap7(ActivityManagerService.java)
01-01 15:48:23.148 W/Watchdog( 4525): at com.android.server.am.ActivityManagerService$UiHandler.handleMessage(ActivityManagerService.java:1770)
01-01 15:48:23.148 W/Watchdog( 4525): at android.os.Handler.dispatchMessage(Handler.java:102)
01-01 15:48:23.148 W/Watchdog( 4525): at android.os.Looper.loop(Looper.java:154)
01-01 15:48:23.148 W/Watchdog( 4525): at android.os.HandlerThread.run(HandlerThread.java:61)
01-01 15:48:23.148 W/Watchdog( 4525): at com.android.server.ServiceThread.run(ServiceThread.java:46)
然后,在Traces文件里,具体查看System server的call stack信息,可以看到android.fg这个thread在等0x0c60a278这个锁,而这个锁由thread 98 lock住。
"android.fg" prio=5 tid=16 Blocked
| group="main" sCount=1 dsCount=0 obj=0x12cf06a0 self=0x724e3fa000
| sysTid=4544 nice=0 cgrp=default sched=0/0 handle=0x7241bff450
| state=S schedstat=( 522077430 728705228 3951 ) utm=34 stm=18 core=1 HZ=100
| stack=0x7241afd000-0x7241aff000 stackSize=1037KB
| held mutexes=
at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:21685)
- waiting to lock <0x0c60a278> (a com.android.server.am.ActivityManagerService) held by thread 98
at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:182)
at android.os.Handler.handleCallback(Handler.java:751)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:154)
at android.os.HandlerThread.run(HandlerThread.java:61)
at com.android.server.ServiceThread.run(ServiceThread.java:46)
由下面的callstack看到,thread 98 持有0x0c60a278这个锁,同时在等thread 84 持有的锁0x0318fd3。
"Binder:4525_20" prio=5 tid=98 Blocked
| group="main" sCount=1 dsCount=0 obj=0x1341c5e0 self=0x723cb50000
| sysTid=26192 nice=-2 cgrp=default sched=0/0 handle=0x723a435450
| state=S schedstat=( 56631669726 22599315657 94187 ) utm=4711 stm=952 core=1 HZ=100
| stack=0x723a33b000-0x723a33d000 stackSize=1005KB
| held mutexes=
at com.android.server.wm.WindowManagerService.notifyAppRelaunchesCleared(WindowManagerService.java:10501)
- waiting to lock <0x0318fd3a> (a java.util.HashMap) held by thread 84
at com.android.server.am.ActivityStack.cleanUpActivityLocked(ActivityStack.java:3816)
at com.android.server.am.ActivityStack.removeHistoryRecordsForAppLocked(ActivityStack.java:4246)
at com.android.server.am.ActivityStack.handleAppDiedLocked(ActivityStack.java:4988)
at com.android.server.am.ActivityStackSupervisor.handleAppDiedLocked(ActivityStackSupervisor.java:1740)
at com.android.server.am.ActivityManagerService.handleAppDiedLocked(ActivityManagerService.java:5101)
at com.android.server.am.ActivityManagerService.appDiedLocked(ActivityManagerService.java:5250)
at com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied(ActivityManagerService.java:1485)
- locked <0x0c60a278> (a com.android.server.am.ActivityManagerService)
at android.os.BinderProxy.sendDeathNotice(Binder.java:688)
下面的call stack看到 thread 84持有锁0x0318fd3,通过binder与surfaceflinger通过,调用的是surfacecreate接口。
"Binder:4525_12" prio=5 tid=84 Native
| group="main" sCount=1 dsCount=0 obj=0x135f9550 self=0x7241da4800
| sysTid=26177 nice=-10 cgrp=default sched=0/0 handle=0x723b20b450
| state=S schedstat=( 58401616494 22320070685 93186 ) utm=4880 stm=960 core=1 HZ=100
| stack=0x723b111000-0x723b113000 stackSize=1005KB
| held mutexes=
kernel: __switch_to+0x74/0x8c
kernel: binder_thread_read+0xa2c/0xfe8
kernel: binder_ioctl_write_read+0x1b4/0x298
kernel: binder_ioctl+0x460/0x654
kernel: do_vfs_ioctl+0x35c/0x588
kernel: SyS_ioctl+0x8c/0xa4
kernel: cpu_switch_to+0x48/0x4c
native: #00 pc 000000000006a438 /system/lib64/libc.so (__ioctl+4)
native: #01 pc 000000000001f8c8 /system/lib64/libc.so (ioctl+144)
native: #02 pc 0000000000055534 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14talkWithDriverEb+260)
native: #03 pc 0000000000056318 /system/lib64/libbinder.so (_ZN7android14IPCThreadState15waitForResponseEPNS_6ParcelEPi+352)
native: #04 pc 000000000004b1e0 /system/lib64/libbinder.so (_ZN7android8BpBinder8transactEjRKNS_6ParcelEPS1_j+72)
native: #05 pc 000000000007b078 /system/lib64/libgui.so (???)
native: #06 pc 00000000000887f4 /system/lib64/libgui.so (_ZN7android21SurfaceComposerClient13createSurfaceERKNS_7String8Ejjij+80)
native: #07 pc 00000000000e52f8 /system/lib64/libandroid_runtime.so (???)
native: #08 pc 0000000000c45e84 /system/framework/arm64/boot-framework.oat (Java_android_view_SurfaceControl_nativeCreate__Landroid_view_SurfaceSession_2Ljava_lang_String_2IIII+208)
at android.view.SurfaceControl.nativeCreate(Native method)
at android.view.SurfaceControl.<init>(SurfaceControl.java:302)
at com.android.server.wm.WindowSurfaceController$SurfaceControlWithBackground.<init>(WindowSurfaceController.java:794)
at com.android.server.wm.WindowSurfaceController.<init>(WindowSurfaceController.java:95)
at com.android.server.wm.WindowStateAnimator.createSurfaceLocked(WindowStateAnimator.java:749)
at com.android.server.wm.WindowManagerService.createSurfaceControl(WindowManagerService.java:3136)
at com.android.server.wm.WindowManagerService.relayoutWindow(WindowManagerService.java:2944)
- locked <0x0318fd3a> (a java.util.HashMap)
at com.android.server.wm.Session.relayout(Session.java:215)
at android.view.IWindowSession$Stub.onTransact(IWindowSession.java:286)
at com.android.server.wm.Session.onTransact(Session.java:136)
at android.os.Binder.execTransact(Binder.java:565)
到这里,可以分析出system server通过binder与surfaceflinger通信,而surfaceflinger进程没有及时返回,进而block住了system server。触发了watcdog。
Trace文件里,同样有surfaceflinger进程的callstack,我们可以分析下surfaceflinger进程在做什么。可以看到surfaceflinger 的binder 1线程在 pthread_cond_wait ,在等某个锁。有可能是surfacelinger自身死锁问题。
"Binder:4173_1" sysTid=4182
#00 pc 000000000001bcec /system/lib64/libc.so (syscall+28)
#01 pc 0000000000067708 /system/lib64/libc.so (pthread_cond_wait+96)
#02 pc 000000000006215c /system/lib64/libsurfaceflinger.so
#03 pc 0000000000023c48 /system/lib64/libsurfaceflinger.so
#04 pc 000000000007aa08 /system/lib64/libgui.so (_ZN7android23BnSurfaceComposerClient10onTransactEjRKNS_6ParcelEPS1_j+208)
#05 pc 0000000000049e24 /system/lib64/libbinder.so (_ZN7android7BBinder8transactEjRKNS_6ParcelEPS1_j+132)
#06 pc 0000000000055ba8 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14executeCommandEi+980)
#07 pc 0000000000055718 /system/lib64/libbinder.so (_ZN7android14IPCThreadState20getAndExecuteCommandEv+156)
#08 pc 0000000000055dc0 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14joinThreadPoolEb+72)
#09 pc 0000000000072dac /system/lib64/libbinder.so
#10 pc 000000000001242c /system/lib64/libutils.so (_ZN7android6Thread11_threadLoopEPv+272)
#11 pc 0000000000067fb0 /system/lib64/libc.so (_ZL15__pthread_startPv+196)
#12 pc 000000000001d980 /system/lib64/libc.so (__start_thread+16)
除了surfaceflinger会block systemserver,其它进程如mediaserver等,也常block system server。
critical process crash
某些native 关键进程crash,也导致system 跟着重启。常见的是surfaceflinger。native 进程crash,会生成tombstone文件。原因多种多样,可以根据tombstone分析。