【安卓稳定性之ANR】第二篇：ANR的信息搜集过程（log，trace信息）
在安卓anr发生的时候，会进行anr现场的log打印以及trace文件的输出，以便于安卓开发者进行问题的分析。
本文介绍了anr发生之后，从AMS的MainHandler接受到超时的消息，到调用mUiHandler进行未响应弹窗之间系统进行anr信息搜集的过程。
调用链：
AMS.MainHandler.handleMessage()
-----> ActiveServices.serviceTimeout()
----->ProcessRecord.appNotResponding()
----->AMS.mUiHandler.sendMessage()1：炸弹引爆前
当anr发生时刻，炸弹引爆，AMS的MainHandler 会接受到超时消息进行处理。AMS调用AS的serviceTimeout方法进行炸弹引爆前的判断。当真正需要引爆炸弹的时候，ProcessRecord.appNotResponding进行炸弹引爆。
ActiveService.java
void serviceTimeout(ProcessRecord proc) {
//定义anrMessage
String anrMessage = null;
synchronized(mAm) {
//1:debugger状态不会报ANR。
if (proc.isDebugging()) {
return;
}
//2：超时进程没有正在执行的Service或者没有线程，不会报ANR。
if (proc.executingServices.size() == 0 || proc.thread == null) {
return;
}
//3：记录当前系统时间，maxTime为前台"now-20s"或者后台"now-200s"。
final long now = SystemClock.uptimeMillis();
final long maxTime = now -
(proc.execServicesFg ? SERVICE_TIMEOUT : SERVICE_BACKGROUND_TIMEOUT);
ServiceRecord timeout = null;
long nextTime = 0;
//4：从proc.executingServices尾巴开始遍历service，找到第一个timeout的service，并记录再SeriviceRecord timeout里。
for (int i=proc.executingServices.size()-1; i>=0; i--) {
ServiceRecord sr = proc.executingServices.valueAt(i);
if (sr.executingStart < maxTime) {
timeout = sr;
break;
}
if (sr.executingStart > nextTime) {
nextTime = sr.executingStart;
}
}
//5：mAm是AS类中持有AMS的一个引用。
//5.1：如果有service超时，且AMS的processList包含超时进程。则进入anr弹窗超时分支。
if (timeout != null && mAm.mProcessList.mLruProcesses.contains(proc)) {
Slog.w(TAG, "Timeout executing service: " + timeout);
StringWriter sw = new StringWriter();
PrintWriter pw = new FastPrintWriter(sw, false, 1024);
pw.println(timeout);
timeout.dump(pw, " ");
pw.close();
mLastAnrDump = sw.toString();
mAm.mHandler.removeCallbacks(mLastAnrDumpClearer);
mAm.mHandler.postDelayed(mLastAnrDumpClearer, LAST_ANR_LIFETIME_DURATION_MSECS);
//6：anrMessage赋值，"执行 service"超时。
anrMessage = "executing service " + timeout.shortInstanceName;
} else {
Message msg = mAm.mHandler.obtainMessage(
ActivityManagerService.SERVICE_TIMEOUT_MSG);
msg.obj = proc;
mAm.mHandler.sendMessageAtTime(msg, proc.execServicesFg
? (nextTime+SERVICE_TIMEOUT) : (nextTime + SERVICE_BACKGROUND_TIMEOUT));
}
}
//7：执行ANR弹窗
if (anrMessage != null) {
proc.appNotResponding(null, null, null, null, false, anrMessage);
}
}2：炸弹引爆后，信息搜集过程
如果一个anr执行到这一步，几乎是必须要弹窗的了。除了几种极端的情况不会弹窗（如重启、crash，进程冻结等，这些时候，也不会打印am_anr，ANR in等再log中，不会输出trace文件。）
2.1：ANR执行过程
当发生ANR时，会按照以下顺序依次执行：
- 打印am_anr到Event log中;
- 输出trace文件;
- 打印ANR in;
- 根据进程类型,来决定直接后台杀掉,还是弹框告知用户。（后台ANR直接杀掉）
2.2：队列信息
ANR输出重要进程的traces信息，这些进程包含:
- firstPids队列：第一个是ANR进程，第二个是system_server，剩余是所有persistent进程；
- Native队列：是指/system/bin/目录的mediaserver,sdcard 以及surfaceflinger进程；
- lastPids队列: 是指mLruProcesses中的不属于firstPids的所有进程。
2.3：ANR不会弹窗的情况：
- 系统正在重启
- 如果超时进程已经一个anr弹窗，则不会弹出另外的anr弹窗。
- 正在crash的超时进程不会弹出anr。
- 已经被杀的进程和已经died的app不会报anr。
- 已经被冻结的进程也不会anr。（MIUI ADD）
void appNotResponding(String activityShortComponentName, ApplicationInfo aInfo,
String parentShortComponentName, WindowProcessController parentProcess,
boolean aboveSystem, String annotation) {
ArrayList<Integer> firstPids = new ArrayList<>(5);
SparseArray<Boolean> lastPids = new SparseArray<>(20);
mWindowProcessController.appEarlyNotResponding(annotation, () -> kill("anr", true));
//1：记录anr时间
long anrTime = SystemClock.uptimeMillis();
//2：mService为ProcessRecord中持有的AMS的引用
if (isMonitorCpuUsage()) {
mService.updateCpuStatsNow();
}
//3：如果发生anr的时候，超时应用处于以下状态，则不报ANR
//3.1：系统正在重启
//3.2：如果已经有一个anr弹窗，则不会弹出另外的anr弹窗。
//3.3：正在crash的超时进程不会弹出anr。
//3.4:已经被杀的进程和已经died的app不会报anr。
//3.4:MIUI已经被冻结的进程也不会anr。
synchronized (mService) {
// PowerManager.reboot() can block for a long time, so ignore ANRs while shutting down.
if (mService.mAtmInternal.isShuttingDown()) {
Slog.i(TAG, "During shutdown skipping ANR: " + this + " " + annotation);
return;
} else if (isNotResponding()) {
Slog.i(TAG, "Skipping duplicate ANR: " + this + " " + annotation);
return;
} else if (isCrashing()) {
Slog.i(TAG, "Crashing app skipping ANR: " + this + " " + annotation);
return;
} else if (killedByAm) {
Slog.i(TAG, "App already killed by AM skipping ANR: " + this + " " + annotation);
return;
} else if (killed) {
Slog.i(TAG, "Skipping died app ANR: " + this + " " + annotation);
return;
}
// MIUI ADD:START
if (ActivityManagerServiceInjector.skipFrozenAppAnr(this.info, this.uid, annotation)) {
return;
}
// END
//当前超时进程第一次弹窗， 设置mNotResponding为true， 之后的弹窗就会被忽略了。
setNotResponding(true);
//打印am_anr
EventLog.writeEvent(EventLogTags.AM_ANR, userId, pid, processName, info.flags,
annotation);
//将当前进程添加到firstPids
firstPids.add(pid);
// Don't dump other PIDs if it's a background ANR
if (!isSilentAnr()) {
int parentPid = pid;
if (parentProcess != null && parentProcess.getPid() > 0) {
parentPid = parentProcess.getPid();
}
if (parentPid != pid) firstPids.add(parentPid);
//将system_server进程添加到firstPids（MY_pid是由AMS中os.getPid（）获取）
if (MY_PID != pid && MY_PID != parentPid) firstPids.add(MY_PID);
for (int i = getLruProcessList().size() - 1; i >= 0; i--) {
ProcessRecord r = getLruProcessList().get(i);
if (r != null && r.thread != null) {
int myPid = r.pid;
if (myPid > 0 && myPid != pid && myPid != parentPid && myPid != MY_PID) {
// MIUI MOD:
// if (r.isPersistent()) {
if (ProcessPolicyManager.isNeedTraceProcess(r)) {
firstPids.add(myPid);
if (DEBUG_ANR) Slog.i(TAG, "Adding persistent proc: " + r);
} else if (r.treatLikeActivity) {
firstPids.add(myPid);
if (DEBUG_ANR) Slog.i(TAG, "Adding likely IME: " + r);
} else {
//lastPids队列: 是指mLruProcesses中的不属于firstPids的所有进程
lastPids.put(myPid, Boolean.TRUE);
if (DEBUG_ANR) Slog.i(TAG, "Adding ANR proc: " + r);
}
}
}
}
}
}
// 4:记录ANR输出到main log， 仅保存在StringBuilder中
StringBuilder info = new StringBuilder();
info.setLength(0);
info.append("ANR in ").append(processName);
if (activityShortComponentName != null) {
info.append(" (").append(activityShortComponentName).append(")");
}
info.append("\n");
info.append("PID: ").append(pid).append("\n");
if (annotation != null) {
info.append("Reason: ").append(annotation).append("\n");
}
if (parentShortComponentName != null
&& parentShortComponentName.equals(activityShortComponentName)) {
info.append("Parent: ").append(parentShortComponentName).append("\n");
}
ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);
// don't dump native PIDs for background ANRs unless it is the process of interest
String[] nativeProcs = null;
if (isSilentAnr()) {
for (int i = 0; i < NATIVE_STACKS_OF_INTEREST.length; i++) {
if (NATIVE_STACKS_OF_INTEREST[i].equals(processName)) {
nativeProcs = new String[] { processName };
break;
}
}
} else {
nativeProcs = NATIVE_STACKS_OF_INTEREST;
}
int[] pids = nativeProcs == null ? null : Process.getPidsForCommands(nativeProcs);
ArrayList<Integer> nativePids = null;
if (pids != null) {
nativePids = new ArrayList<>(pids.length);
for (int i : pids) {
nativePids.add(i);
}
}
// MIUI ADD: START
if (!isSilentAnr()) {
nativePids.addAll(Watchdog.getInstance().getInterestingHalPids());
}
// END
// For background ANRs, don't pass the ProcessCpuTracker to
// avoid spending 1/2 second collecting stats to rank lastPids.
//5:输出打印traces信息
File tracesFile = ActivityManagerService.dumpStackTraces(firstPids,
(isSilentAnr()) ? null : processCpuTracker, (isSilentAnr()) ? null : lastPids,
nativePids);
//6：把CPU信息保存到StringBUilder中
String cpuInfo = null;
if (isMonitorCpuUsage()) {
mService.updateCpuStatsNow();
synchronized (mService.mProcessCpuTracker) {
cpuInfo = mService.mProcessCpuTracker.printCurrentState(anrTime);
}
info.append(processCpuTracker.printCurrentLoad());
info.append(cpuInfo);
}
info.append(processCpuTracker.printCurrentState(anrTime));
//7：Slog再main log中输出ANR in
Slog.e(TAG, info.toString());
if (tracesFile == null) {
// There is no trace file, so dump (only) the alleged culprit's threads to the log
Process.sendSignal(pid, Process.SIGNAL_QUIT);
}
...
synchronized (mService) {
...
//后台ANR直接杀掉完事
if (isSilentAnr() && !isDebugging()) {
kill("bg anr", true);
return;
}
// Set the app's notResponding state, and look up the errorReportReceiver
//设置应用程序的notResponding状态，并查找errorReportReceiver
makeAppNotRespondingLocked(activityShortComponentName,
annotation != null ? "ANR " + annotation : "ANR", info.toString());
// 如果AMS仅使用注射器构造，则mUiHandler可以为null。 这只会在测试中发生。
if (mService.mUiHandler != null) {
// 调出臭名昭著的“应用程序无响应”对话框
Message msg = Message.obtain();
msg.what = ActivityManagerService.SHOW_NOT_RESPONDING_UI_MSG;
msg.obj = new AppNotRespondingDialog.Data(this, aInfo, aboveSystem);
mService.mUiHandler.sendMessage(msg);
}
}
}3：生成trace文件
ActivityManagerService.java
public static File dumpStackTraces(ArrayList<Integer> firstPids,
ProcessCpuTracker processCpuTracker, SparseArray<Boolean> lastPids,
ArrayList<Integer> nativePids) {
ArrayList<Integer> extraPids = null;
Slog.i(TAG, "dumpStackTraces pids=" + lastPids + " nativepids=" + nativePids);
...(测量CPU使用情况)
final File tracesDir = new File(ANR_TRACE_DIR);
// Each set of ANR traces is written to a separate file and dumpstate will process all such files and add them to a captured bug report if they're recent enough.
//每组ANR跟踪都写入一个单独的文件，并且dumpstate将处理所有此类文件，如果它们足够新，则将它们添加到捕获的错误报告中。
maybePruneOldTraces(tracesDir);
// NOTE: We should consider creating the file in native code atomically once we've
// gotten rid of the old scheme of dumping and lot of the code that deals with paths
// can be removed.
File tracesFile = createAnrDumpFile(tracesDir);
if (tracesFile == null) {
return null;
}
dumpStackTraces(tracesFile.getAbsolutePath(), firstPids, nativePids, extraPids);
return tracesFile;
}该方法的主要功能，依次输出：
- 收集firstPids进程的stacks。第一个是发生ANR进程；第二个是system_server；然后是mLruProcesses中所有的persistent进程；
- 收集Native进程的stacks；(dumpNativeBacktraceToFile)。依次是mediaserver,sdcard,surfaceflinger进程；
- 收集lastPids进程的stacks。依次输出CPU使用率top 5的进程；
ActivityManagerService.java
public static void dumpStackTraces(String tracesFile, ArrayList<Integer> firstPids,
ArrayList<Integer> nativePids, ArrayList<Integer> extraPids) {
Slog.i(TAG, "Dumping to " + tracesFile);
// We don't need any sort of inotify based monitoring when we're dumping traces via
// tombstoned. Data is piped to an "intercept" FD installed in tombstoned so we're in full
// control of all writes to the file in question.
// 需要在20秒内dump所有stacks，超过20s则直接返回。
long remainingTime = 20 * 1000;
// First collect all of the stacks of the most important pids.
if (firstPids != null) {
int num = firstPids.size();
for (int i = 0; i < num; i++) {
Slog.i(TAG, "Collecting stacks for pid " + firstPids.get(i));
final long timeTaken = dumpJavaTracesTombstoned(firstPids.get(i), tracesFile,
remainingTime);
remainingTime -= timeTaken;
if (remainingTime <= 0) {
Slog.e(TAG, "Aborting stack trace dump (current firstPid=" + firstPids.get(i) +
"); deadline exceeded.");
return;
}
}
}
// Next collect the stacks of the native pids
if (nativePids != null) {
for (int pid : nativePids) {
Slog.i(TAG, "Collecting stacks for native pid " + pid);
final long nativeDumpTimeoutMs = Math.min(NATIVE_DUMP_TIMEOUT_MS, remainingTime);
final long start = SystemClock.elapsedRealtime();
//输出native进程的trace
Debug.dumpNativeBacktraceToFileTimeout(
pid, tracesFile, (int) (nativeDumpTimeoutMs / 1000));
final long timeTaken = SystemClock.elapsedRealtime() - start;
remainingTime -= timeTaken;
if (remainingTime <= 0) {
Slog.e(TAG, "Aborting stack trace dump (current native pid=" + pid +
"); deadline exceeded.");
return;
}
}
}
// Lastly, dump stacks for all extra PIDs from the CPU tracker.
if (extraPids != null) {
for (int pid : extraPids) {
Slog.i(TAG, "Collecting stacks for extra pid " + pid);
final long timeTaken = dumpJavaTracesTombstoned(pid, tracesFile, remainingTime);
remainingTime -= timeTaken;
if (remainingTime <= 0) {
Slog.e(TAG, "Aborting stack trace dump (current extra pid=" + pid +
"); deadline exceeded.");
return;
}
}
}
Slog.i(TAG, "Done dumping");
}这里分为dumpJavaTracesTombstoned()，以及dumpNativeBacktraceToFileTimeout两种dump的方式。
需要注意的一点是，有时候发生无响应时trace文件中没有java堆栈，但是可以看到debuggerd打印的堆栈，这个堆栈一般anr发生在10秒之后。其实本质就是如下代码：
4281 private static long dumpJavaTracesTombstoned(int pid, String fileName, long timeoutMs) {
4282 final long timeStart = SystemClock.elapsedRealtime();
4283 boolean javaSuccess = Debug.dumpJavaBacktraceToFileTimeout(pid, fileName,
4284 (int) (timeoutMs / 1000));
4285 if (javaSuccess) {
4286 // Check that something is in the file, actually. Try-catch should not be necessary,
4287 // but better safe than sorry.
4288 try {
4289 long size = new File(fileName).length();
4290 if (size < JAVA_DUMP_MINIMUM_SIZE) {
4291 Slog.w(TAG, "Successfully created Java ANR file is empty!");
4292 javaSuccess = false;
4293 }
4294 } catch (Exception e) {
4295 Slog.w(TAG, "Unable to get ANR file size", e);
4296 javaSuccess = false;
4297 }
4298 }
4299 if (!javaSuccess) {
4300 Slog.w(TAG, "Dumping Java threads failed, initiating native stack dump.");
4301 if (!Debug.dumpNativeBacktraceToFileTimeout(pid, fileName,
4302 (NATIVE_DUMP_TIMEOUT_MS / 1000))) {
4303 Slog.w(TAG, "Native stack dump failed!");
4304 }
4305 }
4306
4307 return SystemClock.elapsedRealtime() - timeStart;
4308 }超时10秒没有成功的话，会使用debuggerd进行dump。
java的dump使用的是 kill -3，native的dump使用的debuggerd -b。具体可以查看袁晖晖这里介绍的。http://gityuan.com/2016/12/02/app-not-response/。
而实际在工作中确实也遇到过此类问题。
日志如下：
实际上这个时候进程9319在dump trace时失败了，然后打印了dump失败的日志，他会接着使用debuggderd -b进行dump。
如果你是小米手机部的员工，可以看下这个jira：MIUI-2135693，日志附件我就不上传了。
04-23 22:35:57.616 1000 1693 6639 I ActivityManager: Collecting stacks for pid 9319
04-23 22:36:07.632 1000 1693 6639 W ActivityManager: Dumping Java threads failed, initiating native stack dump.
本文章为转载内容，我们尊重原作者对文章享有的著作权。如有内容错误或侵权问题，欢迎原作者联系我们进行内容更正或删除文章。
