ANR分析（二）

本篇将主要分享:
3.应用如何避免ANR
4.如何分析ANR问题

3. 应用如何避免ANR

造成ANR的原因可以分成两大类，系统原因与应用原因。系统原因是指在手机开发过程中，由于Kernel、FrameWork、驱动存在问题，导致系统工作不稳定，最终在应用层表现出来的ANR。如CPU驱动错误导致四核手机只有一个核运行、Kernel将用户空间冻结导致任何程序都不能执行、I/O吞吐量低下导致应用程序长时间等待I/O，HAL层实时进程长时间占用CPU导致调度队列过长、AMS原生Bug导致系统焦点不能正确转换等等。对于此类问题，如果底层无法在交付时确保系统稳定，就需要在分析大量ANR问题的基础上提炼出其共同规律，针对疑点添加debug信息，再通过长时间的复测才能加以解决。

应用原因是指应用程序主线程死锁、阻塞或者性能低下导致ANR。应用自身为避免发生ANR，应当在程序开发中注意避免将耗时的操作放在主线程，耗时操作包括：

（1）.数据库操作。 数据库操作尽量采用异步方法做处理，Monkey测试中IOWait可能会很高，此时一个微不足道的数据库查询操作都可能需要很长时间才能返回。

（2）初始化的数据和控件太多。可以用布局查看工具HierarchyViewer来优化UI设计，避免深层嵌套。此外还需要注意限制控件输入字符的数量，测试人员曾在一个设计输入40个字的输入框中输入了四十万字然后反复转屏，引发ANR。

（3）频繁的创建线程或者其它大对象。有些应用在Monkey测试中会创建出800+子线程，显然应避免这样做。

（4）加载过大数据和图片。对于彩信或Gallery，设计时应当考虑加载缩略图而不是原始图片，因为测试很喜欢用100M的jpg图片做压力测试。

（5）对大数据排序和循环操作。曾有人写出复杂度为O(n^2)的通讯录联系人匹配算法，测试时发现匹配两千个联系人需要15分钟，最后被优化到25秒。显然这种操作应当放在子线程中处理。

（6）过多的广播和滥用广播。如果处理一个广播需要花费较长时间，应当通过发送Intent给应用的Service来完成。

（7）大对象的传递和共享。

（8） 访问网络。4.4项目曾经遇到过一个从谷歌应用商店下载的程序启动后在主线程中访问Facebook，然后在GFW上撞得头破血流导致ANR。

（9）锁住主线程。Gallery原生代码中会给主线程上一个无限等待的锁，然后由子线程来解锁。但是在Monkey测试中如果系统处于高负载解锁不及时就会发生ANR，应尽量避免

4. 如何分析ANR问题

---

与Native Crash或者Java Crash发生时简单明确的崩溃堆栈不同，分析ANR问题时需要通盘考虑，综合log中各方面的信息，找出是系统原因还是应用原因导致ANR。片面地分析应用程序堆栈或者CPU信息通常都只能得出令人啼笑皆非的错误结论。

在一份标准的sog中，通常有以下文件可用于分析ANR的原因：

system.log 包含ANR发生时间点信息、ANR发生前的CPU信息，还包含大量系统服务输出的信息。

main.log 包含ANR发生前应用自身输出的信息，可供分析应用是否有异常；此外还包含dalvik输出的GC信息，可供分析内存回收的速度，判断系统是否处于低内存或内存碎片化状态。

event.log 包含AMS与WMS输出的应用程序声明周期信息，可供分析窗口创建速度以及焦点转换情况。

kernel.log 包含kernel打出的信息，LowMemoryKiller杀进程、内存碎片化或内存不足，mmc驱动异常都可以在这里找到。

napshot.log‘和trace.log 在有些项目中这两个文件可能被合并为一个，包含ANR发生时的应用堆栈信息、PS信息和meminfo信息。根据定制需要，还可以包含ANR发生时的system_server堆栈、SurfaceFlinger堆栈、文件句柄状况等信息。

