第一篇文章－应用与系统稳定性第一篇---ANR问题分析的一般套路主要梳理了几个ANR案例，讲了分析ANR问题的一般思路。本文基于Android O，深入理解ANR发生时系统的处理逻辑，加深对ANR问题的实战处理。实际处理ANR问题中，对于很多的信息还是比较陌生。比如ANR的trace是怎么输出来的？有时候为什么ANR的trace是无效的？一个进程发生了ANR的过程中又发生了ANR，系统是怎么处理的？什么是后台ANR?等等小问题如果你都能回答，那么可以不用看了。
一、ANR的trace是如何生成的
１、appNotResponding方法解读
发生ANR的时候，一般先搜索ANR in获取最直观的信息，如下：
06-16 16:16:28.590 1853 2073 E ActivityManager: ANR in com.android.camera (com.android.camera/.Camera)
06-16 16:16:28.590 1853 2073 E ActivityManager: PID: 27661
06-16 16:16:28.590 1853 2073 E ActivityManager: Reason: Input dispatching timed out (com.android.camera/com.android.camera.Camera, Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 24. Wait queue head age: 5511.1ms.)
06-16 16:16:28.590 1853 2073 E ActivityManager: Load: 16.25 / 29.48 / 38.33
06-16 16:16:28.590 1853 2073 E ActivityManager: CPU usage from 0ms to 8058ms later:
06-16 16:16:28.590 1853 2073 E ActivityManager: 58% 291/mediaserver: 51% user + 6.7% kernel / faults: 2457 minor 4 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 27% 317/mm-qcamera-daemon: 21% user + 5.8% kernel / faults: 15965 minor
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.4% 288/debuggerd: 0% user + 0.3% kernel / faults: 21615 minor 87 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 17% 27661/com.android.camera: 10% user + 6.8% kernel / faults: 2412 minor 34 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 16% 1853/system_server: 10% user + 6.4% kernel / faults: 1754 minor 87 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 10% 539/sensors.qcom: 7.8% user + 2.6% kernel / faults: 16 minor
06-16 16:16:28.590 1853 2073 E ActivityManager: 4.4% 277/surfaceflinger: 1.8% user + 2.6% kernel / faults: 14 minor
06-16 16:16:28.590 1853 2073 E ActivityManager: 4% 203/mmcqd/0: 0% user + 4% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 2.6% 3510/com.android.phone: 1.9% user + 0.6% kernel / faults: 1148 minor 8 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 2.1% 2902/com.android.systemui: 1.6% user + 0.4% kernel / faults: 1272 minor 32 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 1.6% 3110/com.miui.whetstone: 1.6% user + 0% kernel / faults: 2614 minor 22 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.8% 99/kswapd0: 0% user + 0.8% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 1.4% 217/jbd2/mmcblk0p25: 0% user + 1.4% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 1.4% 223/logd: 0.7% user + 0.7% kernel / faults: 4 minor
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.9% 12808/kworker/0:1: 0% user + 0.9% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.8% 35/kworker/u:2: 0% user + 0.8% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0% 3222/com.miui.sysbase: 0% user + 0% kernel / faults: 1314 minor 12 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.8% 3446/com.android.nfc: 0.4% user + 0.3% kernel / faults: 1223 minor 9 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.7% 10866/kworker/u:1: 0% user + 0.7% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.6% 642/mdss_fb0: 0% user + 0.6% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.6% 29336/kworker/u:7: 0% user + 0.6% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.4% 6/kworker/u:0: 0% user + 0.4% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.4% 22924/kworker/u:6: 0% user + 0.4% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.3% 4421/mpdecision: 0% user + 0.3% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.2% 276/servicemanager: 0.1% user + 0.1% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.2% 289/rild: 0.2% user + 0% kernel / faults: 20 minor
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.1% 4161/mcd: 0% user + 0% kernel / faults: 9 minor 1 major
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.1% 3/ksoftirqd/0: 0% user + 0.1% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.1% 5/kworker/0:0H: 0% user + 0.1% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.1% 7/kworker/u:0H: 0% user + 0.1% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0% 215/flush-179:0: 0% user + 0% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.1% 321/displayfeature: 0.1% user + 0% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.1% 368/irq/33-cpubw_hw: 0% user + 0.1% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.1% 403/qmuxd: 0% user + 0.1% kernel / faults: 60 minor
06-16 16:16:28.590 1853 2073 E ActivityManager: 0% 3491/com.xiaomi.finddevice: 0% user + 0% kernel / faults: 706 minor
06-16 16:16:28.590 1853 2073 E ActivityManager: 0.1% 29330/ksoftirqd/1: 0% user + 0.1% kernel
06-16 16:16:28.590 1853 2073 E ActivityManager: 96% TOTAL: 56% user + 29% kernel + 6.3% iowait + 4.1% softirq
应用在发生ANR的时候，不论是Provider,input还是BroadcastReceiver和Service处理超时等，系统都会调用appNotResponding方法，进行trace的收集，主要记录当时的案发现场，各个相关线程的状态一目了然。下面从appNotResponding入手一起看看源码是怎么写的。
这个方法的参数有5个，如下：
- app 当前发生ANR的进程
- activity 发生ANR的界面
- parent 发生ANR的界面的上一级界面
- aboveSystem 这个参数系统中用的全部都是False，还没有看到有true的地方
- annotation 发生ANR的原因
776 final void appNotResponding(ProcessRecord app, ActivityRecord activity,
777 ActivityRecord parent, boolean aboveSystem, final String annotation) {
// 填充firstPids和lastPids数组，从最近运行进程中挑选
// firstPids: 用于保存ANR进程及其父进程，system_server进程和persistent的进程
// lastPids: 用于保存除firstPids外的其他进程
778 ArrayList<Integer> firstPids = new ArrayList<Integer>(5);
779 SparseArray<Boolean> lastPids = new SparseArray<Boolean>(20);
780
781 if (mService.mController != null) {
782 try {
783 // 0 == continue, -1 = kill process immediately
784 int res = mService.mController.appEarlyNotResponding(
785 app.processName, app.pid, annotation);
786 if (res < 0 && app.pid != MY_PID) {
787 app.kill("anr", true);
788 }
789 } catch (RemoteException e) {
790 mService.mController = null;
791 Watchdog.getInstance().setActivityController(null);
792 }
793 }
794
795 long anrTime = SystemClock.uptimeMillis();
//更新Cpu的信息
796 if (ActivityManagerService.MONITOR_CPU_USAGE) {
797 mService.updateCpuStatsNow();
798 }
799
800 // Unless configured otherwise, swallow ANRs in background processes & kill the process.
//showBackground意味在后台的时候是否让ANR有感知，如果showBackground为fasle就不会弹出ANR的dialog了
801 boolean showBackground = Settings.Secure.getInt(mContext.getContentResolver(),
802 Settings.Secure.ANR_SHOW_BACKGROUND, 0) != 0;
803
804 boolean isSilentANR;
805
806 synchronized (mService) {
//这些场景的ANR直接做忽略处理（关机，app已经ANR了，APP处在crash流程中，被AMS或者其他人杀死的）
807 // PowerManager.reboot() can block for a long time, so ignore ANRs while shutting down.
808 if (mService.mShuttingDown) {
809 Slog.i(TAG, "During shutdown skipping ANR: " + app + " " + annotation);
810 return;
811 } else if (app.notResponding) {
812 Slog.i(TAG, "Skipping duplicate ANR: " + app + " " + annotation);
813 return;
814 } else if (app.crashing) {
815 Slog.i(TAG, "Crashing app skipping ANR: " + app + " " + annotation);
816 return;
817 } else if (app.killedByAm) {
818 Slog.i(TAG, "App already killed by AM skipping ANR: " + app + " " + annotation);
819 return;
820 } else if (app.killed) {
821 Slog.i(TAG, "Skipping died app ANR: " + app + " " + annotation);
822 return;
823 }
824
825 // In case we come through here for the same app before completing
826 // this one, mark as anring now so we will bail out.
827 app.notResponding = true;
828
829 // Log the ANR to the event log.常常搜索的am_anr关键字，记录ANR信息到eventlog中
830 EventLog.writeEvent(EventLogTags.AM_ANR, app.userId, app.pid,
831 app.processName, app.info.flags, annotation);
832
833 // Dump thread traces as quickly as we can, starting with "interesting" processes.
//ANR进程放到firstPids集合中
834 firstPids.add(app.pid);
835
836 // Don't dump other PIDs if it's a background ANR
//如果是后台的ANR，就不dump了
837 isSilentANR = !showBackground && !isInterestingForBackgroundTraces(app);
838 if (!isSilentANR) {
839 int parentPid = app.pid;
840 if (parent != null && parent.app != null && parent.app.pid > 0) {
841 parentPid = parent.app.pid;
842 }
//把ANR的父进程也记录firstPids中
843 if (parentPid != app.pid) firstPids.add(parentPid);
844 //MY_PID是system_server的pid，如果发生的进程不是system，需要把system进程加到firstPids中
845 if (MY_PID != app.pid && MY_PID != parentPid) firstPids.add(MY_PID);
846 //最近运行的进程在mLruProcesses中，遍历这个List
847 for (int i = mService.mLruProcesses.size() - 1; i >= 0; i--) {
848 ProcessRecord r = mService.mLruProcesses.get(i);
849 if (r != null && r.thread != null) {
850 int pid = r.pid;
851 if (pid > 0 && pid != app.pid && pid != parentPid && pid != MY_PID) {
//如果persistent进程，这类是“不死进程”，
//这类进程在启动的时候会针对目标用户进程的IApplicationThread接口，注册一个binder讣告监听器，
//一旦日后用户进程意外挂掉，AMS就能在第一时间感知到，
//并采取相应的措施。如果AMS发现意外挂掉的应用是persistent的，它会尝试重新启动这个应用
852 if (r.persistent) {
853 firstPids.add(pid);
854 if (DEBUG_ANR) Slog.i(TAG, "Adding persistent proc: " + r);
855 } else if (r.treatLikeActivity) {
856 firstPids.add(pid);
857 if (DEBUG_ANR) Slog.i(TAG, "Adding likely IME: " + r);
858 } else {
//其他的都加到lastPids中
859 lastPids.put(pid, Boolean.TRUE);
860 if (DEBUG_ANR) Slog.i(TAG, "Adding ANR proc: " + r);
861 }
862 }
863 }
864 }
865 }
866 }
867
868 // Log the ANR to the main log.输出到main log里面
869 StringBuilder info = new StringBuilder();
870 info.setLength(0);
871 info.append("ANR in ").append(app.processName);
872 if (activity != null && activity.shortComponentName != null) {
873 info.append(" (").append(activity.shortComponentName).append(")");
874 }
875 info.append("\n");
876 info.append("PID: ").append(app.pid).append("\n");
877 if (annotation != null) {
878 info.append("Reason: ").append(annotation).append("\n");
879 }
880 if (parent != null && parent != activity) {
881 info.append("Parent: ").append(parent.shortComponentName).append("\n");
882 }
883
884 ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);
885
886 // don't dump native PIDs for background ANRs unless it is the process of interest
887 String[] nativeProcs = null;
888 if (isSilentANR) {
//NATIVE_STACKS_OF_INTEREST是Watchog中定义的几个关键的进程
889 for (int i = 0; i < NATIVE_STACKS_OF_INTEREST.length; i++) {
890 if (NATIVE_STACKS_OF_INTEREST[i].equals(app.processName)) {
891 nativeProcs = new String[] { app.processName };
892 break;
893 }
894 }
895 } else {
896 nativeProcs = NATIVE_STACKS_OF_INTEREST;
897 }
898 //获取nativeProcs这些进程的pid
899 int[] pids = nativeProcs == null ? null : Process.getPidsForCommands(nativeProcs);
900 ArrayList<Integer> nativePids = null;
901
902 if (pids != null) {
903 nativePids = new ArrayList<Integer>(pids.length);
904 for (int i : pids) {
905 nativePids.add(i);
906 }
907 }
908
909 // For background ANRs, don't pass the ProcessCpuTracker to
910 // avoid spending 1/2 second collecting stats to rank lastPids.
//
911 File tracesFile = mService.dumpStackTraces(true, firstPids,
912 (isSilentANR) ? null : processCpuTracker,
913 (isSilentANR) ? null : lastPids,
914 nativePids);
915
916 String cpuInfo = null;
917 if (ActivityManagerService.MONITOR_CPU_USAGE) {
//更新Cpu的信息
918 mService.updateCpuStatsNow();
919 synchronized (mService.mProcessCpuTracker) {
// 记录ANR之前的cpu使用情况（CPU usage from xxxms to 0ms ago）
920 cpuInfo = mService.mProcessCpuTracker.printCurrentState(anrTime);
921 }
// 记录从anr时间开始的Cpu负载
922 info.append(processCpuTracker.printCurrentLoad());
923 info.append(cpuInfo);
924 }
925 // 记录从anr时间开始的cpu使用情况(CPU usage from xxms to xxms later)
926 info.append(processCpuTracker.printCurrentState(anrTime));
927
928 Slog.e(TAG, info.toString());
929 if (tracesFile == null) {
930 // 如果trace为空，则发送singal 3到发送ANR的进程，相当于执行adb shell kill -3 pid命令
931 Process.sendSignal(app.pid, Process.SIGNAL_QUIT);
932 }
933 //写到DropBox文件夹里面（data/system/dropbox）
934 mService.addErrorToDropBox("anr", app, app.processName, activity, parent, annotation,
935 cpuInfo, tracesFile, null);
936
937 if (mService.mController != null) {
938 try {
939 // 0 == show dialog, 1 = keep waiting, -1 = kill process immediately
940 int res = mService.mController.appNotResponding(
941 app.processName, app.pid, info.toString());
942 if (res != 0) {
943 if (res < 0 && app.pid != MY_PID) {
944 app.kill("anr", true);
945 } else {
946 synchronized (mService) {
947 mService.mServices.scheduleServiceTimeoutLocked(app);
948 }
949 }
950 return;
951 }
952 } catch (RemoteException e) {
953 mService.mController = null;
954 Watchdog.getInstance().setActivityController(null);
955 }
956 }
957
958 synchronized (mService) {
959 mService.mBatteryStatsService.noteProcessAnr(app.processName, app.uid);
960 //如果是后台ANR，直接kill
961 if (isSilentANR) {
962 app.kill("bg anr", true);
963 return;
964 }
965
966 // Set the app's notResponding state, and look up the errorReportReceiver
967 吧 (app,
968 activity != null ? activity.shortComponentName : null,
969 annotation != null ? "ANR " + annotation : "ANR",
970 info.toString());
971
972 // 弹出无响应对话框
973 Message msg = Message.obtain();
974 HashMap<String, Object> map = new HashMap<String, Object>();
975 msg.what = ActivityManagerService.SHOW_NOT_RESPONDING_UI_MSG;
976 msg.obj = map;
977 msg.arg1 = aboveSystem ? 1 : 0;
978 map.put("app", app);
979 if (activity != null) {
980 map.put("activity", activity);
981 }
982 给android.ui线程发生一个消息，弹出对话框
983 mService.mUiHandler.sendMessage(msg);
984 }
985 }
986
上面的代码撸了一遍，总结一下appNotResponding的业务逻辑：
- 1、输出ANR Reason信息到Events log中，关键字是am_anr，一般都是用这个信息来确定Anr的发生时间
- 2、如果是后台的anr，即isSilentANR值为true，那么不显示ANR对话框，直接kill掉ANR所在进程
- 3、输出ANR 信息到main log中，关键字是ANR in，含有Cpu负载信息，一般都是用这个看ANR发生时候的其他进程的资源占用情况
- 4、调用dumpStackTraces去生成trace文件，这个trace文件有哪些进程呢？
a.firstPids队列：第一个是ANR进程，第二个是system_server，剩余是所有persistent进程；
b.Native队列：是指/system/bin/目录的mediaserver,sdcard 以及surfaceflinger进程；
c.lastPids队列: 是指mLruProcesses中的不属于firstPids的所有进程。- 5、将traces文件和 CPU使用情况信息保存到dropbox，即data/system/dropbox目录
- 6、弹窗告知用户
除了上面的业务总结，我们发现有几个小知识点
- 1、关机过程虽然比较耗时，但是不会出现ANR，不必多说，你说人家都关机了，还有提示发生ANR的必要了吗？
- 2、ANR有两种，前台ANR和后台ANR，我在调试中发现，后台ANR非常容易发生，系统直接kill掉这个应用进程，但是用户没有感知。
- 3、am_anr关键字比ANR in要先打印，所以更接近ANR的实际发生时间
２、dumpStackTraces(1/2)方法解读
继续看appNotResponding中的核心逻辑dumpStackTraces
http://androidxref.com/8.1.0_r33/xref/frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java#5492
5483 /**
5484 * If a stack trace dump file is configured, dump process stack traces.
5485 * @param clearTraces causes the dump file to be erased prior to the new
5486 * traces being written, if true; when false, the new traces will be
5487 * appended to any existing file content.
5488 * @param firstPids of dalvik VM processes to dump stack traces for first
5489 * @param lastPids of dalvik VM processes to dump stack traces for last
5490 * @param nativePids optional list of native pids to dump stack crawls
5491 */
5492 public static File dumpStackTraces(boolean clearTraces, ArrayList<Integer> firstPids,
5493 ProcessCpuTracker processCpuTracker, SparseArray<Boolean> lastPids,
5494 ArrayList<Integer> nativePids) {
5495 ArrayList<Integer> extraPids = null;
5496 ......
5524 boolean useTombstonedForJavaTraces = false;
5525 File tracesFile;
5526 //如果dalvik.vm.stack-trace-dir没有配置，trace就写到全局文件data/anr/traces.txt中
5527 final String tracesDirProp = SystemProperties.get("dalvik.vm.stack-trace-dir", "");
5528 if (tracesDirProp.isEmpty()) {
5529 // When dalvik.vm.stack-trace-dir is not set, we are using the "old" trace
5530 // dumping scheme. All traces are written to a global trace file (usually
5531 // "/data/anr/traces.txt") so the code below must take care to unlink and recreate
5532 // the file if requested.
5533 //
5534 // This mode of operation will be removed in the near future.
5535
5536
5537 String globalTracesPath = SystemProperties.get("dalvik.vm.stack-trace-file", null);
5538 if (globalTracesPath.isEmpty()) {
// 没有配置dalvik.vm.stack-trace-file，则返回null
5539 Slog.w(TAG, "dumpStackTraces: no trace path configured");
5540 return null;
5541 }
5542
5543 tracesFile = new File(globalTracesPath);
5544 try {
//删除旧的，创建新的
5545 if (clearTraces && tracesFile.exists()) {
5546 tracesFile.delete();
5547 }
5548
5549 tracesFile.createNewFile();
5550 FileUtils.setPermissions(globalTracesPath, 0666, -1, -1); // -rw-rw-rw-
5551 } catch (IOException e) {
5552 Slog.w(TAG, "Unable to prepare ANR traces file: " + tracesFile, e);
5553 return null;
5554 }
5555 } else {
5556 File tracesDir = new File(tracesDirProp);
5557 // When dalvik.vm.stack-trace-dir is set, we use the "new" trace dumping scheme.
5558 // Each set of ANR traces is written to a separate file and dumpstate will process
5559 // all such files and add them to a captured bug report if they're recent enough.
5560 maybePruneOldTraces(tracesDir);
5561
5562 // NOTE: We should consider creating the file in native code atomically once we've
5563 // gotten rid of the old scheme of dumping and lot of the code that deals with paths
5564 // can be removed.
// 创建trace文件，格式为anr_yyyy-MM-dd-HH-mm-ss-SSS
5565 tracesFile = createAnrDumpFile(tracesDir);
5566 if (tracesFile == null) {
5567 return null;
5568 }
5569
5570 useTombstonedForJavaTraces = true;
5571 }
5572
5573 dumpStackTraces(tracesFile.getAbsolutePath(), firstPids, nativePids, extraPids,
5574 useTombstonedForJavaTraces);
5575 return tracesFile;
5576 }
这段代码并没有真正的执行dump操作，只是确定了trace文件路径，如果”dalvik.vm.stack-trace-dir”这个属性没有配置，就使用旧的dump策略，trace信息写入到全局trace文件/data/anr/traces.txt中，删除旧的traces文件，创建新的traces文件；如果”dalvik.vm.stack-trace-dir”属性被配置了，就创建格式为anr_yyyy-MM-dd-HH-mm-ss-SSS的文件。
dalvik.vm.stack-trace-file特性
dalvik.vm.stack-trace-file特性允许你指定要将线程堆栈追踪写入的文件名，如果不存在，将创建，新的信息将追加到文件尾，文件名通过-Xstacktracefile参数写入虚拟机。例如：
adb shell setprop dalvik.vm.stack-trace-file /tmp/stack-traces.txt
如果这个特性没有被定义，虚拟机会在收到这个信号时将堆栈追踪信息写入android log。
http://androidxref.com/8.1.0_r33/xref/frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java#5581
5581 private static synchronized File createAnrDumpFile(File tracesDir) {
5582 if (sAnrFileDateFormat == null) {
5583 sAnrFileDateFormat = new SimpleDateFormat("yyyy-MM-dd-HH-mm-ss-SSS");
5584 }
5585
5586 final String formattedDate = sAnrFileDateFormat.format(new Date());
5587 final File anrFile = new File(tracesDir, "anr_" + formattedDate);
5588
5589 try {
5590 if (anrFile.createNewFile()) {
5591 FileUtils.setPermissions(anrFile.getAbsolutePath(), 0600, -1, -1); // -rw-------
5592 return anrFile;
5593 } else {
5594 Slog.w(TAG, "Unable to create ANR dump file: createNewFile failed");
5595 }
5596 } catch (IOException ioe) {
5597 Slog.w(TAG, "Exception creating ANR dump file:", ioe);
5598 }
5599
5600 return null;
5601 }
5602
3、dumpStackTraces(2/2)方法解读
http://androidxref.com/8.1.0_r33/xref/frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java#5704
5704 private static void dumpStackTraces(String tracesFile, ArrayList<Integer> firstPids,
5705 ArrayList<Integer> nativePids, ArrayList<Integer> extraPids,
5706 boolean useTombstonedForJavaTraces) {
5707
5708 // We don't need any sort of inotify based monitoring when we're dumping traces via
5709 // tombstoned. Data is piped to an "intercept" FD installed in tombstoned so we're in full
5710 // control of all writes to the file in question.
5711 final DumpStackFileObserver observer;
5712 if (useTombstonedForJavaTraces) {
5713 observer = null;
5714 } else {
5715 // Use a FileObserver to detect when traces finish writing.
5716 // The order of traces is considered important to maintain for legibility.
5717 observer = new DumpStackFileObserver(tracesFile);
5718 }
5719
5720 // 所有的dump操作需要在20秒之内完成
5721 long remainingTime = 20 * 1000;
5722 try {
5723 if (observer != null) {
5724 observer.startWatching();
5725 }
5726
5727 // 第一步收集firstPids中进程的trace，超时会自动放弃
5728 if (firstPids != null) {
5729 int num = firstPids.size();
5730 for (int i = 0; i < num; i++) {
5731 if (DEBUG_ANR) Slog.d(TAG, "Collecting stacks for pid "
5732 + firstPids.get(i));
5733 final long timeTaken;
5734 if (useTombstonedForJavaTraces) {
5735 timeTaken = dumpJavaTracesTombstoned(firstPids.get(i), tracesFile, remainingTime);
5736 } else {
5737 timeTaken = observer.dumpWithTimeout(firstPids.get(i), remainingTime);
5738 }
5739
5740 remainingTime -= timeTaken;
5741 if (remainingTime <= 0) {
5742 Slog.e(TAG, "Aborting stack trace dump (current firstPid=" + firstPids.get(i) +
5743 "); deadline exceeded.");
5744 return;
5745 }
5746
5747 if (DEBUG_ANR) {
5748 Slog.d(TAG, "Done with pid " + firstPids.get(i) + " in " + timeTaken + "ms");
5749 }
5750 }
5751 }
5752
5753 // 第二步收集nativePids中进程的trace，超时会自动放弃
5754 if (nativePids != null) {
5755 for (int pid : nativePids) {
5756 if (DEBUG_ANR) Slog.d(TAG, "Collecting stacks for native pid " + pid);
5757 final long nativeDumpTimeoutMs = Math.min(NATIVE_DUMP_TIMEOUT_MS, remainingTime);
5758
5759 final long start = SystemClock.elapsedRealtime();
5760 Debug.dumpNativeBacktraceToFileTimeout(
5761 pid, tracesFile, (int) (nativeDumpTimeoutMs / 1000));
5762 final long timeTaken = SystemClock.elapsedRealtime() - start;
5763
5764 remainingTime -= timeTaken;
5765 if (remainingTime <= 0) {
5766 Slog.e(TAG, "Aborting stack trace dump (current native pid=" + pid +
5767 "); deadline exceeded.");
5768 return;
5769 }
5770
5771 if (DEBUG_ANR) {
5772 Slog.d(TAG, "Done with native pid " + pid + " in " + timeTaken + "ms");
5773 }
5774 }
5775 }
5776
5777 //第三步收集extraPids中进程的trace，超时会自动放弃，这个代码和第一步一样的
5778 if (extraPids != null) {
5779 for (int pid : extraPids) {
5780 if (DEBUG_ANR) Slog.d(TAG, "Collecting stacks for extra pid " + pid);
5781
5782 final long timeTaken;
5783 if (useTombstonedForJavaTraces) {
5784 timeTaken = dumpJavaTracesTombstoned(pid, tracesFile, remainingTime);
5785 } else {
5786 timeTaken = observer.dumpWithTimeout(pid, remainingTime);
5787 }
5788
5789 remainingTime -= timeTaken;
5790 if (remainingTime <= 0) {
5791 Slog.e(TAG, "Aborting stack trace dump (current extra pid=" + pid +
5792 "); deadline exceeded.");
5793 return;
5794 }
5795
5796 if (DEBUG_ANR) {
5797 Slog.d(TAG, "Done with extra pid " + pid + " in " + timeTaken + "ms");
5798 }
5799 }
5800 }
5801 } finally {
5802 if (observer != null) {
5803 observer.stopWatching();
5804 }
5805 }
5806 }
firstPids和extraPids中的进程dump trace有两种方式，看useTombstonedForJavaTraces的取值；
- 如果useTombstonedForJavaTraces为真，采用dumpJavaTracesTombstoned获取trace
- 如果useTombstonedForJavaTraces为假，采用DumpStackFileObserver#dumpWithTimeout获取trace
对于nativePids中的进程，只能通过 Debug.dumpNativeBacktraceToFileTimeout来获取trace。
除了上面的总结还需要思考几个小问题
- 问题１: 利用am_anr来确定ANR的发生时间真的准确吗？
在上一篇文章就已经说了，不准确，可能由于系统资源比较紧张造成一定程度的滞后，十多秒都可能，此时需要结合eventlog进一步分析。
问题２:ANR中经常出现没有trace，或者无效trace是怎么回事？
- 从appNotResponding方法中，我们看到有不少return的地方，在dumpStackTraces方法，也会有return出现，比如这么多进程的trace需要在20秒之内完成，在系统资源紧张的时候，能不能完成，需要打一个问号了
- 有一些ANR问题需要binder对端的trace，通过上面的分析看，大概率是没有对端的trace的，除非binder call到system_server或者比较重要的几个native进程里面
- 另外发生ANR的时候，线程并没有暂停掉，有可能等到我们去抓这个进程的trace的时候，这个进程的主线程都恢复正常了，比如经常性出现下面的nativePollOnce状态的堆栈。
"main" prio=5 tid=1 Native
| group="main" sCount=1 dsCount=0 obj=0x7685ba50 self=0x7fb0840a00
| sysTid=1460 nice=-10 cgrp=default sched=0/0 handle=0x7fb4824aa0
| state=S schedstat=( 213445473008 99617457476 724519 ) utm=14518 stm=6826 core=0 HZ=100
| stack=0x7fe82c6000-0x7fe82c8000 stackSize=8MB
| held mutexes=
kernel: __switch_to+0x70/0x7c
kernel: SyS_epoll_wait+0x2d4/0x394
kernel: SyS_epoll_pwait+0xc4/0x150
kernel: el0_svc_naked+0x24/0x28
native: #00 pc 000000000001bf2c /system/lib64/libc.so (syscall+28)
native: #01 pc 00000000000e813c /system/lib64/libart.so (_ZN3art17ConditionVariable16WaitHoldingLocksEPNS_6ThreadE+160)
native: #02 pc 000000000054b6f8 /system/lib64/libart.so (_ZN3artL12GoToRunnableEPNS_6ThreadE+328)
native: #03 pc 000000000054b56c /system/lib64/libart.so (_ZN3art12JniMethodEndEjPNS_6ThreadE+28)
native: #04 pc 00000000008ccc50 /system/framework/arm64/boot-framework.oat (Java_android_os_MessageQueue_nativePollOnce__JI+156)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:323)
at android.os.Looper.loop(Looper.java:142)
at com.android.server.SystemServer.run(SystemServer.java:387)
at com.android.server.SystemServer.main(SystemServer.java:245)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:904)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:794)
- 问题3: ANR中的dumpStackTraces是耗时操作，会不会引起系统的ANR?
我觉得是有可能的，而是在系统稳定性很差的情况下，大量应用都ANR了，都需要dumpStackTraces，那么都有引起系统watchdog的可能。AOSP在P上有多个changelist对此进行优化，有兴趣可以自己查看。
3.1、DumpStackFileObserver方式获取trace
http://androidxref.com/8.1.0_r33/xref/frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java#5631
5625 /**
5626 * Legacy code, do not use. Existing users will be deleted.
5627 *
5628 * @deprecated
5629 */
5630 @Deprecated
5631 public static class DumpStackFileObserver extends FileObserver {
5632 // Keep in sync with frameworks/native/cmds/dumpstate/utils.cpp
5633 private static final int TRACE_DUMP_TIMEOUT_MS = 10000; // 10 seconds
5634
5635 private final String mTracesPath;
5636 private boolean mClosed;
5637
5638 public DumpStackFileObserver(String tracesPath) {
5639 super(tracesPath, FileObserver.CLOSE_WRITE);
5640 mTracesPath = tracesPath;
5641 }
5642
5643 @Override
5644 public synchronized void onEvent(int event, String path) {
5645 mClosed = true;
5646 notify();
5647 }
5648
5649 public long dumpWithTimeout(int pid, long timeout) {
//发生singal开输出trace，相当于adb shell kill -3
5650 sendSignal(pid, SIGNAL_QUIT);
5651 final long start = SystemClock.elapsedRealtime();
5652 // timeout为20s，TRACE_DUMP_TIMEOUT_MS为10s，取小则为10s
5653 final long waitTime = Math.min(timeout, TRACE_DUMP_TIMEOUT_MS);
5654 synchronized (this) {
5655 try {
5656 wait(waitTime); // Wait for traces file to be closed.
5657 } catch (InterruptedException e) {
5658 Slog.wtf(TAG, e);
5659 }
5660 }
5661
5662 // This avoids a corner case of passing a negative time to the native
5663 // trace in case we've already hit the overall timeout.
5664 final long timeWaited = SystemClock.elapsedRealtime() - start;
5665 if (timeWaited >= timeout) {
5666 return timeWaited;
5667 }
5668
.......
5683 return (end - start);
5684 }
5685 }
这个方法将会被废弃了，原理上就是用adb shell kill -3抓trace
3.2、dumpJavaTracesTombstoned方式获取trace
5687 /**
5688 * Dump java traces for process {@code pid} to the specified file. If java trace dumping
5689 * fails, a native backtrace is attempted. Note that the timeout {@code timeoutMs} only applies
5690 * to the java section of the trace, a further {@code NATIVE_DUMP_TIMEOUT_MS} might be spent
5691 * attempting to obtain native traces in the case of a failure. Returns the total time spent
5692 * capturing traces.
5693 */
5694 private static long dumpJavaTracesTombstoned(int pid, String fileName, long timeoutMs) {
5695 final long timeStart = SystemClock.elapsedRealtime();
5696 if (!Debug.dumpJavaBacktraceToFileTimeout(pid, fileName, (int) (timeoutMs / 1000))) {
5697 Debug.dumpNativeBacktraceToFileTimeout(pid, fileName,
5698 (NATIVE_DUMP_TIMEOUT_MS / 1000));
5699 }
5700
5701 return SystemClock.elapsedRealtime() - timeStart;
5702 }
实质上还是由dumpJavaBacktraceToFileTimeout来获取trace。dumpNativeBacktraceToFileTimeout是一个native方法，下面来看一看
1131static jboolean android_os_Debug_dumpNativeBacktraceToFileTimeout(JNIEnv* env, jobject clazz,
1132 jint pid, jstring fileName, jint timeoutSecs) {
1133 const bool ret = dumpTraces(env, pid, fileName, timeoutSecs, kDebuggerdNativeBacktrace);
1134 return ret ? JNI_TRUE : JNI_FALSE;
1135}
1107static bool dumpTraces(JNIEnv* env, jint pid, jstring fileName, jint timeoutSecs,
1108 DebuggerdDumpType dumpType) {
1109 const ScopedUtfChars fileNameChars(env, fileName);
1110 if (fileNameChars.c_str() == nullptr) {
1111 return false;
1112 }
1113 //打开 /data/anr/anr_yyyy-MM-dd-HH-mm-ss-SSS文件
1114 android::base::unique_fd fd(open(fileNameChars.c_str(),
1115 O_CREAT | O_WRONLY | O_NOFOLLOW | O_CLOEXEC | O_APPEND,
1116 0666));
1117 if (fd < 0) {
1118 fprintf(stderr, "Can't open %s: %s\n", fileNameChars.c_str(), strerror(errno));
1119 return false;
1120 }
1121
1122 return (dump_backtrace_to_file_timeout(pid, dumpType, timeoutSecs, fd) == 0);
1123}
int dump_backtrace_to_file_timeout(pid_t tid, DebuggerdDumpType dump_type, int timeout_secs, int fd) {
android::base::unique_fd copy(dup(fd));
if (copy == -1) {
return -1;
}
int timeout_ms = timeout_secs > 0 ? timeout_secs * 1000 : 0;
return debuggerd_trigger_dump(tid, dump_type, timeout_ms, std::move(copy)) ? 0 : -1;
}
可以看到实质是调用debuggerd_trigger_dump，可以看debuggerd_client.cpp，可向debuggerd发送命令，利用debuggerd抓trace。
总结：在dumpStackTraces方法中，主要根据useTombstonedForJavaTraces这个属性来设置不同的抓取trace的方式，java的进程实质上是使用adb shell kill -3来抓trace，对于native的进程实质上是使用debuggerd(debuggerd -b [pid])抓trace。而useTombstonedForJavaTraces的值是false还是true取决与"dalvik.vm.stack-trace-dir"这个属性在开机的时候是否设置了。
网友评论