Android 分析ANR和死锁

一 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进行分析