您的位置:首页 > 移动开发 > Android开发

Android死机问题分析

2016-08-30 15:32 302 查看
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 System

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

(6). LCM Driver

* 无法将Framebuffer 数据显示在LCM 上

 

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

* Power 

* Clock

* Memory & Memory Controller

* Fail IC

3. 哪些数据可以用来分析.

* Backtrace 

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

 

* 系统运行环境

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

 

* 程序执行环境

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

 

* 其他的一些资讯

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

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( After 6577.SP/ICS2.MP)

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 解析

下面是一小段system server 的java backtrace 的开始

----- pid 682 at 2014-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:

(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

"main" prio=5 tid=1 NATIVE

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

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

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

  at android.os.MessageQueue.nativePollOnce(Native Method)

  at android.os.MessageQueue.next(MessageQueue.java:138)

  at android.os.Looper.loop(Looper.java:150)

  at com.android.server.ServerThread.initAndLoop(SystemServer.java:1468)

  at com.android.server.SystemServer.main(SystemServer.java:1563)

  at java.lang.reflect.Method.invokeNative(Native Method)

  at java.lang.reflect.Method.invoke(Method.java:515)

  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:829)

  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:645)

  at dalvik.system.NativeStart.main(Native Method)

  

我们一行一行来解析.

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

 

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

 

* 2#  Global DVM mutex value: if 0 unlock,  else lock

 tll:  threadListLock, 

 tsl:  threadSuspendLock, 

 tscl: threadSuspendCountLock

 ghl:  gcHeapLock

 

 (mutexes: tll=0 tsl=0 tscl=0 ghl=0)

 

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

 "main"  -> main thread -> activity thread

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

 DVM thread id, NOT linux thread id

 DVM thread Status:

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

 

 "main" prio=5 tid=1 NATIVE

 

* 4# DVM thread status 

 group: default is “main”

   Compiler,JDWP,Signal Catcher,GC,FinalizerWatchdogDaemon,FinalizerDaemon,ReferenceQueueDaemon are system group

 sCount:  thread suspend count

 dsCount: thread dbg suspend count

 obj:     thread obj address

 Sef:  thread point address

 

 group="main" sCount=1 dsCount=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/0 cgrp=apps handle=1074835940

 

* #6 CPU Sched stat

 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=( 47858718206 26265263191 44902 ) utm=4074 stm=711 core=0

 

* #7-more Call Stack

 

1.3 几种常见的java backtrace

 

1.3.1 ActivityThread 正常状态/ActivityThread Normal Case

Message Queue is empty, and thread wait for next message.

 "main" prio=5 tid=1 NATIVE

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

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

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

   at android.os.MessageQueue.nativePollOnce(Native Method)

   at android.os.MessageQueue.next(MessageQueue.java:138)

   at android.os.Looper.loop(Looper.java:150)

   at android.app.ActivityThread.main(ActivityThread.java:5299)

   at java.lang.reflect.Method.invokeNative(Native Method)

   at java.lang.reflect.Method.invoke(Method.java:515)

   at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:829)

   at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:645)

   at dalvik.system.NativeStart.main(Native Method)

  

1.3.2 Java Backtrace Monitor case

Synchronized Lock: 等待同步锁时的backtrace.

 "AnrMonitorThread" prio=5 tid=24 MONITOR

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

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

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

   at com.android.server.am.ANRManager$AnrDumpMgr.dumpAnrDebugInfoLocked(SourceFile:~832)

   - waiting to lock <0x42838968> (a com.android.server.am.ANRManager$AnrDumpRecord) held by tid=20 (ActivityManager)

   at com.android.server.am.ANRManager$AnrDumpMgr.dumpAnrDebugInfo(SourceFile:824)

   at com.android.server.am.ANRManager$AnrMonitorHandler.handleMessage(SourceFile:220)

   at android.os.Handler.dispatchMessage(Handler.java:110)

   at android.os.Looper.loop(Looper.java:193)

   at android.os.HandlerThread.run(HandlerThread.java:61)

   

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

 "WifiP2pService" prio=5 tid=37 NATIVE

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

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

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

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

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

   #02  pc 00010811  /system/lib/libutils.so (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/libdvm.so (dvmPlatformInvoke+112)

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

   #06  pc 00027ea8  /system/lib/libdvm.so

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

   #08  pc 0002c994  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+188)

   #09  pc 000632a5  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+340)

   #10  pc 000632c9  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)

   #11  pc 00057961  /system/lib/libdvm.so

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

   at android.os.MessageQueue.nativePollOnce(Native Method)

   at android.os.MessageQueue.next(MessageQueue.java:138)

   at android.os.Looper.loop(Looper.java:150)

   at android.os.HandlerThread.run(HandlerThread.java:61)

   

