Android ANR日志粗略分析

平台：Android4.4.2

 

虽然ANR的缩写是application not responding，但是并不是所有的ANR问题都是应用程序的问题。比如说CPU占用率太高、API调用卡死都有可能导致ANR，这些问题都是系统性问题。

 

1. 什么是ANR？

Android应用程序和Windows应用程序一样，采用的也是消息循环模型。就是说应用程序启动后在没有主动创建线程的情况下就只有一个主线程不断的从消息队列取出消息然后处理消息。

目前Android共定义了三种ANR，第一种比较容易理解，就是用户按键或滑动触屏后，应用程序在规定时间内不响应（当前默认值是5秒），从用户的角度看，这个问题是非常严重的，不要说5秒，只要超过1秒不响应其实都是不可接受的。识别这种ANR的原理是通过运行在system_server进程中的InputDispatcher不断检测应用程序是否处理完这个输入事件，一旦超时就打小报告，如弹出应用程序无响应的对话框，产生ANR日志。

另外两种ANR带有预防性质，因为主线程既要响应用户输入又要干其他事情，如果其他事情干的太慢那么就有可能影响对用户的响应。如果这个时候用户没有输入，那么也就算了，如果用户一旦有输入，那么必然产生前一种ANR。针对这种ANR只是产生ANR日志，但不弹框。现在说这两种ANR是什么，一种是主线程在处理通知的onReceive函数中执行超过10秒没有返回，另外一种是主线程在执行后台操作即执行Service的各个生命周期函数超过20秒。

 

如果主线程仅处理用户响应，其他的事情都通过另外一个线程处理那么是不是就没有ANR了呢？我想这样会好一些，因为有些程序员不太清楚哪些事情在主线程干的，比如我开始就不知道service的处理是在主线程中，因为这个名字起的有点坑爹，如果采用了双线程策略，就会防止这种错误。当然了解机制也是程序员的责任，即使平台默认不提供双线程，程序员也可以自己创建线程处理耗时的工作。第二个问题是后两种ANR我们要不要关注，从用户的角度看只要没产生第一种ANR，这两种ANR是没问题的，那么问题就变成这两种ANR有没有可能导致第一种ANR。因为用户随时可能输入，所以我们需要关注的是当前应用的activity组件处于活动状态时，也就是可接受用户输入的状态时，后两种ANR是否有可能发生。第三个问题，为什么后两种ANR的超时不是5秒？我推测原因同问题2，因为目前还没有机制判断后两种ANR是否会导致第一种ANR，如果有的话，那么超时完全可以设置成5秒。这个是我的臆测，如果哪位朋友更清楚这块的原因，那么非常欢迎指点一二。

 

2. ANR日志说明

ANR日志大致可以分成3个部分：基本信息，CPU占用率，线程调用栈。

2.1   基本信息

Process: system

Flags: 0xc8be09

Package: android v17 (4.2.2-eng.jslave.20131102.115504)

Package: com.android.providers.settings v17 (4.2.2-eng.jslave.20131102.115504)

Subject: keyDispatchingTimedOut

Build: xxxxx/xxxx/release-keys

 

Process就是发生ANR的进程名字，如system，android.process.media，com.android.systemui，com.tencent.mm等。

 

Flags是用来记录应用程序标志的。如：Bit0为1代表是安装在system分区的系统程序如system，bit0为0代表不是系统程序，如com.tencent.mm进程的flags为0xb0be44。Bit1为1代表该应用程序允许调试，在发货的版本中该位应该都是0。Bit2从网上资料看为1表示应用程序拥有代码？难道还有没代码的？还真有，例子中就是一个，这个没有搞清楚，欢迎高人指点。        Bit3为1表示该应用程序不能退出，一般的应用程序都设置为0，只有system server或systemUI这样的程序才会设置为1。关于其他标志位的意义可以参考frameworks/base/core/java/android/content/pm/ApplicationInfo.java中的注释也可以去开发者网站http://developer.android.com/reference/android/R.styleable.html#AndroidManifestApplication_persistent查询。

 

