時間:2013-10-16 17:16來源:www.chengxuyuans.com

文章都為原創(chuàng)，轉(zhuǎn)載請注明出處，未經(jīng)允許而盜用者追究法律責(zé)任。
很久之前寫的了，留著有點浪費，共享之。
編寫者：李文棟
P.S. OpenOffice粘貼過來后格式有些混亂。

1.2 如何分析ANR問題

引起ANR問題的根本原因，總的來說可以歸納為兩類：

• 應(yīng)用進(jìn)程自身引起的，例如：

主線程阻塞、掛起、死循環(huán)

應(yīng)用進(jìn)程的其他線程的CPU占用率高，使得主線程無法搶占到CPU時間片

• 其他進(jìn)程間接引起的，例如：

當(dāng)前應(yīng)用進(jìn)程進(jìn)行進(jìn)程間通信請求其他進(jìn)程，其他進(jìn)程的操作長時間沒有反饋

其他進(jìn)程的CPU占用率高，使得當(dāng)前應(yīng)用進(jìn)程無法搶占到CPU時間片

分析ANR問題時，以上述可能的幾種原因為線索，通過分析各種日志信息，大多數(shù)情況下你就可以很容易找到問題所在了。

注意：我很誠懇的向讀者說明，確實有一些ANR問題很難調(diào)查清楚，因為整個系統(tǒng)不穩(wěn)定的因素很多，例如Linux Kernel本身的bug引起的內(nèi)存碎片過多、硬件損壞等。這類比較底層的原因引起的ANR問題往往無從查起，并且這根本不是應(yīng)用程序的問題，浪費了應(yīng)用開發(fā)人員很多時間，如果你從事過整個系統(tǒng)的開發(fā)和維護(hù)工作的話會深有體會。所以我不能保證了解了本章的所有內(nèi)容后能夠解決一切ANR問題，如果出現(xiàn)了很疑難的ANR問題，我建議最好去和做驅(qū)動和內(nèi)核的朋友聊聊，或者，如果問題只是個十萬分之一的偶然現(xiàn)象，不影響程序的正常運行，我倒是建議不去理它。

1.2.1 分析ANR的利器

Android會在ANR發(fā)生時輸出很多有用的信息幫助分析問題原因，我們先來看一下ANR的異常信息，使用logcat命令查看會得到類似如下的log：

//WindowManager所在的進(jìn)程是system_server，進(jìn)程號是127

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

//system_server進(jìn)程中的ActivityManagerService請求kernel向5033進(jìn)程發(fā)送SIGNAL_QUIT請求

//你可以在shell中使用命令達(dá)到相同的目的：adb shell kill -3 5033

//和其他的Java虛擬機一樣，SIGNAL_QUIT也是Dalvik內(nèi)部支持的功能之一

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

//5033進(jìn)程的虛擬機實例接收到SIGNAL_QUIT信號后會將進(jìn)程中各個線程的函數(shù)堆棧信息輸出到traces.txt文件中

//發(fā)生ANR的進(jìn)程正常情況下會第一個輸出

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

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

... ...//另外還有其他一些進(jìn)程

//隨后會輸出CPU使用情況

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

//Reason表示導(dǎo)致ANR問題的直接原因

E/ActivityManager( 127): Reason: keyDispatchingTimedOut

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

//請注意ago，表示ANR發(fā)生之前的一段時間內(nèi)的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發(fā)生之后

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中能夠知道，發(fā)生ANR時Android為我們提供了兩種“利器”：traces文件和CPU使用率。以上做了簡單注釋，不過稍后再詳細(xì)分析它們。

1.2.2 ANR信息是如何輸出的

我們再來看看這些log是怎樣被輸出的，這很重要，知其然，也要知其所以然。代碼在ActivityManagerService類中，找到它的appNotResponding函數(shù)。

final void appNotResponding(ProcessRecord app, ActivityRecord activity,

ActivityRecord parent, final String annotation) {

//firstPids和lastPids兩個集合存放那些將會在traces中輸出信息的進(jìn)程的進(jìn)程號

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

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

//mController是IActivityController接口的實例，是為Monkey測試程序預(yù)留的，默認(rèn)為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;

}

//使用一個標(biāo)志變量避免同一個應(yīng)用在沒有處理完時重復(fù)輸出log

app.notResponding = true;

... ...

