MTK 死机问题快速分析/Phone hang analysis

死机现象

1. 死机/phong hang 定义
当手机长时间无法再被用户控制操作时，我们称为死机或者hang 机。
在这里我们强调长时间，如果是短时间，我们归结为Perfomance 问题，即性能问题.

2. 死机表现
* 用户操作手机无任何响应, 如触摸屏幕，按键操作等.
* 手机屏幕黑屏, 无法点亮屏幕.
* 手机界面显示内容和用户输入风马牛不相及.

可能导致死机的原因

1. 系统简图
当用户对手机进行操作时, 对应的数据流将是下面一个概括的流程图.

* HW 如传感器, 触摸屏(TP), 物理按键(KP)等感知到用户操作后，触发相关的中断(ISR) 传递给Kernel, Kernel 相关的driver 对这些ISR 进行处理后，转化成标准的InputEvent.
* User Space 的System Server 中的Input System 则持续监听Kernel 传递上来的原始InputEvent, 对其进行进一步的处理后, 变成上层APP 可直接处理的Input Event, 如button 点击, 长按, 滑动等等.
* APP 对相关的事件进行处理后，请求更新相关的逻辑界面，而这个则由System Server 中的WMS 等来负责.
* 相关的逻辑界面更新后(Z-Window), 则会请求SurfaceFlinger 来产生FrameBuffer 数据, SurfaceFlinger 则会利用GPU 等来计算生成.
* Display System/Driver 则会将FrameBuffer 中的数据更新显示出来, 这样用户才能感知到他的操作行为.

2. 可能死机的原因
原则上上面流程中，每一步出现问题，都可能引发死机问题. 大的方面将，可以分成硬件HW 和 软件SW 两个层次, 硬件HW 不在我们的讲诉之内.
软件SW 上，死机的原因可以分成两种:
(1). 逻辑行为异常
 ** 逻辑判断错误
 ** 逻辑设计错误
 
(2). 逻辑卡顿(block)
 * 死循环 (Deadloop)
 * 死锁 (Deadlock)
 
从具体的原因上将，可以进一步分成:
(1). Input Driver
* 无法接收HW 的中ISR，产生原始的InputEvent, 或者产生的InputEvent 异常.

(2). Input System
* 无法监听Kernel 传递上来的原始InputEvent, 或者转换与传递异常.

(3). System Logic
* 无法正常响应Input System 传递过来的InputEvent, 或者响应出错.

(4). WMS/Surfaceflinger 行为异常
* WMS/SF 无法正确的对Z-Window 进行叠加转换

(5). Display System3,
* 无法更新Framebuffer 数据，或者填充的数据错误

(6). LCM Driver
* 无法将Framebuffer 数据显示在LCM 上

(7). CPU Scheduler/File System/Memory Manager 等Kernel 支撑性模块.

* 系统支撑性模块无法正常, 导致整个流程都没法正常进行, 如CPU Scheduler 无法正常执行,导致thread 都无法被调度, memory 耗尽导致系统无法快速申请到memory, file system 卡住导致无法进行读写操作等.

对应硬件HW hang, 经常见得的情况有:
* Power 异常
* Clock/26M/32K 失效

* CPU Core 无法启动, 执行异常等.
* Memory & Memory Controller.
* Fail IC.

1. 死机分析数据
俗话说, 巧妇难为无米之炊, 死机分析, 同样需要获取第一手的资料, 方可分析问题. 那么哪些数据可以用来分析死机呢。
大概的讲，可以分成空间数据和时间数据。空间数据，即当时现场环境，如有哪些process 在运行，CPU 的执行情况，memory 的利用情况，以及具体的process 的memory 数据等。 时间数据，即行为上的连续数据，比如某个Process 在一段时间内执行了哪些操作，某段时间内CPU 利用率的变化等。通常时空都是交融的，对应我们抓取资讯时往往也是。

2. 哪些数据可以用来分析.
* Backtrace
Backtrace 又分成Java backtrace, Native Backtrace, Kernel Backtrace. 它是分析死机的非常重要的手段，我们可以快速的知道，对应的process/thread 在当时正在执行哪些动作，卡住哪里等。可以非常直观的分析死机现场。

另外还有一类trace 为ftrace/systrace,  除非特别开启, 以及在特定的流程点上添加, 这类trace 往往不是很详尽,  但也具有比较好的参考作用.

* 系统运行环境
客观的反应系统的执行环境，通常包括如CPU 利用率，Memory 使用情况， Storage 剩余情况等。这些资料也非常重要，比如可以快速的知道，当时是否有Process 在疯狂的执行，当时是不是处于严重的low memory 情况， Storage 是否有耗尽的情况发生等。

* 程序执行环境
客观的反应当时某个程序(Kernel 也可以看成一个程序)的执行现场, 此类资讯通常包括如process 的coredump, java heap prof, kernel 的memory dump 等。完整的执行环境，我们可以快速的知道当时具体的变量的值，寄存器值等，可以精细的分析问题。

