Android 分析ANR和死锁

另外介绍：Android log常用分析方法

一 Google官网对分析ANR日志和死锁的阐述

ANRs and deadlocks

(Reading Bug Reports章节)
Bugreports can help you identify what's causing Application Not Responding (ANR) errors and deadlock events.

Identifying unresponsive apps

When an application does not respond within a certain time, usually due to a blocked or busy main thread, the system kills the process and dumps the stack to /data/anr. To discover the culprit behind an ANR, grep for am_anr in the binary event log.

grep "am_anr" bugreport-2015-10-01-18-13-48.txt
10-01 18:12:49.599 4600 4614 I am_anr : [0,29761,com.google.android.youtube,953695941,executing service com.google.android.youtube/com.google.android.apps.youtube.app.offline.transfer.OfflineTransferService]
10-01 18:14:10.211 4600 4614 I am_anr : [0,30363,com.google.android.apps.plus,953728580,executing service com.google.android.apps.plus/com.google.android.apps.photos.service.PhotosService]

You can also grep for ANR in in the logcat log, which contains more information about what was using CPU at the time of the ANR. 

Finding stack traces

You can often find stack traces that correspond to an ANR. Make sure the timestamp and PID on the VM traces match the ANR you are investigating, then check the main thread of the process. Keep in mind:
1.The main thread tells you only what the thread was doing at the time of the ANR, which may or may not correspond to the true cause of the ANR. (The stack in the bug report may be innocent; something else may have been stuck for a long time—but not quite long enough to ANR—before becoming unstuck.)
2.More than one set of stack traces might exist. Make sure you are viewing the correct section.

Finding deadlocks

Deadlocks often first appear as ANRs because threads are getting stuck. If the deadlock hits the system server, the watchdog will eventually kill it, leading to an entry in the log similar to: WATCHDOG KILLING SYSTEM PROCESS. From the user perspective, the device reboots, although technically this is a runtime restart rather than a true reboot.

1.In a runtime restart, the system server dies and is restarted; the user sees the device return to the boot animation.
2.In a reboot, the kernel has crashed; the user sees the device return to the Google boot logo.
To find deadlocks, check the VM traces sections for a pattern of thread A waiting on something held by thread B, which in turn is waiting on something held by thread A.

根据官网论述，死锁现象也会作为ANR的一种表现方式出现，也会把日志记录到/data/anr目录下，但是如果死锁发生在system server进程中，则看门狗(watchdog)会杀掉system server进程，并且在main log中会看到关键字"WATCHDOG KILLING SYSTEM PROCESS"，系统运行时将会重启，system server也会重启，此时用户会看到开机动画会再次播放。

二 ANR阈值定义

2.1 Android规定ANR出现的场景

A 用户界面内如果5秒钟之内无法响应屏幕触摸事件或者键盘输入事件就会出现ANR
B 前台Service如果20秒之内未结束就会出现ANR，后台Service如果200秒之内未结束就会出现ANR
C 前台Broadcast如果在10秒之内未结束就会出现ANR，后台Broadcast如果60秒之内未结束就会出现ANR

Android 6.0.1 
frameworks/base/services/core/java/com/android/server/am/ActiveServices.java
frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java
frameworks/base/core/java/com/android/internal/os/ProcessCpuTracker.java

frameworks/base/services/core/java/com/android/server/wm/InputMonitor.java
frameworks/base/services/core/java/com/android/server/input/InputManagerService.java
frameworks/base/services/core/java/com/android/server/input/InputApplicationHandle.java
frameworks/base/services/core/java/com/android/server/input/InputWindowHandle.java

frameworks/base/services/core/jni/com_android_server_input_InputManagerService.cpp
frameworks/native/services/inputflinger/InputDispatcher.h
frameworks/native/services/inputflinger/InputDispatcher.cpp

frameworks/base/docs/html/tools/debugging/debugging-memory.jd

通过如下命令查看记录ANR日志的文件路径
zhanghu@winth:~$ adb shell getprop dalvik.vm.stack-trace-file
/data/anr/traces.txt

2.2 ANR阈值常量声明

2.2.1 Android6.0.1 

-->ActiveServices.java
// How long we wait for a service to finish executing.
static final int SERVICE_TIMEOUT = 20*1000; //20秒

// How long we wait for a service to finish executing.
static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10; //200秒

-->ActivityManagerService.java
// How long we allow a receiver to run before giving up on it.
static final int BROADCAST_FG_TIMEOUT = 10*1000; //10秒
static final int BROADCAST_BG_TIMEOUT = 60*1000;//60秒

// How long we wait until we timeout on key dispatching.
static final int KEY_DISPATCHING_TIMEOUT = 5*1000; //5秒

-->InputDispatcher.cpp
// Default input dispatching timeout if there is no focused application or paused window
// from which to determine an appropriate dispatching timeout.
const nsecs_t DEFAULT_INPUT_DISPATCHING_TIMEOUT = 5000 * 1000000LL; // 5 sec

2.2.2 Android1.6

-->ActivityManagerService.java
// How long we allow a receiver to run before giving up on it.
static final int BROADCAST_TIMEOUT = 10*1000; //10秒

// How long we wait for a service to finish executing.
static final int SERVICE_TIMEOUT = 20*1000; //20秒

// How long we wait until we timeout on key dispatching.
static final int KEY_DISPATCHING_TIMEOUT = 5*1000; //5秒

三 ANR出现时调用的函数