//①當(dāng)前發(fā)生ANR的應(yīng)用進(jìn)程被第一個添加進(jìn)firstPids集合中

firstPids.add(app.pid);

... ...

}

... ...

//②dumpStackTraces是輸出traces文件的函數(shù)

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

String cpuInfo = null;

if (MONITOR_CPU_USAGE) { //MONITOR_CPU_USAGE默認(rèn)為true

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

synchronized (mProcessStatsThread) {

//輸出ANR發(fā)生前一段時間內(nèi)的CPU使用率

cpuInfo = mProcessStats.printCurrentState(anrTime);

}

info.append(processStats.printCurrentLoad());

info.append(cpuInfo);

}

//輸出ANR發(fā)生后一段時間內(nèi)的CPU使用率

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

... ...

//③將ANR信息同時輸出到DropBox中

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

cpuInfo, tracesFile, null);

... ...

//在Android4.0中可以設(shè)置是否不顯示ANR提示對話框，如果設(shè)置的話就不會顯示對話框，并且會殺掉ANR進(jìn)程

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);

}

}

有三個關(guān)鍵點需要注意：

① 當(dāng)前發(fā)生ANR的應(yīng)用進(jìn)程被第一個添加進(jìn)firstPids集合中，所以會第一個向traces文件中寫入信息。反過來說，traces文件中出現(xiàn)的第一個進(jìn)程正常情況下就是發(fā)生ANR的那個進(jìn)程。不過有時候會很不湊巧，發(fā)生ANR的進(jìn)程還沒有來得及輸出trace信息，就由于某種原因退出了，所以偶爾會遇到traces文件中找不到發(fā)生ANR的進(jìn)程信息的情況。

② dumpStackTraces是輸出traces文件的函數(shù)，接下來分析這個函數(shù)

③ addErrorToDropBox函數(shù)將ANR信息同時輸出到DropBox中，它也是個非常有用的日志存放工具，后面也會分析它的作用。

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

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

//系統(tǒng)屬性“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是個很有用的函數(shù)，設(shè)置文件屬性時經(jīng)常會用到

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

//clearTraces為true，會刪除舊文件，創(chuàng)建新文件

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;

}

//一個重載函數(shù)

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

return tracesFile;

}

有兩個關(guān)鍵點需要注意：

① 聰明的你肯定已經(jīng)知道，之所以trace信息會輸出到“/data/anr/traces.txt”文件中，就是系統(tǒng)屬性“dalvik.vm.stack-trace-file”設(shè)置的。你可以通過在設(shè)備的shell中使用setprop和getprop對系統(tǒng)屬性進(jìn)行設(shè)置和讀?。?/span>

getpropdalvik.vm.stack-trace-file

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

② 每次發(fā)生ANR時都會刪除舊的traces文件，重新創(chuàng)建新文件。也就是說Android只保留最后一次發(fā)生ANR時的traces信息，那么以前的traces信息就丟失了么？稍后回答。

接著來看重載的dumpStackTraces函數(shù)。

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

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

//使用FileObserver監(jiān)聽?wèi)?yīng)用進(jìn)程是否已經(jīng)完成寫入traces文件的操作

//Android在判斷桌面壁紙文件是否設(shè)置完成時也是用的FileObserver，很有用的類

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

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

};

... ...

//首先輸出firstPids集合中指定的進(jìn)程，這些也是對ANR問題來說最重要的進(jìn)程

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進(jìn)程中各個線程的函數(shù)堆棧信息，就可以使用向目標(biāo)進(jìn)程發(fā)送SIGNAL_QUIT（3）這個技巧。其實這個名稱有點誤導(dǎo)，它并不會讓進(jìn)程真正退出。

1.2.3 DropBox

剛才留了一個問題：Android只保留最后一次發(fā)生ANR時的traces信息，那么以前的traces信息就丟失了么？為了增強Android的異常信息收集管理能力，從2.2開始增加了DropBox功能。

DropBox（簡稱DB）是系統(tǒng)進(jìn)程中的一個服務(wù)，在system_server進(jìn)程啟動時創(chuàng)建，并且它沒有運行在單獨的線程中，而是運行在system_server的ServerThread線程中。我們可以將ServerThread稱作system_server的主線程，ServerThread線程除了啟動并維護(hù)各個服務(wù)外，還負(fù)責(zé)檢測一些重要的服務(wù)是否死鎖，這一點到后面的Watchdog部分再分析<!-- Watchdog寫完后注意補充章節(jié)號 -->。DB被創(chuàng)建的代碼如下。