Package表示该进程加载的所有包名。要注意进程和Package并不是一一对应的，进程是Linux中的概念，Package是Android中的概念。一个进程中可以有多个Package，这个和Windows中进程和exe的关系是完全不同的。要理解这个需要从Android的安全机制入手，在安装Android应用程序的时候，默认情况下，每个应用程序分配一个唯一的Linux用户的ID。权限设置为每个应用程序的文件仅对该用户和应用程序本身可见。这样保证了其他应用程序不能访问此应用程序的数据和资源，保证了信息安全。从这个角度讲，Android系统充分的利用了Linux这一安全特性。在桌面级Linux 系统中一个用户ID 识别一个特定用户，而在Android 系统里，一个用户ID 识别一个应用程序。但是，如果我们需要在两个不同的应用程序之间互相访问资源怎么办呢？为了突破这个限制，Android只能给两个应用程序分配相同的Linux用户ID，这样它们之间就能互相访问对方的资源了。目前Android的实现机制中，就将拥有相同用户ID的应用程序将运行在同一个进程中，共享同一个Dalvik虚拟机。其实这只是Android的实现，对于Linux来说，不同的应用程序完全可以用相同的用户ID运行在不同的进程空间。但既然Android设计之初就是一个程序一个用户ID对应一个虚拟机，那么这么实现也是顺其自然的事情。要实现这个功能需要在应用的Manifest文件里给android:sharedUserId属性设置相同的Linux用户ID，然后给这两个应用程序用相同的签名就可以了。

 

Subject，还记得前边描述的三种ANR么？Subject后边的内容就是用来描述导致ANR的原因的，如“keyDispatchingTimedOut”是用户输入的ANR。如“Broadcast of Intent { act=android.intent.action.SCREEN_OFF flg=0x50000010 }”是处理通知导致的ANR，如“Executing service com.android.providers.media/.MtpService”运行后台工作导致的ANR。

 

Build是版本编译信息。除了以上信息外还有可能包含其他的，如下边的日志中包含的Activity内容。还记得那三种ANR么？只有用户输入导致的ANR才有activity信息，表示在当前activity下未及时响应用户输入。

Process: xxxxx

Flags: 0x2a0be45

Package: xxxxx(1.1.1)

Activity: xxxxx/xxxxx

Subject: keyDispatchingTimedOut

Build: xxxx/xxx,release-keys

 

对于用户输入导致的ANR还有可能包含“Parent-Activity:”，为父activity的名字。如果父activity的进程id和当前进程不同，还会包含其进程名字为“Parent-Process:”。

 

2.2   CPU使用信息

CPU使用信息包括CPU负载和CPU占用率。目前的ANR日志中仅包含CPU占用率，不包含CPU负载。CPU负载仅在logcat的system类型下输出，如下所示：

10-07 13:35:21.829  2387  2406 E ActivityManager: Load: 17.21 / 4.46 / 1.5

 

这三个数字表示的是1分钟，5分钟，15分钟的平均负载。需要注意的是目前linux上统计平均负载时不仅统计running状态的进程，还统计uninterruptable状态的进程。Uninterruptable状态的进程是不占用CPU的，一般情况下处于该状态的进程是在等待IO，所以该状态下进程数量可以反映IO的负载。从这个角度看这个平均负载表示的是系统负载，而且也仅能做参考，因为有的系统中会有很多处于uninterruptable状态的进程，但是这些进程又不是在等待IO。因为这些原因，通过负载没办法直接看出CPU的真正负载到底高不高，IO负载到底高不高，必须结合进程状态以及进程到底因为什么处于uninterruptable状态才能分析出CPU真正的负载。

 

相比较CPU负载，CPU占用率更能反映CPU到底忙还是不忙。统计CPU占用率需要统计一段时间内的平均占用率，如果时间太短的话参考意义很小，但也不能太大。ActivityManager中通过多种场景下不断调用updateCpuStatsNow()函数不断统计两次调用间的CPU占用率，并且在updateCpuStatsNow()函数内部保证两次统计之间的最小时长是5秒。函数appNotResponding()的入口处会首先记录anr时间，并调用updateCpuStatsNow()函数，在准备输出CPU占用率信息时会再次调用updateCpuStatsNow()函数。因为appNotResponding()函数中所作的工作并不多，而updateCpuStatsNow()函数仅统计5秒以上的CPU占用率，所以正常情况下或者说在CPU占用率不高的情况下输出的CPU占用率应该是发生ANR之前一段时间的。如下所示：

CPU usage from 15491ms to 0ms ago with 99% awake:

  1.2% 2373/system_server: 0.3% user + 0.8% kernel / faults: 75 minor

  0.7% 1220/xxxxxxxxx: 0.7% user + 0% kernel

  0.7% 3106/xxxxxxxxb: 0.1% user + 0.5% kernel / faults: 187 minor

  0.3% 2150/kworker/2:2: 0% user + 0.3% kernel

 

注意以上日志中的“with 99% awake”用来表示这段时间系统是否睡眠过及唤醒状态下的时间百分比，如果系统没有睡眠过将不会输出这句话。

如果发生ANR时及输出ANR日志时CPU的占用率还是非常高，并且导致在appNotResponding()函数中两次调用updateCpuStatsNow()函数中间的间隔时间达到了5秒，那么输出的CPU占用率将是发生ANR之后的，如下所示：