tomestone 有些应用的ANR是由于之前应用已经崩溃导致的，需要注意以下在ANR发生前如果在tomestone文件夹中此应用已经发生了Native Crash，那么ANR很有可能就是由此导致的。

Dropbox 该文件会把snapshot中的信息备份一份，如果因为某些原因导致snapshot文件丢失，可以尝试在dropbox中寻找ANR发生时的堆栈信息。

1. System.log中的信息

1. ANR第一时间点
在分析ANR时首先要寻找的就是ANR的第一时间点。参见以下log，可以看到第一个黄色标记处有“Input event dispatching timed out sending to ……”字样，这就是ANR发生的第一时间点。在明确了这个时间点后，才能根据不同ANR的类型分析在超时时间段内系统和应用有什么异常信息。例如广播超时需要分析第一时间点前10秒（后台广播60秒）的广播队列信息；窗口转换超时需要分析第一时间点前5秒的窗口焦点转换过程和event.log中的窗口生命周期信息。通过ANR第一现场的时间和ANR类型，可以找到出错时间段，压缩需要分析的时间范围。

注意不同类型ANR的第一时间点log是不同的，比如广播超时的log如下所示。

2 . ANR in”信息
通常分析ANR问题时第一件事就是打开system.log，找到“ANR in”信息，然后大致了解一下发生ANR的是什么应用，CPU占用情况如何。接下来会详细讲解这段log中包含的诸多信息。

需要特别注意的是“ANR in”并不是ANR发生的第一时间点。它是在输出ANR应用堆栈和主要系统服务堆栈、ps、meminfo等信息后，ANR进程马上就要被杀死时才被输出的。如果ANR发生时输出的debug信息较多，或者当时的CPU或I/O资源比较紧张，“ANR in”可能在ANR发生的第一时间点之后10秒甚至20秒才被输出。

这段log中的信息主要有：

1. 'ANR'进程名称与PID'：进程名和PID是找到发生ANR的应用的主要依据，但是有两种例外情况。如果PID为0，说明应用在发生ANR之前就已经被LowMemoryKiller杀死或者已经崩溃。这种情况下应用程序无法处理广播或按键消息，因此出现ANR。

由于原生Bug，窗口获取焦点超时导致的ANR可能会报告在错误的应用上，这主要是因为焦点应用和焦点窗口不同步导致的，请参考1.2.2节。

2. 'ANR'类别：可以据此判断ANR超时时间，决定需要回溯多久查找ANR的原因。比如用户输入时间处理超时回溯5秒，广播超时回溯10秒。

3. 'CPU'平均负载：表示一、五、十分钟内有多少进程在等待CPU调度。单核手机一般不超过10，四核手机不超过14。如果CPU负载太高应用程序主线程长时间得不到CPU时间片就会发生ANR甚至Watchdog重启。

4. 'CPU'统计时间段：ago和Later分别表示 ANR 发生前后一段时间内的 CPU 使用率,并不是某一时刻的值。需要注意的是，这个统计本身也会收到CPU负载高的影响，可能无法统计到ANR发生之前的CPU状况。

5. '进程CPU'占用率：单核手机上，如果进程CPU占用率较高，且截取到的是ANR发生之前的CPU情况，那么ANR可能与CPU占用率有关。

6. '页错误数量：分为次要页错误和主要页错误，分别表示内存与缓存的命中情况。页错误过高说明内存频繁换页，会导致分配内存与GC速度显著变慢。

7. '新增进程：ANR发生前出现大量的新增进程说明可能广播风暴或密集的延时重启。

8. '总CPU'占用率：在单核设备上可以保证准确，在支持热插拔的设备上一般不准确。

9. '线程CPU'占用率：可配合snapshot中的应用调用堆栈分析单个进程CPU占用率高问题。

在分析System.log时，应当注意应用发生ANR之前是否出现了OutOfMemory错误、Java Crash或者Native Crash。此外还应当注意应用相关的服务是否出现了异常，比如acore被LMK杀死contact就会发生ANR，camera handler发生崩溃会导致camera发生ANR。

2. Main.log中的信息

