Android 系统稳定性 - ANR（二）

【原创】Android 系统稳定性 - ANR（二）

文章都为原创，转载请注明出处，未经容许而盗用者追究法律责任。 
好久以前写的了，留着有点浪费，共享之。
编写者：李文栋
P.S. OpenOffice粘贴过来后格式有些混乱。

1.2 如何分析ANR问题

引发ANR问题的根本缘由，总的来讲能够概括为两类：

• 应用进程自身引发的，例如：

主线程阻塞、挂起、死循环

应用进程的其余线程的CPU占用率高，使得主线程没法抢占到CPU时间片

• 其余进程间接引发的，例如：

当前应用进程进行进程间通讯请求其余进程，其余进程的操做长时间没有反馈

其余进程的CPU占用率高，使得当前应用进程没法抢占到CPU时间片

分析ANR问题时，以上述可能的几种缘由为线索，经过分析各类日志信息，大多数状况下你就能够很容易找到问题所在了。

注意：我很诚恳的向读者说明，确实有一些ANR问题很难调查清楚，由于整个系统不稳定的因素不少，例如Linux Kernel自己的bug引发的内存碎片过多、硬件损坏等。这类比较底层的缘由引发的ANR问题每每无从查起，而且这根本不是应用程序的问题，浪费了应用开发人员不少时间，若是你从事过整个系统的开发和维护工做的话会深有体会。因此我不能保证了解了本章的全部内容后可以解决一切ANR问题，若是出现了很疑难的ANR问题，我建议最好去和作驱动和内核的朋友聊聊，或者，若是问题只是个十万分之一的偶然现象，不影响程序的正常运行，我却是建议不去理它。

1.2.1 分析ANR的利器

Android会在ANR发生时输出不少有用的信息帮助分析问题缘由，咱们先来看一下ANR的异常信息，使用logcat命令查看会获得相似以下的log：

//WindowManager所在的进程是system_server，进程号是127

I/WindowManager( 127): Input event dispatching timed out sending to com.example.anrdemo/com.example.anrdemo.ANRActivity

 

//system_server进程中的ActivityManagerService请求kernel向5033进程发送SIGNAL_QUIT请求

//你能够在shell中使用命令达到相同的目的：adb shell kill -3 5033

//和其余的Java虚拟机同样，SIGNAL_QUIT也是Dalvik内部支持的功能之一

I/Process ( 127): Sending signal. PID: 5033 SIG: 3

 

//5033进程的虚拟机实例接收到SIGNAL_QUIT信号后会将进程中各个线程的函数堆栈信息输出到traces.txt文件中

//发生ANR的进程正常状况下会第一个输出

I/dalvikvm( 5033): threadid=4: reacting to signal 3

I/dalvikvm( 5033): Wrote stack traces to '/data/anr/traces.txt'

... ...//另外还有其余一些进程

 

//随后会输出CPU使用状况

E/ActivityManager( 127): ANR in com.example.anrdemo (com.example.anrdemo/.ANRActivity)

//Reason表示致使ANR问题的直接缘由

E/ActivityManager( 127): Reason: keyDispatchingTimedOut

E/ActivityManager( 127): Load: 3.85 / 3.41 / 3.16

 

//请注意ago，表示ANR发生以前的一段时间内的CPU使用率，并非某一时刻的值

E/ActivityManager( 127): CPU usage from 26835ms to 3662ms ago with 99% awake:

E/ActivityManager( 127): 9.4% 98/mediaserver: 9.4% user + 0% kernel

E/ActivityManager( 127): 8.9% 127/system_server: 6.9% user + 2% kernel / faults: 1823 minor

... ...

E/ActivityManager( 127): +0% 5033/com.example.anrdemo: 0% user + 0% kernel

E/ActivityManager( 127): 39% TOTAL: 32% user + 6.1% kernel

 

//这里是later，表示ANR发生以后