CPU usage from 30378ms to 52370ms later:

  61% 515/logcat: 43% user + 18% kernel / faults: 38891 minor

  47% 497/xxxxxx: 2.8% user + 44% kernel

  46% 174/xxxx: 2.4% user + 43% kernel / faults: 1 minor

  22% 4216/system_server: 12% user + 9.6% kernel / faults: 4073 minor 2 major

  4.2% 928/com.xxx.xxx: 4.2% user + 0% kernel / faults: 2133 minor

  0.7% 3954/xxxx: 0.6% user + 0.1% kernel / faults: 401 minor 44 major

 

在统计CPU占用率这段时间系统中进程数量是有可能发生变化的，对于新增加的进程会在进程前边有个“+”，减少的进程会在前边有个“-”如下所示：

+0% 11024/flush-0:18: 0% user + 0% kernel

+0% 11043/kworker/1:1: 0% user + 0% kernel

        

除了CPU占用率外，有的进程最后边还有faults信息，该信息来自于proc/%d/stat，表示这段时间该进程发生的minor faults次数和major faults次数。Faults表示发生了缺页异常，如果缺页异常处理中需要访问磁盘或emmc等外设存储设备，那么记录一次major faults，如果仅是分配物理内存那么记录一次minor faults。Major faults对性能影响肯定更大。频繁的申请释放内存会导致minor faults增加。日志形式如下：

3.6% 2719/com.xxx.xxx.xxx: 3% user + 0.6% kernel / faults: 3998 minor 4 major

 

所有的进程统计完后最下边是总的CPU占用率。需要注意的是总的CPU占用率并不是所有进程占用率的简单累加，如下边日志进程的CPU占用率相加后大于总的CPU占用率。这种现象是两个原因合成后的结果，一个是总的CPU资源是动态变化的，表现为调频及加减核，另一个是总的CPU占用率和进程CPU占用率的计算方法。计算单个进程CPU占用率，分子是统计时间段内进程处于user和system状态的时间之和，分母是统计时间段内的时长。计算总的CPU占用率时，分子是所有CPU核处于user、system、iowait、irq、softirq状态的时间之和，分母是分子再加上所有核处于idle状态的时间。通过以上分析我们可以清楚他们统计的角度不同，进程的CPU占用率表现的是进程对CPU占用的程度，总的CPU占用率表现的是总的CPU繁忙程度。

CPU usage from 30378ms to 52370ms later:

  61% 515/logcat: 43% user + 18% kernel / faults: 38891 minor

  47% 497/xxxx: 2.8% user + 44% kernel

  46% 174/sdcard: 2.4% user + 43% kernel / faults: 1 minor

  22% 4216/system_server: 12% user + 9.6% kernel / faults: 4073 minor 2 major

  4.2% 928/com.xxx.xxx: 4.2% user + 0% kernel / faults: 2133 minor

  ………..

99% TOTAL: 37% user + 62% kernel + 0% softirq

 

2.3   关键进程调用栈

首先要确定的是什么是关键进程，目前在activityManager中关键进程分成2个梯队。第一个梯队限定最多5个进程，包括发生ANR的进程，ANR进程的父进程，最近有活动的三个常驻进程，活动时间越近，排的位置越靠前。第二梯队是5个最近有活动且CPU占用最高的非常驻进程。这两个梯队都是Android原生支持的，这些进程都是通过虚拟机启动的，获取进程调用栈的方法是通过向进程发送SIGNAL_QUIT信号让虚拟机打印调用栈。

 

----- pid 2387 at 2025-10-07 13:35:20 -----

Cmd line: system_server

 

