Android P 系统稳定性问题分析方法总结

Posted 2023-03-23

参考技术A

Android系统最开始是为手机设计的，在机顶盒，电视，带屏音箱等大屏上运行后，芯片厂家做些适配，产品厂家也会做系统客制化，有时候还要适配第三方应用..等待
这种适配容易引人系统的稳定性问题，系统稳定性对于用户体验至关重要，很多问题也都比较类似，android系统对系统性能，稳定性分析工具也比较多，下面根据工作中遇到的问题做个总结。

从表现来看有: 死机重启, 自动关机, 无法开机,冻屏,黑屏以及闪退, 无响应等情况;

从技术层面来划分无外乎两大类: 长时间无法执行完成(Timeout) 以及异常崩溃(crash). 主要分类如下:

ANR(Application Not responding)，是指普通app进程超过一定时间没有执行完，系统会弹出应用无响应对话框. 如果
该进程运行在system进程, 更准确的来说,应该是(System Not Responding, SNR)

ANR产生的原因可能是各种各样的，但常见的原因可以分为：

1.logcat日志
2.trace文件(保存在/data/anr/traces.txt)
从logcat里可以看到死锁的打印
从traces.txt可以看到线程的函数调用栈

10-16 00:50:10 820 907 E ActivityManager: ANR in com.android.systemui, time=130090695
10-16 00:50:10 820 907 E ActivityManager: Reason: Broadcast of Intent act=android.intent.action.TIME_TICK flg=0x50000114 (has extras)
10-16 00:50:10 820 907 E ActivityManager: Load: 30.4 / 22.34 / 19.94
10-16 00:50:10 820 907 E ActivityManager: Android time :[2015-10-16 00:50:05.76] [130191,266]
10-16 00:50:10 820 907 E ActivityManager: CPU usage from 6753ms to -4ms ago:
10-16 00:50:10 820 907 E ActivityManager: 47% 320/netd: 3.1% user + 44% kernel / faults: 14886 minor 3 major
10-16 00:50:10 820 907 E ActivityManager: 15% 10007/com.sohu.sohuvideo: 2.8% user + 12% kernel / faults: 1144 minor
10-16 00:50:10 820 907 E ActivityManager: 13% 10654/hif_thread: 0% user + 13% kernel
10-16 00:50:10 820 907 E ActivityManager: 11% 175/mmcqd/0: 0% user + 11% kernel
10-16 00:50:10 820 907 E ActivityManager: 5.1% 12165/app_process: 1.6% user + 3.5% kernel / faults: 9703 minor 540 major
10-16 00:50:10 820 907 E ActivityManager: 3.3% 29533/com.android.systemui: 2.6% user + 0.7% kernel / faults: 8402 minor 343 major
......
10-16 00:50:10 820 907 E ActivityManager: +0% 12832/cat: 0% user + 0% kernel
10-16 00:50:10 820 907 E ActivityManager: +0% 13211/zygote64: 0% user + 0% kernel
10-16 00:50:10 820 907 E ActivityManager: 87% TOTAL: 3% user + 18% kernel + 64% iowait + 0.5% softirq

发生ANR的时间 00:50:10 ,可以从这个时间点之前的日志中，还原ANR出现时系统的运行状态
发生ANR的进程 com.android.system.ui
发生ANR的原因 Reason关键字表明了ANR的原因是处理TIME_TICK广播消息超时
CPU负载 Load关键字表明了最近1分钟、5分钟、15分钟内的CPU负载分别是30.4、22.3、19.94.CPU最近1分钟的负载最具参考价值，因为ANR的超时限制基本都是1分钟以内， 这可以近似的理解为CPU最近1分钟平均有30.4个任务要处理，这个负载值是比较高的
CPU使用统计时间段 CPU usage from XX to XX ago关键字表明了这是在ANR发生之前一段时间内的CPU统计,类似的还有CPU usage from XX to XX after关键字，表明是ANR发生之后一段时间内的CPU统计
各进程的CPU使用率
以com.android.systemui进程的CPU使用率为例，它包含以下信息：
总的CPU使用率: 3.3%，其中systemui进程在用户态的CPU使用率是2.6%，在内核态的使用率是0.7%
缺页次数fault：8402 minor表示高速缓存中的缺页次数，343 major表示内存的缺页次数。minor可以理解为进程在做内存访问，major可以理解为进程在做IO操作。 当前minor和major值都是比较高的，从侧面反映了发生ANR之前，systemui进程有有较多的内存访问操作，引发的IO次数也会较多
CPU使用汇总 TOTAL关键字表明了CPU使用的汇总，87%是总的CPU使用率，其中有一项iowait表明CPU在等待IO的时间，占到64%，说明发生ANR以前，有大量的IO操作。app_process、 system_server, com.android.systemui这几个进程的major值都比较大，说明这些进程的IO操作较为频繁，从而拉升了整个iowait的时间