-->ActivityManagerService.java

 final void appNotResponding(ProcessRecord app, ActivityRecord activity,
            ActivityRecord parent, boolean aboveSystem, final String annotation) {
        ArrayList<Integer> firstPids = new ArrayList<Integer>(5);
        SparseArray<Boolean> lastPids = new SparseArray<Boolean>(20);

        if (mController != null) {
            try {
                // 0 == continue, -1 = kill process immediately
                int res = mController.appEarlyNotResponding(app.processName, app.pid, annotation);
                if (res < 0 && app.pid != MY_PID) {
                    app.kill("anr", true);
                }
            } catch (RemoteException e) {
                mController = null;
                Watchdog.getInstance().setActivityController(null);
            }
        }

        long anrTime = SystemClock.uptimeMillis();
        if (MONITOR_CPU_USAGE) {
            updateCpuStatsNow();
        }

        synchronized (this) {
            // PowerManager.reboot() can block for a long time, so ignore ANRs while shutting down.
            if (mShuttingDown) { //关机时忽视ANR
                Slog.i(TAG, "During shutdown skipping ANR: " + app + " " + annotation);
                return;
            } else if (app.notResponding) { //忽视重复的ANR
                Slog.i(TAG, "Skipping duplicate ANR: " + app + " " + annotation);
                return;
            } else if (app.crashing) { //应用发生crash时忽视ANR
                Slog.i(TAG, "Crashing app skipping ANR: " + app + " " + annotation);
                return;
            }

            // In case we come through here for the same app before completing
            // this one, mark as anring now so we will bail out.
            app.notResponding = true;

            // 记录ANR event log
            // Log the ANR to the event log.
            EventLog.writeEvent(EventLogTags.AM_ANR, app.userId, app.pid,
                    app.processName, app.info.flags, annotation);

            // Dump thread traces as quickly as we can, starting with "interesting" processes.
            firstPids.add(app.pid);

            int parentPid = app.pid;
            if (parent != null && parent.app != null && parent.app.pid > 0) parentPid = parent.app.pid;
            if (parentPid != app.pid) firstPids.add(parentPid);

            if (MY_PID != app.pid && MY_PID != parentPid) firstPids.add(MY_PID);

            for (int i = mLruProcesses.size() - 1; i >= 0; i--) {
                ProcessRecord r = mLruProcesses.get(i);
                if (r != null && r.thread != null) {
                    int pid = r.pid;
                    if (pid > 0 && pid != app.pid && pid != parentPid && pid != MY_PID) {
                        if (r.persistent) {
                            firstPids.add(pid);
                        } else {
                            lastPids.put(pid, Boolean.TRUE);
                        }
                    }
                }
            }
        }

        // 记录ANR 到 main log
        // Log the ANR to the main log.
        StringBuilder info = new StringBuilder();
        info.setLength(0);
        info.append("ANR in ").append(app.processName); //关键字"ANR in"
        if (activity != null && activity.shortComponentName != null) {
            info.append(" (").append(activity.shortComponentName).append(")");
        }
        info.append("\n");
        info.append("PID: ").append(app.pid).append("\n");
        if (annotation != null) {
            info.append("Reason: ").append(annotation).append("\n");
        }
        if (parent != null && parent != activity) {
            info.append("Parent: ").append(parent.shortComponentName).append("\n");
        }

        final ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);

        // dump堆栈log
        File tracesFile = dumpStackTraces(true, firstPids, processCpuTracker, lastPids,
                NATIVE_STACKS_OF_INTEREST);

        String cpuInfo = null;
        if (MONITOR_CPU_USAGE) {
            updateCpuStatsNow();
            synchronized (mProcessCpuTracker) {
                cpuInfo = mProcessCpuTracker.printCurrentState(anrTime);
            }
            info.append(processCpuTracker.printCurrentLoad());
            info.append(cpuInfo);
        }

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

        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(app.pid, Process.SIGNAL_QUIT);
        }

        // 将ANR信息丢掉DropBox
        addErrorToDropBox("anr", app, app.processName, activity, parent, annotation,
                cpuInfo, tracesFile, null);

        if (mController != null) {
            try {
                // 0 == show dialog, 1 = keep waiting, -1 = kill process immediately
                int res = mController.appNotResponding(app.processName, app.pid, info.toString());
                if (res != 0) {
                    if (res < 0 && app.pid != MY_PID) {
                        app.kill("anr", true);
                    } else {
                        synchronized (this) {
                            mServices.scheduleServiceTimeoutLocked(app);
                        }
                    }
                    return;
                }
            } catch (RemoteException e) {
                mController = null;
                Watchdog.getInstance().setActivityController(null);
            }
        }

        //一般情况都会弹出ANR对话框，除非已经配置了不让弹出对话框，这种情况直接在后台进行杀死进程的操作
        // Unless configured otherwise, swallow ANRs in background processes & kill the process.
        boolean showBackground = Settings.Secure.getInt(mContext.getContentResolver(),
                Settings.Secure.ANR_SHOW_BACKGROUND, 0) != 0;

        synchronized (this) {
            mBatteryStatsService.noteProcessAnr(app.processName, app.uid);

            if (!showBackground && !app.isInterestingToUserLocked() && app.pid != MY_PID) {
                app.kill("bg anr", true);
                return;
            }

            // Set the app's notResponding state, and look up the errorReportReceiver
            makeAppNotRespondingLocked(app,
                    activity != null ? activity.shortComponentName : null,
                    annotation != null ? "ANR " + annotation : "ANR",
                    info.toString());

            //Set the trace file name to app name + current date format to avoid overrinding trace file
            String tracesPath = SystemProperties.get("dalvik.vm.stack-trace-file", null);
            if (tracesPath != null && tracesPath.length() != 0) {
                File traceRenameFile = new File(tracesPath);
                String newTracesPath;
                int lpos = tracesPath.lastIndexOf (".");
                if (-1 != lpos)
                    newTracesPath = tracesPath.substring (0, lpos) + "_" + app.processName + "_" + mTraceDateFormat.format(new Date()) + tracesPath.substring (lpos);
                else
                    newTracesPath = tracesPath + "_" + app.processName;

                traceRenameFile.renameTo(new File(newTracesPath));
            }

            // 显示ANR对话框
            // Bring up the infamous App Not Responding dialog
            Message msg = Message.obtain();
            HashMap<String, Object> map = new HashMap<String, Object>();
            msg.what = SHOW_NOT_RESPONDING_MSG;
            msg.obj = map;
            msg.arg1 = aboveSystem ? 1 : 0;
            map.put("app", app);
            if (activity != null) {
                map.put("activity", activity);
            }

            mUiHandler.sendMessage(msg);
        }
    }
    
    ......
  public static File dumpStackTraces(boolean clearTraces, ArrayList<Integer> firstPids,
            ProcessCpuTracker processCpuTracker, 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()) {
                tracesDir.mkdirs();
                if (!SELinux.restorecon(tracesDir)) {
                    return null;
                }
            }
            FileUtils.setPermissions(tracesDir.getPath(), 0775, -1, -1);  // drwxrwxr-x

            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, processCpuTracker, lastPids, nativeProcs);
        return tracesFile;
    }

  private static void dumpStackTraces(String tracesPath, ArrayList<Integer> firstPids,
            ProcessCpuTracker processCpuTracker, SparseArray<Boolean> lastPids, String[] nativeProcs) {
        // Use a FileObserver to detect when traces finish writing.
        // The order of traces is considered important to maintain for legibility.
        FileObserver observer = new FileObserver(tracesPath, FileObserver.CLOSE_WRITE) {
            @Override
            public synchronized void onEvent(int event, String path) { notify(); }
        };

        try {
            observer.startWatching();

            // First collect all of the stacks of the most important pids.
            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);  // Wait for write-close, give up after 200msec
                        }
                    }
                } catch (InterruptedException e) {
                    Slog.wtf(TAG, e);
                }
            }

            // Next collect the stacks of the native pids
            if (nativeProcs != null) {
                int[] pids = Process.getPidsForCommands(nativeProcs);
                if (pids != null) {
                    for (int pid : pids) {
                        Debug.dumpNativeBacktraceToFile(pid, tracesPath);
                    }
                }
            }

            // Lastly, measure CPU usage.
            if (processCpuTracker != null) {
                processCpuTracker.init();
                System.gc();
                processCpuTracker.update();
                try {
                    synchronized (processCpuTracker) {
                        processCpuTracker.wait(500); // measure over 1/2 second.
                    }
                } catch (InterruptedException e) {
                }
                processCpuTracker.update();

                // We'll take the stack crawls of just the top apps using CPU.
                final int N = processCpuTracker.countWorkingStats();
                int numProcs = 0;
                for (int i=0; i<N && numProcs<5; i++) {
                    ProcessCpuTracker.Stats stats = processCpuTracker.getWorkingStats(i);
                    if (lastPids.indexOfKey(stats.pid) >= 0) {
                        numProcs++;
                        try {
                            synchronized (observer) {
                                Process.sendSignal(stats.pid, Process.SIGNAL_QUIT);
                                observer.wait(200);  // Wait for write-close, give up after 200msec
                            }
                        } catch (InterruptedException e) {
                            Slog.wtf(TAG, e);
                        }

                    }
                }
            }
        } finally {
            observer.stopWatching();
        }
    }
    
    ......
  public void addErrorToDropBox(String eventType,
            ProcessRecord process, String processName, ActivityRecord activity,
            ActivityRecord parent, String subject,
            final String report, final File logFile,
            final ApplicationErrorReport.CrashInfo crashInfo) {
        // NOTE -- this must never acquire the ActivityManagerService lock,
        // otherwise the watchdog may be prevented from resetting the system.

        final String dropboxTag = processClass(process) + "_" + eventType;
        final DropBoxManager dbox = (DropBoxManager)
                mContext.getSystemService(Context.DROPBOX_SERVICE);

        // Exit early if the dropbox isn't configured to accept this report type.
        if (dbox == null || !dbox.isTagEnabled(dropboxTag)) return;

        final StringBuilder sb = new StringBuilder(1024);
        appendDropBoxProcessHeaders(process, processName, sb);
        if (activity != null) {
            sb.append("Activity: ").append(activity.shortComponentName).append("\n");
        }
        if (parent != null && parent.app != null && parent.app.pid != process.pid) {
            sb.append("Parent-Process: ").append(parent.app.processName).append("\n");
        }
        if (parent != null && parent != activity) {
            sb.append("Parent-Activity: ").append(parent.shortComponentName).append("\n");
        }
        if (subject != null) {
            sb.append("Subject: ").append(subject).append("\n");
        }
        sb.append("Build: ").append(Build.FINGERPRINT).append("\n");
        if (Debug.isDebuggerConnected()) {
            sb.append("Debugger: Connected\n");
        }
        sb.append("\n");

        // Do the rest in a worker thread to avoid blocking the caller on I/O
        // (After this point, we shouldn't access AMS internal data structures.)
        Thread worker = new Thread("Error dump: " + dropboxTag) {
            @Override
            public void run() {
                if (report != null) {
                    sb.append(report);
                }
                if (logFile != null) {
                    try {
                        sb.append(FileUtils.readTextFile(logFile, DROPBOX_MAX_SIZE,
                                    "\n\n[[TRUNCATED]]"));
                    } catch (IOException e) {
                        Slog.e(TAG, "Error reading " + logFile, e);
                    }
                }
                if (crashInfo != null && crashInfo.stackTrace != null) {
                    sb.append(crashInfo.stackTrace);
                }

                String setting = Settings.Global.ERROR_LOGCAT_PREFIX + dropboxTag;
                int lines = Settings.Global.getInt(mContext.getContentResolver(), setting, 0);
                if (lines > 0) {
                    sb.append("\n");

                    // Merge several logcat streams, and take the last N lines
                    InputStreamReader input = null;
                    try {
                        java.lang.Process logcat = new ProcessBuilder("/system/bin/logcat",
                                "-v", "time", "-b", "events", "-b", "system", "-b", "main",
                                "-b", "crash",
                                "-t", String.valueOf(lines)).redirectErrorStream(true).start();

                        try { logcat.getOutputStream().close(); } catch (IOException e) {}
                        try { logcat.getErrorStream().close(); } catch (IOException e) {}
                        input = new InputStreamReader(logcat.getInputStream());

                        int num;
                        char[] buf = new char[8192];
                        while ((num = input.read(buf)) > 0) sb.append(buf, 0, num);
                    } catch (IOException e) {
                        Slog.e(TAG, "Error running logcat", e);
                    } finally {
                        if (input != null) try { input.close(); } catch (IOException e) {}
                    }
                }

                dbox.addText(dropboxTag, sb.toString());
            }
        };

        if (process == null) {
            // If process is null, we are being called from some internal code
            // and may be about to die -- run this synchronously.
            worker.run();
        } else {
            worker.start();
        }
    }