E/ActivityManager( 127): CPU usage from 601ms to 1132ms later with 99% awake:

E/ActivityManager( 127): 10% 127/system_server: 1.7% user + 8.9% kernel / faults: 5 minor

E/ActivityManager( 127): 10% 163/InputDispatcher: 1.7% user + 8.9% kernel

E/ActivityManager( 127): 1.7% 127/system_server: 1.7% user + 0% kernel

E/ActivityManager( 127): 1.7% 135/SurfaceFlinger: 0% user + 1.7% kernel

E/ActivityManager( 127): 1.7% 2814/Binder Thread #: 1.7% user + 0% kernel

... ...

E/ActivityManager( 127): 37% TOTAL: 27% user + 9.2% kernel

从log中可以知道，发生ANR时Android为咱们提供了两种“利器”：traces文件和CPU使用率。以上作了简单注释，不过稍后再详细分析它们。

1.2.2 ANR信息是如何输出的

咱们再来看看这些log是怎样被输出的，这很重要，知其然，也要知其因此然。代码在ActivityManagerService类中，找到它的appNotResponding函数。

final void appNotResponding(ProcessRecord app, ActivityRecord activity,

ActivityRecord parent, final String annotation) {

//firstPids和lastPids两个集合存放那些将会在traces中输出信息的进程的进程号

ArrayList<Integer> firstPids = new ArrayList<Integer>(5);

SparseArray<Boolean> lastPids = new SparseArray<Boolean>(20);

 

//mController是IActivityController接口的实例，是为Monkey测试程序预留的，默认为null

if (mController != null) {

... ...

}

 

long anrTime = SystemClock.uptimeMillis();

if (MONITOR_CPU_USAGE) {

updateCpuStatsNow(); //更新CPU使用率

}

 

synchronized (this) { //一些特定条件下会忽略ANR

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;

}

 

//使用一个标志变量避免同一个应用在没有处理完时重复输出log

app.notResponding = true;

... ...

 

//①当前发生ANR的应用进程被第一个添加进firstPids集合中

firstPids.add(app.pid);

... ...

}

... ...

 

//②dumpStackTraces是输出traces文件的函数

File tracesFile = dumpStackTraces(true, firstPids, processStats, lastPids, null);

 

String cpuInfo = null;

if (MONITOR_CPU_USAGE) { //MONITOR_CPU_USAGE默认为true

updateCpuStatsNow(); //再次更新CPU信息

synchronized (mProcessStatsThread) {

//输出ANR发生前一段时间内的CPU使用率

cpuInfo = mProcessStats.printCurrentState(anrTime);

}

info.append(processStats.printCurrentLoad());

info.append(cpuInfo);

}

//输出ANR发生后一段时间内的CPU使用率

info.append(processStats.printCurrentState(anrTime));

... ...

 

//③将ANR信息同时输出到DropBox中

addErrorToDropBox("anr", app, app.processName, activity, parent, annotation,

cpuInfo, tracesFile, null);

... ...

 

//在Android4.0中能够设置是否不显示ANR提示对话框，若是设置的话就不会显示对话框，而且会杀掉ANR进程

boolean showBackground = Settings.Secure.getInt(mContext.getContentResolver(),

Settings.Secure.ANR_SHOW_BACKGROUND, 0) != 0;

synchronized (this) {

if (!showBackground && !app.isInterestingToUserLocked() && app.pid != MY_PID) {

... ...

Process.killProcessQuiet(app.pid);

return;

}

... ...

 

// 显示ANR提示对话框

Message msg = Message.obtain();

HashMap map = new HashMap();

msg.what = SHOW_NOT_RESPONDING_MSG;

msg.obj = map;

map.put("app", app);

if (activity != null) {

map.put("activity", activity);

}

mHandler.sendMessage(msg);

}

}

 

有三个关键点须要注意：