JNI: CheckJNI is off; workarounds are off; pins=4; globals=628 (plus 13 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=0x41e009a0 self=0x4015d010

  | sysTid=2387 nice=0 sched=0/0 cgrp=apps handle=1075581772

  | state=S schedstat=( 223746664 140890842 579 ) utm=14 stm=8 core=1

  #00  pc 000171a4  /system/lib/libc.so (__ioctl+8)

  #01  pc 0002a9fd  /system/lib/libc.so (ioctl+16)

……..

NATIVE THREADS:

"ndroid.systemui" sysTid=4737 nice=-1 sched=0/0 cgrp=apps

  | state=S schedstat=( 46696015 33539296223 2069 ) utm=0 stm=4 core=0

 

"ndroid.systemui" sysTid=4738 nice=-1 sched=0/0 cgrp=apps

  | state=S schedstat=( 848542014 35584252976 23359 ) utm=33 stm=51 core=0

 

这些日志都是在虚拟机中生成的，日志如上所示。CheckJNI is off表示调用JNI函数时不会进行额外的错误检查，如果是on状态那么会进行检查。在JNI函数通过buffer返回数据时，如果设置了forcecopy，那么会分配临时buffer并进行初始化，将数据从native函数复制到临时buffer，然后再返回给java层，在这种情况下日志中会打印(with forecopy)。有的APK程序版本较老，目标平台在pre-ICS版本之前（<=13），会打印workarounds are on，表示针对这些应用程序虚拟机中会采用一下workaround机制避免错误，默认情况下都是workarounds are off。Pins和golbals的意义尚不清楚，欢迎高人指点。

虚拟机中通过threadList链表维护所有虚拟机中创建的线程，日志中的“DALVIK THREADS:”表示后边的调用栈都是虚拟机中的线程调用栈。Mutexes一行打印的是虚拟机中几个关键mutex的值，tll是保护threadList的threadListLock mutex的值，tsl是保护所有线程suspend状态的_threadSuspendLock mutex的值，tscl是保护变量suspendCount的mutex的值，ghl是保护heap的gcHeapLock的mutex的值。

 

线程信息中首先是线程名字，如“main”。虚拟机中的线程分为守护线程和用户线程，可以这么理解，用户线程是为用户服务的，而守护线程是为用户线程服务的，所以设计上如果所有的守护线程都退出了，那么虚拟机将结束所有守护线程然后退出。在日志中如果该线程是守护线程，那么在线程名字后边会有“daemon”字符串，默认情况下创建的线程都是用户线程。

 

Prio是android中线程的优先级，需要注意的是这个数字和linux线程优先级nice值的对应关系。Prio共分10级，为1到10，和nice值对应关系如下所示（在访问数组时会-1）。从代码中可以看出对于prio为5的线程，其nice值为ANDROID_PRIORITY_NORMAL既为0。

static const int kNiceValues[10] = {

    ANDROID_PRIORITY_LOWEST,                /* 1 (MIN_PRIORITY) */

    ANDROID_PRIORITY_BACKGROUND + 6,

    ANDROID_PRIORITY_BACKGROUND + 3,

    ANDROID_PRIORITY_BACKGROUND,

    ANDROID_PRIORITY_NORMAL,                /* 5 (NORM_PRIORITY) */

    ANDROID_PRIORITY_NORMAL - 2,

    ANDROID_PRIORITY_NORMAL - 4,

    ANDROID_PRIORITY_URGENT_DISPLAY + 3,

    ANDROID_PRIORITY_URGENT_DISPLAY + 2,

    ANDROID_PRIORITY_URGENT_DISPLAY         /* 10 (MAX_PRIORITY) */

};

定义在dalvik/vm/os/android.cpp中

 

enum {

    /*

     * ***********************************************

     * ** Keep in sync with android.os.Process.java **

     * ***********************************************

     *

     * This maps directly to the "nice" priorities we use in Android.

     * A thread priority should be chosen inverse-proportionally to

     * the amount of work the thread is expected to do. The more work

     * a thread will do, the less favorable priority it should get so that

     * it doesn't starve the system. Threads not behaving properly might

     * be "punished" by the kernel.

     * Use the levels below when appropriate. Intermediate values are

     * acceptable, preferably use the {MORE|LESS}_FAVORABLE constants below.

     */

    ANDROID_PRIORITY_LOWEST         =  19,

 

    /* use for background tasks */

    ANDROID_PRIORITY_BACKGROUND     =  10,

 

    /* most threads run at normal priority */

    ANDROID_PRIORITY_NORMAL         =   0,

 

    /* threads currently running a UI that the user is interacting with */

    ANDROID_PRIORITY_FOREGROUND     =  -2,

 

    /* the main UI thread has a slightly more favorable priority */

    ANDROID_PRIORITY_DISPLAY        =  -4,

 

    /* ui service treads might want to run at a urgent display (uncommon) */

    ANDROID_PRIORITY_URGENT_DISPLAY =  HAL_PRIORITY_URGENT_DISPLAY,

 

    /* all normal audio threads */

    ANDROID_PRIORITY_AUDIO          = -16,

 

    /* service audio threads (uncommon) */

    ANDROID_PRIORITY_URGENT_AUDIO   = -19,

 

    /* should never be used in practice. regular process might not

     * be allowed to use this level */

    ANDROID_PRIORITY_HIGHEST        = -20,

 

    ANDROID_PRIORITY_DEFAULT        = ANDROID_PRIORITY_NORMAL,

    ANDROID_PRIORITY_MORE_FAVORABLE = -1,

    ANDROID_PRIORITY_LESS_FAVORABLE = +1,

};

定义在/system/core/include/utils/ThreadDefs.h中

 

tid是虚拟机管理该进程中线程的id，并不是linux系统的进程ID。

 

遗留问题：

通过anr日志每项内容的分析都可以牵出一堆的android实现机制，以上只是粗略了分析了部分内容，还有很多内容需要研究。欢迎各位朋友指点。