......
 public boolean inputDispatchingTimedOut(final ProcessRecord proc,
            final ActivityRecord activity, final ActivityRecord parent,
            final boolean aboveSystem, String reason) {
        if (checkCallingPermission(android.Manifest.permission.FILTER_EVENTS)
                != PackageManager.PERMISSION_GRANTED) {
            throw new SecurityException("Requires permission "
                    + android.Manifest.permission.FILTER_EVENTS);
        }

        final String annotation;
        if (reason == null) {
            annotation = "Input dispatching timed out";
        } else {
            annotation = "Input dispatching timed out (" + reason + ")";
        }

        if (proc != null) {
            synchronized (this) {
                if (proc.debugging) {
                    return false;
                }

                if (mDidDexOpt) {
                    // Give more time since we were dexopting.
                    mDidDexOpt = false;
                    return false;
                }

                if (proc.instrumentationClass != null) {
                    Bundle info = new Bundle();
                    info.putString("shortMsg", "keyDispatchingTimedOut");
                    info.putString("longMsg", annotation);
                    finishInstrumentationLocked(proc, Activity.RESULT_CANCELED, info);
                    return true;
                }
            }
            mHandler.post(new Runnable() {
                @Override
                public void run() {
                    appNotResponding(proc, activity, parent, aboveSystem, annotation);
                }
            });
        }

        return true;
    }

关键字：
当ANR不是发生在system server进程时，mian log会有关键字"ANR in”，如果anr发生在 system server进程，则main log一般不会记录到关键字"ANR in”

-->ProcessCpuTracker.java

    final public String printCurrentLoad() {
        StringWriter sw = new StringWriter();
        PrintWriter pw = new FastPrintWriter(sw, false, 128);
        pw.print("Load: ");
        pw.print(mLoad1);
        pw.print(" / ");
        pw.print(mLoad5);
        pw.print(" / ");
        pw.println(mLoad15);
        pw.flush();
        return sw.toString();
    }

    final public String printCurrentState(long now) {
        buildWorkingProcs();

        StringWriter sw = new StringWriter();
        PrintWriter pw = new FastPrintWriter(sw, false, 1024);

        pw.print("CPU usage from ");
        if (now > mLastSampleTime) {
            pw.print(now-mLastSampleTime);
            pw.print("ms to ");
            pw.print(now-mCurrentSampleTime);
            pw.print("ms ago");
        } else {
            pw.print(mLastSampleTime-now);
            pw.print("ms to ");
            pw.print(mCurrentSampleTime-now);
            pw.print("ms later");
        }

        long sampleTime = mCurrentSampleTime - mLastSampleTime;
        long sampleRealTime = mCurrentSampleRealTime - mLastSampleRealTime;
        long percAwake = sampleRealTime > 0 ? ((sampleTime*100) / sampleRealTime) : 0;
        if (percAwake != 100) {
            pw.print(" with ");
            pw.print(percAwake);
            pw.print("% awake");
        }
        pw.println(":");

        final int totalTime = mRelUserTime + mRelSystemTime + mRelIoWaitTime
                + mRelIrqTime + mRelSoftIrqTime + mRelIdleTime;

        if (DEBUG) Slog.i(TAG, "totalTime " + totalTime + " over sample time "
                + (mCurrentSampleTime-mLastSampleTime));

        int N = mWorkingProcs.size();
        for (int i=0; i<N; i++) {
            Stats st = mWorkingProcs.get(i);
            printProcessCPU(pw, st.added ? " +" : (st.removed ? " -": "  "),
                    st.pid, st.name, (int)st.rel_uptime,
                    st.rel_utime, st.rel_stime, 0, 0, 0, st.rel_minfaults, st.rel_majfaults);
            if (!st.removed && st.workingThreads != null) {
                int M = st.workingThreads.size();
                for (int j=0; j<M; j++) {
                    Stats tst = st.workingThreads.get(j);
                    printProcessCPU(pw,
                            tst.added ? "   +" : (tst.removed ? "   -": "    "),
                            tst.pid, tst.name, (int)st.rel_uptime,
                            tst.rel_utime, tst.rel_stime, 0, 0, 0, 0, 0);
                }
            }
        }

        printProcessCPU(pw, "", -1, "TOTAL", totalTime, mRelUserTime, mRelSystemTime,
                mRelIoWaitTime, mRelIrqTime, mRelSoftIrqTime, 0, 0);

        pw.flush();
        return sw.toString();
    }

    private void printRatio(PrintWriter pw, long numerator, long denominator) {
        long thousands = (numerator*1000)/denominator;
        long hundreds = thousands/10;
        pw.print(hundreds);
        if (hundreds < 10) {
            long remainder = thousands - (hundreds*10);
            if (remainder != 0) {
                pw.print('.');
                pw.print(remainder);
            }
        }
    }

    private void printProcessCPU(PrintWriter pw, String prefix, int pid, String label,
            int totalTime, int user, int system, int iowait, int irq, int softIrq,
            int minFaults, int majFaults) {
        pw.print(prefix);
        if (totalTime == 0) totalTime = 1;
        printRatio(pw, user+system+iowait+irq+softIrq, totalTime);
        pw.print("% ");
        if (pid >= 0) {
            pw.print(pid);
            pw.print("/");
        }
        pw.print(label);
        pw.print(": ");
        printRatio(pw, user, totalTime);
        pw.print("% user + ");
        printRatio(pw, system, totalTime);
        pw.print("% kernel");
        if (iowait > 0) {
            pw.print(" + ");
            printRatio(pw, iowait, totalTime);
            pw.print("% iowait");
        }
        if (irq > 0) {
            pw.print(" + ");
            printRatio(pw, irq, totalTime);
            pw.print("% irq");
        }
        if (softIrq > 0) {
            pw.print(" + ");
            printRatio(pw, softIrq, totalTime);
            pw.print("% softirq");
        }
        if (minFaults > 0 || majFaults > 0) {
            pw.print(" / faults:");
            if (minFaults > 0) {
                pw.print(" ");
                pw.print(minFaults);
                pw.print(" minor");
            }
            if (majFaults > 0) {
                pw.print(" ");
                pw.print(majFaults);
                pw.print(" major");
            }
        }
        pw.println();
    }

事件派发超时ANR：

 

四 一些典型的ANR问题场景

4.1 最常见的错误，UI 线程等待其他线程释放某个锁，导致UI线程无处处理用户输入
4.2 游戏中每帧动画都进行了比较耗时的大量计算，导致CPU忙不过来
4.3 Web应用中，网络状态不稳定，而界面在等待网络数据
4.4 UI线程中进行了一些磁盘IO(包括数据库，SD卡等等)的耗时操作
4.5 手机被其他App占用着CPU，自己获取不到足够的CPU时间片

五 通过ANR日志定位问题

