Make dumpstate vibrate immediately.

Previously, the vibration was not performed until after stacks
were gathered which takes a long time.  Moved the vibration
to happen earlier so we provide better user feedback for the
three-button salute when collecting a bug report.

Deleted some dead code for playing begin/end sounds.

Improved the timing measurement code to help track down why
bug reports are so slow.  (They take over a minute now which
can cause us to lose valuable diagnostic information.)

Bug: 17474152
Change-Id: Iac73f7993d7dc85196aad96f459b22fd4a710f94

cmds/dumpstate/dumpstate.c

@@ -119,7 +119,6 @@ static void dumpstate() {
     dump_file("BUDDYINFO", "/proc/buddyinfo");
     dump_file("FRAGMENTATION INFO", "/d/extfrag/unusable_index");
 
-
     dump_file("KERNEL WAKELOCKS", "/proc/wakelocks");
     dump_file("KERNEL WAKE SOURCES", "/d/wakeup_sources");
     dump_file("KERNEL CPUFREQ", "/sys/devices/system/cpu/cpu0/cpufreq/stats/time_in_state");
@@ -134,6 +133,8 @@ static void dumpstate() {
     do_dmesg();
 
     run_command("LIST OF OPEN FILES", 10, SU_PATH, "root", "lsof", NULL);
+    for_each_pid(do_showmap, "SMAPS OF ALL PROCESSES");
+    for_each_tid(show_wchan, "BLOCKED PROCESS WAIT-CHANNELS");
 
     if (screenshot_path[0]) {
         ALOGI("taking screenshot\n");
@@ -141,9 +142,6 @@ static void dumpstate() {
         ALOGI("wrote screenshot: %s\n", screenshot_path);
     }
 
-    for_each_pid(do_showmap, "SMAPS OF ALL PROCESSES");
-    for_each_tid(show_wchan, "BLOCKED PROCESS WAIT-CHANNELS");
-
     // dump_file("EVENT LOG TAGS", "/etc/event-log-tags");
     run_command("SYSTEM LOG", 20, "logcat", "-v", "threadtime", "-d", "*:v", NULL);
     run_command("EVENT LOG", 20, "logcat", "-b", "events", "-v", "threadtime", "-d", "*:v", NULL);
@@ -382,14 +380,17 @@ static void sigpipe_handler(int n) {
     _exit(EXIT_FAILURE);
 }
 
+static void vibrate(FILE* vibrator, int ms) {
+    fprintf(vibrator, "%d\n", ms);
+    fflush(vibrator);
+}
+
 int main(int argc, char *argv[]) {
     struct sigaction sigact;
     int do_add_date = 0;
     int do_compress = 0;
     int do_vibrate = 1;
     char* use_outfile = 0;
-    char* begin_sound = 0;
-    char* end_sound = 0;
     int use_socket = 0;
     int do_fb = 0;
     int do_broadcast = 0;
@@ -402,14 +403,14 @@ int main(int argc, char *argv[]) {
         // correct program.
         return execl("/system/bin/bugreport", "/system/bin/bugreport", NULL);
     }
+
     ALOGI("begin\n");
 
-
+    /* clear SIGPIPE handler */
     memset(&sigact, 0, sizeof(sigact));
     sigact.sa_handler = sigpipe_handler;
     sigaction(SIGPIPE, &sigact, NULL);
 
-
     /* set as high priority, and protect from OOM killer */
     setpriority(PRIO_PROCESS, 0, -20);
     FILE *oom_adj = fopen("/proc/self/oom_adj", "w");
@@ -418,15 +419,11 @@ int main(int argc, char *argv[]) {
         fclose(oom_adj);
     }
 
-    /* very first thing, collect stack traces from Dalvik and native processes (needs root) */
+    /* parse arguments */
-    dump_traces_path = dump_traces();
-
     int c;
-    while ((c = getopt(argc, argv, "b:de:ho:svqzpB")) != -1) {
+    while ((c = getopt(argc, argv, "dho:svqzpB")) != -1) {
         switch (c) {
-            case 'b': begin_sound = optarg;  break;
             case 'd': do_add_date = 1;       break;
-            case 'e': end_sound = optarg;    break;
             case 'o': use_outfile = optarg;  break;
             case 's': use_socket = 1;        break;
             case 'v': break;  // compatibility no-op
@@ -441,11 +438,14 @@ int main(int argc, char *argv[]) {
         }
     }
 
+    /* open the vibrator before dropping root */
     FILE *vibrator = 0;
     if (do_vibrate) {
-        /* open the vibrator before dropping root */
         vibrator = fopen("/sys/class/timed_output/vibrator/enable", "w");
-        if (vibrator) fcntl(fileno(vibrator), F_SETFD, FD_CLOEXEC);
+        if (vibrator) {
+            fcntl(fileno(vibrator), F_SETFD, FD_CLOEXEC);
+            vibrate(vibrator, 150);
+        }
     }
 
     /* read /proc/cmdline before dropping root */
@@ -455,14 +455,18 @@ int main(int argc, char *argv[]) {
         fclose(cmdline);
     }
 
+    /* collect stack traces from Dalvik and native processes (needs root) */
+    dump_traces_path = dump_traces();
+
+    /* Get the tombstone fds here while we are running as root. */
+    get_tombstone_fds(tombstone_data);
+
+    /* ensure we will keep capabilities when we drop root */
     if (prctl(PR_SET_KEEPCAPS, 1) < 0) {
         ALOGE("prctl(PR_SET_KEEPCAPS) failed: %s\n", strerror(errno));
         return -1;
     }
 
-    /* Get the tombstone fds here while we are running as root. */
-    get_tombstone_fds(tombstone_data);
-
     /* switch to non-root user and group */
     gid_t groups[] = { AID_LOG, AID_SDCARD_R, AID_SDCARD_RW,
             AID_MOUNT, AID_INET, AID_NET_BW_STATS };
@@ -496,6 +500,7 @@ int main(int argc, char *argv[]) {
         return -1;
     }
 
+    /* redirect output if needed */
     char path[PATH_MAX], tmp_path[PATH_MAX];
     pid_t gzip_pid = -1;
 
@@ -520,22 +525,12 @@ int main(int argc, char *argv[]) {
         gzip_pid = redirect_to_file(stdout, tmp_path, do_compress);
     }
 
-    if (begin_sound) {
-        play_sound(begin_sound);
-    } else if (vibrator) {
-        fputs("150", vibrator);
-        fflush(vibrator);
-    }
-
     dumpstate();
 
-    if (end_sound) {
+    /* done */
-        play_sound(end_sound);
+    if (vibrator) {
-    } else if (vibrator) {
+        for (int i = 0; i < 3; i++) {
-        int i;
+            vibrate(vibrator, 75);
-        for (i = 0; i < 3; i++) {
-            fputs("75\n", vibrator);
-            fflush(vibrator);
             usleep((75 + 50) * 1000);
         }
         fclose(vibrator);
@@ -552,6 +547,7 @@ int main(int argc, char *argv[]) {
         fprintf(stderr, "rename(%s, %s): %s\n", tmp_path, path, strerror(errno));
     }
 
+    /* tell activity manager we're done */
     if (do_broadcast && use_outfile && do_fb) {
         run_command(NULL, 5, "/system/bin/am", "broadcast", "--user", "0",
                 "-a", "android.intent.action.BUGREPORT_FINISHED",

cmds/dumpstate/utils.c

@@ -42,6 +42,8 @@
 
 #include "dumpstate.h"
 
+static const int64_t NANOS_PER_SEC = 1000000000;
+
 /* list of native processes to include in the native dumps */
 static const char* native_processes_to_dump[] = {
         "/system/bin/drmserver",
@@ -293,10 +295,16 @@ int dump_file_from_fd(const char *title, const char *path, int fd) {
     return 0;
 }
 
+static int64_t nanotime() {
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    return (int64_t)ts.tv_sec * NANOS_PER_SEC + ts.tv_nsec;
+}
+
 /* forks a command and waits for it to finish */
 int run_command(const char *title, int timeout_seconds, const char *command, ...) {
     fflush(stdout);
-    time_t start = time(NULL);
+    int64_t start = nanotime();
     pid_t pid = fork();
 
     /* handle error case */
@@ -340,18 +348,18 @@ int run_command(const char *title, int timeout_seconds, const char *command, ...
     for (;;) {
         int status;
         pid_t p = waitpid(pid, &status, WNOHANG);
-        time_t elapsed = time(NULL) - start;
+        int64_t elapsed = nanotime() - start;
         if (p == pid) {
             if (WIFSIGNALED(status)) {
                 printf("*** %s: Killed by signal %d\n", command, WTERMSIG(status));
             } else if (WIFEXITED(status) && WEXITSTATUS(status) > 0) {
                 printf("*** %s: Exit code %d\n", command, WEXITSTATUS(status));
             }
-            if (title) printf("[%s: %ds elapsed]\n\n", command, (int) elapsed);
+            if (title) printf("[%s: %.3fs elapsed]\n\n", command, (float)elapsed / NANOS_PER_SEC);
             return status;
         }
 
-        if (timeout_seconds && elapsed > timeout_seconds) {
+        if (timeout_seconds && elapsed / NANOS_PER_SEC > timeout_seconds) {
             printf("*** %s: Timed out after %ds (killing pid %d)\n", command, (int) elapsed, pid);
             kill(pid, SIGTERM);
             return -1;
@@ -578,9 +586,9 @@ const char *dump_traces() {
         if (!strncmp(data, "/system/bin/app_process", strlen("/system/bin/app_process"))) {
             /* skip zygote -- it won't dump its stack anyway */
             snprintf(path, sizeof(path), "/proc/%d/cmdline", pid);
-            int fd = open(path, O_RDONLY);
+            int cfd = open(path, O_RDONLY);
-            len = read(fd, data, sizeof(data) - 1);
+            len = read(cfd, data, sizeof(data) - 1);
-            close(fd);
+            close(cfd);
             if (len <= 0) {
                 continue;
             }
@@ -590,6 +598,7 @@ const char *dump_traces() {
             }
 
             ++dalvik_found;
+            int64_t start = nanotime();
             if (kill(pid, SIGQUIT)) {
                 fprintf(stderr, "kill(%d, SIGQUIT): %s\n", pid, strerror(errno));
                 continue;
@@ -606,12 +615,24 @@ const char *dump_traces() {
                 struct inotify_event ie;
                 read(ifd, &ie, sizeof(ie));
             }
+
+            if (lseek(fd, 0, SEEK_END) < 0) {
+                fprintf(stderr, "lseek: %s\n", strerror(errno));
+            } else {
+                snprintf(data, sizeof(data), "[dump dalvik stack %d: %.3fs elapsed]\n",
+                        pid, (float)(nanotime() - start) / NANOS_PER_SEC);
+                write(fd, data, strlen(data));
+            }
         } else if (should_dump_native_traces(data)) {
             /* dump native process if appropriate */
             if (lseek(fd, 0, SEEK_END) < 0) {
                 fprintf(stderr, "lseek: %s\n", strerror(errno));
             } else {
+                int64_t start = nanotime();
                 dump_backtrace_to_file(pid, fd);
+                snprintf(data, sizeof(data), "[dump native stack %d: %.3fs elapsed]\n",
+                        pid, (float)(nanotime() - start) / NANOS_PER_SEC);
+                write(fd, data, strlen(data));
             }
         }
     }
@@ -639,10 +660,6 @@ error_close_fd:
     return result;
 }
 
-void play_sound(const char* path) {
-    run_command(NULL, 5, "/system/bin/stagefright", "-o", "-a", path, NULL);
-}
-
 void dump_route_tables() {
     const char* const RT_TABLES_PATH = "/data/misc/net/rt_tables";
     dump_file("RT_TABLES", RT_TABLES_PATH);