traces.txt 如下
----- pid 29533 at 2015-10-16 00:48:29 -----
Cmd line: com.android.systemui
DALVIK THREADS (54):
"main" prio=5 tid=1 Blocked
| group="main" sCount=1 dsCount=0 obj=0x75bd5818 self=0x7f8549a000
| sysTid=29533 nice=0 cgrp=bg_non_interactive sched=0/0 handle=0x7f894bbe58
| state=S schedstat=( 289080040422 93461978317 904874 ) utm=20599 stm=8309 core=0 HZ=100
| stack=0x7fdffda000-0x7fdffdc000 stackSize=8MB
| held mutexes=
at com.mediatek.anrappmanager.MessageLogger.println(SourceFile:77)

Android系统中，有硬件WatchDog用于定时检测关键硬件是否正常工作，类似地，在framework层有一个软件WatchDog用于定期检测关键系统服务是否发生死锁事件。
watchdog 每过30s 检测一次， 如果要监控的线程30s 后没有响应，系统会dump出此进程堆栈，如果超过60s 没有相应，会触发watchdog，并重启系统
10:57:23.718 579 1308 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg), Blocked in handler on main thread (main), Blocked in handler on ActivityManager (ActivityManager)
10:57:23.725 579 1308 W Watchdog: android.fg annotated stack trace:
10:57:23.726 579 1308 W Watchdog: at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:26271)
10:57:23.727 579 1308 W Watchdog: - waiting to lock <0x0bb47e39> (a com.android.server.am.ActivityManagerService)
10:57:23.727 579 1308 W Watchdog: at com.android.server.Watchdog DeliveryTracker.alarmTimedOut(AlarmManagerService.java:4151)
10:57:23.733 579 1308 W Watchdog: - waiting to lock <0x00aaee38> (a java.lang.Object)
......
10:57:23.736 579 1308 W Watchdog: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:838)
10:57:23.739 579 1308 W Watchdog: ActivityManager annotated stack trace:
10:57:23.740 579 1308 W Watchdog: at com.android.server.am.ActivityStack$ActivityStackHandler.handleMessage(ActivityStack.java:405)
10:57:23.740 579 1308 W Watchdog: - waiting to lock <0x0bb47e39> (a com.android.server.am.ActivityManagerService)
10:57:23.740 579 1308 W Watchdog: at android.os.Handler.dispatchMessage(Handler.java:106)
10:57:23.741 579 1308 W Watchdog: *** GOODBYE!
分析：
提示 ActivityManagerService的android.fg,main,ActivityManager 线程Block了,但logcat里只能看到
android.fg等待0x0bb47e39 锁,main 等待0x00aaee38锁,ActivityManager等待0x0bb47e39锁,无法进一步分析,需要看traces.txt
Cmd line: system_server
......
"main" prio=5 tid=1 Blocked

当出现应用闪退，可以从两个方面查看：
1、是否应用崩溃：
可以通过logcat –s AndroidRuntime DEBUG过滤日志，查看应用奔溃的具体堆栈信息。
其中AndroidRuntime的TAG打印java层信息，DEBUG的TAG打印native层的信息。
2、是否被lowmemorykiller杀掉：
可以通过 logcat –s lowmemorykiller 过滤日志，注意adj 0是代表前台进程。例如：
03-08 04:16:58.084 310 310 I lowmemorykiller: Killing\'com.google.android.tvlauncher\' (2520), uid 10007, adj 0
发生这种情况，需要dumpsys meminfo 查看当前内存状态，是否有进程内存泄漏，导致系统内存不够，出现前台进程被杀，造成闪退。

测试过程中，经常遇到屏幕闪烁的现象，需要排除是OSD层闪烁，还是video层闪烁。
1、先通过android原生方法：screencap截图, screenrecord 录制视频，这里都是截取的OSD层，查看是否有闪屏现象。
2、OSD没有问题，就需要从更底层的显示模块分析，一般需要芯片厂家提供debug手段，不同芯片厂家方案不一样。
3, 有时候输出不稳定，hdmi/mipi信号干扰，输出频率异常等也会导致闪屏，这种情况需要硬件协助分析。
如果OSD层也闪烁，则需从系统和应用层面分析。如曾遇到在开机向导界面，有个应用不断被唤起，导致走开机向导时出现连续闪灰屏的现象。