SystemServer.java → ServerThread.run()

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

ServiceManager.addService(Context.DROPBOX_SERVICE, //服務(wù)名稱為“dropbox”

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

“/data/system/dropbox”是DB指定的文件存放位置。下面來看一下DB服務(wù)的主要功能。

1. DropBoxManagerService

DropBoxManagerService（簡稱DBMS）就是DB服務(wù)的本尊，它的主要功能接口包括以下幾個函數(shù)：

public voidadd(DropBoxManager.Entryentry)

DBMS將所有要添加的日志都用DropBoxManager.Entry類型的對象表示，通過add函數(shù)添加，并且直到目前為止一個Entry對象對應(yīng)著一個日志文件。

publicboolean isTagEnabled(String tag)

通過給每一個Entry設(shè)置一個tag可以標(biāo)識不同類型的日志，并且可以靈活的啟用/禁用某種類型的日志，isTagEnabled用來判斷指定類型的日志是否被啟用/禁用了，一旦禁用就不會再記錄這種類型的日志。默認(rèn)是不禁用任何類型的日志的。稍后說明如何啟用/禁用日志。

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

我們可以通過getNextEntry函數(shù)獲取指定類型和指定時間點之后的第一條日志，要使用這個功能應(yīng)用程序需要有“android.permission.READ_LOGS”的權(quán)限，并且在使用完畢返回的Entry對象后要調(diào)用其close函數(shù)確保關(guān)閉日志文件的文件描述符（如果不關(guān)閉的話可能造成進(jìn)程打開的文件描述符超過1024而崩潰，Android中限制每個進(jìn)程的文件描述符上限為1024）。

DBMS提供了很多的配置項用來限制對磁盤的使用，通過SettingsProvider應(yīng)用程序維護(hù)，數(shù)據(jù)存放在其settings.db數(shù)據(jù)庫中。這些配置項也都有默認(rèn)值，羅列如下：

• Settings.Secure.DROPBOX_AGE_SECONDS = "dropbox_age_seconds"

日志文件保存的最長時間，默認(rèn)3天

• Settings.Secure.DROPBOX_MAX_FILES = "dropbox_max_files"

日志文件的最大數(shù)量，默認(rèn)值是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:"

//應(yīng)用程序可以利用DropBox來做事情，收集日志等

1.2.4 traces.txt

終于到大明星出場的時候了，一起來看一下traces.txt的廬山真面目。以下是筆者寫的一個演示程序制造出的一次ANR的trace信息：

//文件中輸出的第一個進(jìn)程的trace信息，正是發(fā)生ANR的演示程序

//開頭顯示進(jìn)程號、ANR發(fā)生的時間點和進(jìn)程名稱

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

Cmd line: com.example.anrdemo

DALVIK THREADS: //以下是各個線程的函數(shù)堆棧信息

//mutexes表示虛擬機實例中各種線程相關(guān)對象鎖的value值

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

//依次是：線程名、線程優(yōu)先級、線程創(chuàng)建時的序號、①線程當(dāng)前狀態(tài)

"main" prio=5 tid=1 TIMED_WAIT

//依次是：線程組名稱、suspendCount、debugSuspendCount、線程的Java對象地址、線程的Native對象地址

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

//sysTid是線程號，主線程的線程號和進(jìn)程號相同

| 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線程是進(jìn)程的線程池中用來處理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)

//線程名稱后面標(biāo)識有daemon，說明這是個守護(hù)線程

"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線程是支持虛擬機調(diào)試的線程，不需要關(guān)心

"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”負(fù)責(zé)接收和處理kernel發(fā)送的各種信號，例如SIGNAL_QUIT、SIGNAL_USR1等就是被該線程

//接收到，這個文件的內(nèi)容就是由該線程負(fù)責(zé)輸出的，可以看到它的狀態(tài)是RUNNABLE，不過此線程也不需要關(guān)心

"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

... ...

//省略其他進(jìn)程的信息

有一個關(guān)鍵點需要注意：

線程有很多狀態(tài)，了解這些狀態(tài)的意義對分析ANR的原因是有幫助的，總結(jié)如下：