1.3.4 执行object.wait 等待状态

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

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

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

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

   at java.lang.Object.wait(Native Method)

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

   at java.lang.Thread.parkFor(Thread.java:1212)

   at sun.misc.Unsafe.park(Unsafe.java:325)

   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)

   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2017)

   at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:410)

   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1035)

   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1097)

   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)

   at java.lang.Thread.run(Thread.java:848)

 

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

 "FileObserver" prio=5 tid=23 SUSPENDED

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

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

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

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

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

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

   #03  pc 00055a93  /system/lib/libdvm.so

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

   #05  pc 0004ae7f  /system/lib/libdvm.so

   #06  pc 0004e353  /system/lib/libdvm.so

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

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

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

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

   #11  pc 00027ea8  /system/lib/libdvm.so

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

   #13  pc 0002c994  /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+188)

   #14  pc 000632a5  /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+340)

   #15  pc 000632c9  /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20)

   #16  pc 00057961  /system/lib/libdvm.so

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

   at android.os.FileObserver$ObserverThread.observe(Native Method)

   at android.os.FileObserver$ObserverThread.run(FileObserver.java:88)

 

2. Native Backtrace

 

2.1 Native Backtrace 抓取方式

 

2.1.1 利用debuggerd 抓取

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

rtt built timestamp (Apr 18 2014 15:36:21)

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

  -f funcion : current support functions:

                 bt  (Backtrace function)

  -p pid     : pid to trace

  -t tid     : tid to trace

  -n name    : process name to trace

  -h         : help menu

  

2.1.2 添加代码直接抓取

Google 默认提供了CallStack API, 请参考

system/core/include/libutils/CallStack.h 

system/core/libutils/CallStack.cpp

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

 

2.2 解析Native Backtrace

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

如addr2line 执行

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

 

3. Kernel Backtrace

 

3.1 Kernel Backtrace 抓取方式

 

3.1.1 运行时抓取

* AEE/RTT 工具

 

* Proc System

  cat proc/pid/task/tid/stack

 

* Sysrq-trigger

 adb shell cat proc/kmsg > kmsg.txt

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

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

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

 

* KDB

 Long press volume UP and DOWN more then 10s

 btp             <pid>                

 Display stack for process <pid>

 bta             [DRSTCZEUIMA]        

 Display stack all processes

 btc                                  

 Backtrace current process on each cpu

 btt             <vaddr>              

 Backtrace process given its struct task add

 

3.1.2 添加代码直接抓取

* #include <linux/sched.h>

 当前thread:  dump_stack();

 其他thread:  show_stack(task, NULL);

 

3.2 Process/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 (disk sleep), T (stopped), Z (zombie) 等就要认真审查.

 

4. 几种典型的异常情况

4.1 Deadlock

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