黑屏分UI黑屏，视频播放黑屏但UI正常等，2种场景

1、screencap截屏，排查OSD层图形是否正常，
2、如果OSD图形正常，需要排查显示输出模块是否异常。
3、电视机里面屏显是单独控制，如果屏参配置错误会导致整改黑屏。
OSD异常，需要排查顶层activity是否黑屏，window是否有异常等.

1，排查视频图层或者window是否创建成功。
2，排查解码是否有异常，不同的应用youtube,netflix,iptv解码方式不一样，需要具体问题具体分析。

如下，ActivityManager因为空对象引用而挂掉，导致system_server重启
*** [FATAL EXCEPTION IN SYSTEM PROCESS: ActivityHanager [
^ava.lang.NullPointerException: Attempt to invoke virtual method \'void co®.android.internal.os.KernelSingleUidTimeReader.iBarkDataAsStale(boolean)\' on a null object reference
at com.android.internal.os.BatteryStatsIiaplSConstants.upddteTrackCpuTiinesByProcStdteLocked(BatteryStatslnpl.java:13355)
at com.android.internal.os.BatteryStatsInplSConstants.upddteConstants(BatteryStatsImpl.java:13330)
at com.android.internal-o-batteryStatslMpl$Constants-onChange(BatteryStatsInpl-java:13316)
at android.database.Contentobserver.onChange(ContentObserver.java:145)
解决方法：修复空指针

DEBUG : pid: 296, tid: 1721, name: Binder：296_4 >>> /system/bin/surfaceflinger <<<
DEBUG : signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr ------
DEBUG : Abort message: \'status.cpp:149] Failed HIDL return status not checked: Status(EXTRANSACTIONFAILED):
DEBUG : r0 00000000 rl 000006b9
DEBUG ： C4 00000128 r5 000006b9
r2 00000006 r3 a5c5d620
r6 a235d60c r7 0000010c
DEAD_OB3ECT：
DEBUG : r8 00000019 r9 0000015d
DEBUG : ip a6ablbec sp a235d5f8
rlO a568f090 rll a620dce9
Ir a5be901d pc a5be0da2
/system/lib/libc.so (abort+62)
/system/lib/libbase.so (android::base::DefaultAborter(char const )+6)
backtrace:
/system/lib/libsurfaceflinger.so
/system/lib/libsurfaceflinger.so
/system/lib/libsurfaceflinger.so
/system/lib/libsurfaceflinger.so
/system/lib/libbase.so (android::base::LogMessage::~LogMessage()+502)
/system/lib/libhidlbase.so (android::hardware::details::return_status::~return_status()+184)
(android::Hwc2::impl::Composer::getActiveConfig(unsigned long long, unsigned int )+56)
(HWC2::Display::getActiveConfig(std::_1::shared_ptr<HWC2：:Display::Config const>*) const+38)
(android::HWComposer::getActiveConfig(int) const+64)
(android::SurfaceFlinger::resyncToHardwareVsync(bool)+64)
可以根据backtrace来进行定位异常崩溃的地方。Android P上， backtrace使用Java上下文来显示，省去使用addr2line来转换的一个过程，方便调试分析问题。但是实际场景中，
有些native进程崩溃只有pc地址，而无函数信息，或者需要定位到具体的某个文件某个函数，则可借助堆栈分析工具addr2line。
addr2line：根据堆栈定位具体函数和文件
addr2line -e libsurfaceflinger.so -f 00071a09
addr2line -e libsurfaceflinger.so -f 00071a09
_ZN7android14SurfaceFlinger12waitForEventEv
frameworks/native/services/surfaceflinger/SurfaceFlinger.cpp:1229
需注意两点：
1、需用带debug信息的LINK目录里面的so库，机顶盒上的so库是无法定位的：
out/target/product/xx/obj/SHARED_LIBRARIES/libsurfaceflinger_intermediates/LINKED/libsurfaceflinger.so
或者：out/target/product/xx/symbols/system/lib/libsurfaceflinger.so
2、定位的文件，必现和机器上出现问题的版本一致，否则定位不准确
debuggerd：打印当前进程实时堆栈：debuggerd –b pid

主要可以分为以下3类
1)Data abort
Unable to handle kernel NULL pointer dereference at virtual address...
Unable to handle kernel paging request at virtual address...
Unhandled fault...at...
Unhandled prefetch abort...at...
2)BUG/BUG_ON
Oops - BUG...
例如：
Out of memory and no killable processes...
rbus timeout...
...
PS:WARN_ON只dump stacks，kernel还是正常
3)bad mode
Oops - bad mode...
日志打印:
〃错误类型原因
[214.962667] 08:14:19.315 (2)-0488 Unable to handle kernel paging request at virtual address 6b6b6cl7
[214.973889] 08:14:19.326 (2)-0488 addr：6b6b6c17 pgd = d0824000
[214.980132] [6b6b6c17J •pgd=O000eO0e
〃Oopsttl误码序号
[214.983865] 08:14:19.336 (2)-0488 Internal error： Oops： 805 [#1] PREEMPT SMP ARM
[214.9914S3] Modules linked in: 8192eu ufsd(PO) jnl(O) fusion(O)
〃发生也错误的CPU序号
(215.001878] 08:14:19.354 (2)-0488 CPU： 2 PID: 488 Comm: system_server Tainted: P 4.4.3+ #113
(2)-0488 Hardware name: rtd284x
[215.011865] 08:14:19.364
〃当前PC指针 98:14:19.377 (2)-0488 PC is at mutex_unlo<k+0xc/0x38
(21S.024846] 08:14:19.383 (2)-0488 LR is at storage_pm_event+0xb4/0xe8
(21S.031026]
//Registers 08:14:19.390 (2)-0488 ：[<ceb78ffc>] Ir : [<C0542034>] psr: 200f0013
I 215.037644] sp : ccf79e38 ip : eceoeeee fp : 9b34648c
I 215.037644]
08:14:19.404 (2)-0488 rlO： 00000080 r9 ：Cl8b3864 r8 : oeeeeeoe
215.051370]
215.058692] 08:14:19.411 (2)-0488 P7 ： C1293a98 P6 ：C1293940 r5 : C1293940 r4 ：C1293a80
21S.067345]
[ 215.076014] 08:14:19.420 (2)-0488 r3 : 00000033 r2 ：00000000 ri : 000^000 re ：6b6b6c07
[ 215.085307]
08:14:19.428 (2)-0488 Flags: nzCv IRQs on FIQs on Mode SVC 32 ISA ARM Segment user
08:14:19.438 (2)-0488 Control: 10c5383d Table： 1082406a DAC： 00000055
//Process.不 ,定是该process的错误，只是发生错误时,刚好在运行该process
[215.093168]
//Stacks 08:14:19.446 (2)-0488 Process syste«i_server (pid: 488, stack limit = 0xccf78218)