当ANR发生时，往往通过Logcat和traces文件(目录/data/anr)的相关信息输出来定位问题，主要包括以下几个方面：
5.1 基本信息，包括进程号名，进程号，包名，系统build号，ANR类型等等
5.2 CPU使用信息，包括活跃进程的CPU平均占用率，IO情况等
5.3 线程堆栈信息，所属进程包括发生ANR的进程，其父进程，最近有活动的3个进程等

六 ANR案例分析

6.1 案例1：事件派发超时

package com.example.anrdemo;

import android.app.Activity;
import android.os.Bundle;
import android.os.SystemClock;
import android.view.Menu;
import android.view.MenuItem;
import android.view.MotionEvent;
import android.view.View;

public class MainActivity extends Activity {

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);

        findViewById(R.id.RelativeLayout).setOnTouchListener(new View.OnTouchListener() {
            @Override
            public boolean onTouch(View v, MotionEvent event) {
                SystemClock.sleep(40 * 1000);
                return false;
            }
        });
    }
}

在上面的onTouch方法通过SystemClock.sleep(40 * 1000);模拟事件阻塞，界面启动后手指连续点击就会必现ANR，提取main log和traces文件
traces.log

----- pid 7858 at 2016-09-21 17:39:33 -----
Cmd line: com.example.anrdemo
Build fingerprint: 'CMCC/wt89536/wt89536:6.0.1/MMB29M/09121831:user/release-keys'
ABI: 'arm64'
Build type: optimized
Zygote loaded classes=4004 post zygote classes=16
Intern table: 47269 strong; 17 weak
JNI: CheckJNI is on; globals=298 (plus 232 weak)
Libraries: /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libqti_performance.so /system/lib64/libwebviewchromium_loader.so libjavacore.so (8)
Heap: 26% free, 9MB/13MB; 39779 objects
Dumping cumulative Gc timings
Total number of allocations 39779
Total bytes allocated 9MB
Total bytes freed 0B
Free memory 3MB
Free memory until GC 3MB
Free memory until OOME 246MB
Total memory 13MB
Max memory 256MB
Zygote space size 1024KB
Total mutator paused time: 0
Total time waiting for GC to complete: 0
Total GC count: 0
Total GC time: 0
Total blocking GC count: 0
Total blocking GC time: 0

suspend all histogram: Sum: 48us 99% C.I. 1us-19us Avg: 4.800us Max: 19us
DALVIK THREADS (11):
"Signal Catcher" daemon prio=5 tid=2 Runnable
  | group="system" sCount=0 dsCount=0 obj=0x12cf90a0 self=0x55a8902570
  | sysTid=7863 nice=0 cgrp=default sched=0/0 handle=0x7f8bad6450
  | state=R schedstat=( 998958 30260 2 ) utm=0 stm=0 core=6 HZ=100
  | stack=0x7f8b9da000-0x7f8b9dc000 stackSize=1013KB
  | held mutexes= "mutator lock"(shared held)
  native: #00 pc 0000000000489e28  /system/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, char const*, art::ArtMethod*, void*)+236)
  native: #01 pc 0000000000458fe8  /system/lib64/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&) const+220)
  native: #02 pc 0000000000465bc8  /system/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+688)
  native: #03 pc 0000000000466ae0  /system/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+276)
  native: #04 pc 000000000046719c  /system/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+188)
  native: #05 pc 0000000000467a84  /system/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+492)
  native: #06 pc 0000000000431194  /system/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+96)
  native: #07 pc 000000000043e604  /system/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1256)
  native: #08 pc 000000000043f214  /system/lib64/libart.so (art::SignalCatcher::Run(void*)+452)
  native: #09 pc 0000000000068714  /system/lib64/libc.so (__pthread_start(void*)+52)
  native: #10 pc 000000000001c604  /system/lib64/libc.so (__start_thread+16)
  (no managed stack frames)

"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 obj=0x744a56e8 self=0x55a86782e0
  | sysTid=7858 nice=0 cgrp=default sched=0/0 handle=0x7f8fca4fe8
  | state=S schedstat=( 64275520 798177 96 ) utm=5 stm=1 core=6 HZ=100
  | stack=0x7fd1334000-0x7fd1336000 stackSize=8MB
  | held mutexes=
  at java.lang.Thread.sleep!(Native method)
  - sleeping on <0x0d8505e6> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:1031)
  - locked <0x0d8505e6> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:985)
  at android.os.SystemClock.sleep(SystemClock.java:120)
  at com.example.anrdemo.MainActivity$1.onTouch(MainActivity.java:22)
  at android.view.View.dispatchTouchEvent(View.java:9296)
  at android.view.ViewGroup.dispatchTransformedTouchEvent(ViewGroup.java:2548)
  at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:2241)
  at android.view.ViewGroup.dispatchTransformedTouchEvent(ViewGroup.java:2554)
  at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:2198)
  at android.view.ViewGroup.dispatchTransformedTouchEvent(ViewGroup.java:2554)
  at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:2198)
  at android.view.ViewGroup.dispatchTransformedTouchEvent(ViewGroup.java:2554)
  at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:2198)
  at com.android.internal.policy.PhoneWindow$DecorView.superDispatchTouchEvent(PhoneWindow.java:2442)
  at com.android.internal.policy.PhoneWindow.superDispatchTouchEvent(PhoneWindow.java:1759)
  at android.app.Activity.dispatchTouchEvent(Activity.java:2818)
  at com.android.internal.policy.PhoneWindow$DecorView.dispatchTouchEvent(PhoneWindow.java:2403)
  at android.view.View.dispatchPointerEvent(View.java:9522)
  at android.view.ViewRootImpl$ViewPostImeInputStage.processPointerEvent(ViewRootImpl.java:4230)
  at android.view.ViewRootImpl$ViewPostImeInputStage.onProcess(ViewRootImpl.java:4096)
  at android.view.ViewRootImpl$InputStage.deliver(ViewRootImpl.java:3642)
  at android.view.ViewRootImpl$InputStage.onDeliverToNext(ViewRootImpl.java:3695)
  at android.view.ViewRootImpl$InputStage.forward(ViewRootImpl.java:3661)
  at android.view.ViewRootImpl$AsyncInputStage.forward(ViewRootImpl.java:3787)
  at android.view.ViewRootImpl$InputStage.apply(ViewRootImpl.java:3669)
  at android.view.ViewRootImpl$AsyncInputStage.apply(ViewRootImpl.java:3844)
  at android.view.ViewRootImpl$InputStage.deliver(ViewRootImpl.java:3642)
  at android.view.ViewRootImpl$InputStage.onDeliverToNext(ViewRootImpl.java:3695)
  at android.view.ViewRootImpl$InputStage.forward(ViewRootImpl.java:3661)
  at android.view.ViewRootImpl$InputStage.apply(ViewRootImpl.java:3669)
  at android.view.ViewRootImpl$InputStage.deliver(ViewRootImpl.java:3642)
  at android.view.ViewRootImpl.deliverInputEvent(ViewRootImpl.java:5922)
  at android.view.ViewRootImpl.doProcessInputEvents(ViewRootImpl.java:5896)
  at android.view.ViewRootImpl.enqueueInputEvent(ViewRootImpl.java:5857)
  at android.view.ViewRootImpl$WindowInputEventReceiver.onInputEvent(ViewRootImpl.java:6025)
  at android.view.InputEventReceiver.dispatchInputEvent(InputEventReceiver.java:185)
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:323)
  at android.os.Looper.loop(Looper.java:135)
  at android.app.ActivityThread.main(ActivityThread.java:5429)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)

main log : 搜索关键字"ANR in"

