Android ANR监控
1. 前言
上一篇文章讲到了Java层Crash的监控，其实App除了Crash外，ANR也是一个头疼的问题。
ANR(Application Not Respongding)就是应用无响应，指应用处理一个事件长时间没有结果导致主线程不能处理下一件事件。
2. 分类
- InputDispatching Timeout/KeyDispatching Timeout(其实就是Activity):输入时间分发超过5s，包括按键分发事件的超时（触发了ANR如果没有输入事件，不会弹出ANR对话框，需要下一次input事件产生后5s才弹出ANR提示框）。
- BroadcastQueue Timeout:比如前台广播在10s内执行完成；后台广播60s内执行完成。
- ContentProvider Timeout:内容提供者20s内执行完成
- Service Timeout:前台服务在20s内未执行完成；后台服务在200s没有完成。
3.ANR信息
这里以在点击事件中直接sleep(100s)为例
image.png
在发生ANR的时候，会在logcat中输出如下信息，
E/ActivityManager:
ANR in com.example.administrator.bugdemo (com.example.administrator.bugdemo/.MainActivity)
PID: 13328
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: 7. Wait queue head age: 5546.7ms.)
Load: 4.25 / 4.95 / 5.7
CPU usage from 0ms to 5023ms later (2018-07-04 16:57:23.192 to 2018-07-04 16:57:28.215):
25% 1337/system_server: 15% user + 10% kernel / faults: 4510 minor 39 major
12% 18656/com.tencent.mm:tools: 10% user + 2.3% kernel / faults: 1416 minor 50 major
11% 4146/com.kugou.android: 9.5% user + 1.9% kernel / faults: 1259 minor 24 major
6.1% 22021/com.tencent.mm: 4.9% user + 1.1% kernel / faults: 1609 minor 19 major
4.7% 20915/com.sina.weibo: 3.1% user + 1.5% kernel / faults: 1323 minor 32 major
4.5% 1977/com.android.systemui: 3.1% user + 1.3% kernel / faults: 1105 minor 4 major
CPU usage from 5024ms to 11011ms later ( 2018-07-04 16:57:28.215 to 2018-07-04 16:57:36.215):
25% 1337/system_server: 15% user + 10% kernel / faults: 4510 minor 39 major
12% 18656/com.tencent.mm:tools: 10% user + 2.3% kernel / faults: 1416 minor 50 major
11% 4146/com.kugou.android: 9.5% user + 1.9% kernel / faults: 1259 minor 24 major
6.1% 22021/com.tencent.mm: 4.9% user + 1.1% kernel / faults: 1609 minor 19 major
4.7% 20915/com.sina.weibo: 3.1% user + 1.5% kernel / faults: 1323 minor 32 major
4.5% 1977/com.android.systemui: 3.1% user + 1.3% kernel / faults: 1105 minor 4 major
....
ANR in: 发生ANR具体的类
PID: 发生ANR的进程
Reason: 发生ANR的类型以及原因
CPU usage ：CPU的使用情况，这里会有两个时间节点，1个是发生ANR之前的CPU使用情况；1个是发生ANR之后的使用情况.
当发生ANR时，Logcat中除了能看出ANR发生的类以及原因，还可以参考两个CPU的使用情况，如果CPU的使用量很少，说明主线程可能阻塞；如果IOwait很高，说明ANR有可能是犹豫主线程进行耗时的I/0操作造成的。
不过如果是用户使用过程中发生ANR，我们就查看不到以上信息了，所幸的是，当发生ANR时，会在/data/anr/文件夹下生成一个traces.txt文件，我们可以借助于这个文件来分析ANR。ANR的部分代码如下所示：
----- pid 2502 at 2018-07-07 15:06:44 -----
Cmd line: com.example.administrator.bugdemo
ABI: x86
Build type: optimized
Zygote loaded classes=3593 post zygote classes=394
Intern table: 36545 strong; 897 weak
JNI: CheckJNI is on; globals=647 (plus 1 weak)
Libraries: /system/lib/libandroid.so /system/lib/libaudioeffect_jni.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/librs_jni.so /system/lib/libsoundpool.so /system/lib/libwebviewchromium_loader.so libjavacore.so (10)
Heap: 23% free, 3MB/4MB; 61572 objects
Dumping cumulative Gc timings
Start Dumping histograms for 56 iterations for concurrent mark sweep
ProcessMarkStack: Sum: 158.124ms 99% C.I. 3us-25727.999us Avg: 941.214us
Total number of allocations 190062
Total bytes allocated 10MB
Free memory 1193KB
Free memory until GC 1193KB
Free memory until OOME 188MB
Total memory 4MB
Max memory 192MB
Total mutator paused time: 21.252ms
Total time waiting for GC to complete: 235.785us
DALVIK THREADS (14):
"main" prio=5 tid=1 Sleeping
| group="main" sCount=1 dsCount=0 obj=0x74875000 self=0xb3c25800
| sysTid=2502 nice=0 cgrp=default sched=0/0 handle=0xb771bea0
| state=S schedstat=( 270715994 122220325 1654 ) utm=6 stm=20 core=1 HZ=100
| stack=0xbf495000-0xbf497000 stackSize=8MB
| held mutexes=
at java.lang.Thread.sleep!(Native method)
- sleeping on <0x21a083b6> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:1031)
- locked <0x21a083b6> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:985)
at android.os.SystemClock.sleep(SystemClock.java:120)
at com.example.administrator.bugdemo.MainActivity$2.onClick(MainActivity.java:38)
at android.view.View.performClick(View.java:4780)
at android.view.View$PerformClick.run(View.java:19866)
at android.os.Handler.handleCallback(Handler.java:739)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:135)
at android.app.ActivityThread.main(ActivityThread.java:5254)
at java.lang.reflect.Method.invoke!(Native method)
at java.lang.reflect.Method.invoke(Method.java:372)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:903)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:698)
----- end 77 -----
很容易看出，可以定位到MainActivity中的onClick事件中，所以我们可以考虑把这份traces.txt上传给服务端分析。
4. Analyze Stacktrace
我们得到traces.txt后，可以用Android Studio自带的Analyze Statcktrace来分析出现ANR时线程的一些情况。
比如，有一些ANR是由于多线程之间的同步锁造成的，主线程获取锁的时候，发现已经被子线程占用了，就会导致主线程阻塞。比如，我们写如下代码来模拟多线程之间的同步锁问题
findViewById(R.id.btn_anr).setOnClickListener(new View.OnClickListener() {
@Override
public void onClick(View view) {
new Thread(new Runnable() {
@Override
public void run() {
synchronized (o) {
for (int i = 0; i < 20; i++) {
Log.e(TAG, "子线程:" + i);
SystemClock.sleep(1000);
}
}
}
}).start();
SystemClock.sleep(2 * 1000);
Log.e(TAG, "主线程1");
synchronized (o) {
Log.e(TAG, "主线程2");
}
Log.e(TAG, "主线程3");
}
});
我们在启动了一个子线程去做耗时操作，并占用了o的锁，过了2s，我们在主线程中想使用o的锁时，只能阻塞，等待子线程释放o的锁。
如果我们点击按钮触发如上代码，然后再多次点击屏幕，就会触发ANR。
我们拿到traces.txt以后，点击Android Studio菜单栏上的Analyze->Analyze Statcktrace，然后把traces.txt中的内容复制到如下框中，并勾选Automatically xxx，然后点击Normalize，再点击OK就可以了
image.png
如下，左边是线程列表，右边为线程的具体信息，比如我们这次ANR就是主线程被子线程抢占了o的锁导致的，我们可以点击含有Block的线程，右边就显示了主线程为什么会阻塞，这样就很方便地定位到了问题
image.png
5. ANR的监控
上面讲述了ANR的分析，现在讲讲ANR的监控，也就是我们怎么让后台知道App产生了ANR，我能想到的方式有如下三种：
- 子线程定时检测/data/anr/traces.txt是否存在，这种方式需要读取traces.txt的内容进行分析，并可能存在漏报的情况，另外，还有增加App的开销
- 子线程向主线程发送消息，把发送的时间和接受到的时间做对比，如果没有接受的时间或者时间差比较大，就认为发生了ANR，但这会增加App的开销
- 检测主线程中单个任务的执行时间，如果超过一定时间，就认为ANR了。这是比较推荐的一种方式。
我们知道ANR是指主线程因为处理某件事情时间过长而导致不能在规定时间内处理下一件事件，所以我们需要关心的就是单个时间的处理时间，这个我们可以借助于Handler的机制来实现，如果对Handler机制不是很熟悉的，可以先看这篇文章：图解Handler机制
Handler的原理如下图所示：
image.png
我们知道，我们App就是运行在Looper.loop方法中的，loop中会有一个死循环，去取出我们的消息（Message），然后一个一个处理，也就是上图中的红色圆圈部分，所以我们需要检测的就是，每个Message被分发的时间。
我们来看看Looper.loop方法的部分代码
public static void loop() {
final Looper me = myLooper();
if (me == null) {
throw new RuntimeException("No Looper; Looper.prepare() wasn't called on this thread.");
}
final MessageQueue queue = me.mQueue;
for (;;) {
Message msg = queue.next(); // might block
if (msg == null) {
// No message indicates that the message queue is quitting.
return;
}
// This must be in a local variable, in case a UI event sets the logger
final Printer logging = me.mLogging;
if (logging != null) {
logging.println(">>>>> Dispatching to " + msg.target + " " +
msg.callback + ": " + msg.what);
}
try {
msg.target.dispatchMessage(msg);
} finally {
if (traceTag != 0) {
Trace.traceEnd(traceTag);
}
}
if (logging != null) {
logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);
}
}
}
msg.target.dispatchMessage(msg);就是我们对Message的分发处理，所以我们需要检测的就是这个方法的执行时间，而巧了的是，在这个方法的前后，都有执行logging.println方法，logging是一个Printer对象，那我们是不是可以重写Printer的println方法来检测两次方法调用的时间间隔呢？更巧了的是：
- logging.println方法，只有在这里被调用了两次，其他地方没有使用，这样避免了干扰项
- 这里的Printer对象是Looper中的成员变量，并提供了如下方法去设置值
public void setMessageLogging(@Nullable Printer printer) {
mLogging = printer;
}
完美！！！
6. 具体实现
我们要实现的就是，自定义Printer并重写其println方法，最后把自定义的Printer对象设置到主线程中的Looper对象中。
首先我们来自定义Printer
/**
* 自定义的Printer，用于监听ANR
*/
public class MyPrinter implements Printer {
private static final String TAG = "josan";
private long startTime = 0;
// 处理时间超过5s，则认为ANR
private static final long ANR_TIME = 5 * 1000;
// traces.txt的路径
private static final String ANR_FILEPATH = "/data/anr/traces.txt";
private Context appContext;
public MyPrinter(Context appContext) {
this.appContext = appContext;
}
@Override
public void println(String x) {
try {
if (startTime == 0) {
startTime = System.currentTimeMillis();
Log.e(TAG, "startTime时间：" + startTime);
} else {
// 计算处理message的时间，单位毫秒
long intervalTime = System.currentTimeMillis() - startTime;
Log.e(TAG, "intervalTime时间：" + (intervalTime / 1000.0));
if (intervalTime > ANR_TIME) {
Log.e(TAG, "发生了ANR");
processANR(intervalTime);
}
startTime = 0;
}
} catch (Exception e) {
e.printStackTrace();
}
}
/**
* 处理ANR
*
* @param intervalTime
*/
private void processANR(long intervalTime) {
new Thread(new Runnable() {
@Override
public void run() {
if (hasTracesFile()) {
Log.e(TAG, "traces.txt文件存在，且就是本App发生的ANR,则上传");
} else {
Log.e(TAG, "traces.txt文件不存在或者不是本App发生的ANR, 收集其他信息上传");
}
}
}).start();
}
/**
* 是否存在本App发生ANR保存下的traces.txt
*
* @return
*/
private boolean hasTracesFile() {
File anrFile = new File(ANR_FILEPATH);
if (!anrFile.exists()) {
Log.e(TAG, "没有traces.txt存在！");
return false;
}
try {
BufferedReader bfr = new BufferedReader(new FileReader(anrFile));
String line = bfr.readLine();
StringBuilder sb = new StringBuilder();
while (line != null) {
sb.append(line);
sb.append("\n");
line = bfr.readLine();
}
bfr.close();
// 如果是本App发生的ANR，traces.txt文件中会包含包名信息
if (sb.toString().contains(appContext.getPackageName())) {
return true;
}
} catch (IOException e) {
e.printStackTrace();
}
return false;
}
}
其实逻辑很简单，我们重写了println方法，用startTime记录处理message之前的时间，等message处理完后，会再次调用println方法，这时候startTime已经不为0, 我们就计算处理的时候，如果时间大于我们设定的阀值，就认为ANR了，然后调用processANR来处理ANR。
processANR方法中，直接开启了一个子线程，先调用hasTracesFile去判断是否有本App产生的traces.txt,如果traces.txt文件存在且内容中包含了App的包名，我们就上传traces.txt，否则，我们就自己收集信息进行上报。
我们自定义好Printer以后，需要把它设置到主线程中的Looper中，这就很简单了，我们可以在自定义Application中的onCreate方法中用Looper.getMainLooper().setMessageLogging(new MyPrinter(this))来完成，代码如下：
@Override
public void onCreate() {
Log.e(TAG, "Applicatioin oncreate");
super.onCreate();
Looper.getMainLooper().setMessageLogging(new MyPrinter(this));
}
不过这样是有问题的，比如处理一个message为20s，那在处理之前，调用了一次println方法，第二次调用println方法的时机为20s后，那么很可能在这中间就发生了ANR，弹出了如下的ANR弹框，如果用户点击了“等待”，我们的确是可以等到第二次调用println，但是如果用户点击了“确定”，那么App就会直接被杀死，而println不会调用第二次，进而就不能检测到这次ANR了
image.png
所以，不能等到第二次调用println时再判断是否发生了ANR，那我们可以怎么办呢？
7. 试错
7.1 Handler发延时消息
既然println有可能不会被第二次调用，那么是否可以考虑，在第一次调用println的时候，做延时处理，在第二次println后，再移除掉Runnable，如果过了ANR的时间没有移除，则执行Runnable的run方法，进行ANR的处理，代码如下：
@Override
public void println(String x) {
try {
if (startTime == 0) {
startTime = System.currentTimeMillis();
Log.e(TAG, "startTime时间：" + startTime);
// 发送一个延时消息，如果过了ANR,还没移除掉，则认为发生了ANR
mHandler.postDelayed(mRunnable, ANR_TIME);
} else {
Log.e(TAG, "间隔时间：" + (System.currentTimeMillis() - startTime));
// 如果没有超时，则移除处理ANR的Runnable
mHandler.removeCallbacks(mRunnable);
startTime = 0;
}
} catch (Exception e) {
e.printStackTrace();
}
}
但是，这也是有问题的，因为，延时也是通过handler发送的消息，而延时的消息需要等当前消息（事件）处理完才能得到处理，比如，我们当前处理的事件需要20秒，第一次调用println时，发送一个延时5s处理ANR的消息，5s过去了，发现不会有任何反应，需要等到当前事件处理完，才可能处理延时的消息，但是当前事件处理完，会第二次调用println方法，直接把延时任务的runnable移除掉了，所以这里处理ANR的延时消息，永远都不能得到执行。
显然，这种Handler发送延时消息的方式不可行，那还有什么可以做延时呢？考虑sleep
7.2 线程Sleep做延时处理
我们可以考虑在第一次调用println时，在线程池中做sleep ANR_TIME的处理，如果sleep 5s后，processed还没有被设置为true，则认为发生了ANR（其中processed标识是否处理了当前时间，第一次调用println方法时设置为false；第二次调用println方法时设置为true），代码如下。
public MyPrinter2(Context appContext) {
this.appContext = appContext;
mRunnable = new Runnable() {
@Override
public void run() {
Log.e(TAG, "延时ANR_TIME的时间");
SystemClock.sleep(ANR_TIME);
if (!processed) {
Log.e(TAG, "发生了ANR");
processANR();
} else {
Log.e(TAG, "及时处理了事件");
}
}
};
mExecutor = Executors.newSingleThreadExecutor();
}
@Override
public void println(String x) {
try {
if (startTime == 0) {
startTime = System.currentTimeMillis();
Log.e(TAG, "startTime时间：" + startTime);
processed = false;
mExecutor.execute(mRunnable);
} else {
Log.e(TAG, "间隔时间：" + (System.currentTimeMillis() - startTime));
// 设置标志位，已经处理完了，不用执行ANR了
processed = true;
startTime = 0;
}
} catch (Exception e) {
e.printStackTrace();
}
}
不过，这种方式，也是不行的，单看处理一次事件来说是没问题的，但loop方法会一直遍历MessageQueue，去取出Message来分发，这就有问题了。比如我们现在处理一件事件，第一次调用println时执行了mExecutor.execute(mRunnable)，很快事件处理完了，processed被设置为true了，然而looper会继续取后面的事件处理，比如处理到第N件事件了，这个时候因为处理第N件事件而第一次调用println方法把processed设置成false了，如果这个时候刚好过了5s,第一件事件线程中执行的sleep结束了，这个时候，就会被误判为ANR。
8. 子线程发送消息给主线程的方式检测ANR
虽然，我们想通过Looper+Printer来监控ANR的初衷是好的，但是发现并不能实现我们想要的功能，它适合做页面卡顿的监控，也就是第二次println确定能够被调用到。
最后，还是选择在子线程中不断向主线程发送消息的方式来检测ANR，我们写一个ANRService来实现这个功能，并在Application的onCreate去启动ANRService。
先来看ANRService的实现
/**
* 用于检测ANR的Service
*/
public class ANRService extends Service {
private static final String TAG = "josan";
private static final String ANR_FILEPATH = "/data/anr/traces.txt";
private boolean received;
private static final int ANR_TIME = 5 * 1000;
private Handler mHandler;
@Nullable
@Override
public IBinder onBind(Intent intent) {
return null;
}
@Override
public void onCreate() {
super.onCreate();
mHandler = new Handler();
checkANR();
}
/**
* 检测ANR
*/
private void checkANR() {
new Thread(new Runnable() {
@Override
public void run() {
while (true) {
received = false;
// 发送一个消息，让主线程处理
mHandler.post(new Runnable() {
@Override
public void run() {
received = true;
}
});
// 休眠ANR_TIME的时间
SystemClock.sleep(ANR_TIME);
if (!received) {
Log.e(TAG, "主线程没有处理消息，可能发生了ANR！");
if (hasTracesFile()) {
Log.e(TAG, "traces.txt文件存在，且就是本App发生的ANR,则上传");
} else {
Log.e(TAG, "traces.txt文件不存在或者不是本App发生的ANR, 收集其他信息上传");
}
break;
} else {
Log.e(TAG, "主线程处理了消息！");
}
}
}
}).start();
}
/**
* 是否存在本App发生ANR保存下的traces.txt
*
* @return
*/
private boolean hasTracesFile() {
File anrFile = new File(ANR_FILEPATH);
if (!anrFile.exists()) {
Log.e(TAG, "没有traces.txt存在！");
return false;
}
try {
BufferedReader bfr = new BufferedReader(new FileReader(anrFile));
String line = bfr.readLine();
StringBuilder sb = new StringBuilder();
while (line != null) {
sb.append(line);
sb.append("\n");
line = bfr.readLine();
}
bfr.close();
// 如果是本App发生的ANR，traces.txt文件中会包含包名信息
if (sb.toString().contains(this.getPackageName())) {
return true;
}
} catch (IOException e) {
e.printStackTrace();
}
return false;
}
}
其实就是在子线程里发起一个消息让主线程处理，接着休眠ANR_TIME，ANR_TIME后，发现主线程处理了消息，把received设置为了true，则认为没有发生ANR，否则则认为主线程过了ANR_TIME的时间都没处理该消息，则认为发生了ANR。
然后在Application中去启动这个Service，代码如下（记得清单文件中注册）：
public void onCreate() {
super.onCreate();
startService(new Intent(this, ANRService.class));
}
这种方式是可行的，但是会消耗一定的性能，相当于每5s都会向主线程的MessageQueue中插入一个消息。建议通过服务端控制在部分用户的版本上开启检测，不要做全量检测。
另外，如果有traces.txt，就把它上传给服务端，并删除该文件，还可以在每次启动时，检测一次traces.txt文件是否存在，如果存在，则读取数据看是否是我们的app发生的ANR，如果是，则上传数据，上传完以后照样要删除数据。
- 通监控ANR的弹框来实现监控ANR
考虑监控窗口
考虑过滤掉窗口
