Android的死机、重启问题分析方法

时间:2025-01-25 07:19:12

Android的死机、重启问题分析方法

1.     死机现象

1.1      死机定义

当手机长时间无法再被用户控制操作时,我们称为死机。在这里我们强调长时间,如果是短时间,归结为性能问题。

1.2      死机表现

* 用户操作手机无任何响应,如触摸屏幕,按键操作等。

* 手机屏幕黑屏,无法点亮屏幕。

* 手机界面显示内容和用户输入不相干。

1. 系统简图

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

* HW 如传感器,触摸屏(TP),物理按键(KP)等感知到用户操作后,触发相关的中断(ISR)传递给KernelKernel相关的driver 对这些中断进行处理后,转化成标准的InputEvent 

* UserSpace System Server中的Input System则持续监听Kernel传递上来的原始InputEvent对其进行进一步的处理后,变成上层APP可直接处理的Input Eventbutton点击,长按,滑动等等。

* APP 对相关的事件进行处理后,请求更新相关的逻辑界面,而这个则由System Server中的WMS 等来负责。

* 相关的逻辑界面更新后,则会请求SurfaceFlinger来产生FrameBuffer数据,SurfaceFlinger则会利用GPU 等来计算生成。

* DisplaySystem/Driver 则会将FrameBuffer中的数据更新显示出来,这样用户才能感知到他的操作行为。

2. 可能死机的原因

原则上上面流程中,每一步出现问题,都可能引发死机问题。大的方面讲,可以分成硬件HW软件SW两个层次,硬件HW不在我们的范围之内。

软件SW上,死机的原因可以分成两种:

(1). 逻辑行为异常

 ** 逻辑判断错误

 ** 逻辑设计错误

 (2). 逻辑卡顿(block)

 * 死循环 (Deadloop)

 * 死锁 (Deadlock)

 从具体的原因上将,可以进一步分成:

(1). InputDriver

* 无法接收HW的中ISR,产生原始的InputEvent或者产生的InputEvent异常。

分析死机、触屏无响应的问题的时候,第一步要先看看有没有inputEvent上来,即有没有报点,各个平台inputEvent的设备节点都不一样,可以通过下面方法获取:

adb shellgetevent

这个命令下下去以后会在屏幕上输出当前设备的节点,可从name一行判断哪一个是TW,当然也可以在此时直接在屏幕上触摸看有没有时间上报,正常情况如下:

可以看出event2是触摸事件。

异常情况下触摸是没有事件上报的。

当然也可以直接下adb shell getevent /dev/input/event2检查。

(2). InputSystem

 无法监听Kernel传递上来的原始InputEvent或者转换与传递异常。

(3). SystemLogic

 无法正常响应InputSystem传递过来的InputEvent或者响应出错。

(4).WMS/Surfaceflinger 行为异常

 WMS/ Surfaceflinger 无法正确的对Window进行叠加转换

(5).Display System

 无法更新Framebuffer数据,或者填充的数据错误

(6). LCMDriver

无法将Framebuffer数据显示在LCM

 对应硬件HW异常,经常见得的情况有:

*Power 

* Clock

* Memory& Memory Controller

* Fail IC

2.      死机分析数据

死机分析,同样需要获取第一手的资料,方可分析问题.那么哪些数据可以用来分析死机呢?

大概的讲,可以分成空间数据和时间数据。空间数据,即当时现场环境,如有哪些process在运行,CPU 的执行情况,memory 的利用情况,以及具体的processmemory 数据等。时间数据,即行为上的连续数据,比如某个Process在一段时间内执行了哪些操作,某段时间内CPU利用率的变化等。通常时空都是交融的,对应我们抓取log时往往也是。 

Backtrace 

Backtrace 又分成Java backtraceNative BacktraceKernel Backtrace它是分析死机的非常重要的手段,借助Backtrace,我们可以快速的知道,对应的process/thread在当时正在执行哪些动作,卡住哪里等。可以非常直观的分析死机现场。

1 Java Backtrace

Java Backtrace我们可以知道当时Process的虚拟机执行状态。 JavaBacktrace依靠SignalCatcher来抓取。

Googledefault: SignalCatcher catchs SIGQUIT(3) and thenprint the java backtrace to /data/anr/

MTKEnhance:  SignalCatcher catchs SIGSTKFLT(16) and thenprint the java backtrace to /data/anr/( After /)

可以通过修改系统属性-trace-file改变trace文件路径, 默认路径为/data/anr/

1.1       抓取的方式

一般进程出现无响应的问题,Android系统会发送SIGQUIT3)信号给该进程,收到这个信号会,进程会将当前的调用栈打印在文件里。

手动抓取进程的Backtrace方法如下:

adb remount

adb shellchmod 0777 data/anr

adb shellkill -3 pid

adb pull/data/anr

 1.2JavaBacktrace 解析

下面是一小段system serverjava backtrace的开始

----- pid 682 at 2015-07-30 18:04:53 -----

Cmd line: system_server

JNI: CheckJNI is off; workarounds are off;pins=4; globals=1484 (plus 50 weak)

DALVIK THREADS:

"main" prio=5 tid=1 NATIVE

  | group="main" sCount=1dsCount=0 obj=0x4193fde0 self=0x418538f8

  | sysTid=682 nice=-2 sched=0/0cgrp=apps handle=1074835940

  | state=S schedstat=( 4785871820626265263191 44902 ) utm=4074 stm=711 core=0

  at (NativeMethod)

  at (:138)

  at (:150)

  at (:1468)

  at (:1563)

  at (NativeMethod)

  at (:515)

  at $(:829)

  at (:645)

  at (NativeMethod)

  我们一行一行来解析.

0# 最开始是 -----PID at Time  然后接着 Cmd line: process name

1#  the backtrace header: dvm thread :“DALVIK THREADS:”

 2# thread name, java thread Priority, [daemon], DVM thread id, DVM thread status.

 "main"  -> mainthread -> activity thread

 prio  -> java threadpriority default is 5, (nice =0, linux thread priority 120), domain is [1,10]

 DVMthread id, NOT linux thread id

 DVM thread Status:

  ZOMBIE,  RUNNABLE, TIMED_WAIT, MONITOR, WAIT, INITALIZING,STARTING, NATIVE, VMWAIT, SUSPENDED,UNKNOWN

  "main" prio=5 tid=1NATIVE

 3# DVM thread status 

 group: default is “main”

   Compiler,JDWP,Signal Catcher,GC,FinalizerWatchdogDaemon,FinalizerDaemon,ReferenceQueueDaemonare system group

 sCount:  thread suspend count

 dsCount: thread dbg suspend count

 obj:     threadobj address

 Sef:  thread point address

 group="main" sCount=1dsCount=0 obj=0x4193fde0 self=0x418538f8

#5 Linux thread status

 sysTId:  linux thread tid

 Nice: linux thread nice value

 sched: cgroup policy/gourp id

 cgrp:  c group  

 handle:  handle address

 sysTid=682 nice=-2 sched=0/0cgrp=apps handle=1074835940

 #6 CPU Schedstat

 Schedstat (Run CPU Clock/ns, Wait CPU Clock/ns,  Slice times)

 utm: utime, user space time(jiffies)

 stm: stime, kernel space time(jiffies)

 Core now running in cpu.

 state=S schedstat=( 4785871820626265263191 44902 ) utm=4074 stm=711 core=0

 #7-more CallStack

1.3 几种常见的java backtrace

1.3.1ActivityThread 正常状态的Backtrace

MessageQueue is empty and thread wait fornext message.

 "main" prio=5 tid=1 NATIVE

   | group="main"sCount=1 dsCount=0 obj=0x4193fde0 self=0x418538f8

   | sysTid=11559 nice=0sched=0/0 cgrp=apps/bg_non_interactive handle=1074835940

   | state=S schedstat=(2397315020 9177261498 7975 ) utm=100 stm=139 core=1

   at (NativeMethod)

   at (:138)

   at (:150)

   at (:5299)

   at (NativeMethod)

   at (:515)

   at $(:829)

   at (:645)

   at (NativeMethod)