Mian.log中主要是应用输出的信息，相对System.log而言会比较散乱。从中挖掘ANR的关键信息需要一定的耐心。在分析时应当关注以下几个方面。

• 反复打出相同log’: 如果应用CPU占用率很高，且反复打出相同log，很可能是出现死循环.

05-20 14:26:32.875  2896  2896 V BluetoothSettings: onPreferenceChange()shouldScanDisabled = false

05-20 14:26:32.895  2896  2896 V BluetoothSettings: onPreferenceChange()shouldScanDisabled = false

05-20 14:26:32.915  2896  2896 V BluetoothSettings: onPreferenceChange()shouldScanDisabled = false

05-20 14:26:32.925  2896  2896 V BluetoothSettings: onPreferenceChange()shouldScanDisabled = false

05-20 14:26:32.945  2896  2896 V BluetoothSettings: onPreferenceChange()shouldScanDisabled = false

05-20 14:26:32.965  2896  2896 V BluetoothSettings: onPreferenceChange()shouldScanDisabled = false

05-20 14:26:32.975  2896  2896 V BluetoothSettings: onPreferenceChange()shouldScanDisabled = false

05-20 14:26:33.005  2896  2896 V BluetoothSettings: onPreferenceChange()shouldScanDisabled = false 05-20 14:26:33.025  2896  2896 V BluetoothSettings: onPreferenceChange()shouldScanDisabled = false

• 应用输出的log’是否存在异常：如下例，Camera尝试分配26214400
  Byte显存，但是从16:42:16开始申请直到16:42:27才分配完毕，这段时间主线程一直被阻塞，因此发生ANR。在应用程序容易出现性能问题的关键点适度添加log，对查找ANR问题非常有帮助。

01-01 16:42:16.942   150  1676 I SprdCameraHardware: allocateCaptureMem, mJpegHeapSize = 26214400, mRawHeapSize = 26214400

01-01 16:42:16.942   150  1676 I SprdCameraHardware: allocateCaptureMem:mRawHeap align size = 26214400 . count 1

......

01-01 16:42:27.142   150  1676 I SprdCameraHardware: allocCameraMem: mm_iova: phys_addr 0x20000000, data: 0xaf50d000, size: 0x1900000, phys_size: 0x1900000.

01-01 16:42:27.142   150  1676 I SprdCameraHardware: allocateCaptureMem: initJpeg

• 是否有多个应用都打出相同的异常信息：有时一些ANR问题是由共同的底层问题导致的。如下例，每次ANR前log中都会报出io异常，且多个应用都有相同现象。分析后发现问题出现在kernel中的mmc驱动。

FileExplorer出现ANR前，log中报出大量的io异常：

05-10 16:31:27.580  1875  1911 W System.err: Caused by: libcore.io.ErrnoException: read failed: EIO (I/O error)

05-10 16:31:27.580  1875  1910 W System.err: java.io.IOException: read failed: EIO (I/O error)

Gallery出现ANR前，log中也报出的了同样的io异常：

05-10 16:31:45.620  1627  1627 W System.err: java.io.IOException: read failed: EIO (I/O error)

05-10 16:31:45.620  1627  1627 W System.err:         at libcore.io.IoBridge.read(IoBridge.java:450)

结合Kernel.log分析发现，是mmc驱动出现错误造成I/O异常，最终导致ANR。

<3>[ 1208.760352] c3 mmcblk1: error -110 sending status command, aborting

<4>[ 1208.760385] c3 mmc1: mmc_blk_reset return EEXIST

<3>[ 1208.761006] c0 mmc1: !!!!! error in sending cmd:18, int:0x10000, err:-110

<3>[ 1208.761023] c0 sdhci: =========== REGISTER DUMP (mmc1)===========

<3>[ 1208.761036] c0 sdhci: 0x80a52fc0 | 0x00087200 | 0x00397a46 | 0x123a0033

<3>[ 1208.761048] c0 sdhci: 0x00000000 | 0x00000000 | 0x00000000 | 0x00000000

<3>[ 1208.761048] c0 sdhci: 0x00000000 |