Android应用ANR分析
2017-02-14 本文已影响9636人
silentleaf
一.ANR是什么
Application Not Responding，字面意思就是应用无响应，稍加解释就是用户的一些操作无法从应用中获取反馈。在实际的应用中应当去避免这种现象，虽然他暂时不会造成应用崩溃，但是却极大的损坏了用户体验。
二.ANR的触发原因
出现ANR之后一个直观现象就是系统会展示出一个ANR对话框，大概是这样。
谷歌文档中对ANR产生的原因是这么描述的：
- Android系统中的应用被Activity Manager及Window Manager两个系统服务监控着，Android系统会在如下两种情况展示出ANR的对话框
- 5秒内无法对输入事件（按键及触摸）做出响应
广播接收器无法在10秒内结束运行
因此如何避免上面两种情况的发生就是解决ANR问题的方向
三.ANR时系统做了什么
这里暂时不去从源码上追究为什么出现上面两种情况就会导致ANR，是不是只有这两种情况才会导致ANR，这部分在后续有时间的时候再回来补充，我们先来看看ANR时系统做了什么然后从源码分析为什么会做这些事情，知道他做了什么，对我们分析ANR是很有帮助的。
1.弹出一个丑陋无比的对话框
哪怕你的应用有多帅，比如这样
我相信这个对话框大家都看过，就不做叙述了
2.将ANR信息输出到traces.txt文件中
traces.txt文件是一个ANR记录文件，用于开发人员调试，目录位于/data/anr中，无需root权限即可通过pull命令获取，下面的命令可以将traces.txt文件拷贝到当前目录下
adb pull /data/anr .
这部分的内容可能以前没接触过ANR的同学已经不太清楚了，第四部分会对如何分析这个文件做详细描述。
3.将ANR信息输出到Logcat中
这部分的信息如果不注意是很难发现的，截图的内容只是其中输出的一部分，简要解释一下这些内容的含义
1) ANR in xxx，PID: xxx，Reason：xxx
这里简要叙述了出现ANR的应用以及进程号，比如上面的截图，ANR发生在androitest应用中，对应的进程号是7650，后续还给出了出现ANR的原因，当然这种原因并不能帮我们直接发现问题根源
一般来说原因有两类，分别对应于InputDispatcher.cpp文件的两段代码，InputDispatcher是派发事件过程中的一个中转类，每次派发事件时他会进行如下判断
a) 判断是否有focused组件以及focusedApplication
这种一般是在应用启动时触发，比如启动时间过长在这过程中触发了keyevent或者trackball moteionevent就会出现
这种情况下，对应的Reason类似于这样
Reason: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
我们Monkey脚本中出现的ANR问题绝大部分都是属于这种问题，实际上出现这种ANR之前我们应用一般发生了崩溃需要重启，但是重启进行的操作比较耗时，但是具体并不清楚耗时的地方。
b) 判断前面的事件是否及时完成
这里的事件包含keyevent和touchevent，虽然它们对允许的延时要求不一样，但最终都会执行到如下代码
这种情况下，对应的Reason类似于这样
Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 10. Wait queue head age: 5591.3ms.)
出现这种问题意味着主线程正在执行其他的事件但是比较耗时导致输入事件无法及时处理。
2) Load: 12.43/5.25/1.97
这里输出了CPU的负载情况
CPU负载是指某一时刻系统中运行队列长度之和加上当前正在CPU上运行的进程数，而CPU平均负载可以理解为一段时间内正在使用和等待使用CPU的活动进程的平均数量。在Linux中“活动进程”是指当前状态为运行或不可中断阻塞的进程。通常所说的负载其实就是指平均负载。
用一个从网上看到的很生动的例子来说明（不考虑CPU时间片的限制），把设备中的一个单核CPU比作一个电话亭，把进程比作正在使用和等待使用电话的人，假如有一个人正在打电话，有三个人在排队等待，此刻电话亭的负载就是4。使用中会不断的有人打完电话离开，也会不断的有其他人排队等待，为了得到一个有参考价值的负载值，可以规定每隔5秒记录一下电话亭的负载，并将某一时刻之前的一分钟、五分钟、十五分钟的的负载情况分别求平均值，最终就得到了三个时段的平均负载。
实际上我们通常关心的就是在某一时刻的前一分钟、五分钟、十五分钟的CPU平均负载，例如以上日志中这三个值分别是12.43,5.25,1.97，说明前一分钟内正在使用和等待使用CPU的活动进程平均有12.43个，依此类推。在大型服务器端应用中主要关注的是第五分钟和第十五分钟的两个值，但是Android主要应用在便携手持设备中，有特殊的软硬件环境和应用场景，短时间内的系统的较高负载就有可能造成ANR，所以我认为一分钟内的平均负载相对来说更具有参考价值。
CPU的负载和使用率没有必然关系，有可能只有一个进程在使用CPU，但执行的是复杂的操作；也有可能等待和正在使用CPU的进程很多，但每个进程执行的都是简单操作。
实际处理问题时偶尔会遇到由于平均负载高引起的ANR，典型的特征就是系统中应用进程数量多，CPU总使用率较高，但是每个进程的CPU使用率不高，当前应用进程主线程没有异常阻塞，一分钟内的CPU平均负载较高。
3) CPU usage xxx
CPU usage from 75634ms to 0ms ago:
25% 869/system_server: 19% user + 6.1% kernel / faults: 86246 minor
...
CPU usage from 601ms to 1132ms later with 99% awake
...
这里会分两段打印出出现ANR前后CPU的使用率情况，每一段包含了所有进程的CPU使用率，如果说某个进程在ANR发生时CPU使用率出现很高的情况，那么就可以知道这个进程在做非常消耗CPU的事情，一般这种情况下这个进程就是ANR进程，而消耗CPU的这个事情往往就是导致ANR的根源。
4.源码分析
最后来看看做出上述反应的源代码，这部分代码位于ActivityManagerService类中
final void appNotResponding(ProcessRecord app, ActivityRecord activity,
ActivityRecord parent, boolean aboveSystem, final String annotation) {
ArrayList<Integer> firstPids = new ArrayList<Integer>(5);
SparseArray<Boolean> lastPids = new SparseArray<Boolean>(20);
// mController是IActivityController接口的实例，是为Monkey测试程序预留的，默认为null
if (mController != null) {
try {
// 0 == continue, -1 = kill process immediately
int res = mController.appEarlyNotResponding(app.processName, app.pid, annotation);
if (res < 0 && app.pid != MY_PID) {
app.kill("anr", true);
}
} catch (RemoteException e) {
mController = null;
Watchdog.getInstance().setActivityController(null);
}
}
// 更新CPU状态信息
long anrTime = SystemClock.uptimeMillis();
if (MONITOR_CPU_USAGE) {
updateCpuStatsNow();
}
synchronized (this) {
// 某些特定情况下忽略本次ANR，比如系统关机，比如该进程已经处于anr状态或者crash状态
if (mShuttingDown) {
Slog.i(TAG, "During shutdown skipping ANR: " + app + " " + annotation);
return;
} else if (app.notResponding) {
Slog.i(TAG, "Skipping duplicate ANR: " + app + " " + annotation);
return;
} else if (app.crashing) {
Slog.i(TAG, "Crashing app skipping ANR: " + app + " " + annotation);
return;
}
// 为了防止多次对相同app的anr执行重复代码，在此处标注记录，属于上面的特定情况种的一种
app.notResponding = true;
// 记录ANR信息到Event Log中
EventLog.writeEvent(EventLogTags.AM_ANR, app.userId, app.pid,
app.processName, app.info.flags, annotation);
// 添加当前app到firstpids列表中
firstPids.add(app.pid);
// 如果可能添加父进程到firstpids列表种
int parentPid = app.pid;
if (parent != null && parent.app != null && parent.app.pid > 0) parentPid = parent.app.pid;
if (parentPid != app.pid) firstPids.add(parentPid);
if (MY_PID != app.pid && MY_PID != parentPid) firstPids.add(MY_PID);
// 添加所有进程到firstpids中
for (int i = mLruProcesses.size() - 1; i >= 0; i--) {
ProcessRecord r = mLruProcesses.get(i);
if (r != null && r.thread != null) {
int pid = r.pid;
if (pid > 0 && pid != app.pid && pid != parentPid && pid != MY_PID) {
if (r.persistent) {
firstPids.add(pid);
} else {
lastPids.put(pid, Boolean.TRUE);
}
}
}
}
}
// 将ANR信息存在info变量中，后续打印到LOGCAT，这部分的信息会以ActivityManager为Tag打印出来，包含了ANR的进程，出现原因以及当时的CPU状态，这些对分析ANR是非常重要的信息
StringBuilder info = new StringBuilder();
info.setLength(0);
info.append("ANR in ").append(app.processName);
if (activity != null && activity.shortComponentName != null) {
info.append(" (").append(activity.shortComponentName).append(")");
}
info.append("\n");
info.append("PID: ").append(app.pid).append("\n");
if (annotation != null) {
info.append("Reason: ").append(annotation).append("\n");
}
if (parent != null && parent != activity) {
info.append("Parent: ").append(parent.shortComponentName).append("\n");
}
final ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);
// 将ANR信息输出到traces文件
File tracesFile = dumpStackTraces(true, firstPids, processCpuTracker, lastPids,
NATIVE_STACKS_OF_INTEREST);
String cpuInfo = null;
if (MONITOR_CPU_USAGE) {
updateCpuStatsNow();
synchronized (mProcessCpuTracker) {
cpuInfo = mProcessCpuTracker.printCurrentState(anrTime);
}
info.append(processCpuTracker.printCurrentLoad());
info.append(cpuInfo);
}
info.append(processCpuTracker.printCurrentState(anrTime));
// 输出到logcat的语句
Slog.e(TAG, info.toString());
// 如果traces文件未创建，则只记录当前进程trace并且发送QUIT信号到进程
if (tracesFile == null) {
// There is no trace file, so dump (only) the alleged culprit's threads to the log
Process.sendSignal(app.pid, Process.SIGNAL_QUIT);
}
// 将ANR信息处处到DropBox目录下，也就是说除了traces文件还会有一个dropbox文件用于记录ANR
addErrorToDropBox("anr", app, app.processName, activity, parent, annotation,
cpuInfo, tracesFile, null);
//...
synchronized (this) {
mBatteryStatsService.noteProcessAnr(app.processName, app.uid);
if (!showBackground && !app.isInterestingToUserLocked() && app.pid != MY_PID) {
app.kill("bg anr", true);
return;
}
// Set the app's notResponding state, and look up the errorReportReceiver
makeAppNotRespondingLocked(app,
activity != null ? activity.shortComponentName : null,
annotation != null ? "ANR " + annotation : "ANR",
info.toString());
// 发送SHOW_NOT_RESPONDING_MSG，准备显示ANR对话框
Message msg = Message.obtain();
HashMap<String, Object> map = new HashMap<String, Object>();
msg.what = SHOW_NOT_RESPONDING_MSG;
msg.obj = map;
msg.arg1 = aboveSystem ? 1 : 0;
map.put("app", app);
if (activity != null) {
map.put("activity", activity);
}
mUiHandler.sendMessage(msg);
}
}
四.ANR的分析方法
由上面对ANR源码的分析可以看出来，我们ANR可以生成traces.txt以及DropBox目录下的ANR历史纪录，因此可以考虑阅读该文件来分析，除此之外我们还有DDMS帮助我们分析ANR，这两种方式实际上是大同小异的，只是应用的场景不同。在讲ANR分析之前，我会先说Java应用的分析
1.Java线程调用分析方法
为什么要在讲Android的ANR分析方法之前提到Java的分析方法呢，因为需要在解释ANR之前稍微介绍一下线程状态的概念，以便后面做叙述，同时也可以更方便的带入分析的方法。JDK中有一个关键命令可以帮助我们分析和调试Java应用——jstack，命令的使用方法是
jstack {pid}
其中pid可以通过jps命令获得，jps命令会列出当前系统中运行的所有Java虚拟机进程，比如这样
wangchen15:~ wangchen$ jps
7249
7266 Test
7267 Jps
上面的命令可以发现系统中目前有7266和7267两个Java虚拟机进程，此时如果我想知道当前Test进程的情况，就可以通过jstack命令来查看，jstack命令的输出结果很简单，它会打印出该进程中所有线程的状态以及调用关系，甚至会给出一些简单的分析结果
wangchen15:~ wangchen$ jstack 7266
2016-06-20 14:01:54
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.71-b01 mixed mode):
"Attach Listener" daemon prio=5 tid=0x00007fde7385d800 nid=0x3507 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"DestroyJavaVM" prio=5 tid=0x00007fde73873000 nid=0x1303 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Thread-1" prio=5 tid=0x00007fde73872800 nid=0x4a03 waiting for monitor entry [0x000000011cb30000]
java.lang.Thread.State: BLOCKED (on object monitor)
at Test.rightLeft(Test.java:48)
- waiting to lock <0x00000007d56540a0> (a Test$LeftObject)
- locked <0x00000007d5656180> (a Test$RightObject)
at Test$2.run(Test.java:68)
at java.lang.Thread.run(Thread.java:745)
"Thread-0" prio=5 tid=0x00007fde73871800 nid=0x4803 waiting for monitor entry [0x000000011ca2d000]
java.lang.Thread.State: BLOCKED (on object monitor)
at Test.leftRight(Test.java:34)
- waiting to lock <0x00000007d5656180> (a Test$RightObject)
- locked <0x00000007d56540a0> (a Test$LeftObject)
at Test$1.run(Test.java:60)
at java.lang.Thread.run(Thread.java:745)
"Service Thread" daemon prio=5 tid=0x00007fde73821000 nid=0x4403 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" daemon prio=5 tid=0x00007fde73035000 nid=0x4203 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" daemon prio=5 tid=0x00007fde7381e000 nid=0x4003 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=5 tid=0x00007fde7481d800 nid=0x300f runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=5 tid=0x00007fde73010000 nid=0x2d03 in Object.wait() [0x000000011aacb000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007d55047f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
- locked <0x00000007d55047f8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
"Reference Handler" daemon prio=5 tid=0x00007fde7300f000 nid=0x2b03 in Object.wait() [0x000000011a9c8000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007d5504410> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
- locked <0x00000007d5504410> (a java.lang.ref.Reference$Lock)
"VM Thread" prio=5 tid=0x00007fde7300c800 nid=0x2903 runnable
"GC task thread#0 (ParallelGC)" prio=5 tid=0x00007fde74000800 nid=0x2103 runnable
"GC task thread#1 (ParallelGC)" prio=5 tid=0x00007fde7400c000 nid=0x2303 runnable
"GC task thread#2 (ParallelGC)" prio=5 tid=0x00007fde7400c800 nid=0x2503 runnable
"GC task thread#3 (ParallelGC)" prio=5 tid=0x00007fde7400d000 nid=0x2703 runnable
"VM Periodic Task Thread" prio=5 tid=0x00007fde7481e000 nid=0x4603 waiting on condition
JNI global references: 110
Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x00007fde73818ab8 (object 0x00000007d56540a0, a Test$LeftObject),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x00007fde73819f58 (object 0x00000007d5656180, a Test$RightObject),
which is held by "Thread-1"
Java stack information for the threads listed above:
===================================================
"Thread-1":
at Test.rightLeft(Test.java:48)
- waiting to lock <0x00000007d56540a0> (a Test$LeftObject)
- locked <0x00000007d5656180> (a Test$RightObject)
at Test$2.run(Test.java:68)
at java.lang.Thread.run(Thread.java:745)
"Thread-0":
at Test.leftRight(Test.java:34)
- waiting to lock <0x00000007d5656180> (a Test$RightObject)
- locked <0x00000007d56540a0> (a Test$LeftObject)
at Test$1.run(Test.java:60)
at java.lang.Thread.run(Thread.java:745)
Found 1 deadlock.
1) Thread基础信息
输出种包含所有的线程，取其中的一条
"Thread-1" prio=5 tid=0x00007fde73872800 nid=0x4a03 waiting for monitor entry [0x000000011cb30000]
java.lang.Thread.State: BLOCKED (on object monitor)
at Test.rightLeft(Test.java:48)
- waiting to lock <0x00000007d56540a0> (a Test$LeftObject)
- locked <0x00000007d5656180> (a Test$RightObject)
at Test$2.run(Test.java:68)
at java.lang.Thread.run(Thread.java:745)
a) "Thread-1" prio=5 tid=0x00007fde73872800 nid=0x4a03 waiting for monitor entry [0x000000011cb30000]
首先描述了线程名是『Thread-1』，然后prio=5表示优先级，tid表示的是线程id，nid表示native层的线程id，他们的值实际都是一个地址，后续给出了对于线程状态的描述，waiting for monitor entry [0x000000011cb30000]这里表示该线程目前处于一个等待进入临界区状态，该临界区的地址是[0x000000011cb30000]
这里对线程的描述多种多样，简单解释下上面出现的几种状态
- waiting on condition（等待某个事件出现）
- waiting for monitor entry（等待进入临界区）
- runnable（正在运行）
- in Object.wait(处于等待状态)
b) java.lang.Thread.State: BLOCKED (on object monitor)
这段是描述线程状态，我们知道Java的6种线程状态定义在Thread.java中
//Thread.java
public class Thread implements Runnable {
...
public enum State {
/**
* The thread has been created, but has never been started.
*/
NEW,
/**
* The thread may be run.
*/
RUNNABLE,
/**
* The thread is blocked and waiting for a lock.
*/
BLOCKED,
/**
* The thread is waiting.
*/
WAITING,
/**
* The thread is waiting for a specified amount of time.
*/
TIMED_WAITING,
/**
* The thread has been terminated.
*/
TERMINATED
}
...
}
由此我们知道Thread-1这个线程的状态是BLOCKED，根据线程状态的描述知道它在等待一个锁
c) at xxx 调用栈
at Test.rightLeft(Test.java:48)
- waiting to lock <0x00000007d56540a0> (a Test$LeftObject)
- locked <0x00000007d5656180> (a Test$RightObject)
at Test$2.run(Test.java:68)
at java.lang.Thread.run(Thread.java:745)
这段线程的调用栈，可以看到线程在我们执行jstack命令的时候运行到Test.java的48行，而在68行到48行之间，线程对一个Test$RightObject上了锁，并且目前在等待Test$LeftObject锁
2) jstack分析信息
Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x00007fde73818ab8 (object 0x00000007d56540a0, a Test$LeftObject),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x00007fde73819f58 (object 0x00000007d5656180, a Test$RightObject),
which is held by "Thread-1"
Java stack information for the threads listed above:
===================================================
"Thread-1":
at Test.rightLeft(Test.java:48)
- waiting to lock <0x00000007d56540a0> (a Test$LeftObject)
- locked <0x00000007d5656180> (a Test$RightObject)
at Test$2.run(Test.java:68)
at java.lang.Thread.run(Thread.java:745)
"Thread-0":
at Test.leftRight(Test.java:34)
- waiting to lock <0x00000007d5656180> (a Test$RightObject)
- locked <0x00000007d56540a0> (a Test$LeftObject)
at Test$1.run(Test.java:60)
at java.lang.Thread.run(Thread.java:745)
说明中的信息很详细，它认为我们的应用出现了一个Java层的死锁，即Thread-1等待一个被Thread-0持有的锁，Thread-0等待一个被Thread-1持有的锁，实际上的确也是这样，最后再来看看源代码是不是这么回事
public class Test {
public static class LeftObject {
}
public static class RightObject {
}
private Object leftLock = new LeftObject();
private Object rightLock = new RightObject();
public void leftRight() {
synchronized (leftLock) {
try {
TimeUnit.SECONDS.sleep(3);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (rightLock) {
System.out.println("leftRight");
}
}
}
public void rightLeft() {
synchronized (rightLock) {
try {
TimeUnit.SECONDS.sleep(3);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (leftLock) {
System.out.println("leftRight");
}
}
}
public static void main(String[] args) {
final Test test = new Test();
new Thread(new Runnable() {
@Override
public void run() {
test.leftRight();
}
}).start();
new Thread(new Runnable() {
@Override
public void run() {
test.rightLeft();
}
}).start();
}
}
一目了然的故意死锁行为。。。实际的死锁可能比这个复杂，但是原理就是这样了
2.DDMS分析ANR问题
有了上面的基础，再来看看Android的ANR如何分析，Android的DDMS工具其实已经给我们提供了一个类似于jstack命令的玩意，可以很好的让我们调试的时候实时查看Android虚拟机的线程状况。
1) 使用DDMS——Update Threads工具
使用DDMS的Update Threads工具可以分为如下几步
- 选择需要查看的进程
- 点击Update Threads按钮
- 在Threads视图查看该进程的所有线程状态
选择需要查看的进程并点击更新线程按钮
查看线程状态
2) 阅读Update Threads的输出
Update Threads工具可以输出当前进程的所有线程的状态，上半部分是线程列表，选中其中一条下半部分将展现出该线程当前的调用栈
a) 线程列表
上半部分种的线程列表分为好几列，其中ID栏表示的序号，其中带有『*』标志的是守护线程，Tid是线程号，Status表示线程状态，utime表示执行用户代码的累计时间，stime表示执行系统代码的累计时间，Name表示的是线程名字。实际上utime还有stime他们具体的含义我也不是太清楚，不过这不影响我们分析问题，这里需要特别注意的是main线程啦，还有线程状态。
b) main线程
main线程就是应用主线程啦，点击上半部分线程列表选中main线程，我们可以发现，绝大多数不操作应用的情况下，调用栈应该是如下样式的
这是一个空闲等待状态，等待其他线程或者进程发送消息到主线程，再由主线程处理相应事件，具体可以看看老罗写的一篇关于Looper和Handler的文章(http://blog.csdn.net/luoshengyang/article/details/6817933) 。 如果主线程在执行过程中出现了问题，就会出现ANR，结合下面关于线程状态的分析可以知道如果主线程的状态是MONITOR一般肯定就是出现了ANR了。
c) 线程状态
我们刚刚在分心Java线程状态时明明只有6个状态，但是现在Android虚拟机给出的线程状态超出了这6个的限制，这也是需要在源码中寻找答案的,VMThread.java类中有这么一段代码
/**
* Holds a mapping from native Thread statuses to Java one. Required for
* translating back the result of getStatus().
*/
static final Thread.State[] STATE_MAP = new Thread.State[] {
Thread.State.TERMINATED, // ZOMBIE
Thread.State.RUNNABLE, // RUNNING
Thread.State.TIMED_WAITING, // TIMED_WAIT
Thread.State.BLOCKED, // MONITOR
Thread.State.WAITING, // WAIT
Thread.State.NEW, // INITIALIZING
Thread.State.NEW, // STARTING
Thread.State.RUNNABLE, // NATIVE
Thread.State.WAITING, // VMWAIT
Thread.State.RUNNABLE // SUSPENDED
};
而且，native层的Thread.cpp中还有一段代码
const char* dvmGetThreadStatusStr(ThreadStatus status)
{
switch (status) {
case THREAD_ZOMBIE: return "ZOMBIE";
case THREAD_RUNNING: return "RUNNABLE";
case THREAD_TIMED_WAIT: return "TIMED_WAIT";
case THREAD_MONITOR: return "MONITOR";
case THREAD_WAIT: return "WAIT";
case THREAD_INITIALIZING: return "INITIALIZING";
case THREAD_STARTING: return "STARTING";
case THREAD_NATIVE: return "NATIVE";
case THREAD_VMWAIT: return "VMWAIT";
case THREAD_SUSPENDED: return "SUSPENDED";
default: return "UNKNOWN";
}
}
由此我们可以看到Android虚拟机中有10种线程状态，对应于Java的6种线程状态，表格如下
Android线程状态
Java线程状态
ZOMBIE TERMINATED
RUNNABLE RUNNABLE
TIMED_WAIT TIMED_WAITING in Object.wait()
MONITOR BLOCKED（on a monitor）
WAIT WAITING
INITIALIZING NEW allocated not yet running
STARTING NEW started not yet on thread list
NATIVE RUNNABLE off in a JNI native method
VMWAIT WAITING waiting on a VM resource
SUSPENDED RUNNABLE suspended usually by GC or debugger
于是各自含义就清晰了。
3) 举个梨子
package com.example.wangchen.androitest;
import android.os.Bundle;
import android.os.Environment;
import android.support.v7.app.AppCompatActivity;
import android.util.Log;
import android.view.View;
import android.widget.Button;
import java.io.BufferedReader;
import java.io.File;
import java.io.FileReader;
import java.io.IOException;
public class MainActivity extends AppCompatActivity {
@Override
protected void onCreate(Bundle savedInstanceState) {
super.onCreate(savedInstanceState);
setContentView(R.layout.activity_main);
Button mBtn = (Button) findViewById(R.id.button);
mBtn.setOnClickListener(new View.OnClickListener() {
@Override
public void onClick(View v) {
print();
}
});
}
public void print() {
BufferedReader bufferedReader = null;
String tmp = null;
try {
bufferedReader = new BufferedReader(new FileReader(new File(Environment.getExternalStorageDirectory() + "/test")));
while ((tmp = bufferedReader.readLine()) != null) {
Log.i("wangchen", tmp);
}
} catch (IOException e) {
e.printStackTrace();
} finally {
if (bufferedReader != null) {
try {
bufferedReader.close();
} catch (IOException e) {
e.printStackTrace();
}
}
}
}
}
简单的一个Activity，点击按钮时将读取文件内容并进行打印到logcat，本身没有什么大问题，但是在该Activity的按钮被点击时却出现了未响应的情况
通过DDMS，我们查看到当前未响应时主线程一直处于如下调用状态
at android.util.Log.println_native(Native Method)
at android.util.Log.i(Log.java:173)
at com.example.wangchen.androitest.MainActivity.print(MainActivity.java:37)
at com.example.wangchen.androitest.MainActivity$1.onClick(MainActivity.java:26)
at android.view.View.performClick(View.java:4446)
at android.view.View$PerformClick.run(View.java:18480)
at android.os.Handler.handleCallback(Handler.java:733)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5314)
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:864)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:680)
at dalvik.system.NativeStart.main(Native Method)
由上面对主线程的分析可以知道，正常情况下主线程应当是处于空闲等待状态，如果长时间处于处理某一个任务时就会导致其他被发送到主线程的事件无法被及时处理，导致ANR，实际上这里的test文件有30M，完全打印是非常耗时的，导致ANR也就理所当然了，所以对于文件读写操作还是建议在非主线程操作。
3.traces文件分析ANR问题
我们在开发调试过程中遇到ANR问题大多是可以通过DDMS方法来分析问题原因的，但是所有的ANR问题不一定会在开发阶段出现，如果在测试或者发版之后出现了ANR问题，那么就需要通过traces文件来分析。根据之前的分析我们知道，traces文件位于/data/anr目录下，即便是没有root的手机也是可以通过adb命令将该文件pull出来，一个traces文件中包含了出现ANR时当前系统的所有活动进程的情况，其中每一个进程会包含所有线程的情况，因此文件的内容量往往比较大。但是一般造成ANR的进程会被记录在头一段，因此尽可能详细的分析头一段进程是解析traces文件的重要方法。
1) 文件内容解析
在traces文件中我们会看到很多段类似于如下文本的内容，其中每一段是一个进程，N段表示N个进程，共同描述了出现ANR时系统进程的状况
----- pid 4280 at 2016-05-30 00:17:13 -----
Cmd line: com.quicinc.cne.CNEService
Build fingerprint: 'Xiaomi/virgo/virgo:6.0.1/MMB29M/6.3.21:user/release-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=4124 post zygote classes=18
Intern table: 51434 strong; 17 weak
JNI: CheckJNI is off; globals=286 (plus 277 weak)
Libraries: /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libmiuinative.so /system/lib/libsechook.so /system/lib/libwebviewchromium_loader.so libjavacore.so (9)
Heap: 50% free, 16MB/33MB; 33690 objects
Dumping cumulative Gc timings
Total number of allocations 33690
Total bytes allocated 16MB
Total bytes freed 0B
Free memory 16MB
Free memory until GC 16MB
Free memory until OOME 111MB
Total memory 33MB
Max memory 128MB
Zygote space size 1624KB
Total mutator paused time: 0
Total time waiting for GC to complete: 0
Total GC count: 0
Total GC time: 0
Total blocking GC count: 0
Total blocking GC time: 0
suspend all histogram: Sum: 102us 99% C.I. 3us-25us Avg: 8.500us Max: 25us
DALVIK THREADS (10):
"Signal Catcher" daemon prio=5 tid=2 Runnable
| group="system" sCount=0 dsCount=0 obj=0x12c470a0 self=0xaeb8b000
| sysTid=4319 nice=0 cgrp=default sched=0/0 handle=0xb424f930
| state=R schedstat=( 111053493 34114006 33 ) utm=6 stm=5 core=0 HZ=100
| stack=0xb4153000-0xb4155000 stackSize=1014KB
| held mutexes= "mutator lock"(shared held)
native: #00 pc 00370e89 /system/lib/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, char const*, art::ArtMethod*, void*)+160)
native: #01 pc 003504f7 /system/lib/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&) const+150)
native: #02 pc 0035a3fb /system/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+442)
native: #03 pc 0035afb9 /system/lib/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+212)
native: #04 pc 0035b4e7 /system/lib/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+142)
native: #05 pc 0035bbf7 /system/lib/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+334)
native: #06 pc 00333d3f /system/lib/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+74)
native: #07 pc 0033b0a5 /system/lib/libart.so (art::SignalCatcher::HandleSigQuit()+928)
native: #08 pc 0033b989 /system/lib/libart.so (art::SignalCatcher::Run(void*)+340)
native: #09 pc 0003f54f /system/lib/libc.so (__pthread_start(void*)+30)
native: #10 pc 00019c2f /system/lib/libc.so (__start_thread+6)
(no managed stack frames)
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 obj=0x7541b3c0 self=0xb4cf6500
| sysTid=4280 nice=-1 cgrp=default sched=0/0 handle=0xb6f5cb34
| state=S schedstat=( 52155108 81807757 159 ) utm=2 stm=3 core=0 HZ=100
| stack=0xbe121000-0xbe123000 stackSize=8MB
| held mutexes=
native: #00 pc 00040984 /system/lib/libc.so (__epoll_pwait+20)
native: #01 pc 00019f5b /system/lib/libc.so (epoll_pwait+26)
native: #02 pc 00019f69 /system/lib/libc.so (epoll_wait+6)
native: #03 pc 00012c57 /system/lib/libutils.so (android::Looper::pollInner(int)+102)
native: #04 pc 00012ed3 /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+130)
native: #05 pc 00082bed /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, _jobject*, int)+22)
native: #06 pc 0000055d /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+96)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:323)
at android.os.Looper.loop(Looper.java:135)
at android.app.ActivityThread.main(ActivityThread.java:5435)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:735)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:625)
// ...
----- end 4280 -----
a) 进程头部信息
----- pid 4280 at 2016-05-30 00:17:13 -----
Cmd line: com.quicinc.cne.CNEService
这里记录了出现ANR时该进程的pid号以及当前时间，进程名是com.quicinc.cne.CNEService
b) 进程资源状态信息
Build fingerprint: 'Xiaomi/virgo/virgo:6.0.1/MMB29M/6.3.21:user/release-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=4124 post zygote classes=18
Intern table: 51434 strong; 17 weak
JNI: CheckJNI is off; globals=286 (plus 277 weak)
Libraries: /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libmiuinative.so /system/lib/libsechook.so /system/lib/libwebviewchromium_loader.so libjavacore.so (9)
Heap: 50% free, 16MB/33MB; 33690 objects
Dumping cumulative Gc timings
Total number of allocations 33690
Total bytes allocated 16MB
Total bytes freed 0B
Free memory 16MB
Free memory until GC 16MB
Free memory until OOME 111MB
Total memory 33MB
Max memory 128MB
Zygote space size 1624KB
Total mutator paused time: 0
Total time waiting for GC to complete: 0
Total GC count: 0
Total GC time: 0
Total blocking GC count: 0
Total blocking GC time: 0
这里打印了一大段关于硬件状态的信息，虽然目前我还没用到这里的信息，不过我觉得在某些时候这里的数据是会有作用的
c) 每条线程的信息
"main" prio=5 tid=1 Native // 输出了线程名，优先级，线程号，线程状态，带有『deamon』字样的线程表示守护线程，即DDMS中『*』线程
| group="main" sCount=1 dsCount=0 obj=0x7541b3c0 self=0xb4cf6500 // 输出了线程组名，sCount被挂起次数，dsCount被调试器挂起次数，obj表示线程对象的地址，self表示线程本身的地址
| sysTid=4280 nice=-1 cgrp=default sched=0/0 handle=0xb6f5cb34 // sysTid是Linux下的内核线程id，nice是线程的调度优先级，sched分别标志了线程的调度策略和优先级，cgrp是调度属组，handle是线程的处理函数地址。
| state=S schedstat=( 52155108 81807757 159 ) utm=2 stm=3 core=0 HZ=100 // state是调度状态；schedstat从 /proc/[pid]/task/[tid]/schedstat读出，三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度，有的android内核版本不支持这项信息，得到的三个值都是0；utm是线程用户态下使用的时间值(单位是jiffies）;stm是内核态下的调度时间值；core是最后执行这个线程的cpu核的序号。
| stack=0xbe121000-0xbe123000 stackSize=8MB
| held mutexes=
native: #00 pc 00040984 /system/lib/libc.so (__epoll_pwait+20)
native: #01 pc 00019f5b /system/lib/libc.so (epoll_pwait+26)
native: #02 pc 00019f69 /system/lib/libc.so (epoll_wait+6)
native: #03 pc 00012c57 /system/lib/libutils.so (android::Looper::pollInner(int)+102)
native: #04 pc 00012ed3 /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+130)
native: #05 pc 00082bed /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, _jobject*, int)+22)
native: #06 pc 0000055d /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+96)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:323)
at android.os.Looper.loop(Looper.java:135)
at android.app.ActivityThread.main(ActivityThread.java:5435)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:735)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:625)
该有的描述上面已经用注释的方式放入了，最后的部分是调用栈信息。
2) 再举个梨子
----- pid 12838 at 2016-05-30 10:41:04 -----
Cmd line: 略
// 进程状态信息省略
suspend all histogram: Sum: 1.456ms 99% C.I. 3us-508.799us Avg: 97.066us Max: 523us
DALVIK THREADS (19):
"Signal Catcher" daemon prio=5 tid=2 Runnable
| group="system" sCount=0 dsCount=0 obj=0x32c02100 self=0xb82f1d40
| sysTid=12843 nice=0 cgrp=bg_non_interactive sched=0/0 handle=0xb39ec930
| state=R schedstat=( 10914800 1156480 11 ) utm=0 stm=0 core=2 HZ=100
| stack=0xb38f0000-0xb38f2000 stackSize=1014KB
| held mutexes= "mutator lock"(shared held)
native: #00 pc 00371069 /system/lib/libart.so (_ZN3art15DumpNativeStackERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEEiPKcPNS_9ArtMethodEPv+160)
native: #01 pc 003508c3 /system/lib/libart.so (_ZNK3art6Thread4DumpERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+150)
native: #02 pc 0035a5bb /system/lib/libart.so (_ZN3art14DumpCheckpoint3RunEPNS_6ThreadE+442)
native: #03 pc 0035b179 /system/lib/libart.so (_ZN3art10ThreadList13RunCheckpointEPNS_7ClosureE+212)
native: #04 pc 0035b6a7 /system/lib/libart.so (_ZN3art10ThreadList4DumpERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+142)
native: #05 pc 0035bdb7 /system/lib/libart.so (_ZN3art10ThreadList14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+334)
native: #06 pc 00331179 /system/lib/libart.so (_ZN3art7Runtime14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+72)
native: #07 pc 0033b27d /system/lib/libart.so (_ZN3art13SignalCatcher13HandleSigQuitEv+928)
native: #08 pc 0033bb61 /system/lib/libart.so (_ZN3art13SignalCatcher3RunEPv+340)
native: #09 pc 00041737 /system/lib/libc.so (_ZL15__pthread_startPv+30)
native: #10 pc 00019433 /system/lib/libc.so (__start_thread+6)
(no managed stack frames)
"main" prio=5 tid=1 Blocked
| group="main" sCount=1 dsCount=0 obj=0x759002c0 self=0xb737fee8
| sysTid=12838 nice=-1 cgrp=bg_non_interactive sched=0/0 handle=0xb6f1eb38
| state=S schedstat=( 743081924 64813008 709 ) utm=50 stm=23 core=4 HZ=100
| stack=0xbe54e000-0xbe550000 stackSize=8MB
| held mutexes=
kernel: (couldn't read /proc/self/task/12838/stack)
native: #00 pc 00016aa4 /system/lib/libc.so (syscall+28)
native: #01 pc 000f739d /system/lib/libart.so (_ZN3art17ConditionVariable4WaitEPNS_6ThreadE+96)
native: #02 pc 002bcd8d /system/lib/libart.so (_ZN3art7Monitor4LockEPNS_6ThreadE+408)
native: #03 pc 002bed73 /system/lib/libart.so (_ZN3art7Monitor4WaitEPNS_6ThreadExibNS_11ThreadStateE+922)
native: #04 pc 002bfbaf /system/lib/libart.so (_ZN3art7Monitor4WaitEPNS_6ThreadEPNS_6mirror6ObjectExibNS_11ThreadStateE+142)
native: #05 pc 002d1403 /system/lib/libart.so (_ZN3artL11Object_waitEP7_JNIEnvP8_jobject+38)
native: #06 pc 0000036f /data/dalvik-cache/arm/system@framework@boot.oat (Java_java_lang_Object_wait__+74)
at java.lang.Object.wait!(Native method)
- waiting to lock <0x0520de84> (a java.lang.Object) held by thread 22
at com.xx(unavailable:-1)
- locked <0x00e3266d>
- locked <0x0520de84> (a java.lang.Object)
at com.xx.R(unavailable:-1)
at com.xx.ux(unavailable:-1)
// 其余栈略
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:684)
// 其他线程省略
"Thread-654" prio=5 tid=22 Blocked
| group="main" sCount=1 dsCount=0 obj=0x32c027c0 self=0xb83e9750
| sysTid=12891 nice=0 cgrp=bg_non_interactive sched=0/0 handle=0x9cf1c930
| state=S schedstat=( 50601200 1215760 62 ) utm=4 stm=0 core=7 HZ=100
| stack=0x9ce1a000-0x9ce1c000 stackSize=1038KB
| held mutexes=
at com.yy(unavailable:-1)
- waiting to lock <0x00e3266d> held by thread 1
at com.yy.MX(unavailable:-1)
at com.yy.run(unavailable:-1)
- locked <0x0520de84> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:833)
从traces文件种可以很明显的看到我们的主线程处于Blcoked状态，详细查看Blcoked的原因知道，它在等待一个被22号线程持有的对象锁，于是我们查看tid=22的线程，可以看出这个线程的确锁住了一个对象，该对象正是主线程正在等待上锁的对象，那这个线程为何没有释放锁呢，因为它在等一个被1号线程持有的对象锁，因此死锁问题导致了ANR现象。
五.总结
略