Thread.java中定義的狀態(tài)	Thread.cpp中定義的狀態(tài)	說明
TERMINATED	ZOMBIE	線程死亡，終止運行
RUNNABLE	RUNNING/RUNNABLE	線程可運行或正在運行
TIMED_WAITING	TIMED_WAIT	執(zhí)行了帶有超時參數(shù)的wait、sleep或join函數(shù)
BLOCKED	MONITOR	線程阻塞，等待獲取對象鎖
WAITING	WAIT	執(zhí)行了無超時參數(shù)的wait函數(shù)
NEW	INITIALIZING	新建，正在初始化，為其分配資源
NEW	STARTING	新建，正在啟動
RUNNABLE	NATIVE	正在執(zhí)行JNI本地函數(shù)
WAITING	VMWAIT	正在等待VM資源
RUNNABLE	SUSPENDED	線程暫停，通常是由于GC或debug被暫停
	UNKNOWN	未知狀態(tài)

Thread.java中的狀態(tài)和Thread.cpp中的狀態(tài)是有對應(yīng)關(guān)系的?？梢钥吹角罢吒痈爬?，也比較容易理解，面向Java的使用者；而后者更詳細(xì)，面向虛擬機內(nèi)部的環(huán)境。traces.txt中顯示的線程狀態(tài)都是Thread.cpp中定義的。另外，所有的線程都是遵循POSIX標(biāo)準(zhǔn)的本地線程。關(guān)于線程更多的說明可以查閱源碼/dalvik/vm/Thread.cpp中的說明。<!-- 線程的ThreadGroup最好也寫進(jìn)去 -->

traces.txt文件中的這些信息是由每個Dalvik進(jìn)程的SignalCatcher線程輸出的，相關(guān)代碼可以查看/dalvik/vm/目錄下的SignalCatcher.cpp::logThreadStacks函數(shù)和Thread.cpp:: dvmDumpAllThreadsEx函數(shù)。另外請注意，輸出堆棧信息時SignalCatcher會暫停所有線程。

通過該文件很容易就能知道問題進(jìn)程的主線程發(fā)生ANR時正在執(zhí)行怎樣的操作。例如上述示例， ANRActivity在makeANR函數(shù)中執(zhí)行線程sleep時發(fā)生ANR，可以推測sleep時間過長，超過了超時上限導(dǎo)致。這是一種比較簡單的情況，實際開發(fā)中會遇到很多詭異的、更加復(fù)雜的情況，在后面的實例講解一節(jié)會詳細(xì)說明。

1.2.5 CPU使用率

這部分的內(nèi)容主要涉及到Linux的相關(guān)知識，數(shù)據(jù)是從“/proc/stat”文件中讀取的，Android中僅僅是匯總和記錄這些數(shù)據(jù)而已，熟悉Linux的讀者可以跳過本節(jié)內(nèi)容。

前面簡單說明了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平均負(fù)載

//②ANR發(fā)生之前的一段時間內(nèi)的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的頁錯誤次數(shù)

... ...

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

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

//⑦ANR發(fā)生之后的一段時間內(nèi)的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負(fù)載和CPU使用率，它們是不同的。不過負(fù)載的概念主要是做大型服務(wù)器端應(yīng)用時關(guān)注的性能指標(biāo)，在Android開發(fā)中我們更加關(guān)注的是使用率。下面詳細(xì)說明，有八個關(guān)鍵點需要注意：

① CPU負(fù)載/平均負(fù)載

CPU負(fù)載是指某一時刻系統(tǒng)中運行隊列長度之和加上當(dāng)前正在CPU上運行的進(jìn)程數(shù)，而CPU平均負(fù)載可以理解為一段時間內(nèi)正在使用和等待使用CPU的活動進(jìn)程的平均數(shù)量。在Linux中“活動進(jìn)程”是指當(dāng)前狀態(tài)為運行或不可中斷阻塞的進(jìn)程。通常所說的負(fù)載其實就是指平均負(fù)載。

用一個從網(wǎng)上看到的很生動的例子來說明（不考慮CPU時間片的限制），把設(shè)備中的一個單核CPU比作一個電話亭，把進(jìn)程比作正在使用和等待使用電話的人，假如有一個人正在打電話，有三個人在排隊等待，此刻電話亭的負(fù)載就是4。使用中會不斷的有人打完電話離開，也會不斷的有其他人排隊等待，為了得到一個有參考價值的負(fù)載值，可以規(guī)定每隔5秒記錄一下電話亭的負(fù)載，并將某一時刻之前的一分鐘、五分鐘、十五分鐘的的負(fù)載情況分別求平均值，最終就得到了三個時段的平均負(fù)載。