09-21 17:43:16.320  1597  1610 E ActivityManager: ANR in com.example.anrdemo (com.example.anrdemo/.MainActivity)
09-21 17:43:16.320  1597  1610 E ActivityManager: PID: 7988
09-21 17:43:16.320  1597  1610 E ActivityManager: Reason: Input dispatching timed out (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: 5554.6ms.)
09-21 17:43:16.320  1597  1610 E ActivityManager: Load: 5.12 / 5.02 / 5.17
09-21 17:43:16.320  1597  1610 E ActivityManager: CPU usage from 0ms to 9121ms later:
09-21 17:43:16.320  1597  1610 E ActivityManager:   53% 1597/system_server: 10% user + 43% kernel / faults: 6415 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.2% 790/debuggerd: 0% user + 0.1% kernel / faults: 3979 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   5% 2117/com.android.systemui: 2.1% user + 2.8% kernel / faults: 1827 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   5% 2981/com.android.phone: 2.3% user + 2.7% kernel / faults: 2941 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   4.1% 5495/cmccwm.miguinside: 1.5% user + 2.6% kernel / faults: 1306 minor 14 major
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 791/debuggerd64: 0% user + 0% kernel / faults: 3395 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   1.9% 4271/kworker/u16:6: 0% user + 1.9% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 2931/com.android.managedprovisioning: 0% user + 0% kernel / faults: 923 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   1.8% 4207/kworker/u16:0: 0% user + 1.8% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   1.8% 5017/com.UCMobile:ppappstore: 1% user + 0.7% kernel / faults: 880 minor 4 major
09-21 17:43:16.320  1597  1610 E ActivityManager:   1.6% 2944/com.cmdc.phonekeeper: 0.8% user + 0.7% kernel / faults: 1079 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   1.5% 572/surfaceflinger: 0.7% user + 0.7% kernel / faults: 10 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   1.3% 2994/com.cmcc.nqweather: 0.6% user + 0.6% kernel / faults: 806 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   1.3% 5545/cmccwm.miguinside: 0% user + 1.3% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   1.2% 73/kworker/u16:1: 0% user + 1.2% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   1% 5546/cmccwm.miguinside: 0.1% user + 0.9% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.9% 635/adbd: 0.1% user + 0.8% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.9% 2810/com.quicinc.cne.CNEService: 0.7% user + 0.2% kernel / faults: 830 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.9% 6608/kworker/u16:3: 0% user + 0.9% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.8% 2864/com.android.BMCT: 0.6% user + 0.2% kernel / faults: 802 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.8% 2890/com.cmcc.personalcenter: 0.5% user + 0.3% kernel / faults: 735 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.7% 2878/com.qti.dpmserviceapp: 0.1% user + 0.6% kernel / faults: 688 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.6% 7988/com.example.anrdemo: 0.4% user + 0.2% kernel / faults: 1362 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 2166/com.wingtech.smartalertlight: 0% user + 0% kernel / faults: 511 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 2834/com.qualcomm.qti.GBAHttpAuthentication.auth: 0% user + 0% kernel / faults: 587 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.4% 425/logd: 0.2% user + 0.2% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 2919/com.qualcomm.qti.loadcarrier: 0% user + 0% kernel / faults: 433 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 2957/com.quicinc.wbcserviceapp: 0% user + 0% kernel / faults: 433 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.3% 328/cfinteractive: 0% user + 0.3% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 2821/com.wt.secret_code_manager: 0% user + 0% kernel / faults: 433 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.3% 2848/com.android.nfc: 0.1% user + 0.2% kernel / faults: 510 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 2904/com.fingerprints.serviceext: 0% user + 0% kernel / faults: 433 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.2% 7/rcu_preempt: 0% user + 0.2% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.2% 334/mmc-cmdqd/0: 0% user + 0.2% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.2% 7242/logcat: 0.2% user + 0% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.2% 7982/logcat: 0% user + 0.2% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 8/rcu_sched: 0% user + 0% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 39/rcuop/4: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 40/rcuos/4: 0% user + 0% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 53/rcuop/6: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0% 54/rcuos/6: 0% user + 0% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 60/rcuop/7: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 657/sensors.qcom: 0.1% user + 0% kernel / faults: 2 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 803/ptt_socket_app: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 805/thermal-engine: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 965/msm_irqbalance: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 6472/com.tencent.mm:exdevice: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 7438/com.tencent.mm: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 7820/kworker/7:1: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 7958/mdss_fb0: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 11193/wpa_supplicant: 0.1% user + 0% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   0.1% 32252/VosMCThread: 0% user + 0.1% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager: 12% TOTAL: 3.4% user + 8.6% kernel + 0.3% iowait + 0.2% irq + 0% softirq
09-21 17:43:16.320  1597  1610 E ActivityManager: CPU usage from 8127ms to 8659ms later with 99% awake:
09-21 17:43:16.320  1597  1610 E ActivityManager:   19% 1597/system_server: 3.6% user + 16% kernel / faults: 16 minor
09-21 17:43:16.320  1597  1610 E ActivityManager:     9% 1610/ActivityManager: 0% user + 9% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:     3.6% 1606/HeapTaskDaemon: 3.6% user + 0% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:     1.8% 1603/ReferenceQueueD: 1.8% user + 0% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:     1.8% 1604/FinalizerDaemon: 1.8% user + 0% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:     1.8% 1909/InputReader: 1.8% user + 0% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   4.7% 4271/kworker/u16:6: 0% user + 4.7% kernel
09-21 17:43:16.320  1597  1610 E ActivityManager:   2.6% 73/kworker/u16:1: 0% user + 2.6% ke

event log：搜索关键字“am_anr”

案例2：system_server进程发生死锁

trace log

----- pid 3256 at 2016-09-19 16:27:54 -----
Cmd line: system_server
Build fingerprint: 'CMCC/wt89536/wt89536:6.0.1/MMB29M/FACTORY01:eng/dev-keys'
ABI: 'arm64'
Build type: optimized
Zygote loaded classes=4005 post zygote classes=3619
Intern table: 52211 strong; 7249 weak
JNI: CheckJNI is on; globals=1893 (plus 222 weak)
Libraries: /system/lib64/libandroid.so /system/lib64/libandroid_servers.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libqti_performance.so /system/lib64/libsoundpool.so /system/lib64/libwebviewchromium_loader.so /system/lib64/libwifi-service.so /vendor/lib64/liblocationservice_glue.so libantradio.so libjavacore.so (13)
Heap: 5% free, 27MB/29MB; 340966 objects
Dumping cumulative Gc timings
Start Dumping histograms for 7 iterations for concurrent mark sweep
ProcessMarkStack: Sum: 411.222ms 99% C.I. 0.006ms-72.256ms Avg: 19.582ms Max: 73.081ms
MarkConcurrentRoots: Sum: 25.367ms 99% C.I. 0.005ms-8.215ms Avg: 1.811ms Max: 8.512ms
MarkRootsCheckpoint: Sum: 17.199ms 99% C.I. 0.317ms-4.168ms Avg: 1.228ms Max: 4.304ms
SweepMallocSpace: Sum: 15.622ms 99% C.I. 0.003ms-8.007ms Avg: 1.115ms Max: 8.303ms
UpdateAndMarkImageModUnionTable: Sum: 9.425ms 99% C.I. 0.546ms-4.595ms Avg: 1.346ms Max: 4.697ms
ScanGrayAllocSpaceObjects: Sum: 7.647ms 99% C.I. 0.500us-1897.500us Avg: 546.214us Max: 1911us
ReMarkRoots: Sum: 4.633ms 99% C.I. 198us-833us Avg: 661.857us Max: 833us
SweepSystemWeaks: Sum: 4.052ms 99% C.I. 412us-1154us Avg: 578.857us Max: 1154us
MarkNonThreadRoots: Sum: 2.542ms 99% C.I. 17us-811.499us Avg: 181.571us Max: 813us
FinishPhase: Sum: 2.287ms 99% C.I. 288us-446us Avg: 326.714us Max: 446us
AllocSpaceClearCards: Sum: 2.264ms 99% C.I. 0.500us-629.999us Avg: 80.857us Max: 668us
EnqueueFinalizerReferences: Sum: 1.461ms 99% C.I. 62us-430us Avg: 208.714us Max: 430us
SweepLargeObjects: Sum: 1.072ms 99% C.I. 15us-517us Avg: 153.142us Max: 517us
MarkAllocStackAsLive: Sum: 589us 99% C.I. 30us-202us Avg: 84.142us Max: 202us
ImageModUnionClearCards: Sum: 580us 99% C.I. 29us-139us Avg: 41.428us Max: 139us
(Paused)ScanGrayAllocSpaceObjects: Sum: 548us 99% C.I. 0.437us-104us Avg: 39.142us Max: 104us
ProcessReferences: Sum: 409us 99% C.I. 7us-127us Avg: 58.428us Max: 127us
RevokeAllThreadLocalAllocationStacks: Sum: 310us 99% C.I. 14us-58us Avg: 44.285us Max: 58us
ScanGrayZygoteSpaceObjects: Sum: 266us 99% C.I. 14us-177us Avg: 38us Max: 177us
ScanGrayImageSpaceObjects: Sum: 194us 99% C.I. 23us-38us Avg: 27.714us Max: 38us
SweepZygoteSpace: Sum: 191us 99% C.I. 16us-63us Avg: 27.285us Max: 63us
(Paused)ScanGrayImageSpaceObjects: Sum: 161us 99% C.I. 21us-25us Avg: 23us Max: 25us
ZygoteModUnionClearCards: Sum: 101us 99% C.I. 5us-20us Avg: 7.214us Max: 20us
SwapBitmaps: Sum: 77us 99% C.I. 10us-13us Avg: 11us Max: 13us
MarkingPhase: Sum: 56us 99% C.I. 5us-19us Avg: 8us Max: 19us
ProcessCards: Sum: 50us 99% C.I. 2us-7us Avg: 3.571us Max: 7us
PreCleanCards: Sum: 44us 99% C.I. 5us-7us Avg: 6.285us Max: 7us
(Paused)PausePhase: Sum: 40us 99% C.I. 5us-7us Avg: 5.714us Max: 7us
ReclaimPhase: Sum: 37us 99% C.I. 4us-9us Avg: 5.285us Max: 9us
BindBitmaps: Sum: 26us 99% C.I. 2us-10us Avg: 3.714us Max: 10us
(Paused)ScanGrayZygoteSpaceObjects: Sum: 22us 99% C.I. 2us-5us Avg: 3.142us Max: 5us
InitializePhase: Sum: 12us 99% C.I. 1us-6us Avg: 1.714us Max: 6us
MarkRoots: Sum: 11us 99% C.I. 1us-5us Avg: 1.571us Max: 5us
SwapStacks: Sum: 2us 99% C.I. 250ns-1000ns Avg: 285ns Max: 1000ns
FindDefaultSpaceBitmap: Sum: 1us 99% C.I. 250ns-1000ns Avg: 142ns Max: 1000ns
(Paused)ProcessMarkStack: Sum: 0 99% C.I. 0ns-0ns Avg: 0ns Max: 0ns
Done Dumping histograms 
concurrent mark sweep paused: Sum: 5.947ms 99% C.I. 302us-1035us Avg: 849.571us Max: 1035us
concurrent mark sweep total time: 508.558ms mean time: 72.651ms
concurrent mark sweep freed: 136603 objects with total size 8MB
concurrent mark sweep throughput: 268904/s / 17MB/s
Start Dumping histograms for 3 iterations for partial concurrent mark sweep
ProcessMarkStack: Sum: 161.810ms 99% C.I. 0.009ms-62.437ms Avg: 17.978ms Max: 62.437ms
SweepMallocSpace: Sum: 10.055ms 99% C.I. 0.011ms-4.652ms Avg: 1.675ms Max: 4.654ms
ScanGrayAllocSpaceObjects: Sum: 8.239ms 99% C.I. 0.000ms-3.132ms Avg: 1.373ms Max: 3.148ms
MarkConcurrentRoots: Sum: 8.219ms 99% C.I. 0.005ms-3.215ms Avg: 1.369ms Max: 3.215ms
UpdateAndMarkImageModUnionTable: Sum: 6.186ms 99% C.I. 1.698ms-2.265ms Avg: 2.062ms Max: 2.265ms
MarkRootsCheckpoint: Sum: 5.693ms 99% C.I. 196us-1833us Avg: 948.833us Max: 1833us
UpdateAndMarkZygoteModUnionTable: Sum: 2.513ms 99% C.I. 180us-2119us Avg: 837.666us Max: 2119us
MarkAllocStackAsLive: Sum: 2.328ms 99% C.I. 199us-1651us Avg: 776us Max: 1651us
ReMarkRoots: Sum: 1.960ms 99% C.I. 196us-917us Avg: 653.333us Max: 917us
SweepLargeObjects: Sum: 1.855ms 99% C.I. 107us-1058us Avg: 618.333us Max: 1058us
EnqueueFinalizerReferences: Sum: 1.400ms 99% C.I. 19us-808us Avg: 466.666us Max: 808us
FinishPhase: Sum: 1.217ms 99% C.I. 282us-591us Avg: 405.666us Max: 591us
SweepSystemWeaks: Sum: 1.072ms 99% C.I. 53us-515us Avg: 357.333us Max: 515us
MarkNonThreadRoots: Sum: 795us 99% C.I. 18us-270us Avg: 132.500us Max: 270us
AllocSpaceClearCards: Sum: 733us 99% C.I. 0.500us-179us Avg: 61.083us Max: 179us
(Paused)ScanGrayAllocSpaceObjects: Sum: 389us 99% C.I. 0.500us-144us Avg: 64.833us Max: 144us
ProcessReferences: Sum: 336us 99% C.I. 3us-171us Avg: 112us Max: 171us
ImageModUnionClearCards: Sum: 219us 99% C.I. 32us-43us Avg: 36.500us Max: 43us
RevokeAllThreadLocalAllocationStacks: Sum: 126us 99% C.I. 12us-59us Avg: 42us Max: 59us
ScanGrayImageSpaceObjects: Sum: 115us 99% C.I. 32us-45us Avg: 38.333us Max: 45us
(Paused)ProcessMarkStack: Sum: 91us 99% C.I. 0.375us-87us Avg: 30.333us Max: 87us
(Paused)ScanGrayImageSpaceObjects: Sum: 83us 99% C.I. 24us-31us Avg: 27.666us Max: 31us
MarkingPhase: Sum: 41us 99% C.I. 12us-15us Avg: 13.666us Max: 15us
ZygoteModUnionClearCards: Sum: 38us 99% C.I. 5us-7us Avg: 6.333us Max: 7us
SwapBitmaps: Sum: 34us 99% C.I. 9us-15us Avg: 11.333us Max: 15us
PreCleanCards: Sum: 23us 99% C.I. 7us-9us Avg: 7.666us Max: 9us
(Paused)PausePhase: Sum: 22us 99% C.I. 7us-8us Avg: 7.333us Max: 8us
ReclaimPhase: Sum: 19us 99% C.I. 5us-8us Avg: 6.333us Max: 8us
ProcessCards: Sum: 16us 99% C.I. 2us-3us Avg: 2.666us Max: 3us
Sweep: Sum: 15us 99% C.I. 4us-6us Avg: 5us Max: 6us
ScanGrayZygoteSpaceObjects: Sum: 13us 99% C.I. 4us-5us Avg: 4.333us Max: 5us
(Paused)ScanGrayZygoteSpaceObjects: Sum: 12us 99% C.I. 3us-5us Avg: 4us Max: 5us
MarkRoots: Sum: 7us 99% C.I. 2us-3us Avg: 2.333us Max: 3us
BindBitmaps: Sum: 6us 99% C.I. 1us-3us Avg: 2us Max: 3us
InitializePhase: Sum: 3us 99% C.I. 0.250us-2us Avg: 1us Max: 2us
SwapStacks: Sum: 2us 99% C.I. 250ns-1000ns Avg: 666ns Max: 1000ns
FindDefaultSpaceBitmap: Sum: 0 99% C.I. 0ns-0ns Avg: 0ns Max: 0ns
Done Dumping histograms 
partial concurrent mark sweep paused: Sum: 2.879ms 99% C.I. 500us-1265us Avg: 959.666us Max: 1265us
partial concurrent mark sweep total time: 215.693ms mean time: 71.897ms
partial concurrent mark sweep freed: 65542 objects with total size 7MB
partial concurrent mark sweep throughput: 304847/s / 36MB/s
Start Dumping histograms for 33 iterations for sticky concurrent mark sweep
ScanGrayAllocSpaceObjects: Sum: 199.268ms 99% C.I. 0.001ms-12.939ms Avg: 1.509ms Max: 13.464ms
FreeList: Sum: 139.825ms 99% C.I. 8.235us-537.249us Avg: 121.270us Max: 873us
MarkRootsCheckpoint: Sum: 100.400ms 99% C.I. 0.191ms-12.409ms Avg: 1.521ms Max: 13.350ms
MarkConcurrentRoots: Sum: 90.719ms 99% C.I. 0.005ms-4.150ms Avg: 1.374ms Max: 4.184ms
ProcessMarkStack: Sum: 89.186ms 99% C.I. 1.517us-10887.999us Avg: 675.651us Max: 12903us
SweepArray: Sum: 53.138ms 99% C.I. 0.330ms-4.593ms Avg: 1.610ms Max: 4.730ms
ReMarkRoots: Sum: 30.469ms 99% C.I. 178us-3587.999us Avg: 923.303us Max: 4003us
ScanGrayImageSpaceObjects: Sum: 26.627ms 99% C.I. 23us-2620.999us Avg: 403.439us Max: 3005us
SweepSystemWeaks: Sum: 18.264ms 99% C.I. 80us-747us Avg: 553.454us Max: 747us
MarkingPhase: Sum: 13.230ms 99% C.I. 250us-851us Avg: 400.909us Max: 851us
AllocSpaceClearCards: Sum: 12.037ms 99% C.I. 0.500us-569.999us Avg: 91.189us Max: 892us
MarkNonThreadRoots: Sum: 9.078ms 99% C.I. 17us-243us Avg: 137.545us Max: 243us
(Paused)ScanGrayAllocSpaceObjects: Sum: 5.298ms 99% C.I. 0.500us-569us Avg: 80.272us Max: 569us
ResetStack: Sum: 5.203ms 99% C.I. 23us-608.750us Avg: 157.666us Max: 634us
EnqueueFinalizerReferences: Sum: 4.923ms 99% C.I. 3us-1017.499us Avg: 149.181us Max: 1096us
ImageModUnionClearCards: Sum: 4.851ms 99% C.I. 24us-1322.499us Avg: 73.500us Max: 1896us
FinishPhase: Sum: 4.141ms 99% C.I. 33us-255us Avg: 125.484us Max: 255us
RevokeAllThreadLocalAllocationStacks: Sum: 1.726ms 99% C.I. 9us-86us Avg: 52.303us Max: 86us
(Paused)ScanGrayImageSpaceObjects: Sum: 1.497ms 99% C.I. 21us-425.749us Avg: 45.363us Max: 464us
ScanGrayZygoteSpaceObjects: Sum: 1.192ms 99% C.I. 2us-166.999us Avg: 18.060us Max: 176us
ProcessReferences: Sum: 721us 99% C.I. 3us-95us Avg: 21.848us Max: 95us
ZygoteModUnionClearCards: Sum: 478us 99% C.I. 4us-28us Avg: 7.242us Max: 28us
(Paused)PausePhase: Sum: 306us 99% C.I. 5us-28us Avg: 9.272us Max: 28us
ReclaimPhase: Sum: 250us 99% C.I. 4us-38us Avg: 7.575us Max: 38us
ProcessCards: Sum: 204us 99% C.I. 2us-7us Avg: 3.090us Max: 7us
PreCleanCards: Sum: 203us 99% C.I. 4us-10us Avg: 6.151us Max: 10us
SwapBitmaps: Sum: 180us 99% C.I. 4us-15us Avg: 5.454us Max: 15us
ForwardSoftReferences: Sum: 146us 99% C.I. 0.257us-117us Avg: 4.424us Max: 117us
(Paused)ScanGrayZygoteSpaceObjects: Sum: 143us 99% C.I. 2us-8us Avg: 4.333us Max: 8us
MarkRoots: Sum: 76us 99% C.I. 1us-4us Avg: 2.303us Max: 4us
BindBitmaps: Sum: 74us 99% C.I. 1us-7us Avg: 2.242us Max: 7us
(Paused)ProcessMarkStack: Sum: 72us 99% C.I. 0.250us-10us Avg: 2.181us Max: 10us
UnBindBitmaps: Sum: 66us 99% C.I. 1us-3us Avg: 2us Max: 3us
InitializePhase: Sum: 55us 99% C.I. 1us-5us Avg: 1.666us Max: 5us
FindDefaultSpaceBitmap: Sum: 35us 99% C.I. 0.250us-23us Avg: 1.060us Max: 23us
RecordFree: Sum: 28us 99% C.I. 250ns-4000ns Avg: 848ns Max: 4000ns
SwapStacks: Sum: 14us 99% C.I. 250ns-2000ns Avg: 424ns Max: 2000ns
PreSweepingGcVerification: Sum: 0 99% C.I. 0ns-0ns Avg: 0ns Max: 0ns
Done Dumping histograms 
sticky concurrent mark sweep paused: Sum: 41.499ms 99% C.I. 0.354ms-4.087ms Avg: 1.257ms Max: 4.296ms
sticky concurrent mark sweep total time: 814.123ms mean time: 24.670ms
sticky concurrent mark sweep freed: 1137520 objects with total size 128MB
sticky concurrent mark sweep throughput: 1.39744e+06/s / 158MB/s
Total time spent in GC: 1.538s
Mean GC size throughput: 80MB/s
Mean GC object throughput: 870424 objects/s
Total number of allocations 1680004
Total bytes allocated 150MB
Total bytes freed 123MB
Free memory 1737KB
Free memory until GC 1737KB
Free memory until OOME 484MB
Total memory 29MB
Max memory 512MB
Zygote space size 992KB
Total mutator paused time: 50.325ms
Total time waiting for GC to complete: 36.195us
Total GC count: 43
Total GC time: 1.538s
Total blocking GC count: 7
Total blocking GC time: 509.590ms
Histogram of GC count per 10000 ms: 0:36,1:5,2:2,3:2,4:3,5:1,6:1
Histogram of blocking GC count per 10000 ms: 0:47,1:3

suspend all histogram: Sum: 2.064ms 99% C.I. 1us-187.200us Avg: 39.692us Max: 198us
DALVIK THREADS (92):
"Signal Catcher" daemon prio=5 tid=2 Runnable
  | group="system" sCount=0 dsCount=0 obj=0x12c010a0 self=0x556fc4e8a0
  | sysTid=3259 nice=0 cgrp=default sched=0/0 handle=0x7f7c18e450
  | state=R schedstat=( 35405418 92031 10 ) utm=3 stm=0 core=5 HZ=100
  | stack=0x7f7c092000-0x7f7c094000 stackSize=1013KB
  | held mutexes= "mutator lock"(shared held)
  native: #00 pc 0000000000489e28  /system/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, char const*, art::ArtMethod*, void*)+236)
  native: #01 pc 0000000000458fe8  /system/lib64/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&) const+220)
  native: #02 pc 0000000000465bc8  /system/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+688)
  native: #03 pc 0000000000466ae0  /system/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+276)
  native: #04 pc 000000000046719c  /system/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+188)
  native: #05 pc 0000000000467a84  /system/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+492)
  native: #06 pc 0000000000431194  /system/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+96)
  native: #07 pc 000000000043e604  /system/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1256)
  native: #08 pc 000000000043f214  /system/lib64/libart.so (art::SignalCatcher::Run(void*)+452)
  native: #09 pc 0000000000068714  /system/lib64/libc.so (__pthread_start(void*)+52)
  native: #10 pc 000000000001c604  /system/lib64/libc.so (__start_thread+16)
  (no managed stack frames)

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x750f06e8 self=0x556fa316e0
  | sysTid=3256 nice=-2 cgrp=default sched=0/0 handle=0x7f80392fe8
  | state=S schedstat=( 8947519954 553733099 4728 ) utm=755 stm=139 core=5 HZ=100
  | stack=0x7fde469000-0x7fde46b000 stackSize=8MB
  | held mutexes=
  at com.android.server.am.ActivityManagerService.onWakefulnessChanged(ActivityManagerService.java:10469)
  - waiting to lock <0x02e6b629> (a com.android.server.am.ActivityManagerService) held by thread 9
  at com.android.server.am.ActivityManagerService$LocalService.onWakefulnessChanged(ActivityManagerService.java:20830)
  at com.android.server.power.Notifier$1.run(Notifier.java:306)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:148)
  at com.android.server.SystemServer.run(SystemServer.java:339)
  at com.android.server.SystemServer.main(SystemServer.java:182)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)

通过trace log得知ANR发生在system_server进程，主线程在等待一个锁：
- waiting to lock <0x02e6b629> (a com.android.server.am.ActivityManagerService) held by thread 9
从此处无法得知问题点在哪里，根据第一节的介绍：如果ANR发生在system_server进程，那么main log会记录"WATCHDOG KILLING SYSTEM PROCESS"关键字及异常信息，我们去main log里面看看，确实存在该"WATCHDOG KILLING SYSTEM PROCESS"关键字，如下信息：

