From 544416e7027f9f5e491de56c135f046d88cc48f6 Mon Sep 17 00:00:00 2001
From: Andreas Gampe <agampe@google.com>
Date: Fri, 26 Jan 2018 11:39:46 -0800
Subject: [PATCH] Watchdog: Print annotated stack trace, if possible

Use VMStack.getAnnotatedStackTrace() to print an annotated stack.
Aids in diagnostics of watchdog aborts.

Bug: 70538431
Test: m
Test: art/test/testrunner/testrunner.py -b --host -t 168
Test: runtest -c com.android.server.WatchdogDiagnosticsTest frameworks-services
Test: manual - insert a deadlock into ActivityManagerService
Change-Id: I5bd43920edb8b569240432b6f299e56cabf5ef2a
---
 .../core/java/com/android/server/Watchdog.java     |   9 +-
 .../com/android/server/WatchdogDiagnostics.java    |  88 ++++++++++
 .../android/server/WatchdogDiagnosticsTest.java    | 189 +++++++++++++++++++++
 3 files changed, 278 insertions(+), 8 deletions(-)
 create mode 100644 services/core/java/com/android/server/WatchdogDiagnostics.java
 create mode 100644 services/tests/servicestests/src/com/android/server/WatchdogDiagnosticsTest.java

diff --git a/services/core/java/com/android/server/Watchdog.java b/services/core/java/com/android/server/Watchdog.java
index 18b00ac21222..53285e6a07d7 100644
--- a/services/core/java/com/android/server/Watchdog.java
+++ b/services/core/java/com/android/server/Watchdog.java
@@ -566,14 +566,7 @@ public class Watchdog extends Thread {
                 Slog.w(TAG, "Restart not allowed: Watchdog is *not* killing the system process");
             } else {
                 Slog.w(TAG, "*** WATCHDOG KILLING SYSTEM PROCESS: " + subject);
-                for (int i=0; i<blockedCheckers.size(); i++) {
-                    Slog.w(TAG, blockedCheckers.get(i).getName() + " stack trace:");
-                    StackTraceElement[] stackTrace
-                            = blockedCheckers.get(i).getThread().getStackTrace();
-                    for (StackTraceElement element: stackTrace) {
-                        Slog.w(TAG, "    at " + element);
-                    }
-                }
+                WatchdogDiagnostics.diagnoseCheckers(blockedCheckers);
                 Slog.w(TAG, "*** GOODBYE!");
                 Process.killProcess(Process.myPid());
                 System.exit(10);
diff --git a/services/core/java/com/android/server/WatchdogDiagnostics.java b/services/core/java/com/android/server/WatchdogDiagnostics.java
new file mode 100644
index 000000000000..01db2d3a49c8
--- /dev/null
+++ b/services/core/java/com/android/server/WatchdogDiagnostics.java
@@ -0,0 +1,88 @@
+/*
+ * Copyright (C) 2018 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.android.server;
+
+import android.util.Log;
+import android.util.LogWriter;
+import android.util.Slog;
+
+import com.android.internal.annotations.VisibleForTesting;
+import com.android.server.Watchdog.HandlerChecker;
+
+import dalvik.system.AnnotatedStackTraceElement;
+import dalvik.system.VMStack;
+
+import java.io.PrintWriter;
+import java.util.List;
+
+/**
+ * Class to give diagnostic messages for Watchdogs.
+ */
+class WatchdogDiagnostics {
+    private static String getBlockedOnString(Object blockedOn) {
+        return String.format("- waiting to lock <0x%08x> (a %s)",
+                System.identityHashCode(blockedOn), blockedOn.getClass().getName());
+    }
+
+    private static String getLockedString(Object heldLock) {
+        return String.format("- locked <0x%08x> (a %s)", System.identityHashCode(heldLock),
+                heldLock.getClass().getName());
+    }
+
+    /**
+     * Print the annotated stack for the given thread. If the annotated stack cannot be retrieved,
+     * returns false.
+     */
+    @VisibleForTesting
+    public static boolean printAnnotatedStack(Thread thread, PrintWriter out) {
+        AnnotatedStackTraceElement stack[] = VMStack.getAnnotatedThreadStackTrace(thread);
+        if (stack == null) {
+            return false;
+        }
+        out.println(thread.getName() + " annotated stack trace:");
+        for (AnnotatedStackTraceElement element : stack) {
+            out.println("    at " + element.getStackTraceElement());
+            if (element.getBlockedOn() != null) {
+                out.println("    " + getBlockedOnString(element.getBlockedOn()));
+            }
+            if (element.getHeldLocks() != null) {
+                for (Object held : element.getHeldLocks()) {
+                    out.println("    " + getLockedString(held));
+                }
+            }
+        }
+        return true;
+    }
+
+    public static void diagnoseCheckers(final List<HandlerChecker> blockedCheckers) {
+        PrintWriter out = new PrintWriter(new LogWriter(Log.WARN, Watchdog.TAG, Log.LOG_ID_SYSTEM),
+                true);
+        for (int i=0; i<blockedCheckers.size(); i++) {
+            Thread blockedThread = blockedCheckers.get(i).getThread();
+            if (printAnnotatedStack(blockedThread, out)) {
+                continue;
+            }
+
+            // Fall back to "regular" stack trace, if necessary.
+            Slog.w(Watchdog.TAG, blockedThread.getName() + " stack trace:");
+            StackTraceElement[] stackTrace = blockedThread.getStackTrace();
+            for (StackTraceElement element : stackTrace) {
+                Slog.w(Watchdog.TAG, "    at " + element);
+            }
+        }
+    }
+}
diff --git a/services/tests/servicestests/src/com/android/server/WatchdogDiagnosticsTest.java b/services/tests/servicestests/src/com/android/server/WatchdogDiagnosticsTest.java
new file mode 100644
index 000000000000..6e76b679940b
--- /dev/null
+++ b/services/tests/servicestests/src/com/android/server/WatchdogDiagnosticsTest.java
@@ -0,0 +1,189 @@
+/*
+ * Copyright (C) 2018 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.android.server;
+
+import static org.junit.Assert.assertEquals;
+
+import android.support.test.runner.AndroidJUnit4;
+
+import java.io.PrintWriter;
+import java.io.StringWriter;
+
+import org.junit.Test;
+import org.junit.runner.RunWith;
+
+/**
+ * Unit tests for {@link WatchdogDiagnostics}
+ */
+@RunWith(AndroidJUnit4.class)
+public class WatchdogDiagnosticsTest {
+
+    private static class TestThread1 extends Thread {
+        Object lock1;
+        Object lock2;
+        volatile boolean inB = false;
+
+        public TestThread1(Object lock1, Object lock2) {
+            super("TestThread1");
+            this.lock1 = lock1;
+            this.lock2 = lock2;
+        }
+
+        @Override
+        public void run() {
+            a();
+        }
+
+        private void a() {
+            synchronized(lock1) {
+                b();
+            }
+        }
+
+        private void b() {
+            inB = true;
+            synchronized(lock2) {
+                // Nothing.
+            }
+        }
+    }
+
+    private static class TestThread2 extends Thread {
+        Object lock1;
+        Object lock2;
+        volatile boolean inY = false;
+
+        public TestThread2(Object lock1, Object lock2) {
+            super("TestThread2");
+            this.lock1 = lock1;
+            this.lock2 = lock2;
+        }
+
+        @Override
+        public void run() {
+            x();
+        }
+
+        private void x() {
+            synchronized(lock1) {
+                y();
+            }
+        }
+
+        private void y() {
+            synchronized(lock2) {
+                inY = true;
+                try {
+                    lock2.wait();
+                } catch (Exception exc) {
+                    throw new RuntimeException(exc);
+                }
+            }
+        }
+    }
+
+    @Test
+    public void printAnnotatedStack() throws Exception {
+        // Preparation.
+
+        Object heldLock1 = new Object();
+        Object heldLock2 = 0;
+        Object waitLock = "123";
+
+        TestThread1 thread1 = new TestThread1(heldLock1, heldLock2);
+        TestThread2 thread2 = new TestThread2(heldLock2, waitLock);
+
+        // Start the second thread, ensure it grabs heldLock2.
+        thread2.start();
+        while(!thread2.inY) {
+            Thread.yield();
+        }
+
+        // Start the first thread, ensure it made progress.
+        thread1.start();
+        while(!thread1.inB) {
+            Thread.yield();
+        }
+
+        // Now wait till both are no longer in runnable state.
+        while (thread1.getState() == Thread.State.RUNNABLE) {
+            Thread.yield();
+        }
+        while (thread2.getState() == Thread.State.RUNNABLE) {
+            Thread.yield();
+        }
+
+        // Now do the test.
+        StringWriter stringBuffer = new StringWriter();
+        PrintWriter print = new PrintWriter(stringBuffer, true);
+
+        {
+            WatchdogDiagnostics.printAnnotatedStack(thread1, print);
+
+            String output = stringBuffer.toString();
+            String expected =
+                    "TestThread1 annotated stack trace:\n" +
+                    "    at com.android.server.WatchdogDiagnosticsTest$TestThread1.b(" +
+                            "WatchdogDiagnosticsTest.java:59)\n" +
+                    "    - waiting to lock <HASH> (a java.lang.Integer)\n" +
+                    "    at com.android.server.WatchdogDiagnosticsTest$TestThread1.a(" +
+                            "WatchdogDiagnosticsTest.java:53)\n" +
+                    "    - locked <HASH> (a java.lang.Object)\n" +
+                    "    at com.android.server.WatchdogDiagnosticsTest$TestThread1.run(" +
+                            "WatchdogDiagnosticsTest.java:48)\n";
+            assertEquals(expected, filterHashes(output));
+        }
+
+        stringBuffer.getBuffer().setLength(0);
+
+        {
+            WatchdogDiagnostics.printAnnotatedStack(thread2, print);
+
+            String output = stringBuffer.toString();
+            String expected =
+                    "TestThread2 annotated stack trace:\n" +
+                    "    at java.lang.Object.wait(Native Method)\n" +
+                    "    at com.android.server.WatchdogDiagnosticsTest$TestThread2.y(" +
+                            "WatchdogDiagnosticsTest.java:91)\n" +
+                    "    - locked <HASH> (a java.lang.String)\n" +
+                    "    at com.android.server.WatchdogDiagnosticsTest$TestThread2.x(" +
+                            "WatchdogDiagnosticsTest.java:83)\n" +
+                    "    - locked <HASH> (a java.lang.Integer)\n" +
+                    "    at com.android.server.WatchdogDiagnosticsTest$TestThread2.run(" +
+                            "WatchdogDiagnosticsTest.java:78)\n";
+            assertEquals(expected, filterHashes(output));
+        }
+
+        // Let the threads finish.
+        synchronized (waitLock) {
+            waitLock.notifyAll();
+        }
+
+        thread1.join();
+        thread2.join();
+    }
+
+    /**
+     * A filter function that removes hash codes (which will change between tests and cannot be
+     * controlled.)
+     * <p>
+     * Note: leaves "<HASH>" to indicate that something was replaced.
+     */
+    private static String filterHashes(String t) {
+        return t.replaceAll("<0x[0-9a-f]{8}>", "<HASH>");
+    }
+}
-- 
2.11.0