實際上我們通常關(guān)心的就是在某一時刻的前一分鐘、五分鐘、十五分鐘的CPU平均負(fù)載，例如以上日志中這三個值分別是3.85、3.41、3.16，說明前一分鐘內(nèi)正在使用和等待使用CPU的活動進(jìn)程平均有3.85個，依此類推。在大型服務(wù)器端應(yīng)用中主要關(guān)注的是第五分鐘和第十五分鐘的兩個值，但是Android主要應(yīng)用在便攜手持設(shè)備中，有特殊的軟硬件環(huán)境和應(yīng)用場景，短時間內(nèi)的系統(tǒng)的較高負(fù)載就有可能造成ANR，所以筆者認(rèn)為一分鐘內(nèi)的平均負(fù)載相對來說更具有參考價值。

CPU的負(fù)載和使用率沒有必然關(guān)系，有可能只有一個進(jìn)程在使用CPU，但執(zhí)行的是復(fù)雜的操作；也有可能等待和正在使用CPU的進(jìn)程很多，但每個進(jìn)程執(zhí)行的都是簡單操作。

實際處理問題時偶爾會遇到由于平均負(fù)載高引起的ANR，典型的特征就是系統(tǒng)中應(yīng)用進(jìn)程數(shù)量多，CPU總使用率較高，但是每個進(jìn)程的CPU使用率不高，當(dāng)前應(yīng)用進(jìn)程主線程沒有異常阻塞，一分鐘內(nèi)的CPU平均負(fù)載較高。

提示：Linux內(nèi)核不斷進(jìn)行著CPU負(fù)載的記錄，我們可以在任意時刻通過在shell中執(zhí)行“cat /proc/loadavg”查看。

② ANR發(fā)生之前和之后一段時間的CPU使用率

CPU使用率可以理解為一段時間（記作T）內(nèi)除CPU空閑時間（記作I）之外的時間與這段時間T的比值，用公式表示可以寫為：

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

而時間段T是兩個采樣時間點的時間差值。

之所以可以這樣計算，是因為Linux內(nèi)核會把從系統(tǒng)啟動開始到當(dāng)前時刻CPU活動的所有時間信息都記錄下來，我們可以通過查看“/proc/stat”文件獲取這些信息。主要包括以下幾種時間，這些時間都是從系統(tǒng)啟動開始計算的，單位都是0.01秒：

user： CPU在用戶態(tài)的運行時間，不包括nice值為負(fù)數(shù)的進(jìn)程運行的時間

nice： CPU在用戶態(tài)并且nice值為負(fù)數(shù)的進(jìn)程運行的時間

system：CPU在內(nèi)核態(tài)運行的時間

idle： CPU空閑時間，不包括iowait時間

iowait： CPU等待I/O操作的時間

irq： CPU硬中斷的時間

softirq：CPU軟中斷的時間

注意：隨著Linux內(nèi)核版本的不同，包含的時間類型有可能不同，例如2.6.11中增加的stealstolen等。但根據(jù)Android源碼，我們只需要關(guān)心以上七種類型即可。

CPU使用率的計算是在ProcessStats類中實現(xiàn)的。如果在某兩個時刻T1和T2（T1 < T2）進(jìn)行采樣記錄，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

有了以上數(shù)據(jù)就可以計算具體的使用率了，例如用戶態(tài)CPU使用率為：

userCpuUsage = userTime / TotalTime

依此類推可以計算其他類型的使用率。而整個時間段內(nèi)CPU使用率為：

CpuUsage = (TotalTime – idleTime) / TotalTime

以上計算的是整個系統(tǒng)的CPU使用率，對于指定進(jìn)程的使用率是通過讀取該進(jìn)程的“/proc/進(jìn)程號/stat”文件計算的，而對于指定進(jìn)程的指定線程的使用率是通過讀取該線程的“/proc/進(jìn)程號/task/線程號/stat”文件計算的。進(jìn)程和線程的CPU使用率只包含該進(jìn)程或線程的總使用率、用戶態(tài)使用率和內(nèi)核態(tài)使用率。

