每次发生ANR,这个文件都会被清空,写入新的内容。如果想查看以前发生ANR的信息,可以去查看DB文件,
也就是DropBox的中的日志
跟踪功能,保存历史上发生的所有ANR的日志
“/ data / system / dropbox”是DB指定的文件存放位置。
日志保存的最长时间,默认是3天
ANR的异常信息
使用logcat命令查看会得到类似如下的log
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35
| I/WindowManager( 127): Input event dispatching timed out sending to com.example.anrdemo/com.example.anrdemo.ANRActivity
I/Process ( 127): Sending signal. PID: 5033 SIG: 3
I/dalvikvm( 5033): threadid=4: reacting to signal 3 I/dalvikvm( 5033): Wrote stack traces to '/data/anr/traces.txt' ... ...
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
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
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
|
发生ANR时Android为我们提供了两种“利器”:traces文件和CPU使用率
ANR信息是如何输出的
ActivityManagerService类中,找到它的appNotResponding函数
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73
| final void appNotResponding(ProcessRecord app, ActivityRecord activity, ActivityRecord parent, final String annotation) {
ArrayList<Integer> firstPids = new ArrayList<Integer>(5); SparseArray<Boolean> lastPids = new SparseArray<Boolean>(20);
if (mController != null) { ... ... } long anrTime = SystemClock.uptimeMillis(); if (MONITOR_CPU_USAGE) { updateCpuStatsNow(); } synchronized (this) { 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; } app.notResponding = true; ... ... firstPids.add(app.pid); ... ... } ... ... File tracesFile = dumpStackTraces(true, firstPids, processStats, lastPids, null); String cpuInfo = null; if (MONITOR_CPU_USAGE) { updateCpuStatsNow(); synchronized (mProcessStatsThread) { cpuInfo = mProcessStats.printCurrentState(anrTime); } info.append(processStats.printCurrentLoad()); info.append(cpuInfo); } info.append(processStats.printCurrentState(anrTime)); ... ... addErrorToDropBox("anr", app, app.processName, activity, parent, annotation, cpuInfo, tracesFile, null); ... ... 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; } ... ... 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中,它也是个非常有用的日志存放工具,后面也会分析它的作用。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25
| public static File dumpStackTraces(boolean clearTraces, ArrayList<Integer> firstPids, ProcessStats processStats, SparseArray<Boolean> lastPids, String[] nativeProcs) {
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(tracesDir.getPath(), 0775, -1, -1);
if (clearTraces && tracesFile.exists()) tracesFile.delete(); tracesFile.createNewFile(); FileUtils.setPermissions(tracesFile.getPath(), 0666, -1, -1); } 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对系统属性进行设置和读取:
1 2
| getpropdalvik.vm.stack-trace-file setprop dalvik.vm.stack-trace-file /tmp/stack-traces.txt
|
每次发生ANR时都会删除旧的traces文件,重新创建新文件。也就是说Android只保留最后一次发生ANR时的traces信息,那么以前的traces信息就丢失了么?稍后回答。
接着来看重载的dumpStackTraces函数。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21
| private static void dumpStackTraces(String tracesPath, ArrayList<Integer> firstPids, ProcessStats processStats, SparseArray<Boolean> lastPids, String[] nativeProcs) {
FileObserver observer = new FileObserver(tracesPath, FileObserver.CLOSE_WRITE) { public synchronized void onEvent(int event, String path) { notify(); } }; ... ...
if (firstPids != null) { try { int num = firstPids.size(); for (int i = 0; i < num; i++) { synchronized (observer) {
Process.sendSignal(firstPids.get(i), Process.SIGNAL_QUIT); observer.wait(200); ... ... }
|
分析ANR的trace信息
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84
|
----- pid 9183 at 2012-09-28 22:20:42 ----- Cmd line: com.example.anrdemo DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)
"main" prio=5 tid=1 TIMED_WAIT
| group="main" sCount=1 dsCount=0 obj=0x4025b1b8 self=0xce68
| 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 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)
"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" 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" 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 ... ...
|
线程状态
Thread.java中定义的状态 |
Thread.cpp中定义的状态 |
说明 |
TERMINATED |
ZOMBIE |
线程死亡,终止运行 |
RUNNABLE |
RUNNING/RUNNABLE |
线程可运行或正在运行 |
TIMED_WAITING |
TIMED_WAIT |
执行了带有超时参数的wait、sleep或join函数 |
BLOCKED |
MONITOR |
线程阻塞,等待获取对象锁 |
WAITING |
WAIT |
执行了无超时参数的wait函数 |
NEW |
INITIALIZING |
新建,正在初始化,为其分配资源 |
NEW |
STARTING |
新建,正在启动 |
RUNNABLE |
NATIVE |
正在执行JNI本地函数 |
WAITING |
VMWAIT |
正在等待VM资源 |
RUNNABLE |
SUSPENDED |
线程暂停,通常是由于GC或debug被暂停 |
|
UNKNOWN |
未知状态 |
Thread.java中的状态和Thread.cpp中的状态是有对应关系的。可以看到前者更加概括,也比较容易理解,面向Java的使用者;而后者更详细,面向虚拟机内部的环境。traces.txt中显示的线程状态都是Thread.cpp中定义的。另外,所有的线程都是遵循POSIX标准的本地线程。关于线程更多的说明可以查阅源码/dalvik/vm/Thread.cpp中的说明。 |
|
|
traces.txt文件中的这些信息是由每个Dalvik进程的SignalCatcher线程输出的,相关代码可以查看/dalvik/vm/目录下的SignalCatcher.cpp::logThreadStacks函数和Thread.cpp:: dvmDumpAllThreadsEx函数。另外请注意,输出堆栈信息时SignalCatcher会暂停所有线程。 |
|
|
通过该文件很容易就能知道问题进程的主线程发生ANR时正在执行怎样的操作。例如上述示例, ANRActivity在makeANR函数中执行线程sleep时发生ANR,可以推测sleep时间过长,超过了超时上限导致。 |
|
|
CPU使用率
内容读取自/proc/stat
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21
| 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 ... ... E/ActivityManager( 127): 37% TOTAL: 27% user + 9.2% kernel
|
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的比值,用公式表示可以写为:
而时间段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内核版本的不同,包含的时间类型有可能不同,Android源码只需要关心以上七种类型即可
CPU使用率的计算是在ProcessStats类中实现的。如果在某两个时刻T1和T2(T1 < T2)进行采样记录,CPU使用率的整个算法可以归纳为以下几个公式:
1 2 3 4 5 6 7
| 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函数
代码位置ActivityManagerService.java → appNotResponding
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31
| if(MONITOR_CPU_USAGE)
{ updateCpuStatsNow(); } ...... final ProcessStats processStats = new ProcessStats(true); File tracesFile = dumpStackTraces(true, firstPids, processStats, lastPids); String cpuInfo = null; if(MONITOR_CPU_USAGE)
{
updateCpuStatsNow(); synchronized (mProcessStatsThread) {
cpuInfo = mProcessStats.printCurrentState(anrTime); } info.append(processStats.printCurrentLoad()); info.append(cpuInfo); }
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使用率采样时间段内新建的;反之如果是“-”,说明该进程或线程在采样时间段内终止了;如果是空,说明该进程或线程是在倒数第二次采样时间点之前已经存在。