* 其他的一些资讯
这些资讯相对来说，比较零散了，如通常的LOG, 一些debug 命令的结果, JTAG & CVD 的数据等。

Backtrace 分析

1. Java Backtrace
从Java Backtrace, 我们可以知道当时Process 的虚拟机执行状态. Java Backtrace 依靠SignalCatcher 来抓取.
Google default: SignalCatcher catchs SIGQUIT(3), and then print the java backtrace to /data/anr/trace.txt
MTK Enhance:  SignalCatcher catchs SIGSTKFLT(16), and then print the java backtrace to /data/anr/mtktrace.txt( 仅仅 Android ICS 4.0 <-> Android M 6.0版本)
You can update system properties dalvik.vm.stack-trace-file to  Change the address,  default is /data/anr/traces.txt

1.1 抓取的方式
* 在ENG Build 中
adb remount
adb shell chmod 0777 data/anr
adb shell kill -3 pid
adb pull /data/anr

* 在User Build 中
没有root 权限的情况下，只能直接pull 已经存在的backtrace.
adb pull /data/anr

* 你可以尝试直接使用下面的脚本一次性抓取

adb remount

adb shell chmod 0777 data/anr

adb shell ps

@echo off
set processid=
set /p processid=Please Input process id:

@echo on
adb shell kill -3 %processid%

@echo off
ping -n 8 127.0.0.1>nul

@echo on
adb pull data/anr/traces.txt trace-%processid%.txt

pause

1.2 JavaBacktrace 解析

Android 比较新的版本的java backtrace, 除了直接的thread backtrace 之外, 同时也会把ART 的一些基本状态也打印出来, 比较方便观察ART 的基本状态, 比如:

 ----- pid 1051 at 2018-09-29 23:23:52 -----