1.3.2 JavaBacktrace Monitor case

SynchronizedLock等待同步锁时的backtrace.

 "AnrMonitorThread" prio=5tid=24 MONITOR

   | group="main"sCount=1 dsCount=0 obj=0x41fd80c8 self=0x551ac808

   | sysTid=711 nice=0 sched=0/0cgrp=apps handle=1356369328

   | state=S schedstat=(8265377638 4744771625 6892 ) utm=160 stm=666 core=0

   at $(SourceFile:~832)

   - waiting to lock<0x42838968> (a $AnrDumpRecord) held bytid=20 (ActivityManager)

   at $(SourceFile:824)

   at $(SourceFile:220)

   at (:110)

   at (:193)

   at (:61)

1.3.3 执行JNI code未返回,状态是native的情况

 "WifiP2pService" prio=5tid=37 NATIVE

   | group="main"sCount=1 dsCount=0 obj=0x427a9910 self=0x55f088d8

   | sysTid=734 nice=0 sched=0/0cgrp=apps handle=1443230288

   | state=S schedstat=( 91121772135245305 170 ) utm=7 stm=2 core=1

   #00  pc 00032700 /system/lib/ (epoll_wait+12)

   #01  pc 000105e3 /system/lib/ (android::Looper::pollInner(int)+94)

   #02  pc 00010811 /system/lib/ (android::Looper::pollOnce(int, int*, int*, void**)+92)

   #03  pc 0006c96d /system/lib/libandroid_runtime.so(android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)

   #04  pc 0001eacc /system/lib/ (dvmPlatformInvoke+112)

   #05  pc 0004fed9 /system/lib/ (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+484)

   #06  pc 00027ea8 /system/lib/

   #07  pc 0002f4b0 /system/lib/ (dvmMterpStd(Thread*)+76)

   #08  pc 0002c994 /system/lib/ (dvmInterpret(Thread*, Methodconst*, JValue*)+188)

   #09  pc 000632a5 /system/lib/ (dvmCallMethodV(Thread*, Methodconst*, Object*, bool, JValue*,std::__va_list)+340)

   #10  pc 000632c9 /system/lib/ (dvmCallMethod(Thread*, Methodconst*, Object*, JValue*, ...)+20)

   #11  pc 00057961 /system/lib/

   #12  pc 0000dd40 /system/lib/ (__thread_entry+72)

   at (NativeMethod)

   at (:138)

   at (:150)

   at (:61)