"PowerManagerService" prio=5 tid=25 MONITOR

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

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

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

  at com.android.server.am.ActivityManagerService.bindService(ActivityManagerService.java:~14079)

  - waiting to lock <0x42aa0f78> (a com.android.server.am.ActivityManagerService) held by tid=16 (ActivityManager)

  at android.app.ContextImpl.bindServiceCommon(ContextImpl.java:1665)

  at android.app.ContextImpl.bindService(ContextImpl.java:1648)

  at com.android.server.power.PowerManagerService.bindSmartStandByService(PowerManagerService.java:4090)

  at com.android.server.power.PowerManagerService.handleSmartStandBySettingChangedLocked(PowerManagerService.java:4144)

  at com.android.server.power.PowerManagerService.access$5600(PowerManagerService.java:102)

  at com.android.server.power.PowerManagerService$SmartStandBySettingObserver.onChange(PowerManagerService.java:4132)

  at android.database.ContentObserver$NotificationRunnable.run(ContentObserver.java:181)

  at android.os.Handler.handleCallback(Handler.java:809)

  at android.os.Handler.dispatchMessage(Handler.java:102)

  at android.os.Looper.loop(Looper.java:139)

  at android.os.HandlerThread.run(HandlerThread.java:58)

  

  "ActivityManager" prio=5 tid=16 MONITOR

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

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

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

  at com.android.server.wm.WindowManagerService.setAppVisibility(WindowManagerService.java:~4783)

  - waiting to lock <0x42d17590> (a java.util.HashMap) held by tid=12 (WindowManager)

  at com.android.server.am.ActivityStack.stopActivityLocked(ActivityStack.java:2432)

  at com.android.server.am.ActivityStackSupervisor.activityIdleInternalLocked(ActivityStackSupervisor.java:2103)

  at com.android.server.am.ActivityStackSupervisor$ActivityStackSupervisorHandler.activityIdleInternal(ActivityStackSupervisor.java:2914)

  at com.android.server.am.ActivityStackSupervisor$ActivityStackSupervisorHandler.handleMessage(ActivityStackSupervisor.java:2921)

  at android.os.Handler.dispatchMessage(Handler.java:110)

  at android.os.Looper.loop(Looper.java:147)

  at com.android.server.am.ActivityManagerService$AThread.run(ActivityManagerService.java:2112)

  

  "WindowManager" prio=5 tid=12 MONITOR

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

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

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

  at com.android.server.power.PowerManagerService.setScreenBrightnessOverrideFromWindowManagerInternal(PowerManagerService.java:~3207)

  - waiting to lock <0x42a95140> (a java.lang.Object) held by tid=25 (PowerManagerService)

  at com.android.server.power.PowerManagerService.setScreenBrightnessOverrideFromWindowManager(PowerManagerService.java:3196)

  at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLockedInner(WindowManagerService.java:9686)

  at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLockedLoop(WindowManagerService.java:8923)

  at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLocked(WindowManagerService.java:8879)

  at com.android.server.wm.WindowManagerService.access$500(WindowManagerService.java:170)

  at com.android.server.wm.WindowManagerService$H.handleMessage(WindowManagerService.java:7795)

  at android.os.Handler.dispatchMessage(Handler.java:110)

  at android.os.Looper.loop(Looper.java:147)

  at android.os.HandlerThread.run(HandlerThread.java:58)

 

 

4.2 执行JNI native code 后一去不复返

"main" prio=5 tid=1 NATIVE

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

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

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

  (native backtrace unavailable)

  at android.hardware.SystemSensorManager$BaseEventQueue.nativeDisableSensor(Native Method)

  at android.hardware.SystemSensorManager$BaseEventQueue.disableSensor(SystemSensorManager.java:399)

  at android.hardware.SystemSensorManager$BaseEventQueue.removeAllSensors(SystemSensorManager.java:325)

  at android.hardware.SystemSensorManager.unregisterListenerImpl(SystemSensorManager.java:194)

  at android.hardware.SensorManager.unregisterListener(SensorManager.java:560)

  at com.android.internal.policy.impl.WindowOrientationListener.disable(WindowOrientationListener.java:139)

  at com.android.internal.policy.impl.PhoneWindowManager.updateOrientationListenerLp(PhoneWindowManager.java:774)

  at com.android.internal.policy.impl.PhoneWindowManager.screenTurnedOff(PhoneWindowManager.java:4897)

  at com.android.server.power.Notifier.sendGoToSleepBroadcast(Notifier.java:518)

  at com.android.server.power.Notifier.sendNextBroadcast(Notifier.java:434)

  at com.android.server.power.Notifier.access$500(Notifier.java:63)

  at com.android.server.power.Notifier$NotifierHandler.handleMessage(Notifier.java:584)

  at android.os.Handler.dispatchMessage(Handler.java:110)

  at android.os.Looper.loop(Looper.java:193)

  at com.android.server.ServerThread.initAndLoop(SystemServer.java:1436)

  at com.android.server.SystemServer.main(SystemServer.java:1531)

  at java.lang.reflect.Method.invokeNative(Native Method)

  at java.lang.reflect.Method.invoke(Method.java:515)

  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:824)

  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:640)

  at dalvik.system.NativeStart.main(Native Method)

  

===>