(21S.101827] 08:14:19.454 (2)-0488 Stack: 0xccf79e38 (Oxccf79d7。 to 0xccf7a08Q) - par(0xcf796d4)

---[ end trace 45d55384id6a0974 ]--- Kernel panic not syncing: Fatal exception
[217.359794] 08:14:21.712 (0)-0488
解决方案: kernel异常一般找芯片原厂协助分析。

系统卡顿时，一般先分三步走：
1、查看当前系统的CPU，IO等参数，输入top、iotop命令： （如：iotop -s io -m 9）
如果有异常飙高的进程，kill掉后会发现系统恢复正常。
之前项目上遇到过某些U盘IO性能比较差，媒体中心又在后台扫描媒体问题，导致系统各种卡顿，io wait时间比较长。
2、系统进程卡住，触发Watchdog：ps –A |grep system_server,一般而言，system_server正常的进程号是200多，如果发现进程号变成几千，则可能出现重启，结合tombstone和 /data/anr下的trace文件分析重启原因
3、当前应用出现卡顿，造成ANR。输入logcat | grep ANR，如果有ANR打印，再去/data/anr下面查看相应进程的traces文件
有时在应用里面操作卡顿，按键响应延迟，但是却没有生成ANR，此时如果退出该应用（如果无法退出，在抓取足够信息的情况下，可以串口直接kill掉卡顿的应用），则一切正常，可能是应用自身实现问题，或者调用了其它接口导致（例如曾遇到应用调用了中间件、mediaplayer某些接口导致操作严重卡顿，按键响应延迟），这种情况则需应用和相应接口的实现者去排查。

系统完全卡死，一般分三种情况
1，串口无响应，大概率kernel panic，
2，串口日志狂输出，把系统堵塞， 优化日志输出，关注关闭后压测。
3，Input系统完全堵塞，导致任何输入都无响应。