① 当前发生ANR的应用进程被第一个添加进firstPids集合中，因此会第一个向traces文件中写入信息。反过来讲，traces文件中出现的第一个进程正常状况下就是发生ANR的那个进程。不过有时候会很不凑巧，发生ANR的进程尚未来得及输出trace信息，就因为某种缘由退出了，因此偶尔会遇到traces文件中找不到发生ANR的进程信息的状况。

② dumpStackTraces是输出traces文件的函数，接下来分析这个函数

③ addErrorToDropBox函数将ANR信息同时输出到DropBox中，它也是个很是有用的日志存放工具，后面也会分析它的做用。

public static File dumpStackTraces(boolean clearTraces, ArrayList<Integer> firstPids,

ProcessStats processStats, SparseArray<Boolean> lastPids, String[] nativeProcs) {

//系统属性“dalvik.vm.stack-trace-file”用来配置trace信息输出文件

String tracesPath = SystemProperties.get("dalvik.vm.stack-trace-file", null);

if (tracesPath == null || tracesPath.length() == 0) {

return null;

}

 

File tracesFile = new File(tracesPath);

try {

File tracesDir = tracesFile.getParentFile();

if (!tracesDir.exists()) tracesFile.mkdirs();

//FileUtils.setPermissions是个颇有用的函数，设置文件属性时常常会用到

FileUtils.setPermissions(tracesDir.getPath(), 0775, -1, -1); // drwxrwxr-x

 

//clearTraces为true，会删除旧文件，建立新文件

if (clearTraces && tracesFile.exists()) tracesFile.delete();

tracesFile.createNewFile();

FileUtils.setPermissions(tracesFile.getPath(), 0666, -1, -1); // -rw-rw-rw-

} catch (IOException e) {

Slog.w(TAG, "Unable to prepare ANR traces file: " + tracesPath, e);

return null;

}

 

//一个重载函数

dumpStackTraces(tracesPath, firstPids, processStats, lastPids, nativeProcs);

return tracesFile;

}

 

有两个关键点须要注意：

① 聪明的你确定已经知道，之因此trace信息会输出到“/data/anr/traces.txt”文件中，就是系统属性“dalvik.vm.stack-trace-file”设置的。你能够经过在设备的shell中使用setprop和getprop对系统属性进行设置和读取：

getpropdalvik.vm.stack-trace-file

setprop dalvik.vm.stack-trace-file /tmp/stack-traces.txt

② 每次发生ANR时都会删除旧的traces文件，从新建立新文件。也就是说Android只保留最后一次发生ANR时的traces信息，那么之前的traces信息就丢失了么？稍后回答。

接着来看重载的dumpStackTraces函数。

 