KERNEL SPACE BACKTRACE, sysTid=814

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

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

 [<c07e57b0>] schedule+0xc/0x80 from [<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/0x5bc from [<c018b33c>] sys_ioctl+0x7c/0x8c

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

 [<ffffffff>]  from [<ffffffff>] 

1. 系统运行环境

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

 

2. CPU Usage

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

 

2.1 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 (cpu,vss,rss,thr).

    -t      Show threads instead of processes.

    -h      Display this help screen.

 

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

 

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

I.E 正常情况

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

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

  PID   TID PR CPU% S     VSS     RSS PCY UID      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 + IOW 0 + IRQ 0 + SIRQ 0 = 545

  PID   TID PR CPU% S     VSS     RSS PCY UID      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 的进程.

 

I.E 异常情况

 

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 PCY UID      Thread          Proc

16132 32195  3  14% R 997100K  53492K  bg u0_a60   Thread-1401     com.android.mms

16132 32190  1  14% R 997100K  53492K  bg u0_a60   Thread-1400     com.android.mms

16132 32188  2  14% R 997100K  53492K  bg u0_a60   Thread-1399     com.android.mms

16132 32187  0  14% R 997100K  53492K  bg u0_a60   Thread-1398     com.android.mms

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 PCY UID      Thread          Proc

16132 32195  3  16% R 997100K  53492K  bg u0_a60   Thread-1401     com.android.mms

16132 32188  2  16% R 997100K  53492K  bg u0_a60   Thread-1399     com.android.mms

16132 32190  0  16% R 997100K  53492K  bg u0_a60   Thread-1400     com.android.mms

16132 32187  1  16% R 997100K  53492K  bg u0_a60   Thread-1398     com.android.mms

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

 

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

 

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

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

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

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

  at com.yulong.android.mms.c.f.d(MmsChatDataServer.java:~1095)

  at com.yulong.android.mms.ui.MmsChatActivity$37.run(MmsChatActivity.java:7582)

  at java.lang.Thread.run(Thread.java:841)

 

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

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

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

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

  at com.yulong.android.mms.ui.MmsChatActivity$37.run(MmsChatActivity.java:~7586)

  at java.lang.Thread.run(Thread.java:841)

 

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

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

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

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

  at com.yulong.android.mms.ui.MmsChatActivity$37.run(MmsChatActivity.java:~7586)

  at java.lang.Thread.run(Thread.java:841)

 

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

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

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

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

  at com.yulong.android.mms.ui.MmsChatActivity$37.run(MmsChatActivity.java:~7586)

  at java.lang.Thread.run(Thread.java:841)

 

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

 

2.2 cputime

通常用cputime 来打印一段时间内, CPU 的利用率的统计情况, 资讯比top 更加详细.

cputime -h

Usage: cputime  [-start/-stop]  [-n iterations] [-d delay] [-e time] [ -m max_count ]  [-p] [-s sort_column] [-i id] [-h]

 -start       Start cpu time monitor.

 -stop        Stop cpu time monitor.

 -n  num      Updates to show before exiting.

 -d  num      Seconds to wait between updates.

 -m  num      Maximum number of information to display.

 -e  num      Enable CPU time monitor and stop monitor after num seconds. If no this parameter will

              show last cputime monitor data.

 -p           Show process instead of thread. If no this parameter default will show thread information.

 -s  col      Column to sort by time/user/kernel/id/isr_c/isr_t(cputime/user time/kernel time/id/isr_count/

              isr_time). If no this parameter default will sort by cputime.

 -i  id       show isr information of thread id.

 -h           Display this help screen.

*       Example     *

cputime -e 100: Enable cputime monitor and stop after 100 seconds. Then show thread cputime, and sort by cputime.

cputime -e 200  -s user: Enable cputime monitor and stop after 200 seconds. Then show thread cputime, and sort by user time.

cputime: Show thread cputime, and sort by cputime.

cputime -p -s id: Show process cputime, and sort by process id.

 

2.3 ftrace

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

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

 

2.4 Kernel core status

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

* CPU Sched status

     adb shell cat proc/sched_debug

     Use sysrq-trigger

* CPU interrupts

     adb shell cat proc/interrupts

     adb shell cat proc/irq/irq_id/spurious

 

3. Memory Usage

Memory Usage, 我们通常会审查,系统当时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. 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  .

1. 系统运行环境

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

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

2. Java 运行环境分析

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

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

* 抓取Hprof 的手法,如:

第一种方式: 使用am 命令

    adb shell am dumpheap {Process} file

    如: 

 adb shell chmod 777 /data/anr

 adb shell am dumpheap com.android.phone /data/anr/phone.hprof

    adb pull /data/anr/phone.hprof

 

第二种方式: 使用DDMS 命令

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

 

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

    在android.os.Debug 这个class 中有定义相关的抓取hprof 的method.

 如: public static void dumpHprofData(String fileName) throws IOException;

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

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

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

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

 

第四种方式: 发送SIGUSER1 

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

 heap-dump-tm1357153307-pid1882.hprof

 

* 快速分析

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

    hprof-conv in.hprof out.hprof

其次, 使用如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 Dump 的Tools 很多, 比如traces32, GDB 等,这里就不详加说明,可以参考网络上的相关文档.

 

4. Kernel 运行环境分析

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

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

在projectConfig.mk里的MTK_SHARED_SDCARD必须为no即MTK_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/

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

1. 死机现场分析手法

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

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

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

 



 

 

2. 基本分析流程

 



 

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

 

3. Test Phone Usage

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

* 通常用于QA 发现hang 机时,或者让客户进行初步的确认。

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

 

* Touch Panel

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

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

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

 

* Power Key/ Volumn Up/Down Key

   - 是否可以点亮,关闭屏幕(注意最好关灯测试,不然背光可能观测不到)

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

 

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

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

 

* SystemUI & Status Bar

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

 

* LockScreen & Call MT Phone

   - 测试LockScreen 是否可以解锁,

   - 测试modem 是否已经关闭

   - 可进入电话界面,说明是lockscreen 无法解锁的情况

   

* Home Key/ Back Key/Search Key

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

 

* 插入USB 观察充电情况

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

 

4. USB/ADB Debug Hang

 

整体的分析流程如下图.

 



 

 

4.1 USB/ADB Debug 准备

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

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

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

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

 

* 正常的ADB 连接情况如下图



* 正常adb devices 查看结果如下图



4.2 USB/ADB 连接分析

 

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

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

 

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

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

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

 

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

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

- PC adb 版本过低

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

 

* Case4:  RSA 指纹认证无法通过

- 需要手机确认PC  RSA 指纹

 

4.3 机器状态基本检测

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

  -t  以线程为单位打印

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

 

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

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

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

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

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

 

 

* df

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

 

* cat proc/meminfo, procrank

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

 

* getprop 

- 审查当前system properties 情况

 

* top -t -m 5 -n 2

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

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

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

 



 

4.4 确认hang机的module

 

我们又回到了最开始的可能影响hang 的那些modules, 下面我们将针对每一个module 做详细的说明.

 

4.4.1 Input Driver-Input System

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

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

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

C:\Users\mtk71029\Desktop>adb shell getevent

add device 1: /dev/input/event0

  name:     "mtk-kpd"

could not get driver version for /dev/input/mouse0, Not a typewriter

add device 2: /dev/input/event3

  name:     "mtk-tpd"

add device 3: /dev/input/event2

  name:     "hwmdata"

add device 4: /dev/input/event1

  name:     "ACCDET"

could not get driver version for /dev/input/mice, Not a typewriter

 

对应的操作命令是:

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 可以看到相关的行为.

C:\Users\mtk71029\Desktop>adb shell 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 以及模拟按键是否正常

C:\Users\mtk71029\Desktop>adb shell 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 工程师来分析.

 

4.4.2 system-server logic

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

 

System server 是整个android 上层的中枢,容纳了最为重要的居多service。

 

对System server 的审查主要是通过java native 的backtrace 来追查System server 的关键thread 有没有被lock/dead lock,有没有进入dead loop,状态是否正常。

 

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

(1). JB 以及JB 以前的版本

Serverthread:

System-server 的main 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, 机器死机就成必然.

 

(2). KK 以及KK 以后的版本

Google 取消了serverthread 这样的main looper thread, 直接使用system server 的第一个thread 作为main looper.  原本第一个thread 是加入binder thread pool, 作为binder thread 使用.

Google 对system server 的threads 做了进一步的整合,以减少繁杂的线程数,  新增了如android.io,android.ui,android.fg,android.bg 等threads. 将大量的普通型的Handler 按时效分类分散到上面的4个threads 中.

所以KK 上除追查JB 上同样的thread(server thread 除外), 还需要审查android.io, android.ui, android.fg, android.bg 等thread.

 

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

Java:

  at android.os.MessageQueue.nativePollOnce(Native Method)

  at android.os.MessageQueue.next(MessageQueue.java:138)

  at android.os.Looper.loop(Looper.java:150)

 

Native:

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

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

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

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

 

一旦不是就要给出所以然来.

 

Binder Thread

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

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

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

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

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

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

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

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

  #05  pc 00021a79  /system/lib/libbinder.so

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

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

  #08  pc 0000e533  /system/lib/libutils.so

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

  at dalvik.system.NativeStart.run(Native Method)

 

抓取system server 的java backtrace,依次check serverthread(JB), ActivityManager, WindowManager, WindowManagerPolicy, PowerManagerService 以及android.io, android.bg, android.fg, android.ui的状态,如状态异常,则依次推导。

当发现java backtrace 最后钻入到异常native method时,抓取其native backtace,通过native backtrace 进一步追查。

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

 

Case 1: Abnormal Java Backtrace “Deadlock”

图片deadlock-java-backtrace.png



 

Case 2: Abnormal Java Backtrace “Lock in native thread"

图片lock-in-native-thread.png



 

Case 3: Abnormal native Backtrace “Lock in Binder”

图片lock-in-binder.png



 

Case 4: Abnormal native Backtrace "Lock in Binder thread"

图片lock-in-binder-thread.png



 

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

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

 

Input Reader 正常的backtrace:

"InputReader" sysTid=611

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

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

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

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

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

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

#06 pc 00014948 /system/lib/libutils.so

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

 

Input Dispatcher 正常的backtrace:

"InputDispatcher" sysTid=610

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

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

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

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

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

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

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

#07 pc 00014948 /system/lib/libutils.so

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

 

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

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

--- Native Backtrace 处于R 状态

--- Java Backtrace 处于 Suspend 状态, Running 状态

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

--- Double Backtrace 确认是否CPU 有运转

 

随着android 版本的推进,system-server 越来越显得庞大,为此Google 对system-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 signal SIGQUIT(3), 将导致对应的process 直接退出

 

4.4.3 Display logic

Display Control Flow

图片: display-control-flow.png

 



 

* Surface Manager(Surfaceflinger)

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

** 当系统同时执行多个应用程序时,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 模型的MTK Framebuffer 实作,主要来管理frame buffer。

 

*DDP(Display Data Path)

** MTK Display Hardware Controller,包括OVL, DMA, Color Processor,BLS,  DSI/DBI/DPI Controller

 

Display Data Flow

图片: display-data-flow.jpg



 

 

* 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 合成的图层,设定到OVL 的HW Register,并trigger HW Engine

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

 

 

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

* 确认FrameBuffer 数据和理想数据一致, 那么说明android 上层的处理行为都是正常的, 而问题就很可能出在LCM 的driver 或者 LCM 本身问题, 此时需要联系LCM 的driver 工程师以及 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 的执行情况. binder thread 和 system server 情况一致, 不再详细说明. Event Loop 在JB 以及, JB 以及KK 上都不相同, 这里分别说明.

 

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

图片: surfaceflinger-event-loop-beforce-jb.png



 

在JB 版本, SurfaceFlinger 的Event Loop 换成了Message Queue-Looper, 对应的backtrace 是:

图片: surfaceflinger-event-loop-jb.png



 

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

图片: surfaceflinger-event-loop-kk.png



 

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

 

4.5 hang module 内部分析 

当您确认了对应的module 后,通常需要拉module owner 来一起cowork.

Module owner 可能有一些独门秘籍来确认module state。通常情况下,我们可以通过dump coredump/heap dump 的方式来确认每一个module state 的state.

对于java process, 通过hprof-MAT 分析java heap 的情况进行确认.

对于native process, 通过dump coredump gdb-trace32 分析process state.

如果module 已经深入kernel 那么就必须依赖uart/kdb 来协助, 目前KDump 在客户版本中没有开启。

 

5. UART/KDB Debug

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

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

ENG 版本默认开启,User 版本默认关闭,参考相关FAQ。

在hang 机时,所有利用Uart Console 输入 的命令,务必都带 &, 转入background 运行。

原则上在adb shell 中能够输入的命令,除无法adb 特有的pull/push 命令,在UART 中一样都能够输入。

如果客户是ENG 版本,默认已经开启了KDB, 同时按住volumn UP + Down 15s 即可进入

图片: enter-kdb.png



 

常见的debug 命令和手法有:

*追查每一个process 的kernel backtrace

** ps; btp <pid> ;  bta ;  btc;

*追查或者更新memory

** md

** mm

*追查更新register

** rd

** rm

* 设置breakproint 进行debug 确认

6. JTAG Debug

如果uart 都无法吐出任何的资讯,此时可能机器HW & BUS 都有完全卡住,需要利用JTAG/CVD 来进行深入的Debug.

常见的分析有:

* 进程状态以及 Backtrace.

* MMU & CPU register.

* Mmeory 数据以及状态变化情况.

通常不到万不得已,一般不会使用JTAG/Debug 来分析。让客户接JTAG,并到我司来debug, 代价太大。

当问题涉及到HW 时,就需要大量的owner 进来一起分析,目前还没有成熟的套路来处理。

 

1. 无场景猜测与分析

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

* 已经重启过的手机

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

  

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

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

  

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

 

2. 死机资讯的完整纪录

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

* 发现hang 机的时间

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

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

 

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

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

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

--- 复现流程的视频

 

* 复现手机情况

--- 复现的软件版本: 版本号? USER/ENG Build ?

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

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

 

*复现的概率

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

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

 

其中hang 机的时间点至关重要, 需要现场的工程师一定要比较精确的纪录。 如果测试工程师提一大堆LOG, 有时可能超过1G, 然后说死机, 让你看, 有的时候真的可能会使得你吐血。 特别是有一些死机情况,普通的mobile log 无法纪录到的话,你可能分析了大半天,把LOG 看完,发现一无所获。

 

3. Hang 机Log 分析

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

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

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

* Log 中通常没有明确的字眼说明已经卡住,如果RD 自己知道已经这样的情况,那就不是问题了。只能结合多方面的情况来做整体的推理分析。

 

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

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

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

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

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

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

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

 

3.1 按Power Key 分析案例.

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

* KPD receives Interrupt and generate Power Key

图片: power-key-1.png



* System server receives Key and call set_screen_state

图片: power-key-2.png



* Power State Update:  request_suspend_state

图片: power-key-3.png



* Set screen on:  mt65xx_leds_set_cust

图片: power-key-4.png



 

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

 

3.2 Hang 机Log 分析, trace 辅助

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

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

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

1. 死机资讯抓取

 

通常情况下,依靠Log 可以找到对应的root module,  但无法找出root cause. 需要依赖更多的信息来debug 确认,所以针对这种情况,我们需要让客户抓出更多的信息来分析。

 

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

@echo "Pull important information from 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 for surfaceflinger"

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/mobilelog mtklog/data_mobilelog

 

@echo "attach NE core"

adb pull /data/core mtklog/data_core

 

@echo "attach tombstones"

adb pull /data/tombstones mtklog/tombstones

 

@echo “attach phone state”

adb shell ps -t> mtklog/ps.txt

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

adb shell service list  >  mtklog/serviceList.txt

adb shell cat /proc/meminfo > mtklog/meminfo

adb shell cat /proc/buddyinfo > mtklog/buddyinfo

adb shell procrank > mtklog/procrank.txt

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

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

adb shell dumpstate > mtklog/dumpstate.txt

@echo "finish."

pause

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

%Writed by Yanghui Li%

adb devices

@echo "抓出sdcard/mtklog"

adb pull /sdcard/mtklog mtklog/

 

@echo “抓出sdcard2/mtklog”

adb pull /sdcard2/mtklog mtklog/sdcard2

 

@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

 

1. 死机还是重启

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

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

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

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

 

2. 死机如何转换成重启

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

 

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

 

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

当然并非所有的死机问题都能转换成重启, 下面我就对一些常见的cases 说明。

 

3. 死机VS重启

HW Hang                           [maybe]

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

SoftIRQ run long time             [Reboot]

Preempt Disable long time         [Reboot]

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

Kernel Module Hang                [maybe]

---- Not block watchdog thread reboot.

Native Module Hang                [maybe]

---- Not block watchdog thread reboot.

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

Display subsystem Hang            [Hang]

LCM Hang                          [Hang]

Input Driver Fail                 [Hang]

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

WindowManagerPolicy Hang          [Maybe]

---- Need check the serverthread state

System server deadlock            [Reboot]

System server logic abnormal      [Maybe]

Surfaceflinger logic abnormal     [Maybe]

1. 案例1 ICS 版本输入法界面拖动死机.

1.1 现象

–.进入输入法编辑界面;

–.输入文字,选中输入的文字内容;3.长按发出振动并拖动文字到输入法任意位置滑动,然后出现死机现象,需要拔电池才能重启手机。(讯飞输入法和谷歌输入法都高概率出现)

 

1.2 现象初步分析

–从/data/anr 中可看到full trace 信息,说明是system server watchdog 卡住

–按power key 可开启-关闭屏幕,说明kernel 实际正常,并且WindowManagerPolicy-SurfaceFlinger 正常

–尝试连接adb,可正常连接。

 

1.3 Java Trace 分析

- Watchdog 最为关心的就是system server 的ServerThread.

- 阅读ServerThread 是否被卡住,然后根据依赖关系抓出凶手。

- 如果ServerThread 正常,再阅读WindowManager, WindowManagerPolicy, ActivityManager, PowerManager 等关键thread 是否运行正常。

参考下图:



 

 

1.4 Native Trace 分析

- 当追查Java backtrace 进入Native code 时,就需要native trace 分析。

- Java Trace 和 Native Trace 的结合部位,关键在于Java Trace 上的sysTid, 两者的sysTid 是标准的linux tid. 而Java Trace 上的tid=xxx, 是在DVM 中分配的tid, 在Native Trace 中不在存在。 

- 当然您也可以根据两者方法的调用关系来追查,不过如果对该领域不熟悉时,可能产生错误的匹配。

参考下图:



 

- 结合代码来猜测卡住哪里,死循环while, for…; lock mutex….. 或者加LOG 确认.

- 一般稍微标准的代码,lock, mutex 之类不会随意使用。可review 代码, 然后加上当前的trace 分析。查看trace 中是否有拿着lock 在干其他事情的thread, 抓出来, 如下图:



 

  前一页对应的source code. android_view_InputQueue.cpp, 如下图:



 

 

1.5 Input领域分析

- 通过一路的trace 分析,此时我们已经知道ServerThread 最终卡在哪里了。即因为lock 的依赖关系卡在了WindowManager 的event consume 中。因为sem_wait 涉及到semaphore 的处理,从trace 中将比较难以分析。

- 再次阅读LOG,是否可以从LOG 发现更加有价值的线索。打开相应领域的LOG 开关,获取更多的信息, 对于重点地方加入相关LOG,厘清流程, 把异常流程和正常流程比较,寻找关键点。

如下图:



- 关键LOG 对比分析,如下图:



 

- 从LOG 对比来看,中途插入了一个event 的reset 动作,这个动作会使得message 中的semaphore 被清零,从而导致sem_wait 一直被卡住。

如下图:


- 值得说明的是,在我们PC 上进行sem_destroy 测试,并不会使得sem_wait 卡住,而在android 会附带有清零的动作。

- 为什么有这种情况发生。既然已经请求unregister input channel, 为何此时还会有event 发生呢。Window / Input Manager 的逻辑控制上还有同步问题,应当是迟发了一个event.

- Input 中代码兼容性问题,既然您把sem 都已经destory 了,也把event message 给destory 了,就意味者这个event 已经不能够再被consume 了。更多的逻辑分析这里不再一一深入撰写了,有兴趣者可以研读代码。

 

1.6 问题解法

- 修正Window / input Manager 的同步问题,改动比较大,有一定的风险性。

- 提高InputTransport 中的兼容性,简单易操作,不会有side-effect.

修改方法如下图:



 
内容来自用户分享和网络整理,不保证内容的准确性,如有侵权内容,可联系管理员处理 点击这里给我发消息
标签: