From 42471dd5552a346dd82a58a663159875ccc4fb79 Mon Sep 17 00:00:00 2001 From: Dan Egnor Date: Thu, 7 Jan 2010 17:25:22 -0800 Subject: [PATCH] Simplify & update ANR logging; report ANR data into the dropbox. Eliminate the per-process 200ms timeout during ANR thread-dumping. Dump all the threads at once, then wait for the file to stabilize. Seems to work great and is much, much, much faster. Don't dump stack traces to traces.txt on app crashes (it isn't very useful and mostly just clutters up the file). Tweak the formatting of the dropbox dumpsys a bit, for readability, and avoid running out of memory when dumping large log files. Report build & kernel version with kernel log dropbox entries. --- core/java/android/os/Build.java | 9 + core/java/android/os/FileUtils.java | 8 +- core/java/android/provider/Settings.java | 8 +- .../java/com/android/server/BootReceiver.java | 27 +- .../android/server/DropBoxManagerService.java | 7 + .../java/com/android/server/SystemServer.java | 2 - .../server/am/ActivityManagerService.java | 342 ++++++++---------- .../server/am/AppNotRespondingDialog.java | 3 +- .../am/AppWaitingForDebuggerDialog.java | 3 +- 9 files changed, 203 insertions(+), 206 deletions(-) diff --git a/core/java/android/os/Build.java b/core/java/android/os/Build.java index 4870b7c710e13..fcd8f38477dde 100644 --- a/core/java/android/os/Build.java +++ b/core/java/android/os/Build.java @@ -53,6 +53,15 @@ public class Build { /** The end-user-visible name for the end product. */ public static final String MODEL = getString("ro.product.model"); + /** @pending The system bootloader version number. */ + public static final String BOOTLOADER = getString("ro.bootloader"); + + /** @pending The radio firmware version number. */ + public static final String RADIO = getString("gsm.version.baseband"); + + /** @pending The device serial number. */ + public static final String SERIAL = getString("ro.serialno"); + /** Various version strings. */ public static class VERSION { /** diff --git a/core/java/android/os/FileUtils.java b/core/java/android/os/FileUtils.java index 51dfb5b30c96e..4780cf3145dd5 100644 --- a/core/java/android/os/FileUtils.java +++ b/core/java/android/os/FileUtils.java @@ -153,14 +153,16 @@ public class FileUtils public static String readTextFile(File file, int max, String ellipsis) throws IOException { InputStream input = new FileInputStream(file); try { - if (max > 0) { // "head" mode: read the first N bytes + long size = file.length(); + if (max > 0 || (size > 0 && max == 0)) { // "head" mode: read the first N bytes + if (size > 0 && (max == 0 || size < max)) max = (int) size; byte[] data = new byte[max + 1]; int length = input.read(data); if (length <= 0) return ""; if (length <= max) return new String(data, 0, length); if (ellipsis == null) return new String(data, 0, max); return new String(data, 0, max) + ellipsis; - } else if (max < 0) { // "tail" mode: read it all, keep the last N + } else if (max < 0) { // "tail" mode: keep the last N int len; boolean rolled = false; byte[] last = null, data = null; @@ -180,7 +182,7 @@ public class FileUtils } if (ellipsis == null || !rolled) return new String(last); return ellipsis + new String(last); - } else { // "cat" mode: read it all + } else { // "cat" mode: size unknown, read it all in streaming fashion ByteArrayOutputStream contents = new ByteArrayOutputStream(); int len; byte[] data = new byte[1024]; diff --git a/core/java/android/provider/Settings.java b/core/java/android/provider/Settings.java index a3472c0134747..7db9fdc61e611 100644 --- a/core/java/android/provider/Settings.java +++ b/core/java/android/provider/Settings.java @@ -2942,7 +2942,13 @@ public final class Settings { */ public static final String MOUNT_UMS_NOTIFY_ENABLED = "mount_ums_notify_enabled"; - + /** + * If nonzero, ANRs in invisible background processes bring up a dialog. + * Otherwise, the process will be silently killed. + * @hide + */ + public static final String ANR_SHOW_BACKGROUND = "anr_show_background"; + /** * @hide */ diff --git a/services/java/com/android/server/BootReceiver.java b/services/java/com/android/server/BootReceiver.java index 4279e00701634..debbbb4ac1092 100644 --- a/services/java/com/android/server/BootReceiver.java +++ b/services/java/com/android/server/BootReceiver.java @@ -38,6 +38,10 @@ import java.io.IOException; public class BootReceiver extends BroadcastReceiver { private static final String TAG = "BootReceiver"; + // Negative meaning capture the *last* 64K of the file + // (passed to FileUtils.readTextFile) + private static final int LOG_SIZE = -65536; + @Override public void onReceive(Context context, Intent intent) { try { @@ -67,16 +71,20 @@ public class BootReceiver extends BroadcastReceiver { private void logBootEvents(Context context) throws IOException { DropBoxManager db = (DropBoxManager) context.getSystemService(Context.DROPBOX_SERVICE); - String build = - "Build: " + Build.FINGERPRINT + "\nKernel: " + - FileUtils.readTextFile(new File("/proc/version"), 1024, "...\n"); + StringBuilder props = new StringBuilder(); + props.append("Build: ").append(Build.FINGERPRINT).append("\n"); + props.append("Hardware: ").append(Build.BOARD).append("\n"); + props.append("Bootloader: ").append(Build.BOOTLOADER).append("\n"); + props.append("Radio: ").append(Build.RADIO).append("\n"); + props.append("Kernel: "); + props.append(FileUtils.readTextFile(new File("/proc/version"), 1024, "...\n")); if (SystemProperties.getLong("ro.runtime.firstboot", 0) == 0) { String now = Long.toString(System.currentTimeMillis()); SystemProperties.set("ro.runtime.firstboot", now); - if (db != null) db.addText("SYSTEM_BOOT", build); + if (db != null) db.addText("SYSTEM_BOOT", props.toString()); } else { - if (db != null) db.addText("SYSTEM_RESTART", build); + if (db != null) db.addText("SYSTEM_RESTART", props.toString()); return; // Subsequent boot, don't log kernel boot log } @@ -98,6 +106,13 @@ public class BootReceiver extends BroadcastReceiver { String setting = "logfile:" + filename; long lastTime = Settings.Secure.getLong(cr, setting, 0); if (lastTime == fileTime) return; // Already logged this particular file - db.addFile(tag, file, DropBoxManager.IS_TEXT); + Settings.Secure.putLong(cr, setting, fileTime); + + StringBuilder report = new StringBuilder(); + report.append("Build: ").append(Build.FINGERPRINT).append("\n"); + report.append("Kernel: "); + report.append(FileUtils.readTextFile(new File("/proc/version"), 1024, "...\n")); + report.append(FileUtils.readTextFile(new File(filename), LOG_SIZE, "[[TRUNCATED]]\n")); + db.addText(tag, report.toString()); } } diff --git a/services/java/com/android/server/DropBoxManagerService.java b/services/java/com/android/server/DropBoxManagerService.java index 7a708f9d2f035..090e9d3854004 100644 --- a/services/java/com/android/server/DropBoxManagerService.java +++ b/services/java/com/android/server/DropBoxManagerService.java @@ -305,6 +305,7 @@ public final class DropBoxManagerService extends IDropBoxManagerService.Stub { if (!match) continue; numFound++; + if (doPrint) out.append("========================================\n"); out.append(date).append(" ").append(entry.tag == null ? "(no tag)" : entry.tag); if (entry.file == null) { out.append(" (no file)\n"); @@ -339,6 +340,12 @@ public final class DropBoxManagerService extends IDropBoxManagerService.Stub { if (n <= 0) break; out.append(buf, 0, n); newline = (buf[n - 1] == '\n'); + + // Flush periodically when printing to avoid out-of-memory. + if (out.length() > 65536) { + pw.write(out.toString()); + out.setLength(0); + } } if (!newline) out.append("\n"); } else { diff --git a/services/java/com/android/server/SystemServer.java b/services/java/com/android/server/SystemServer.java index 214ecc1b2c4dc..674ade971874f 100644 --- a/services/java/com/android/server/SystemServer.java +++ b/services/java/com/android/server/SystemServer.java @@ -74,8 +74,6 @@ class ServerThread extends Thread { EventLog.writeEvent(EventLogTags.BOOT_PROGRESS_SYSTEM_RUN, SystemClock.uptimeMillis()); - ActivityManagerService.prepareTraceFile(false); // create dir - Looper.prepare(); android.os.Process.setThreadPriority( diff --git a/services/java/com/android/server/am/ActivityManagerService.java b/services/java/com/android/server/am/ActivityManagerService.java index 172bcdbfffdba..40d194c524b92 100644 --- a/services/java/com/android/server/am/ActivityManagerService.java +++ b/services/java/com/android/server/am/ActivityManagerService.java @@ -70,11 +70,12 @@ import android.content.res.Configuration; import android.graphics.Bitmap; import android.net.Uri; import android.os.Binder; -import android.os.Bundle; import android.os.Build; +import android.os.Bundle; import android.os.Debug; import android.os.DropBoxManager; import android.os.Environment; +import android.os.FileObserver; import android.os.FileUtils; import android.os.Handler; import android.os.IBinder; @@ -355,7 +356,7 @@ public final class ActivityManagerService extends ActivityManagerNative implemen Integer.valueOf(SystemProperties.get("ro.EMPTY_APP_MEM"))*PAGE_SIZE; } - final int MY_PID; + static final int MY_PID = Process.myPid(); static final String[] EMPTY_STRING_ARRAY = new String[0]; @@ -1222,7 +1223,7 @@ public final class ActivityManagerService extends ActivityManagerNative implemen mSystemThread.getApplicationThread(), info, info.processName); app.persistent = true; - app.pid = Process.myPid(); + app.pid = MY_PID; app.maxAdj = SYSTEM_ADJ; mSelf.mProcessNames.put(app.processName, app.info.uid, app); synchronized (mSelf.mPidsSelfLocked) { @@ -1383,8 +1384,6 @@ public final class ActivityManagerService extends ActivityManagerNative implemen Log.i(TAG, "Memory class: " + ActivityManager.staticGetMemoryClass()); - MY_PID = Process.myPid(); - File dataDir = Environment.getDataDirectory(); File systemDir = new File(dataDir, "system"); systemDir.mkdirs(); @@ -4555,142 +4554,141 @@ public final class ActivityManagerService extends ActivityManagerNative implemen } } - final String readFile(String filename) { - try { - FileInputStream fs = new FileInputStream(filename); - byte[] inp = new byte[8192]; - int size = fs.read(inp); - fs.close(); - return new String(inp, 0, 0, size); - } catch (java.io.IOException e) { + /** + * If a stack trace dump file is configured, dump process stack traces. + * @param pids of dalvik VM processes to dump stack traces for + * @return file containing stack traces, or null if no dump file is configured + */ + private static File dumpStackTraces(ArrayList pids) { + String tracesPath = SystemProperties.get("dalvik.vm.stack-trace-file", null); + if (tracesPath == null || tracesPath.length() == 0) { + return null; } - return ""; + + File tracesFile = new File(tracesPath); + try { + File tracesDir = tracesFile.getParentFile(); + if (!tracesDir.exists()) tracesFile.mkdirs(); + FileUtils.setPermissions(tracesDir.getPath(), 0775, -1, -1); // drwxrwxr-x + + if (tracesFile.exists()) tracesFile.delete(); + tracesFile.createNewFile(); + FileUtils.setPermissions(tracesFile.getPath(), 0666, -1, -1); // -rw-rw-rw- + } catch (IOException e) { + Log.w(TAG, "Unable to prepare ANR traces file: " + tracesPath, e); + return null; + } + + // 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) { + public synchronized void onEvent(int event, String path) { notify(); } + }; + + try { + observer.startWatching(); + int num = pids.size(); + for (int i = 0; i < num; i++) { + synchronized (observer) { + Process.sendSignal(pids.get(i), Process.SIGNAL_QUIT); + observer.wait(200); // Wait for write-close, give up after 200msec + } + } + } catch (InterruptedException e) { + Log.wtf(TAG, e); + } finally { + observer.stopWatching(); + } + + return tracesFile; } - final void appNotRespondingLocked(ProcessRecord app, HistoryRecord activity, - HistoryRecord reportedActivity, final String annotation) { + final void appNotRespondingLocked(ProcessRecord app, HistoryRecord activity, + HistoryRecord parent, final String annotation) { if (app.notResponding || app.crashing) { return; } - + // Log the ANR to the event log. EventLog.writeEvent(EventLogTags.ANR, app.pid, app.processName, annotation); - - // If we are on a secure build and the application is not interesting to the user (it is - // not visible or in the background), just kill it instead of displaying a dialog. - boolean isSecure = "1".equals(SystemProperties.get(SYSTEM_SECURE, "0")); - if (isSecure && !app.isInterestingToUserLocked() && Process.myPid() != app.pid) { - Process.killProcess(app.pid); - return; - } - - // DeviceMonitor.start(); - String processInfo = null; - if (MONITOR_CPU_USAGE) { - updateCpuStatsNow(); - synchronized (mProcessStatsThread) { - processInfo = mProcessStats.printCurrentState(); + // Dump thread traces as quickly as we can, starting with "interesting" processes. + ArrayList pids = new ArrayList(20); + pids.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) pids.add(parentPid); + + if (MY_PID != app.pid && MY_PID != parentPid) pids.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) pids.add(pid); } } + File tracesFile = dumpStackTraces(pids); + + // Log the ANR to the main log. StringBuilder info = mStringBuilder; info.setLength(0); - info.append("ANR in process: "); - info.append(app.processName); - if (reportedActivity != null && reportedActivity.app != null) { - info.append(" (last in "); - info.append(reportedActivity.app.processName); - info.append(")"); + info.append("ANR in ").append(app.processName); + if (activity != null && activity.shortComponentName != null) { + info.append(" (").append(activity.shortComponentName).append(")"); } if (annotation != null) { - info.append("\nAnnotation: "); - info.append(annotation); + info.append("\nReason: ").append(annotation).append("\n"); } - if (MONITOR_CPU_USAGE) { - info.append("\nCPU usage:\n"); - info.append(processInfo); + if (parent != null && parent != activity) { + info.append("\nParent: ").append(parent.shortComponentName); } - Log.i(TAG, info.toString()); - // The application is not responding. Dump as many thread traces as we can. - boolean fileDump = prepareTraceFile(true); - if (!fileDump) { - // Dumping traces to the log, just dump the process that isn't responding so - // we don't overflow the log - Process.sendSignal(app.pid, Process.SIGNAL_QUIT); - } else { - // Dumping traces to a file so dump all active processes we know about - synchronized (this) { - // First, these are the most important processes. - final int[] imppids = new int[3]; - int i=0; - imppids[0] = app.pid; - i++; - if (reportedActivity != null && reportedActivity.app != null - && reportedActivity.app.thread != null - && reportedActivity.app.pid != app.pid) { - imppids[i] = reportedActivity.app.pid; - i++; - } - imppids[i] = Process.myPid(); - for (i=0; i= 0 ; i--) { - ProcessRecord r = mLruProcesses.get(i); - boolean done = false; - for (int j=0; j 0 && app.pid != MY_PID) { - if (crashed) { - handleAppCrashLocked(app); - } + handleAppCrashLocked(app); Log.i(ActivityManagerService.TAG, "Killing process " + app.processName + " (pid=" + app.pid + ") at user's request"); Process.killProcess(app.pid); } - } } - + private boolean handleAppCrashLocked(ProcessRecord app) { long now = SystemClock.uptimeMillis(); @@ -8808,7 +8755,7 @@ public final class ActivityManagerService extends ActivityManagerNative implemen crashInfo.throwFileName, crashInfo.throwLineNumber); - addExceptionToDropBox("crash", r, null, crashInfo); + addErrorToDropBox("crash", r, null, null, null, null, null, crashInfo); crashApplication(r, crashInfo); } @@ -8828,7 +8775,7 @@ public final class ActivityManagerService extends ActivityManagerNative implemen app == null ? "system" : (r == null ? "unknown" : r.processName), tag, crashInfo.exceptionMessage); - addExceptionToDropBox("wtf", r, tag, crashInfo); + addErrorToDropBox("wtf", r, null, null, tag, null, null, crashInfo); if (Settings.Secure.getInt(mContext.getContentResolver(), Settings.Secure.WTF_IS_FATAL, 0) != 0) { @@ -8865,18 +8812,24 @@ public final class ActivityManagerService extends ActivityManagerNative implemen } /** - * Write a description of an exception (from a crash or WTF report) to the drop box. + * Write a description of an error (crash, WTF, ANR) to the drop box. * @param eventType to include in the drop box tag ("crash", "wtf", etc.) - * @param r the process which crashed, null for the system server - * @param tag supplied by the application (in the case of WTF), or null - * @param crashInfo describing the exception + * @param process which caused the error, null means the system server + * @param activity which triggered the error, null if unknown + * @param parent activity related to the error, null if unknown + * @param subject line related to the error, null if absent + * @param report in long form describing the error, null if absent + * @param logFile to include in the report, null if none + * @param crashInfo giving an application stack trace, null if absent */ - private void addExceptionToDropBox(String eventType, ProcessRecord r, String tag, + private void addErrorToDropBox(String eventType, + ProcessRecord process, HistoryRecord activity, HistoryRecord parent, + String subject, String report, File logFile, ApplicationErrorReport.CrashInfo crashInfo) { - String dropboxTag, processName; - if (r == null) { + String dropboxTag; + if (process == null || process.pid == MY_PID) { dropboxTag = "system_server_" + eventType; - } else if ((r.info.flags & ApplicationInfo.FLAG_SYSTEM) != 0) { + } else if ((process.info.flags & ApplicationInfo.FLAG_SYSTEM) != 0) { dropboxTag = "system_app_" + eventType; } else { dropboxTag = "data_app_" + eventType; @@ -8885,20 +8838,37 @@ public final class ActivityManagerService extends ActivityManagerNative implemen DropBoxManager dbox = (DropBoxManager) mContext.getSystemService(Context.DROPBOX_SERVICE); if (dbox != null && dbox.isTagEnabled(dropboxTag)) { StringBuilder sb = new StringBuilder(1024); - sb.append("Build: ").append(Build.FINGERPRINT).append("\n"); - if (r == null) { + if (process == null || process.pid == MY_PID) { sb.append("Process: system_server\n"); } else { - sb.append("Package: ").append(r.info.packageName).append("\n"); - if (!r.processName.equals(r.info.packageName)) { - sb.append("Process: ").append(r.processName).append("\n"); + sb.append("Process: ").append(process.processName).append("\n"); + } + 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"); + sb.append("\n"); + if (report != null) { + sb.append(report); + } + if (logFile != null) { + try { + sb.append(FileUtils.readTextFile(logFile, 128 * 1024, "\n\n[[TRUNCATED]]")); + } catch (IOException e) { + Log.e(TAG, "Error reading " + logFile, e); } } - if (tag != null) { - sb.append("Tag: ").append(tag).append("\n"); - } if (crashInfo != null && crashInfo.stackTrace != null) { - sb.append("\n").append(crashInfo.stackTrace); + sb.append(crashInfo.stackTrace); } dbox.addText(dropboxTag, sb.toString()); } @@ -8924,14 +8894,6 @@ public final class ActivityManagerService extends ActivityManagerNative implemen AppErrorResult result = new AppErrorResult(); synchronized (this) { - if (r != null) { - // The application has crashed. Send the SIGQUIT to the process so - // that it can dump its state. - Process.sendSignal(r.pid, Process.SIGNAL_QUIT); - //Log.i(TAG, "Current system threads:"); - //Process.sendSignal(MY_PID, Process.SIGNAL_QUIT); - } - if (mController != null) { try { String name = r != null ? r.processName : null; @@ -10320,7 +10282,7 @@ public final class ActivityManagerService extends ActivityManagerNative implemen if (r.startRequested) { info.flags |= ActivityManager.RunningServiceInfo.FLAG_STARTED; } - if (r.app != null && r.app.pid == Process.myPid()) { + if (r.app != null && r.app.pid == MY_PID) { info.flags |= ActivityManager.RunningServiceInfo.FLAG_SYSTEM_PROCESS; } if (r.app != null && r.app.persistent) { @@ -11623,7 +11585,7 @@ public final class ActivityManagerService extends ActivityManagerNative implemen } if (timeout != null && mLruProcesses.contains(proc)) { Log.w(TAG, "Timeout executing service: " + timeout); - appNotRespondingLocked(proc, null, null, "Executing service " + timeout.name); + appNotRespondingLocked(proc, null, null, "Executing service " + timeout.shortName); } else { Message msg = mHandler.obtainMessage(SERVICE_TIMEOUT_MSG); msg.obj = proc; diff --git a/services/java/com/android/server/am/AppNotRespondingDialog.java b/services/java/com/android/server/am/AppNotRespondingDialog.java index 185185358976e..17f3467796090 100644 --- a/services/java/com/android/server/am/AppNotRespondingDialog.java +++ b/services/java/com/android/server/am/AppNotRespondingDialog.java @@ -104,8 +104,7 @@ class AppNotRespondingDialog extends BaseErrorDialog { switch (msg.what) { case FORCE_CLOSE: // Kill the application. - mService.killAppAtUsersRequest(mProc, - AppNotRespondingDialog.this, true); + mService.killAppAtUsersRequest(mProc, AppNotRespondingDialog.this); break; case WAIT_AND_REPORT: case WAIT: diff --git a/services/java/com/android/server/am/AppWaitingForDebuggerDialog.java b/services/java/com/android/server/am/AppWaitingForDebuggerDialog.java index 0992d4dc2d06c..8e9818d8e3b4f 100644 --- a/services/java/com/android/server/am/AppWaitingForDebuggerDialog.java +++ b/services/java/com/android/server/am/AppWaitingForDebuggerDialog.java @@ -62,8 +62,7 @@ class AppWaitingForDebuggerDialog extends BaseErrorDialog { switch (msg.what) { case 1: // Kill the application. - mService.killAppAtUsersRequest(mProc, - AppWaitingForDebuggerDialog.this, true); + mService.killAppAtUsersRequest(mProc, AppWaitingForDebuggerDialog.this); break; } }