AMS在執(zhí)行appNotResponding函數(shù)過程中，共輸出了兩個時間段的CPU使用率，通常情況下在ANR發(fā)生時間點之前和之后各有一段。兩段使用率都是兩次調(diào)用ProcessStats對象的update函數(shù)，每次調(diào)用update函數(shù)時會保留上一時間點的采樣數(shù)據(jù)，并記錄當(dāng)前時間點的采樣數(shù)據(jù)。然后再調(diào)用ProcessStats對象的printCurrentState函數(shù)，按照上述公式歸納的算法計算CPU使用率，并輸出最終的結(jié)果。再詳細(xì)看一下代碼：

ActivityManagerService.java → appNotResponding

//第一次使用成員變量mProcessStats采樣

if (MONITOR_CPU_USAGE) {

updateCpuStatsNow();

}

... ...

//聲明了一個局部變量，參數(shù)true表示包括線程信息

final ProcessStats processStats = new ProcessStats(true);

//將processStats作為實參傳入，在dumpStackTraces中相隔500毫秒兩次調(diào)用其update函數(shù)進(jìn)行采樣

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

String cpuInfo = null;

if (MONITOR_CPU_USAGE) {

//因為在第一次調(diào)用后，可能由于輸出trace信息等操作，中間執(zhí)行了較長的時間，所以有第二次使用成員變量

//mProcessStats采樣，盡量使得采樣時間點靠后。

//此函數(shù)中要求連續(xù)兩次采樣時間間隔不少于5秒，所以一般不會執(zhí)行第二次采樣。一旦執(zhí)行，就會出現(xiàn)兩個采樣

//時間點一個在ANR發(fā)生之前，另一個在其之后，或者兩個時間點都在ANR發(fā)生之后的情況。

updateCpuStatsNow();

synchronized (mProcessStatsThread) {

//mProcessStats是成員變量，創(chuàng)建對象時傳入的參數(shù)是false，所以不包括線程信息

//此處先輸出ANR發(fā)生之前一段時間內(nèi)的CPU使用率

cpuInfo = mProcessStats.printCurrentState(anrTime);

}

info.append(processStats.printCurrentLoad());

info.append(cpuInfo);

}

//processStats對象是在ANR發(fā)生后創(chuàng)建并采樣的，所以輸出的是ANR發(fā)生之后一段時間內(nèi)的CPU使用率

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

③ 非睡眠時間百分比

在記錄CPU使用率的每個采樣時間點時使用了兩種記錄方法：SystemClock.uptimeMillis()和SystemClock.elapsedRealtime()，兩者的區(qū)別就是uptimeMillis不包含睡眠時間，所以兩個采樣時間點之間的uptimeMillis和elapsedRealtime之比就是非睡眠時間百分比。

頁錯誤次數(shù)

進(jìn)程的CPU使用率最后輸出的“faults: xxx minor/major”部分表示的是頁錯誤次數(shù)，當(dāng)次數(shù)為0時不顯示。major是指Major Page Fault（主要頁錯誤，簡稱MPF），內(nèi)核在讀取數(shù)據(jù)時會先后查找CPU的高速緩存和物理內(nèi)存，如果找不到會發(fā)出一個MPF信息，請求將數(shù)據(jù)加載到內(nèi)存。Minor是指Minor Page Fault（次要頁錯誤，簡稱MnPF），磁盤數(shù)據(jù)被加載到內(nèi)存后，內(nèi)核再次讀取時，會發(fā)出一個MnPF信息。一個文件第一次被讀寫時會有很多的MPF，被緩存到內(nèi)存后再次訪問MPF就會很少，MnPF反而變多，這是內(nèi)核為減少效率低下的磁盤I/O操作采用的緩存技術(shù)的結(jié)果。

如果ANR發(fā)生時發(fā)現(xiàn)CPU使用率中iowait占比很高，可以通過查看進(jìn)程的major次數(shù)來推斷是哪個進(jìn)程在進(jìn)行磁盤I/O操作。<!-- 求證一下 -->

新增和移除的進(jìn)程或線程

如果一個進(jìn)程或線程的CPU使用率前有“+”，說明該進(jìn)程或線程是在最后兩次CPU使用率采樣時間段內(nèi)新建的；反之如果是“-”，說明該進(jìn)程或線程在采樣時間段內(nèi)終止了；如果是空，說明該進(jìn)程或線程是在倒數(shù)第二次采樣時間點之前已經(jīng)存在。

至此，所有與ANR相關(guān)的日志內(nèi)容都已介紹完畢，相信讀者以后處理ANR問題時能夠有的放矢了。