private static void dumpStackTraces(String tracesPath, ArrayList<Integer> firstPids,

ProcessStats processStats, SparseArray<Boolean> lastPids, String[] nativeProcs) {

//使用FileObserver监听应用进程是否已经完成写入traces文件的操做

//Android在判断桌面壁纸文件是否设置完成时也是用的FileObserver，颇有用的类

FileObserver observer = new FileObserver(tracesPath, FileObserver.CLOSE_WRITE) {

public synchronized void onEvent(int event, String path) { notify(); }

};

... ...

//首先输出firstPids集合中指定的进程，这些也是对ANR问题来讲最重要的进程

if (firstPids != null) {

try {

int num = firstPids.size();

for (int i = 0; i < num; i++) {

synchronized (observer) {

//前面提到的SIGNAL_QUIT

Process.sendSignal(firstPids.get(i), Process.SIGNAL_QUIT);

observer.wait(200);

... ...

}

提示：若是你在解决其余问题时也须要查看Java进程中各个线程的函数堆栈信息，就可使用向目标进程发送SIGNAL_QUIT（3）这个技巧。其实这个名称有点误导，它并不会让进程真正退出。

1.2.3 DropBox

刚才留了一个问题：Android只保留最后一次发生ANR时的traces信息，那么之前的traces信息就丢失了么？为了加强Android的异常信息收集管理能力，从2.2开始增长了DropBox功能。

DropBox（简称DB）是系统进程中的一个服务，在system_server进程启动时建立，而且它没有运行在单独的线程中，而是运行在system_server的ServerThread线程中。咱们能够将ServerThread称做system_server的主线程，ServerThread线程除了启动并维护各个服务外，还负责检测一些重要的服务是否死锁，这一点到后面的Watchdog部分再分析<!-- Watchdog写完后注意补充章节号 -->。DB被建立的代码以下。

SystemServer.java → ServerThread.run()

Slog.i(TAG, "DropBox Service");

ServiceManager.addService(Context.DROPBOX_SERVICE, //服务名称为“dropbox”

new DropBoxManagerService(context, new File("/data/system/dropbox")));

 

“/data/system/dropbox”是DB指定的文件存放位置。下面来看一下DB服务的主要功能。

1. DropBoxManagerService

DropBoxManagerService（简称DBMS）就是DB服务的本尊，它的主要功能接口包括如下几个函数：

public voidadd(DropBoxManager.Entryentry)

DBMS将全部要添加的日志都用DropBoxManager.Entry类型的对象表示，经过add函数添加，而且直到目前为止一个Entry对象对应着一个日志文件。

publicboolean isTagEnabled(String tag)

经过给每个Entry设置一个tag能够标识不一样类型的日志，而且能够灵活的启用/禁用某种类型的日志，isTagEnabled用来判断指定类型的日志是否被启用/禁用了，一旦禁用就不会再记录这种类型的日志。默认是不由用任何类型的日志的。稍后说明如何启用/禁用日志。

publicsynchronized DropBoxManager.Entry getNextEntry(String tag, long millis)

咱们能够经过getNextEntry函数获取指定类型和指定时间点以后的第一条日志，要使用这个功能应用程序须要有“android.permission.READ_LOGS”的权限，而且在使用完毕返回的Entry对象后要调用其close函数确保关闭日志文件的文件描述符（若是不关闭的话可能形成进程打开的文件描述符超过1024而崩溃，Android中限制每一个进程的文件描述符上限为1024）。

 

DBMS提供了不少的配置项用来限制对磁盘的使用，经过SettingsProvider应用程序维护，数据存放在其settings.db数据库中。这些配置项也都有默认值，罗列以下：

• Settings.Secure.DROPBOX_AGE_SECONDS = "dropbox_age_seconds"

日志文件保存的最长时间，默认3天

• Settings.Secure.DROPBOX_MAX_FILES = "dropbox_max_files"

日志文件的最大数量，默认值是1000

• Settings.Secure.DROPBOX_QUOTA_KB = "dropbox_quota_kb"

磁盘空间最大使用量

• Settings.Secure.DROPBOX_QUOTA_PERCENT = "dropbox_quota_percent"

 

• Settings.Secure.DROPBOX_RESERVE_PERCENT = "dropbox_reserve_percent"

 

• Settings.Secure.DROPBOX_TAG_PREFIX = "dropbox:"

 

//应用程序能够利用DropBox来作事情，收集日志等

1.2.4 traces.txt

终于到大明星出场的时候了，一块儿来看一下traces.txt的庐山真面目。如下是笔者写的一个演示程序制造出的一次ANR的trace信息：

//文件中输出的第一个进程的trace信息，正是发生ANR的演示程序

//开头显示进程号、ANR发生的时间点和进程名称

----- pid 9183 at 2012-09-28 22:20:42 -----

Cmd line: com.example.anrdemo

 

DALVIK THREADS: //如下是各个线程的函数堆栈信息

//mutexes表示虚拟机实例中各类线程相关对象锁的value值

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

//依次是：线程名、线程优先级、线程建立时的序号、①线程当前状态

"main" prio=5 tid=1 TIMED_WAIT

//依次是：线程组名称、suspendCount、debugSuspendCount、线程的Java对象地址、线程的Native对象地址

| group="main" sCount=1 dsCount=0 obj=0x4025b1b8 self=0xce68

//sysTid是线程号，主线程的线程号和进程号相同

| sysTid=9183 nice=0 sched=0/0 cgrp=default handle=-1345002368

| schedstat=( 140838632 210998525 213 )

at java.lang.VMThread.sleep(Native Method)

at java.lang.Thread.sleep(Thread.java:1213)

at java.lang.Thread.sleep(Thread.java:1195)

at com.example.anrdemo.ANRActivity.makeANR(ANRActivity.java:44)

at com.example.anrdemo.ANRActivity.onClick(ANRActivity.java:38)

at android.view.View.performClick(View.java:2486)

at android.view.View$PerformClick.run(View.java:9130)

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

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

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

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

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

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

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

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

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

 

//②Binder线程是进程的线程池中用来处理binder请求的线程

"Binder Thread #2" prio=5 tid=8 NATIVE

| group="main" sCount=1 dsCount=0 obj=0x40750b90 self=0x1440b8

| sysTid=9190 nice=0 sched=0/0 cgrp=default handle=1476256

| schedstat=( 915528 18463135 4 )

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

 

"Binder Thread #1" prio=5 tid=7 NATIVE

| group="main" sCount=1 dsCount=0 obj=0x4074f848 self=0x78d40

| sysTid=9189 nice=0 sched=0/0 cgrp=default handle=1308088

| schedstat=( 3509523 25543212 10 )

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

 

//线程名称后面标识有daemon，说明这是个守护线程

"Compiler" daemon prio=5 tid=6 VMWAIT

| group="system" sCount=1 dsCount=0 obj=0x4074b928 self=0x141e78

| sysTid=9188 nice=0 sched=0/0 cgrp=default handle=1506000

| schedstat=( 21606438 21636964 101 )

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

 

//JDWP线程是支持虚拟机调试的线程，不须要关心

"JDWP" daemon prio=5 tid=5 VMWAIT

| group="system" sCount=1 dsCount=0 obj=0x4074b878 self=0x16c958

| sysTid=9187 nice=0 sched=0/0 cgrp=default handle=1510224

| schedstat=( 366211 2807617 7 )

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

//“Signal Catcher”负责接收和处理kernel发送的各类信号，例如SIGNAL_QUIT、SIGNAL_USR1等就是被该线程

//接收到，这个文件的内容就是由该线程负责输出的，能够看到它的状态是RUNNABLE，不过此线程也不须要关心

"Signal Catcher" daemon prio=5 tid=4 RUNNABLE

| group="system" sCount=0 dsCount=0 obj=0x4074b7b8 self=0x150008

| sysTid=9186 nice=0 sched=0/0 cgrp=default handle=1501664

| schedstat=( 1708985 6286621 9 )

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

 

"GC" daemon prio=5 tid=3 VMWAIT

| group="system" sCount=1 dsCount=0 obj=0x4074b710 self=0x168010

| sysTid=9185 nice=0 sched=0/0 cgrp=default handle=1503184

| schedstat=( 305176 4821778 2 )

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

 

"HeapWorker" daemon prio=5 tid=2 VMWAIT

| group="system" sCount=1 dsCount=0 obj=0x4074b658 self=0x16a080

| sysTid=9184 nice=0 sched=0/0 cgrp=default handle=550856

| schedstat=( 33691407 26336669 15 )

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

 

----- end 9183 -----

 

----- pid 127 at 2012-09-28 22:20:42 -----

Cmd line: system_server

... ...

//省略其余进程的信息

 

有一个关键点须要注意：

➀ 线程有不少状态，了解这些状态的意义对分析ANR的缘由是有帮助的，总结以下：

Thread.java中的状态和Thread.cpp中的状态是有对应关系的。能够看到前者更加归纳，也比较容易理解，面向Java的使用者；然后者更详细，面向虚拟机内部的环境。traces.txt中显示的线程状态都是Thread.cpp中定义的。另外，全部的线程都是遵循POSIX标准的本地线程。关于线程更多的说明能够查阅源码/dalvik/vm/Thread.cpp中的说明。<!-- 线程的ThreadGroup最好也写进去 -->

traces.txt文件中的这些信息是由每一个Dalvik进程的SignalCatcher线程输出的，相关代码能够查看/dalvik/vm/目录下的SignalCatcher.cpp::logThreadStacks函数和Thread.cpp:: dvmDumpAllThreadsEx函数。另外请注意，输出堆栈信息时SignalCatcher会暂停全部线程。

经过该文件很容易就能知道问题进程的主线程发生ANR时正在执行怎样的操做。例如上述示例，ANRActivity在makeANR函数中执行线程sleep时发生ANR，能够推测sleep时间过长，超过了超时上限致使。这是一种比较简单的状况，实际开发中会遇到不少诡异的、更加复杂的状况，在后面的实例讲解一节会详细说明。

1.2.5 CPU使用率

这部分的内容主要涉及到Linux的相关知识，数据是从“/proc/stat”文件中读取的，Android中仅仅是汇总和记录这些数据而已，熟悉Linux的读者能够跳过本节内容。

前面简单说明了CPU使用率信息，咱们回顾一下，此次会有更多的知识点要说明。

E/ActivityManager( 127): ANR in com.example.anrdemo (com.example.anrdemo/.ANRActivity)

E/ActivityManager( 127): Reason: keyDispatchingTimedOut

E/ActivityManager( 127): Load: 3.85 / 3.41 / 3.16 //➀ CPU平均负载

 

//②ANR发生以前的一段时间内的CPU使用率

E/ActivityManager( 127): CPU usage from 26835ms to 3662ms ago with 99% awake://③

E/ActivityManager( 127): 9.4% 98/mediaserver: 9.4% user + 0% kernel

E/ActivityManager( 127): 8.9% 127/system_server: 6.9% user + 2% kernel / faults: 1823 minor //⑤ minor或者major的页错误次数

... ...

E/ActivityManager( 127)://⑥+0% 5033/com.example.anrdemo: 0% user + 0% kernel

E/ActivityManager( 127): 39% TOTAL: 32% user + 6.1% kernel

 

//⑦ANR发生以后的一段时间内的CPU使用率

E/ActivityManager( 127): CPU usage from 601ms to 1132ms later with 99% awake:

E/ActivityManager( 127): 10% 127/system_server: 1.7% user + 8.9% kernel / faults: 5 minor

E/ActivityManager( 127): 10% 163/InputDispatcher: 1.7% user + 8.9% kernel

E/ActivityManager( 127): 1.7% 127/system_server: 1.7% user + 0% kernel

E/ActivityManager( 127): 1.7% 135/SurfaceFlinger: 0% user + 1.7% kernel

E/ActivityManager( 127): 1.7% 2814/Binder Thread #: 1.7% user + 0% kernel

... ...

E/ActivityManager( 127): 37% TOTAL: 27% user + 9.2% kernel

以上信息其实包含了两个概念：CPU负载和CPU使用率，它们是不一样的。不过负载的概念主要是作大型服务器端应用时关注的性能指标，在Android开发中咱们更加关注的是使用率。下面详细说明，有八个关键点须要注意：

① CPU负载/平均负载

CPU负载是指某一时刻系统中运行队列长度之和加上当前正在CPU上运行的进程数，而CPU平均负载能够理解为一段时间内正在使用和等待使用CPU的活动进程的平均数量。在Linux中“活动进程”是指当前状态为运行或不可中断阻塞的进程。一般所说的负载其实就是指平均负载。

用一个从网上看到的很生动的例子来讲明（不考虑CPU时间片的限制），把设备中的一个单核CPU比做一个电话亭，把进程比做正在使用和等待使用电话的人，假若有一我的正在打电话，有三我的在排队等待，此刻电话亭的负载就是4。使用中会不断的有人打完电话离开，也会不断的有其余人排队等待，为了获得一个有参考价值的负载值，能够规定每隔5秒记录一下电话亭的负载，并将某一时刻以前的一分钟、五分钟、十五分钟的的负载状况分别求平均值，最终就获得了三个时段的平均负载。

实际上咱们一般关心的就是在某一时刻的前一分钟、五分钟、十五分钟的CPU平均负载，例如以上日志中这三个值分别是3.85、3.41、3.16，说明前一分钟内正在使用和等待使用CPU的活动进程平均有3.85个，依此类推。在大型服务器端应用中主要关注的是第五分钟和第十五分钟的两个值，可是Android主要应用在便携手持设备中，有特殊的软硬件环境和应用场景，短期内的系统的较高负载就有可能形成ANR，因此笔者认为一分钟内的平均负载相对来讲更具备参考价值。

CPU的负载和使用率没有必然关系，有可能只有一个进程在使用CPU，但执行的是复杂的操做；也有可能等待和正在使用CPU的进程不少，但每一个进程执行的都是简单操做。

实际处理问题时偶尔会遇到因为平均负载高引发的ANR，典型的特征就是系统中应用进程数量多，CPU总使用率较高，可是每一个进程的CPU使用率不高，当前应用进程主线程没有异常阻塞，一分钟内的CPU平均负载较高。

提示：Linux内核不断进行着CPU负载的记录，咱们能够在任意时刻经过在shell中执行“cat /proc/loadavg”查看。

② ANR发生以前和以后一段时间的CPU使用率

CPU使用率能够理解为一段时间（记做T）内除CPU空闲时间（记做I）以外的时间与这段时间T的比值，用公式表示能够写为：

CPU使用率= (T – I) / T

而时间段T是两个采样时间点的时间差值。

之因此能够这样计算，是由于Linux内核会把从系统启动开始到当前时刻CPU活动的全部时间信息都记录下来，咱们能够经过查看“/proc/stat”文件获取这些信息。主要包括如下几种时间，这些时间都是从系统启动开始计算的，单位都是0.01秒：

user： CPU在用户态的运行时间，不包括nice值为负数的进程运行的时间

nice： CPU在用户态而且nice值为负数的进程运行的时间

system：CPU在内核态运行的时间

idle： CPU空闲时间，不包括iowait时间

iowait： CPU等待I/O操做的时间

irq： CPU硬中断的时间

softirq：CPU软中断的时间

注意：随着Linux内核版本的不一样，包含的时间类型有可能不一样，例如2.6.11中增长的stealstolen等。但根据Android源码，咱们只须要关心以上七种类型便可。

CPU使用率的计算是在ProcessStats类中实现的。若是在某两个时刻T1和T2（T1 < T2）进行采样记录，CPU使用率的整个算法能够概括为如下几个公式：

userTime = (user2 + nice2) – (user1 + nice1)

systemTime = system2 - system1

idleTime = idle2 - idle1

iowaitTime = iowait2 - iowait1

irqTime = irq2 - irq1

softirqTime = softirq2 - softirq1

TotalTime = userTime + systemTime + idleTime + iowaitTime + irqTime + softirqTime

有了以上数据就能够计算具体的使用率了，例如用户态CPU使用率为：

userCpuUsage = userTime / TotalTime

依此类推能够计算其余类型的使用率。而整个时间段内CPU使用率为：

CpuUsage = (TotalTime – idleTime) / TotalTime

以上计算的是整个系统的CPU使用率，对于指定进程的使用率是经过读取该进程的“/proc/进程号/stat”文件计算的，而对于指定进程的指定线程的使用率是经过读取该线程的“/proc/进程号/task/线程号/stat”文件计算的。进程和线程的CPU使用率只包含该进程或线程的总使用率、用户态使用率和内核态使用率。

AMS在执行appNotResponding函数过程当中，共输出了两个时间段的CPU使用率，一般状况下在ANR发生时间点以前和以后各有一段。两段使用率都是两次调用ProcessStats对象的update函数，每次调用update函数时会保留上一时间点的采样数据，并记录当前时间点的采样数据。而后再调用ProcessStats对象的printCurrentState函数，按照上述公式概括的算法计算CPU使用率，并输出最终的结果。再详细看一下代码：

ActivityManagerService.java → appNotResponding

//第一次使用成员变量mProcessStats采样

if (MONITOR_CPU_USAGE) {

updateCpuStatsNow();

}

... ...

 

//声明了一个局部变量，参数true表示包括线程信息

final ProcessStats processStats = new ProcessStats(true);

//将processStats做为实参传入，在dumpStackTraces中相隔500毫秒两次调用其update函数进行采样

File tracesFile = dumpStackTraces(true, firstPids, processStats, lastPids);

 

String cpuInfo = null;

if (MONITOR_CPU_USAGE) {

//由于在第一次调用后，可能因为输出trace信息等操做，中间执行了较长的时间，因此有第二次使用成员变量

//mProcessStats采样，尽可能使得采样时间点靠后。

//此函数中要求连续两次采样时间间隔很多于5秒，因此通常不会执行第二次采样。一旦执行，就会出现两个采样

//时间点一个在ANR发生以前，另外一个在其以后，或者两个时间点都在ANR发生以后的状况。

updateCpuStatsNow();

synchronized (mProcessStatsThread) {

//mProcessStats是成员变量，建立对象时传入的参数是false，因此不包括线程信息

//此处先输出ANR发生以前一段时间内的CPU使用率

cpuInfo = mProcessStats.printCurrentState(anrTime);

}

info.append(processStats.printCurrentLoad());

info.append(cpuInfo);

}

//processStats对象是在ANR发生后建立并采样的，因此输出的是ANR发生以后一段时间内的CPU使用率

info.append(processStats.printCurrentState(anrTime));

③ 非睡眠时间百分比

在记录CPU使用率的每一个采样时间点时使用了两种记录方法：SystemClock.uptimeMillis()和SystemClock.elapsedRealtime()，二者的区别就是uptimeMillis不包含睡眠时间，因此两个采样时间点之间的uptimeMillis和elapsedRealtime之比就是非睡眠时间百分比。

➃页错误次数

进程的CPU使用率最后输出的“faults: xxx minor/major”部分表示的是页错误次数，当次数为0时不显示。major是指Major Page Fault（主要页错误，简称MPF），内核在读取数据时会前后查找CPU的高速缓存和物理内存，若是找不到会发出一个MPF信息，请求将数据加载到内存。Minor是指Minor Page Fault（次要页错误，简称MnPF），磁盘数据被加载到内存后，内核再次读取时，会发出一个MnPF信息。一个文件第一次被读写时会有不少的MPF，被缓存到内存后再次访问MPF就会不多，MnPF反而变多，这是内核为减小效率低下的磁盘I/O操做采用的缓存技术的结果。

若是ANR发生时发现CPU使用率中iowait占比很高，能够经过查看进程的major次数来推断是哪一个进程在进行磁盘I/O操做。<!-- 求证一下 -->

➄新增和移除的进程或线程

若是一个进程或线程的CPU使用率前有“+”，说明该进程或线程是在最后两次CPU使用率采样时间段内新建的；反之若是是“-”，说明该进程或线程在采样时间段内终止了；若是是空，说明该进程或线程是在倒数第二次采样时间点以前已经存在。

至此，全部与ANR相关的日志内容都已介绍完毕，相信读者之后处理ANR问题时可以有的放矢了。