1.3.4 执行等待状态

 "AsyncTask #1" prio=5tid=33 WAIT

   | group="main"sCount=1 dsCount=0 obj=0x427a8480 self=0x56036b40

   | sysTid=733 nice=10sched=0/0 cgrp=apps/bg_non_interactive handle=1443076000

   | state=S schedstat=(1941480839 10140523154 4229 ) utm=119 stm=75 core=0

   at (NativeMethod)

   - waiting on<0x427a8618> (a ) held by tid=33 (AsyncTask #1)

   at (:1212)

   at (:325)

   at (:157)

   at $(:2017)

   at (:410)

   at (:1035)

   at (:1097)

   at $(:587)

   at (:848)

1.3.5Suspend 状态,通常表明是抓取backtrace时,当时还正在执行java代码,被强制suspend的情况

 "FileObserver" prio=5tid=23 SUSPENDED

   | group="main"sCount=1 dsCount=0 obj=0x41fd1dc8 self=0x551abda0

   | sysTid=710 nice=0 sched=0/0cgrp=apps handle=1427817920

   | state=S schedstat=(130152222 399783851 383 ) utm=9 stm=4 core=0

   #00  pc 000329f8 /system/lib/ (__futex_syscall3+8)

   #01  pc 000108cc /system/lib/ (__pthread_cond_timedwait_relative+48)

   #02  pc 0001092c /system/lib/ (__pthread_cond_timedwait+64)

   #03  pc 00055a93 /system/lib/

   #04  pc 0005614d  /system/lib/(dvmChangeStatus(Thread*, ThreadStatus)+34)

   #05  pc 0004ae7f /system/lib/

   #06  pc 0004e353 /system/lib/

   #07  pc 000518d5 /system/lib/libandroid_runtime.so

   #08  pc 0008af9f /system/lib/libandroid_runtime.so

   #09  pc 0001eacc /system/lib/ (dvmPlatformInvoke+112)

   #10  pc 0004fed9 /system/lib/ (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+484)

   #11  pc 00027ea8 /system/lib/

   #12  pc 0002f4b0 /system/lib/ (dvmMterpStd(Thread*)+76)

   #13  pc 0002c994 /system/lib/ (dvmInterpret(Thread*, Methodconst*, JValue*)+188)

   #14  pc 000632a5 /system/lib/ (dvmCallMethodV(Thread*, Methodconst*, Object*, bool, JValue*, std::__va_list)+340)

   #15  pc 000632c9 /system/lib/ (dvmCallMethod(Thread*, Methodconst*, Object*, JValue*, ...)+20)

   #16  pc 00057961 /system/lib/

   #17  pc 0000dd40 /system/lib/ (__thread_entry+72)

   at $(NativeMethod)

   at $(:88)

2 Native Backtrace

 2.1Native Backtrace 抓取方式

  2.1.1添加代码直接抓取

Google 默认提供了CallStack API请参考

system/core/include/libutils/ 

system/core/libutils/

可快速打印单个线程的backtrace.

2.1.2 自动抓取

Natice层的进程发生异常后一般都在/data/tombstones目录下生成文件(墓碑文件),该文件描述了该进程当前的Backtrace,不过是链接地址,需要进行解析。

 2.1.3利用debuggerd抓取

MTK 已经制作了一个利用debuggerd抓取Native backtracetool RTT(Runtime Trace)对应的执行命令是:

rtt builttimestamp (Apr 18 2014 15:36:21)

USAGE : rtt[-h] -f function -p pid [-t tid]

  -ffuncion : current support functions:

                bt  (Backtrace function)

  -ppid     : pid to trace

  -ttid     : tid to trace

  -nname    : process name to trace

 -h         : help menu

 2.2解析Native Backtrace

你可以使用GDB或者addr2line tool 来解析抓回的Native Backtrace从而知道当时正在执行的native代码,

arm-linux-androideabi-addr2line-f -C -e symbols address

公司将addr2line封装后实现了一套解析NativeBacktrace(show Stack)。参考下文

3 Kernel Backtrace

 3.1Kernel Backtrace 抓取方式

3.1.1 运行时抓取

* AEE/RTT 工具

* ProcSystem

  catproc/pid/task/tid/stack

*Sysrq-trigger

 adbshell cat proc/kmsg >

 adbshell "echo 8 > proc/sys/kernel/printk“ //修改printk loglevel

 adbshell "echo t > /proc/sysrq-trigger“ //打印所有的backtrace

 adbshell "echo w > /proc/sysrq-trigger“//打印'-D' status'D' process

* KDB

 Longpress volume UP and DOWN more then 10s

 btp            <pid>                

 Displaystack for process <pid>

 bta            [DRSTCZEUIMA]        

 Displaystack all processes

 btc                                  

 Backtracecurrent process on each cpu

 btt            <vaddr>              

 Backtraceprocess given its struct task add

3.1.2 添加代码直接抓取

* #include<linux/>

 当前thread:  dump_stack();

 其他thread:  show_stack(task NULL);

3.2Process/Thread 状态

 "R(running)"  /*  0 */

 "S(sleeping)"  /*  1 */

 "D(disk sleep)" /*   2*/

 "T(stopped)"  /*  4 */

 "t(tracing stop)" /*   8*/

 "Z(zombie)"  /* 16 */

 "X(dead)"  /* 32 */

 "x(dead)"  /* 64 */

 "K(wakekill)"  /* 128 */

 "W(waking)"  /* 256 */

通常一般的Process处于的状态都是S(sleeping)而如果一旦发现处于如D (disksleep) T (stopped) Z (zombie)等就要认真审查。

系统运行环境

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

程序执行环境

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

其他的一些资讯

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

3.      几种典型的异常情况

3.1       Deadlock

下面这个case可以看到PowerManagerService ActivityManager WindowManager相互之间发生deadlock

"PowerManagerService" prio=5tid=25 MONITOR

  | group="main" sCount=1dsCount=0 obj=0x42bae270 self=0x6525d5c0

  | sysTid=913 nice=0 sched=0/0cgrp=apps handle=1696964440

  | state=S schedstat=( 508893941110237027338 34016 ) utm=232 stm=276 core=2

  (:~14079)

  - waiting to lock <0x42aa0f78> () held by tid=16 (ActivityManager)

  (:1665)

  (:1648)

  (:4090)

  (:4144)

  at $5600(:102)

  $(:4132)

  $(:181)

  (:809)

  (:102)

  (:139)

  (:58)

  "ActivityManager" prio=5tid=16 MONITOR

  | group="main" sCount=1dsCount=0 obj=0x42aa0d08 self=0x649166b0

  | sysTid=902 nice=-2 sched=0/0cgrp=apps handle=1687251744

  | state=S schedstat=( 3936088146025703061063 69675 ) utm=1544 stm=2392 core=2

  at (:~4783)

  - waiting to lock <0x42d17590> () held by tid=12 (WindowManager)

  (:2432)

  at (:2103)

  $(:2914)

  at $(:2921)

  (:110)

  (:147)

  $(:2112)

  "WindowManager" prio=5tid=12 MONITOR

  | group="main" sCount=1dsCount=0 obj=0x42a92550 self=0x6491dd48

  | sysTid=898 nice=-4 sched=0/0cgrp=apps handle=1687201104

  | state=S schedstat=( 60734070955 41987172579219755 ) utm=4659 stm=1414 core=1

  (:~3207)

  - waiting to lock <0x42a95140> () held by tid=25 (PowerManagerService)

  (:3196)

  (:9686)

  (:8923)

  (:8879)

  at $500(:170)

  $(:7795)

  (:110)

  at (:147)

  (:58)

3.2       执行JNI native code 后一直不见返回

"main" prio=5 tid=1 NATIVE

  | group="main" sCount=1dsCount=0 obj=0x41bb3d98 self=0x41ba2878

  | sysTid=814 nice=-2 sched=0/0cgrp=apps handle=1074389380

  | state=D schedstat=( 2204889092819526803112 32612 ) utm=1670 stm=534 core=0

  (native backtrace unavailable)

  at $(NativeMethod)

  at $(:399)

  at $(:325)

  at (:194)

  at (:560)

  at (:139)

  at (:774)

  at (:4897)

  at (:518)

  at (:434)

  at $500(:63)

  at $(:584)

  at (:110)

  at (:193)

  at (:1436)

  at (:1531)

  at (NativeMethod)

  at (:515)

  at $(:824)

  at (:640)

  at (NativeMethod)

===>

KERNEL SPACE BACKTRACE, sysTid=814

 [<ffffffff>] 0xffffffff from[<c07e5140>] __schedule+0x3fc/0x950

 [<c07e4d50>]__schedule+0xc/0x950 from [<c07e57e4>] schedule+0x40/0x80

 [<c07e57b0>] schedule+0xc/0x80from [<c07e5ae4>] schedule_preempt_disabled+0x20/0x2c

 [<c07e5ad0>]schedule_preempt_disabled+0xc/0x2c from [<c07e3c3c>]mutex_lock_nested+0x1b8/0x560

 [<c07e3a90>]mutex_lock_nested+0xc/0x560 from [<c05667d8>] gsensor_operate+0x1bc/0x2c0

 [<c0566628>]gsensor_operate+0xc/0x2c0 from [<c0495fa0>] hwmsen_enable+0xa8/0x30c

 [<c0495f04>]hwmsen_enable+0xc/0x30c from [<c0496500>]hwmsen_unlocked_ioctl+0x2fc/0x528

 [<c0496210>]hwmsen_unlocked_ioctl+0xc/0x528 from [<c018ad98>] do_vfs_ioctl+0x94/0x5bc

 [<c018ad10>] do_vfs_ioctl+0xc/0x5bcfrom [<c018b33c>] sys_ioctl+0x7c/0x8c

 [<c018b2cc>]sys_ioctl+0xc/0x8c from [<c000e480>] ret_fast_syscall+0x0/0x40

 [<ffffffff>]  from[<ffffffff>] 

4.     死机运行环境分析

4.1       系统运行环境

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

4.2       CPU Usage

追查CPU利用率可大体的知道,当时机器是否有Process在疯狂的运行,当时系统运行是否繁忙。通常死机分析,只需要抓取基本的使用情况即可。下面说一下一般的抓取方式

top

top 可以简单的查询Cpu的基本使用情况

Usage: top[ -m max_procs ] [ -n iterations ] [ -d delay ] [ -s sort_column ] [ -t ] [ -h]

   -m num  Maximum number of processes to display.

   -n num  Updates to show before exiting.

   -d num  Seconds to wait between updates.

   -s col  Column to sort by (cpuvssrssthr).

   -t      Show threads instead of processes.

   -h      Display this help screen.

注意的是topCPU% 是按全部CPU 来计算的,如果以单线程来计算,比如当时有开启4个核心,那么最多吃到25% 

个人常见的操作方式如:  top -t -m 5 -n 2

正常情况

User 2%, System 12%, IOW 0%, IRQ 0%

User 14 + Nice 0 + Sys 67 + Idle 471 + IOW0 + IRQ 0 + SIRQ 2 = 554

  PID   TID PR CPU%S     VSS     RSS PCYUID     Thread          Proc

 2423  2423  1  8% R   2316K   1128K    root    top             top

  270   270 0   1% S   2160K   924K     root    aee_resmon      /system/bin/aee_resmon

  159   159 0   0% D     0K      0K    root     bat_thread_kthr

   3     3  0   0%S      0K     0K     root     ksoftirqd/0

   57    57 0   0% D     0K      0K    root     hps_main

User 1%, System 7%, IOW 0%, IRQ 0%

User 10 + Nice 0 + Sys 41 + Idle 494 + IOW0 + IRQ 0 + SIRQ 0 = 545

  PID   TID PR CPU%S     VSS     RSS PCYUID     Thread          Proc

 2423  2423  1  8% R   2324K   1152K    root    top             top

   57    57 0   0% D     0K      0K    root     hps_main

  242   419 0   0% S   8600K   4540K    shell    mobile_log_d    /system/bin/mobile_log_d

  982   991 0   0% S   4364K   1156K    media_rw sdcard         /system/bin/sdcard

  272   272 0   0% S  30680K   9048K    root    em_svr          /system/bin/em_svr

  从上面可以看出,系统基本运行正常,没有很吃CPU的进程。

异常情况

User 59%, System 4%, IOW 2%, IRQ 0%

User 1428 + Nice 0 + Sys 110 + Idle 811 +IOW 67 + IRQ 0 + SIRQ 1 = 2417

  PID   TID PR CPU%S     VSS     RSS PCYUID     Thread          Proc

16132 32195  3  14% R997100K  53492K  bg u0_a60  Thread-1401    

16132 32190  1  14% R997100K  53492K  bg u0_a60  Thread-1400    

16132 32188  2  14% R997100K  53492K  bg u0_a60  Thread-1399    

16132 32187  0  14% R997100K  53492K  bg u0_a60  Thread-1398    

18793 18793  4   1%R   2068K   1020K    shell   top             top

User 67%, System 3%, IOW 7%, IRQ 0%

User 1391 + Nice 0 + Sys 75 + Idle 435 +IOW 146 + IRQ 0 + SIRQ 1 = 2048

  PID   TID PR CPU%S     VSS     RSS PCYUID     Thread          Proc

16132 32195  3  16% R997100K  53492K  bg u0_a60  Thread-1401    

16132 32188  2  16% R997100K  53492K  bg u0_a60  Thread-1399    

16132 32190  0  16% R997100K  53492K  bg u0_a60  Thread-1400    

16132 32187  1  16% R997100K  53492K  bg u0_a60  Thread-1398    

18793 18793  4   2%R   2196K   1284K    shell   top             top

可以明显的看到,贵司的mms4thread都有进入了deadloop分别占用了一个cpu core. 同时可以快速抓取他们的java trace 进一步可以看到当时MMS的四个backtrace以便快速分析。

"Thread-1401" prio=5 tid=32SUSPENDED JIT

  | group="main" sCount=1dsCount=0 obj=0x4264f860 self=0x7b183558

  | sysTid=32195 nice=0 sched=0/0cgrp=apps/bg_non_interactive handle=2078705952

  | state=S schedstat=( 3284456714198104216273858 383002 ) utm=324720 stm=3725 core=5

  at (:~1095)

  at $(:7582)

  at (:841)

"Thread-1400" prio=5 tid=31SUSPENDED JIT

  | group="main" sCount=1dsCount=0 obj=0x41f5d8f0 self=0x7be2a8e8

  | sysTid=32190 nice=0 sched=0/0cgrp=apps/bg_non_interactive handle=2078029504

  | state=S schedstat=( 3284905134412105526230562 382946 ) utm=324805 stm=3685 core=5

  at $(:~7586)

  at (:841)

"Thread-1399" prio=5 tid=30SUSPENDED JIT

  | group="main" sCount=1dsCount=0 obj=0x42564d28 self=0x7b0e6838

  | sysTid=32188 nice=0 sched=0/0cgrp=apps/bg_non_interactive handle=2077662640

  | state=S schedstat=( 3288042313685103203810616 375959 ) utm=325143 stm=3661 core=7

  at $(:~7586)

  at (:841)

"Thread-1398" prio=5 tid=29SUSPENDED

  | group="main" sCount=1dsCount=0 obj=0x4248e5a8 self=0x7be0d128

  | sysTid=32187 nice=0 sched=0/0cgrp=apps/bg_non_interactive handle=2079251904

  | state=S schedstat=( 3287248372432105116936413 379634 ) utm=325055 stm=3669 core=6

  at $(:~7586)

  at (:841)

当时处于suspend即意味着当时这四个thread正在执行java code而抓取backtrace时强制将thread suspend。看起来客户改动所致,并且客户有Proguard麻烦客户自己review代码。

systrace

ftrace 可以纪录CPU最为详细的执行情况,linux scheduler的执行情况。通常默认只开启 sched_switch 

如何抓取ftrace可以查询相关的FAQ

Kernelcore status

有的时候我们需要追查一下,当时Kernel的基本调度情况,以及接收中断的情况,以判断当前CPU执行的基本情况是否异常。比如有时候如果某个中断上来太过频繁,就容易导致系统运行缓慢,甚至死机。

* CPU Sched status

     adb shell catproc/sched_debug

     Use sysrq-trigger

* CPU interrupts

     adb shell catproc/interrupts

     adb shell catproc/irq/irq_id/spurious

4.3       Memory Usage

MemoryUsage我们通常会审查,系统当时memory是否足够,是否处于low memory状态,是否可能出现因无法申请到memory而卡死的情况。

常见的一些基本信息如下:

* meminfo: basic memory status

adb shell cat proc/meminfo

adb shell cat proc/pid/maps

adb shell cat proc/pid/smaps

* procrank info: all process memory status

adb shell procrank

adb shell procmem pid

adb shell dumpsys meminfo pid

* zoneinfo:

adb shell cat proc/zoneinfo

* buddyinfo:

adb shell cat /proc/buddyinfo

4.4       Storage Usage

查看Storage的情况,通常主要是查询data分区是否已经刷满, sdcard是否已经刷满,剩余的空间是否足够。以及是否有产生超大文件等。

通常使用的命令如 df

df

Filesystem              Size     Used     Free  Blksize

/dev                  446.0M   128.0K   445.8M   4096

/sys/fs/cgroup        446.0M    12.0K   445.9M   4096

/mnt/secure           446.0M     0.0K   446.0M   4096

/mnt/asec             446.0M     0.0K   446.0M   4096

/mnt/obb              446.0M     0.0K   446.0M   4096

/system                 1.2G   915.3M   355.5M   4096

/data                   1.1G   136.7M  1010.1M   4096

/cache                106.2M    48.0K   106.2M   4096

/protect_f              4.8M    52.0K     4.8M   4096

/protect_s              4.8M    48.0K     4.8M   4096

/mnt/cd-rom             1.2M     1.2M     0.0K   2048

/mnt/media_rw/sdcard0    4.6G     1.1G     3.4G  32768

/mnt/secure/asec        4.6G     1.1G     3.4G  32768

/storage/sdcard0        4.6G     1.1G     3.4G  32768

以及ls, du 等命令,如du

du -help

usage: du [-H | -L | -P] [-a | -d depth |-s] [-cgkmrx] [file …]

du -LP -d 1

8       ./lost+found

88      ./local

384     ./misc

48      ./nativebenchmark

912     ./nativetest

8       ./dontpanic

13376  ./data

8       ./app-private

8       ./app-asec

129424  ./app-lib

8       ./app

136     ./property

16      ./ssh

116312  ./dalvik-cache

8       ./resource-cache

48      ./drm

8       ./mediadrm

8       ./security

3888    ./nvram

8       ./amit

8       ./acdapi

88      ./@btmtk

32      ./sec

8       ./user

16      ./media

16      ./agps_supl

8       ./anr

8       ./gps_mnl

8       ./nfc_socket

16      ./ccci_cfg

32      ./mdlog

1312    ./system

176     ./recovery

32      ./backup

274688  .

5.     进程运行环境分析

5.1       系统运行环境

当我们怀疑死机问题可能是某个进程出现问题而引发时,通常我们需要对这个进程进行深入的分析,即进程运行环境分析。通常包括分析如,线程状态,各种变量值,寄存器状态等。在Android系统中,我们将其划分成三个层次。

Java运行环境分析, Native运行环境分析, Kernel运行环境分析。下面分别说明。

5.2       Java 运行环境分析

我们对于Zygote fork出来的processAPP以及system_server都会进行Java运行环境分析。其关键是分析Java Heap以便快速知道某个Java变量的值,以及Java对象的分布和引用情况。

通常Java Heap的分析方式则是抓取Java Hprof然后使用MAT等工具进行分析。

* 抓取Hprof的手法,如:

第一种方式:使用am 命令

   adb shell am dumpheap {Process} file

   如: 

 adbshell chmod 777 /data/anr

 adbshell am dumpheap /data/anr/

 adbpull /data/anr/

 第二种方式:使用DDMS 命令

 DDMS中选择对应的process然后在Devices按钮栏中选择Dump Hprof file保存即可

 第三种方式:通过代码的方式

   这个class 中有定义相关的抓取hprof method

 : public static void dumpHprofData(String fileName) throwsIOException;

 这样即可在代码中直接将这个processhprof 保存到相对应的文件中,注意这个只能抓取当时的process

 如果想抓其他的processhprof那么就必须通过AMS帮忙了。

 可以先获取IActivityManager接口,然后调用它的dumpheap方法。具体的代码,大家可以参考

 frameworks/base/cmds/am/src/com/android/commands/am/中的调用代码

第四种方式:发送SIGUSER1 

   在部分机器中,如果具有root权限,可以直接发送SIG 10来抓取,此时对应的Hprof保存在/data/misc下面,文件名如:

 

* 快速分析

首先, DVMHprof 和标准的Java Hprof 有一些差别,需要使用hprof-conv进行一次转换,DVM格式的hprof 转换成标准的java 命令的hprof

   hprof-conv

其次,使用如MAT Tool打开转换后的hprof文件,通常我们会

 analysis java thread information

 analysis java var value

 analysis Object reference

 analysis GC path

具体如何使用MAT分析可以参考MAT 的官方网站。

 3. Native 运行环境分析

Native 运行环境分析,我们通常会采用Core dump分析手法。 Core dump纪录了当时进程的各类关键资讯,比如变量参数,线程stack heap register等。通常可以认为是这个Process当时最为完整的资讯了。Core dump往往比较大,有时甚至会超过1G属于比较重量型的分析手法了。

* 如何抓取Core Dump

  目前MTK的机器会将Core Dump转换成AEE DB否则对应的Core dump文件即存放在/data/core目录下

  手工抓取时,可以:

  adb shell aee -d coreon

  adb shell kill -31 PID

  此时core dump就可能存放在两个目录下:/data/core以及/sdcard/mtklog/aee_exp下面新的DB 文件。

* 如何分析Core Dump

  因为通常已经将Core Dump转换成了AEE DB所以首先将AEE DB解开,即可以看到PROCESS_COREDUMP的文件,有的时候此文件很大,比如超过1G

  而分析Core DumpTools 很多,比如traces32 GDB等,这里就不详加说明,可以参考网络上的相关文档。

5.3       Kernel 运行环境分析

82平台上多了ramdump功能,可以发生KE后将82/92的物理内存压缩保存到EMMC的内置卡(默认保存到EMMC内置卡上)(92可以选择外置t)上,拿到该文件后就可以转换为kernel space,查看kernel各种变量,比查看kernel log更加方便快捷。

只有在eng版本下支持该功能,并且是EMMC的,存在内置T卡才行,

里的MTK_SHARED_SDCARD必须为noMTK_SHARED_SDCARD=no

连上adb后:

adb shell

#echo Y> /sys/module/mrdump/parameters/enable

#echo emmc> /sys/module/mrdump/parameters/device  (注意82只能在EMMC内置t卡上,不能下这条命令,92可以下这条命令修改到sdcard#echo sdcard > /sys/module/mrdump/parameters/device)

这样就开启了ramdump功能,注意重启后无效,必须重新设置才行

之后重新开机,此时会在

内置T卡:/storage/sdcard0/

或外置T卡:/storage/sdcard1/

看到文件,结合kernel/out/vmlinuxout/target/product/$proj/obj/KERNEL_OBJ/vmlinux一起提供给Mediatek即可做进一步kernel异常重启的分析。

6.     死机问题场景

当你遇到死机问题时,你可能面临的是下面三种情况。

* 有死机现场

  资讯最为充足,你可以快速的利用死机现场来分析。

* 已经重启过的手机

  死机现场已经不复存在,但手机还没有刷机,可以从手机中抓取已经存在的资讯来分析。

* 仅仅一些LOG或者其他的资讯

  需要从这些LOG或者资讯中猜测当时手机的状态,以及可能死机的原因。

 从这三种情况,不难得知,有死机现场的情况下是最容易分析的。而如果仅仅只有一些LOG的话,就需要工程师具有非常丰富的经验,从仅有的LOG中,提取有价值的资讯,来猜测出当时死机的原因。

7.     死机问题现场分析

7.1       死机现场分析手法

死机分析如同医生给病人诊断病情,所有的手法不在乎分为两种。

* 高科技的诊断设备,分析病人的病情。死机分析就依靠各种技术方法去诊断当时手机的运行的真实状态。

* 通过病人的各种活动,分析病人的潜在病因。就依靠各种对手机的操作,以及命令,让手机跑相应的流程,从而进一步分析。

7.2       基本分析流程

 下面我们将针对每一个流程进行具体的说明。

7.3       Test Phone Usage

* 通过做一些基本的测试,可大体上确认可能引发死机的模块,为后续Debug确定好方向。

* 通常只能正向推理,可以做什么 =》推断什么模块正常;逆向推理可能因为各种原因而失常。

 *Touch Panel

  - 屏幕是否有响应(一般情况下没响应)

  - 如果有响应,可能机器已经活过来了,或者当时把ANR认为了hang 机;需要进一步确认情况。

  - 确认按键的情况,通常都设定振动反馈,如果有,那么就认为当时按键事件可以传递到SystemServer,此时可能System Server 逻辑异常。

 *Power Key/ Volumn Up/Down Key

  - 是否可以亮、灭屏

  - 可点亮关闭屏幕,说明KPD ->input manager->PowerManagerService->Power->LCDdriver正常;通常可以怀疑TPD以及SurfaceFlinger

 * 是否可以显示音量调整情况

  - 可显示音量调整情况,进一步说明SurfaceFlinger也正常,进一步怀疑TPD,或者直接的APP无响应的情况。

 *SystemUI & Status Bar

  - Status Bar 是否可以拉下,以便防止只是活动区卡住的情况,可下拉,说明只是APP卡住,或者lockscreen无法解锁的情况

*LockScreen

  - 测试LockScreen是否可以解锁,

* Home Key/ Back Key/Menu Key

  - 确认当时是否只是APP hang住的情况,避免将ANR误判为死机

* 插入USB观察充电情况

  - 可确认Surfaceflinger System Server的运行情况

7.4       USB/ADB Debug Hang

7.4.1 USB/ADB Debug 准备

* 插入USB确认ADB是否可以使用

 - 首先查看windows的设备管理器里面是否出现对应的设备

 - 在命令行中输入adb devices看是否可以打印设备信息,在输入之前您最好先输入adb kill-server 保证pc上的adb client没有卡住

 - 请确保您使用的PC上已经安装ADBUSB端口本身正常

7.4.2 USB/ADB 连接分析

 *Case1: adb 能正常连接,adb shell #

- adb 目前可以正常接入,可以进行USB/ADB Debug

 *Case2: windows 设备管理器有反应,adb shell提示device not found

- 确认adb驱动是否安装好,USBuid vid 是否和driver匹配。

- 可能机器的adbd已经无法对接,尝试adbkill-server来确认

 *Case3:  windows 设备管理器有反应,adb shell提示offline

- 机器的adbd拒绝连接,或者adbd无法拉起。

- PC adb 版本过低

- 很可能adbd已经卡住, adbdprocess status ‘D’

7.4.3 机器状态基本检测

* ps or ps-t or ps -t -p查看进程基本状态

 -t  以线程为单位打印

 -p  附加打印线程优先级信息

 ** 追查如system server surfaceflinger service manager media server(ss sf smms)zygote,等关键进程的状态,进行初步确认。正常情况下,都应处于’S’异常情况有如’D’ ‘T’ ‘Z’ ‘R’

** 大体追查ss sf sm ms zygote等的memory情况,是否有明显的溢出情况

** 大体查看当时的ss pid sf pid,如果机器上层没有重启过,通常sf pid < 200 ss pid < 600,如果pid比较大就说明上层重启过。

** 是否还存在特别进程,如ipod表示在ipo关机中,如aee_core_forworder表示在抓core dumpaee_dumpstate表示aee 在抓取db 信息等。 

** 追查debuggerdprocess 数量,通常正常时,只有一个debuggerd processpid < 200如果有达到4debuggerd,这个时候将无法进行rtt之类的操作

* df

- 审查storage的使用情况,查看SD 卡和 data 分区使用情况,特别是如SD卡已满,或者data 分区写满等。

 * catproc/meminfo procrank

- 审查当前的memory使用情况,追查各个进程的memory情况

*getprop 

- 审查当前system properties情况

 * top-t -m 5 -n 2

- 摸一摸手机,感觉有点热,或者发烫的话,说明通常是CPU利用率比较高

- 大体上审查当前CPU的利用情况,不求精湛

总之,机器状态基本检测,目标就是通过简单几个命令直接侦测当前手机最为可能的异常情况。包括关键进程基本状态, CPU利用率,memory 状况,storage 状况等。做出基本的预先分析,从而为下一步的debug打好基础。

7.5       UART Debug

usb/adb无法确认问题时或者已经无法连接时,我们需要利用UART/KDB来进一步厘清问题。

确认UART以及 UART Console已经开启。

ENG 版本默认开启,User版本默认关闭。通常在User版本上如果需要抓取UART日志的话需要用散件工具单烧ENG版本的LK分区重启就可以抓取UART日志了。

目前我司一般的UART端口都不支持输入,所以只能通过输出的UART输出的log来分析问题。

7.6       确认死机的模块

我们又回到了最开始的可能会导致死机的模块,下面我们将针对每一个模块做详细的说明。

Input Driver-Input System

* 确认Input Driver-Input System通路是否正常,即inputdriver是否可以传上正常的输入

* 最常见的检测方式是 adb shell getevent

如直接输入adb shell getevent可以看到:

D:\log>adbshell getevent

add device1: /dev/input/event0

 name:     "mtk-kpd"

could notget driver version for /dev/input/mouse0 Not atypewriter

add device2: /dev/input/event3

 name:     "mtk-tpd"

add device3: /dev/input/event2

 name:     "hwmdata"

add device4: /dev/input/event1

 name:     "ACCDET"

could notget driver version for /dev/input/mice Not atypewriter

 对应的操作命令是:

Usage:getevent [-t] [-n] [-s switchmask] [-S] [-v [mask]] [-d] [-p] [-i] [-l] [-q][-c count] [-r] [device]

   -t: show time stamps

   -n: don't print newlines

   -s: print switch states for given bits

   -S: print all switch states

   -v: verbosity mask (errs=1 dev=2 name=4 info=8 vers=16 pos. events=32 props=64)

   -d: show HID descriptor if available

   -p: show possible events (errs dev name pos. events)

   -i: show all device info and possible events

   -l: label event types and names in plain text

   -q: quiet (clear verbosity mask)

   -c: print given number of events then exit

   -r: print rate events are received

 通常我们会一项一项的确认native层是否可以收到Kernel传递来的input event事件。

比如我们追查KPD是否有效果,power key可以看到相关的行为。

D:\log >adbshell getevent -t -l /dev/input/event0

[1388629316.433356]EV_KEY       KEY_POWER           DOWN

[1388629316.433356]EV_SYN      SYN_REPORT           00000000

[1388629316.527596]EV_KEY      KEY_POWER            UP

[1388629316.527596]EV_SYN      SYN_REPORT           00000000

[1388629317.824871]EV_KEY      KEY_POWER           DOWN

[1388629317.824871]EV_SYN      SYN_REPORT           00000000

[1388629317.996095]EV_KEY      KEY_POWER            UP

[1388629317.996095]EV_SYN      SYN_REPORT           00000000

[1388629319.495346]EV_KEY      KEY_POWER           DOWN

[1388629319.495346]EV_SYN      SYN_REPORT           00000000

[1388629319.530963]EV_KEY      KEY_POWER            UP

[1388629319.530963]EV_SYN      SYN_REPORT           00000000

 当然如果屏幕是点亮时,肯定就要快速追查tpd以及模拟按键是否正常

D:\log >adbshell getevent -t -l /dev/input/event5

[1388629590.432516]EV_ABS       ABS_MT_TOUCH_MAJOR  00000012

[1388629590.432516]EV_ABS       ABS_MT_TRACKING_ID  00000000

[1388629590.432516]EV_KEY      BTN_TOUCH           DOWN

[1388629590.432516]EV_ABS       ABS_MT_POSITION_X   000000d4

[1388629590.432516]EV_ABS       ABS_MT_POSITION_Y   00000280

[1388629590.432516]EV_SYN      SYN_MT_REPORT        00000000

[1388629590.432516]EV_SYN      SYN_REPORT           00000000

[1388629590.496797]EV_ABS       ABS_MT_TOUCH_MAJOR  00000010

[1388629590.496797]EV_ABS       ABS_MT_TRACKING_ID  00000000

[1388629590.496797]EV_ABS       ABS_MT_POSITION_X   000000d4

[1388629590.496797]EV_ABS       ABS_MT_POSITION_Y   0000027d

[1388629590.496797]EV_SYN      SYN_MT_REPORT        00000000

[1388629590.496797]EV_SYN      SYN_REPORT           00000000

[1388629590.506985]EV_ABS       ABS_MT_TOUCH_MAJOR  00000010

[1388629590.506985]EV_ABS       ABS_MT_TRACKING_ID  00000000

[1388629590.506985]EV_ABS       ABS_MT_POSITION_X   000000d3

[1388629590.506985]EV_ABS       ABS_MT_POSITION_Y   0000027a

[1388629590.506985]EV_SYN      SYN_MT_REPORT        00000000

[1388629590.506985]EV_SYN      SYN_REPORT           00000000

[1388629590.517713]EV_KEY      BTN_TOUCH            UP

[1388629590.517713] EV_SYN      SYN_MT_REPORT        00000000

[1388629590.517713]EV_SYN      SYN_REPORT           00000000

 如果发现无法收到此类资讯,那么就可以确认对应的devices可能有故障,需要请对应的driver& vendor工程师来分析。

system-server logic

此分析的关键在于分析 system-server是否还在正常的运转,这是非常重要的,据统计,40%usb可以debug hang 机问题,都可以通过对system-server逻辑的审查找出原因。

 Systemserver 是整个android上层的中枢,容纳了最为重要的service

 System server的分析主要是通过java nativebacktrace来追查Systemserver的关键thread 有没有被lock/dead lock,有没有进入dead loop,状态是否正常。

 从死机机的角度来看system server关键的thread :

Serverthread:

System-servermain looper建立在serverthread上,所有service如果不单独创立thread-looper那么都将运行在这个Server thread上,其关键性不言而喻,用watchdog来监测该thread

ActivityManager:

处理所有的Activity状态切换,broadcast,以及ANR 监测等等,非常重要。

WindowManager:

处理各种window叠加与切换,Input相关处理。

WindowManagerPolicy/UI:

主要处理LockScreen相关流程,它卡住,lockscreen无法解锁

PowerManagerService:

处理Power相关事宜,它卡住,屏幕无法熄灭,点亮

InputDispatcher/InputReader

处理Input System相关事宜,一旦他们卡住,那么所有的Input Event都无法反馈到其他的module机器死机就成必然。

KK以及KK 以后的版本中Google 取消了serverthread这样的main looper thread直接使用system server 的第一个thread作为main looper Googlesystem serverthreads 做了进一步的整合,以减少繁杂的线程数,新增了如threads将大量的普通型的Handler按时效分类分散到上面的4threads中。

所以KK及更高的版本还需要分析 thread

 这些thread都通过执行MQ-Looper-Handler的模式运行,所以正常的时候的java/native backtrace都是:

Java:

  at (NativeMethod)

  at (:138)

  at (:150)

Native:

  #00  pc 0002599c /system/lib/ (epoll_wait+12)

  #01  pc 000105e3 /system/lib/ (android::Looper::pollInner(int)+94)

  #02  pc 00010811 /system/lib/ (android::Looper::pollOnce(int, int*, int*, void**)+92)

  #03  pc 0006ca5d /system/lib/libandroid_runtime.so(android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)

 一旦不是就可能已经出现异常了。

BinderThread

Systemserver 为外界提供服务,绝大多数都通过binder与其他process 对接。BinderThread 的数量动态调整,默认不会超过16个,如果数量达到16个,即说明当前system server可能非常繁忙,有process非常频繁的和Process通信。

JB以及以前版本,System-server的第一个thread在调起serverthread后,自己加IPCthread pool中,成为Binder Thread的一员。 

对于Binder Thread正常时对应的Backtrace:

  #00  pc 000247e8  /system/lib/(__ioctl+8)

  #01  pc 00038248  /system/lib/ (ioctl+28)

  #02  pc 0001d3a9  /system/lib/(android::IPCThreadState::talkWithDriver(bool)+140)

  #03  pc 0001dae3  /system/lib/(android::IPCThreadState::getAndExecuteCommand()+6)

  #04  pc 0001db79  /system/lib/(android::IPCThreadState::joinThreadPool(bool)+48)

  #05  pc 00021a79  /system/lib/

  #06  pc 0000ea01  /system/lib/(android::Thread::_threadLoop(void*)+216)

  #07  pc 0004f1c9 /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)

  #08  pc 0000e533  /system/lib/

  #09  pc 0000d600  /system/lib/(__thread_entry+72)

  at (Native Method)

 抓取system serverjava backtrace,依次check serverthread(JB)ActivityManager WindowManager WindowManagerPolicyPowerManagerService以及 的状态,如状态异常,则依次推导。

当发现java backtrace最后调用到异常nativemethod时,抓取其native backtace,通过native backtrace 进一步追查.

如果在native backtrace中,发现已经调入binderdriver那就是通过binder进行IPC call这个时候就要知道binder的对端process然后查阅它的binder thread进程进一步分析问题。

 Case1: Abnormal Java Backtrace “Deadlock”

图片

 Case2: Abnormal Java Backtrace “Lock in native thread"

图片

 Case3: Abnormal native Backtrace “Lock in Binder”

图片

 Case4: Abnormal native Backtrace "Lock in Binder thread"

图片

 当确认前面的key thread都没用问题,而通过getevent确认event 已经传递system server。问题可能出在inputsystem中。

WindowManagerService通过InputManager提供的接口开启一个线程驱动InputReader不断地从/dev/input /目录下面的设备文件读取事件,然后通过InputDispatcher分发给连接到WindowManagerService服务的客户端。

 Input Reader 正常的backtrace:

"InputReader" sysTid=611

#00 pc 00027754 /system/lib/(epoll_wait+12)

#01 pc 0001f345 /system/lib/(android::EventHub::getEvents(int, android::RawEvent*, unsigned int)+1092)

#02 pc 0002aaf7 /system/lib/(android::InputReader::loopOnce()+142)

#03 pc 00027613 /system/lib/(android::InputReaderThread::threadLoop()+8)

#04 pc 00015318 /system/lib/(android::Thread::_threadLoop(void*)+492)

#05 pc 0004d12b/system/lib/libandroid_runtime.so(android::AndroidRuntime::javaThreadShell(void*)+150)

#06 pc 00014948 /system/lib/

#07 pc 0000f66c /system/lib/ (__thread_entry+80)

 Input Dispatcher 正常的backtrace:

"InputDispatcher" sysTid=610

#00 pc 00027754 /system/lib/(epoll_wait+12)

#01 pc 0001c05c /system/lib/(android::Looper::pollInner(int)+140)

#02 pc 0001c3d4 /system/lib/ (android::Looper::pollOnce(int, int*, int*, void**)+76)

#03 pc 00026317 /system/lib/(android::InputDispatcher::dispatchOnce()+94)

#04 pc 0001f5bd /system/lib/(android::InputDispatcherThread::threadLoop()+8)

#05 pc 00015318 /system/lib/(android::Thread::_threadLoop(void*)+492)

#06 pc 0004d12b/system/lib/libandroid_runtime.so(android::AndroidRuntime::javaThreadShell(void*)+150)

#07 pc 00014948 /system/lib/

#08 pc 0000f66c /system/lib/(__thread_entry+80)

 Backtrace通常都可以精确的定位问题点,比如卡在了哪一行。

那有没有可能您抓backtrace时,恰好运行到,造成乌龙的情况呢?这个通常需要具体情况具体分析

--- NativeBacktrace 处于R状态

--- JavaBacktrace 处于 Suspend状态, Running状态

---Backtrace 处于明确的非block状态

--- DoubleBacktrace 确认是否CPU有运转

随着android版本的推进,system-server越来越显得庞大,为此Googlesystem-server做了分拆动作.

After 4.0 SurfaceFlinger removed from system-server and created by init single process SurfaceFlinger

SurfaceFlinger外,对system-server影响最大的是MediaServer

注意对于surfaceflinger mediaserver等非DVM Process,切忌不要对他们send signalSIGQUIT(3)将导致对应的process直接退出

Display logic

DisplayControl Flow

图片:

 

 *Surface Manager(Surfaceflinger)

**Surfaceflinger 是用户空间中Frameworklibraries中负责显示相关的一个模块 

** 当系统同时执行多个应用程序时,Surfaceflinger负责管理显示,主要包括显示的叠加和显示的渲染 

** 其中显示的叠加,MTK架构按照一定的原则和算法,主要用到GPU OVL 模块的overlay 功能来做2D/3D 绘图的显示合成

 * HWC

** 基于DDP OVL硬件做HW Overlay功能

 * GPU(Graphic Processing Unit )

**aspecialized electronic circuit designed to accelerate the image processing frame buffer rendering for output to a display

 *FrameBuffer 

** 基于Linux Frame buffer模型的MTKFramebuffer实作,主要来管理frame buffer

 *DDP(DisplayData Path)

** MTKDisplay Hardware Controller,包括OVL DMA Color ProcessorBLS  DSI/DBI/DPIController

 DisplayData Flow

图片:

 * Display大致的流程说明

** APP(包括WMS)会把数据透过Surface送到SF(surfaceflinger)

** SF 按照一定规则,通过GPU/HWC把多个Surface合成,并设定到DDP OVL 的对应layer

*** MTK OVL一般有4 layer(可能不同平台会有差异,目前基本都是4 layer),每个layer都可以设定一个对应的图层,然后OVL把这写图层合成后送给DDP的下一级Module

*** 某些情况下(比如总的图层超过4个,OVL无法处理等各种case),会使用GPU 去做2D/3D 的图层合成到frame buffer

** SF/HWC 最后把GPU合成图层以及需要OVL合成的图层,设定到OVLHW Register,并trigger HW Engine

** MTK DDP 就会把合成的数据像管道一样流向LCM module,最后Panel显示相关的画面

  Display的快速分析,我们主要是两个手段,第一个确认FrameBuffer数据是否和理想数据一致,第二个确认SurfaceFlinger状态是否正确。

* 确认FrameBuffer数据和理想数据一致,那么说明android上层的处理行为都是正常的,而问题就很可能出在LCMdriver 或者 LCM 本身问题,此时需要联系LCMdriver 工程师以及 LCM vendor 来确认分析,这里不再详细说明。

 * 确认SurfaceFlinger的状态,用于审查SurfaceFlinger的行为是否正常,对应的Thread是否能够正常工作,我司已经在SurfaceFlinger里面导入了Watchdog机制,审查SurfaceFlinger是否有卡住的情况,对应在main log里面会打印如

 [SF-WD]detect SF maybe hang!!! 

这样的LOG并且会纪录卡顿的时机,如果持续卡顿,毫无疑问, SurfaceFlinger已经卡住,此时就要分析对应的backtrace以及 LOG

*SurfaceFlinger 的线程情况在不同的版本上变化比较大,最直接的方式是审查它binder thread情况,以及Event Loop的执行情况。 binderthread system server情况一致,不再详细说明。 Event LoopJB 以及,JB 以及KK上都不相同,这里分别说明。

 JB以前的版本,SurfaceFlingerEvent Loop使用的是普通的pthread控制,并且SurfaceFlinger的第一个Thread 在执行SurfaceFlinger 的初始化后,转换为了binder threadEvent Loopthread 是新起的 "SurfaceFlinger" thread对应的正常backtrace:

图片:

 JB版本,SurfaceFlingerEvent Loop换成了Message Queue-Looper对应的backtrace:

图片:

 KK版本,SurfaceFlinger的第一个thread 直接作为了Event Loop thread对应的backtrace:

图片:

 然后再根据SurfaceFlinger的代码逻辑,以及backtracelock 情况进行审查分析。

8.     无现场猜测分析

8.1       无场景猜测与分析

前面已经提到,无场景分成两类

* 已经重启过的手机

  死机现场已经不复存在,但手机还没有刷机,可以从手机中抓取已经存在的资讯来分析。

  *仅仅一些LOG或者其他的资讯

  需要从这些LOG或者资讯中猜测,当时手机的状态,以及可能死机的原因。

  对于前者,如同法医解剖逝者遗体,分析可能的死亡原因。而对于后者,就相当于警察叔叔对一些曾年旧案的考证,挖掘与分析,难度可想而知。

8.2       死机资讯的完整纪录

为了能够更好更快的分析死机问题,通常我们都强烈建议保存好现场,如果一些特殊环境下无法保存现场,那么就要求测试工程师详细的纪录当时现场环境,包括但不限于下面的资讯:

* 发现死机的时间

--- 如果是发现时,感觉机器早已经死机,也请说明

--- 如有截图,拍照,可以从图像上先获取

 * 复现手法,操作的流程,当时环境

--- 强调在正常使用到死机过程中的操作。

--- 环境状态通常包括温度,湿度,网络信号状况。

--- 复现流程的视频

 * 复现手机情况

--- 复现的软件版本:版本号?

--- 外部设备情况:有插入SD卡?耳机?SIM

--- 软件开启情况:  开启蓝牙? WIFI?数据服务?GPS?

 *复现的概率

--- 多少台手机做过测试,多少台手机可以复现。

--- 前后多少个版本可以复现,从哪个版本开始可以复现。

 其中死机的时间点至关重要,需要现场的工程师一定要比较精确的纪录。

8.3       死机Log 分析

* 确认hang机时间,和当时是否已经死机至关重要

* 如果当时kernel已经异常,mobile log无法抓取log那么log的价值大打折扣。

* 反过来如果当时mobile log还在继续,说明至少kernel整体功能正常,先分析android上层的情况。

* LOG中分析SystemServer Surfaceflinger行为是否正常,是否有Lock住。

* 查看System Server中关键Service 执行情况,AMS WMS PowerManagerService WindowManagerPolicy

* 观测AMS是比较快速的方法,因为AMS工作时,会使用到很多其他ServiceLock,比如broadcast start activity start service通常一旦system server有卡住,则AMS 也会卡住,反过来如果AMS 没有卡住,那么通常就意味着systemserver没有直接卡住。

* 查看Surfaceflinger先查sf-wd看看是否surfaceflinger是否已经卡住,然后再追查fps情况,HWComposer等情况。

* 查看Power Key行为来确认上下通路是否正常,一般人看到死机,通常会去按一下Power Key来确认是否死机。

* 查看Binder信息,看看Systemserver Surfaceflinger等的IPC 情况。

* 按Power Key 分析

因为死机,一般人都会习惯性的按Power key来查看是否可以恢复,而按Power Key的处理流程,涉及从Kernel => Input System => System Server => SurfaceFlinger等的整个流程,我们可以观察这个流程来查看hang机情况。

* KPDreceives Interrupt and generate Power Key

图片: power-key-1png

* Systemserver receives Key and call set_screen_state

图片: power-key-2png

* PowerState Update:  request_suspend_state

图片:

* Setscreen on:  mt65xx_leds_set_cust

图片:

 通过审查每一个阶段流程,确认可能的hang机点。注意的是不同的版本可能有所不同,可以先用正常的机器复现一次后比对。

8.4死机Log 分析, trace 辅助

* 如果有提供/data/anr下的trace,或者相关的db文件。在确认死机的时间下,check trace对应的时间点,如果时间在死机或者hang机后,则是一份非常有价值的trace。通常查“-----”or “pid”

* 借机审查system server surfaceflinger的状况。

* 如果/data/anr下有标准full_traces_xx即标柱这个backtrace SWT 产生的宝贵backtrace里面一定有system server等的backtrace

9.     死机日志抓取

 通常情况下,依靠Log可以找到对应的异常模块,但无法找出根本原因。需要依赖更多的信息来debug确认,所以针对这种情况,我们需要让测试人员抓出更多的信息来分析。

9.1       当机器死机时,建议使用下面脚本抓取资讯:

@echo "Pull important informationfrom hang phone, written by Yanghui Li"

adb devices

@echo "attach sdcard/mtklog"

adb pull /sdcard/mtklog mtklog/

 @echo “attach sdcard2/mtklog”

adb pull /sdcard2/mtklog mtklog/sdcard2

 @echo "attach trace"

adb pull /data/anr mtklog/anr

@echo "attach rtt dump forsurfaceflinger"

adb pull /data/rtt_dump* mtklog/sf_dump

adb pull /data/anr/sf_rtt mtklog/sf_rtt_1

@echo "attach data aee db"

adb pull /data/aee_exp mtklog/data_aee_exp

@echo "attach data mobilelog"

adb pull /data/mobilelogmtklog/data_mobilelog

 @echo "attach NE core"

adb pull /data/core mtklog/data_core

 @echo "attach tombstones"

adb pull /data/tombstonesmtklog/tombstones

 @echo “attach phone state”

adb shell ps -t> mtklog/

adb shell top -t -m 5 -n 3 > mtklog/

adb shell service list  > mtklog/

adb shell cat /proc/meminfo >mtklog/meminfo

adb shell cat /proc/buddyinfo >mtklog/buddyinfo

adb shell procrank > mtklog/

adb shell cat proc/sched_debug >mtklog/sched_debug.txt

adb shell cat proc/interrupts >mtklog/

adb shell dumpstate > mtklog/

@echo "finish."

pause

9.2       当机器重启后,可以使用下面脚本抓取:

adb devices

@echo"抓出sdcard/mtklog"

adb pull/sdcard/mtklog mtklog/

 @echo"抓出trace"

adb pull/data/anr mtklog/anr

 @echo"抓出data aee db"

adb pull/data/aee_exp mtklog/data_aee_exp

 @echo"抓出data mobilelog"

adb pull/data/mobilelog mtklog/data_mobilelog

 @echo"抓出NE core"

adb pull/data/core mtklog/data_core

 @echo"抓出tombstones"

adb pull/data/tombstones mtklog/tombstones

 @echo"sf rtt"

adb pull/data/rtt_dump* mtklog/sf_rtt

adb pull/data/anr/sf_rtt mtklog/sf_rtt_1

 @echo"完成"

pause

应当说针对不同的场景,死机和重启意义不一样。

对于普通用户来说,死机的危害性和重要性远大于重启。死机意味着机器在很长一段时间内机器都运行不正常,不能使用。危害性仅次于不能开机。重启很多时候用户都无法感知到,除非当时正在操作手机,并且通常很快就可以恢复。所以在USER版本中,我们要尽可能的把死机转换成重启。

对于开发者来说,重要的是解决问题,通常把死机转换成重启,为了规避一些未知因素,通常抓取的资讯比较少,难以直接分析问题。而如果有死机的现场,分析起来就相对容易得多。

所以针对ENG版本,我们建议不要把死机转换成重启。针对USER版本,尽可能的把死机转换成重启。

10.2   死机如何转换成重启

死机转换成重启的通用手段就是Watchdog机制,通过watchdog监测系统执行情况,一旦发生watchdog timeout则做相应的异常处理。通常对于严重的情况,就是重启系统。

 android中有两个最为重要的Watchdog机制,一个是System Server内部的Watchdog用于监测System Server重要Thread 是否正常,关键Lock是否可以快速获取。一旦出现故障,则快速重启android上层。另外一个就是整个系统的Watchdog这个依赖于不同平台厂商的实现,对于MTK平台来说,大体的做法是每一个cpu core对应一个Watchdog Thread [wdtk-X]周期性(20s)的去写RGUregisterRGUregistertimeout 时间是30s即如果出现一个corewatchdog thread没有按时踢狗,那么就会触发一个timeoutFIQ产生一个KE引发系统完整重启。

 MTK KK以后的平台,又做了hangmonitor机制, system serverwatchdog thread周期性的踢kernel中的一个计时器,并设定下一次踢狗的时间,如果在设定的时间内没有踢狗,即意味着system serverwatchdog 本身可能卡住,那么hang monitor机制就会自己触发一个HWT引发系统完整重启。

当然并非所有的死机问题都能转换成重启。

10.3  死机VS重启

HWHang                          [maybe]

IRQ Disable & run longtime       [After ICS Reboot, GB Hang]

SoftIRQ run longtime            [Reboot]

Preempt Disable longtime         [Reboot]

RT Thread busy[RT <99]           [Hang or Hanglong time then reboot]

Kernel ModuleHang               [maybe]

---- Not block watchdog thread reboot.

Native ModuleHang               [maybe]

---- Not block watchdog thread reboot.

SurfaceFlingerHang              [GB reboot, ICS/JB Hang, KK Hang long time then reboot] 

Display subsystemHang            [Hang]

LCMHang                         [Hang]

Input DriverFail                [Hang]

Input SystemHang                [GB, ICS Hang and JB, KK Reboot]

WindowManagerPolicyHang          [Maybe]

---- Need check the serverthread state

System serverdeadlock           [Reboot]

System server logicabnormal      [Maybe]

Surfaceflinger logic abnormal    [Maybe]