09-19 16:28:37.034  3256  4581 E Watchdog: Triggering SysRq for system_server watchdog
09-19 16:28:37.034  3256  4581 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg), Blocked in handler on main thread (main), Blocked in handler on display thread (android.display), Blocked in handler on ActivityManager (ActivityManager), Blocked in handler on PowerManagerService (PowerManagerService)
09-19 16:28:37.034  3256  4581 W Watchdog: foreground thread stack trace:
09-19 16:28:37.034  3256  4581 W Watchdog:     at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:19985)
09-19 16:28:37.034  3256  4581 W Watchdog:     at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:175)
09-19 16:28:37.034  3256  4581 W Watchdog:     at android.os.Handler.handleCallback(Handler.java:739)
09-19 16:28:37.034  3256  4581 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:95)
09-19 16:28:37.034  3256  4581 W Watchdog:     at android.os.Looper.loop(Looper.java:148)
09-19 16:28:37.034  3256  4581 W Watchdog:     at android.os.HandlerThread.run(HandlerThread.java:61)
09-19 16:28:37.034  3256  4581 W Watchdog:     at com.android.server.ServiceThread.run(ServiceThread.java:46)
09-19 16:28:37.034  3256  4581 W Watchdog: main thread stack trace:
09-19 16:28:37.034  3256  4581 W Watchdog:     at com.android.server.am.ActivityManagerService.onWakefulnessChanged(ActivityManagerService.java:10469)
09-19 16:28:37.034  3256  4581 W Watchdog:     at com.android.server.am.ActivityManagerService$LocalService.onWakefulnessChanged(ActivityManagerService.java:20830)
09-19 16:28:37.034  3256  4581 W Watchdog:     at com.android.server.power.Notifier$1.run(Notifier.java:306)
09-19 16:28:37.034  3256  4581 W Watchdog:     at android.os.Handler.handleCallback(Handler.java:739)
09-19 16:28:37.034  3256  4581 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:95)
09-19 16:28:37.034  3256  4581 W Watchdog:     at android.os.Looper.loop(Looper.java:148)
09-19 16:28:37.034  3256  4581 W Watchdog:     at com.android.server.SystemServer.run(SystemServer.java:339)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.SystemServer.main(SystemServer.java:182)
09-19 16:28:37.035  3256  4581 W Watchdog:     at java.lang.reflect.Method.invoke(Native Method)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
09-19 16:28:37.035  3256  4581 W Watchdog: display thread stack trace:
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.am.ActivityManagerService.getTasks(ActivityManagerService.java:8464)
09-19 16:28:37.035  3256  4581 W Watchdog:     at android.app.ActivityManager.getRunningTasks(ActivityManager.java:1311)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.policy.PhoneWindowManager.isStayTopActivity(PhoneWindowManager.java:8306)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.policy.PhoneWindowManager.handleKeyguardOccluded(PhoneWindowManager.java:8137)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.policy.PhoneWindowManager.setKeyguardOccludedLw(PhoneWindowManager.java:5103)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.policy.PhoneWindowManager.finishPostLayoutPolicyLw(PhoneWindowManager.java:5039)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLockedInner(WindowManagerService.java:9973)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLockedLoop(WindowManagerService.java:8983)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLocked(WindowManagerService.java:8930)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.wm.WindowManagerService.access$400(WindowManagerService.java:189)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.wm.WindowManagerService$H.handleMessage(WindowManagerService.java:7825)
09-19 16:28:37.035  3256  4581 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:102)
09-19 16:28:37.035  3256  4581 W Watchdog:     at android.os.Looper.loop(Looper.java:148)
09-19 16:28:37.035  3256  4581 W Watchdog:     at android.os.HandlerThread.run(HandlerThread.java:61)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.ServiceThread.run(ServiceThread.java:46)
09-19 16:28:37.035  3256  4581 W Watchdog: ActivityManager stack trace:
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.am.ActivityStack$ActivityStackHandler.handleMessage(ActivityStack.java:300)
09-19 16:28:37.035  3256  4581 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:102)
09-19 16:28:37.035  3256  4581 W Watchdog:     at android.os.Looper.loop(Looper.java:148)
09-19 16:28:37.035  3256  4581 W Watchdog:     at android.os.HandlerThread.run(HandlerThread.java:61)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.ServiceThread.run(ServiceThread.java:46)
09-19 16:28:37.035  3256  4581 W Watchdog: PowerManagerService stack trace:
09-19 16:28:37.036  3256  4581 W Watchdog:     at com.android.server.am.ActivityManagerService$LocalService.acquireSleepToken(ActivityManagerService.java:20844)
09-19 16:28:37.036  3256  4581 W Watchdog:     at com.android.server.policy.PhoneWindowManager.updateScreenOffSleepToken(PhoneWindowManager.java:6858)
09-19 16:28:37.036  3256  4581 W Watchdog:     at com.android.server.policy.PhoneWindowManager.screenTurnedOff(PhoneWindowManager.java:6133)
09-19 16:28:37.036  3256  4581 W Watchdog:     at com.android.server.display.DisplayPowerController.setScreenState(DisplayPowerController.java:807)
09-19 16:28:37.036  3256  4581 W Watchdog:     at com.android.server.display.DisplayPowerController.animateScreenStateChange(DisplayPowerController.java:925)
09-19 16:28:37.036  3256  4581 W Watchdog:     at com.android.server.display.DisplayPowerController.updatePowerState(DisplayPowerController.java:603)
09-19 16:28:37.036  3256  4581 W Watchdog:     at com.android.server.display.DisplayPowerController.access$400(DisplayPowerController.java:78)
09-19 16:28:37.036  3256  4581 W Watchdog:     at com.android.server.display.DisplayPowerController$DisplayControllerHandler.handleMessage(DisplayPowerController.java:1229)
09-19 16:28:37.036  3256  4581 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:102)
09-19 16:28:37.036  3256  4581 W Watchdog:     at android.os.Looper.loop(Looper.java:148)
09-19 16:28:37.036  3256  4581 W Watchdog:     at android.os.HandlerThread.run(HandlerThread.java:61)
09-19 16:28:37.036  3256  4581 W Watchdog:     at com.android.server.ServiceThread.run(ServiceThread.java:46)
09-19 16:28:37.036  3256  4581 W Watchdog: *** GOODBYE!
09-19 16:28:37.036  3256  4581 I Process : Sending signal. PID: 3256 SIG: 9

通过上面堆栈信息，问题点可以锁定在如下地方，然后去查看源码，发生是之前的修改引入的死锁：

09-19 16:28:37.035  3256  4581 W Watchdog: display thread stack trace:
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.am.ActivityManagerService.getTasks(ActivityManagerService.java:8464)
09-19 16:28:37.035  3256  4581 W Watchdog:     at android.app.ActivityManager.getRunningTasks(ActivityManager.java:1311)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.policy.PhoneWindowManager.isStayTopActivity(PhoneWindowManager.java:8306)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.policy.PhoneWindowManager.handleKeyguardOccluded(PhoneWindowManager.java:8137)
09-19 16:28:37.035  3256  4581 W Watchdog:     at com.android.server.policy.PhoneWindowManager.setKeyguardOccludedLw(PhoneWindowManager.java:5103)

以下的修改引入的死锁：
Android6.0.1
-->PhoneWindowManager.java
setKeyguardOccludedLw方法中如果调用了下面这段代码，就会必现死锁现象：

    private boolean isStayTopActivity(Context context, String pkgName, String clazzName) {
        ActivityManager mActivityManager = (ActivityManager) context
                .getSystemService(Context.ACTIVITY_SERVICE);
        ComponentName topActivity = mActivityManager.getRunningTasks(1).get(0).topActivity;
        String mPkgname = topActivity.getPackageName();
        String mClassname = topActivity.getClassName();

        if (mPkgname.equals(pkgName) && mClassname.equals(clazzName)) {
            return true;
        }
        return false;
    }

复现路径：设置安全锁(如图形密码)-->在锁屏界面来电-->接听-->按Back按键将电话界面退到后台-->双击锁屏界面的电话消息框然后弹出输入密码界面-->输入正确密码-->此时冻屏，界面卡死-->过一会发现开机动画又一次播放了

博客原文:http://blog.csdn.net/yelangjueqi/article/details/52622080

 

总结：trace文件记录的main线程堆栈信息不一定直接指向发生ANR的问题点，查找发生ANR的问题点还需要结合main log和event log进行分析