Cmd line: system_server
Build fingerprint: 'XXXXX/A73/A73:8.1.0/O11019/1537977601:user/release-keys'
ABI: 'arm64'
Build type: optimized
Zygote loaded classes=5413 post zygote classes=6049
Intern table: 61702 strong; 12632 weak
JNI: CheckJNI is off; globals=10050 (plus 1015 weak)
Libraries: /system/lib64/libandroid.so /system/lib64/libandroid_servers.so /system/lib64/libcompiler_rt.so /system/lib64/libdcfdecoderjni.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libmediatek_exceptionlog.so /system/lib64/libperfframeinfo_jni.so /system/lib64/librutils.so /system/lib64/libsoundpool.so /system/lib64/libwebviewchromium_loader.so /system/lib64/libwifi-service.so /vendor/lib64/libnativecheck-jni.so libjavacore.so libopenjdk.so (17)
Heap: 9% free, 80MB/89MB; 1893251 objects
Dumping cumulative Gc timings
Start Dumping histograms for 12601 iterations for concurrent copying
ProcessMarkStack: Sum: 3760.617s 99% C.I. 35.990ms-1218.784ms Avg: 298.438ms Max: 14617.568ms
ScanImmuneSpaces: Sum: 216.241s 99% C.I. 2.719ms-110.340ms Avg: 17.160ms Max: 1644.161ms
FlipOtherThreads: Sum: 136.969s 99% C.I. 0.517ms-174.411ms Avg: 10.869ms Max: 5585.050ms
VisitConcurrentRoots: Sum: 119.937s 99% C.I. 1.928ms-50.934ms Avg: 9.518ms Max: 1356.509ms
ClearFromSpace: Sum: 66.775s 99% C.I. 0.168ms-21.473ms Avg: 5.299ms Max: 118.068ms
SweepSystemWeaks: Sum: 58.215s 99% C.I. 0.196ms-19.387ms Avg: 4.619ms Max: 342.553ms
GrayAllDirtyImmuneObjects: Sum: 57.570s 99% C.I. 0.133ms-123.041ms Avg: 4.568ms Max: 2010.547ms
ForwardSoftReferences: Sum: 37.474s 99% C.I. 0.037ms-13.834ms Avg: 2.973ms Max: 118.213ms
EnqueueFinalizerReferences: Sum: 30.905s 99% C.I. 0.094ms-22.239ms Avg: 2.452ms Max: 248.969ms
MarkingPhase: Sum: 24.277s 99% C.I. 0.257ms-51.155ms Avg: 1.926ms Max: 3743.053ms
VisitNonThreadRoots: Sum: 23.507s 99% C.I. 0.065ms-15.260ms Avg: 1.865ms Max: 190.694ms
ProcessReferences: Sum: 17.221s 99% C.I. 9.019us-4689.544us Avg: 683.321us Max: 94215us
EmptyRBMarkBitStack: Sum: 15.343s 99% C.I. 0.026ms-13.119ms Avg: 1.217ms Max: 145.672ms
ThreadListFlip: Sum: 10.730s 99% C.I. 128.387us-25549.046us Avg: 851.524us Max: 1555533us
InitializePhase: Sum: 7.689s 99% C.I. 125us-9536.627us Avg: 610.256us Max: 434902us
FlipThreadRoots: Sum: 4.346s 99% C.I. 16.387us-13773.217us Avg: 344.930us Max: 241943us
RecordFree: Sum: 4.106s 99% C.I. 95us-2474.875us Avg: 325.895us Max: 31656us
SweepAllocSpace: Sum: 2.746s 99% C.I. 32.035us-6375.082us Avg: 217.946us Max: 397272us
SweepLargeObjects: Sum: 2.611s 99% C.I. 10us-1976.352us Avg: 207.248us Max: 36205us
ResumeOtherThreads: Sum: 2.453s 99% C.I. 8.115us-8079.599us Avg: 194.712us Max: 86018us
ReclaimPhase: Sum: 2.086s 99% C.I. 9us-4266.285us Avg: 165.567us Max: 155093us
ResumeRunnableThreads: Sum: 1.759s 99% C.I. 8.063us-2676.218us Avg: 139.607us Max: 87029us
MarkStackAsLive: Sum: 782.752ms 99% C.I. 5us-799.362us Avg: 62.118us Max: 41297us
MarkZygoteLargeObjects: Sum: 741.028ms 99% C.I. 12us-899.899us Avg: 58.807us Max: 24679us
(Paused)GrayAllNewlyDirtyImmuneObjects: Sum: 651.153ms 99% C.I. 12us-373.754us Avg: 51.674us Max: 14328us
ClearRegionSpaceCards: Sum: 412.842ms 99% C.I. 8us-199.633us Avg: 32.762us Max: 16297us
(Paused)SetFromSpace: Sum: 357.553ms 99% C.I. 3us-286.340us Avg: 28.374us Max: 14500us
SwapBitmaps: Sum: 151.902ms 99% C.I. 4us-99.729us Avg: 12.054us Max: 5447us
Sweep: Sum: 110.635ms 99% C.I. 2us-49.924us Avg: 8.779us Max: 1087us
(Paused)FlipCallback: Sum: 105.455ms 99% C.I. 2us-99.800us Avg: 8.368us Max: 8433us
(Paused)ClearCards: Sum: 89.377ms 99% C.I. 1000ns-199016ns Avg: 295ns Max: 17545000ns
UnBindBitmaps: Sum: 17.838ms 99% C.I. 0.250us-49.765us Avg: 1.415us Max: 1516us
Done Dumping histograms
concurrent copying paused: Sum: 10.999s 99% C.I. 320.432us-63766.026us Avg: 872.888us Max: 1214342us
concurrent copying total time: 4607.007s mean time: 365.606ms
concurrent copying freed: 4075114399 objects with total size 152GB
concurrent copying throughput: 884547/s / 33MB/s
Cumulative bytes moved 115136403208
Cumulative objects moved 2160415247
Total time spent in GC: 4607.007s
Mean GC size throughput: 32MB/s
Mean GC object throughput: 884504 objects/s
Total number of allocations 4076810306
Total bytes allocated 145GB
Total bytes freed 145GB
Free memory 8MB
Free memory until GC 8MB
Free memory until OOME 431MB
Total memory 89MB
Max memory 512MB
Zygote space size 652KB
Total mutator paused time: 10.999s
Total time waiting for GC to complete: 71.458s
Total GC count: 12601
Total GC time: 4607.007s
Total blocking GC count: 3305
Total blocking GC time: 1302.402s
Histogram of GC count per 10000 ms: 0:11034,1:7128,2:1807,3:417,4:87,5:21,6:6,7:3,8:2,9:2,11:2,12:2,17:1
Histogram of blocking GC count per 10000 ms: 0:17706,1:2336,2:443,3:26,4:1
Registered native bytes allocated: 57354982
/system/framework/oat/arm64/com.android.location.provider.odex: speed
/system/priv-app/FusedLocation/oat/arm64/FusedLocation.odex: speed
/system/priv-app/Telecom/oat/arm64/Telecom.odex: speed
/system/framework/oat/arm64/mediatek-framework-net.odex: quicken
/system/framework/oat/arm64/mediatek-framework-net.odex: quicken
/system/framework/oat/arm64/mediatek-framework-net.odex: quicken
/system/framework/oat/arm64/mediatek-framework-net.odex: quicken
/system/framework/oat/arm64/com.coloros.statistics.odex: quicken
/system/priv-app/SettingsProvider/oat/arm64/SettingsProvider.odex: speed
/system/framework/oat/arm64/services.odex: speed
/system/framework/oat/arm64/ethernet-service.odex: speed
/system/framework/oat/arm64/wifi-service.odex: speed
/system/framework/oat/arm64/com.android.location.provider.odex: speed
/system/framework/oat/arm64/mediatek-services.odex: quicken
/system/framework/oat/arm64/mediatek-framework-net.odex: quicken
/system/framework/oat/arm64/mediatek-framework-net.odex: quicken
/system/framework/oat/arm64/mediatek-framework-net.odex: quicken
/system/framework/oat/arm64/mediatek-framework-net.odex: quicken
/data/dalvik-cache/arm64/vendor@app@LPPeSer