Prints out how long it takes to generate each section.
It's done using a DurationReporter helper class that prints starts
counting when constructed and prints the duration when destructed.
Typical usage:
function do_something() {
DurationReporter duration_reporter(title);
// Do something.
}
Change-Id: I87134d9a1b003300384376c242a3c034a46244c4
diff --git a/cmds/dumpstate/dumpstate.cpp b/cmds/dumpstate/dumpstate.cpp
index a08014d..ec1fd60 100644
--- a/cmds/dumpstate/dumpstate.cpp
+++ b/cmds/dumpstate/dumpstate.cpp
@@ -52,6 +52,8 @@
static char cmdline_buf[16384] = "(unknown)";
static const char *dump_traces_path = NULL;
+static char build_type[PROPERTY_VALUE_MAX];
+
#define PSTORE_LAST_KMSG "/sys/fs/pstore/console-ramoops"
#define RAFT_DIR "/data/misc/raft/"
@@ -270,13 +272,11 @@
/* End copy from system/core/logd/LogBuffer.cpp */
/* dumps the current system state to stdout */
-static void dumpstate(const std::string& screenshot_path) {
- unsigned long timeout;
+static void print_header() {
time_t now = time(NULL);
char build[PROPERTY_VALUE_MAX], fingerprint[PROPERTY_VALUE_MAX];
char radio[PROPERTY_VALUE_MAX], bootloader[PROPERTY_VALUE_MAX];
char network[PROPERTY_VALUE_MAX], date[80];
- char build_type[PROPERTY_VALUE_MAX];
property_get("ro.build.display.id", build, "(unknown)");
property_get("ro.build.fingerprint", fingerprint, "(unknown)");
@@ -301,6 +301,11 @@
dump_file(NULL, "/proc/version");
printf("Command line: %s\n", strtok(cmdline_buf, "\n"));
printf("\n");
+}
+
+static void dumpstate(const std::string& screenshot_path) {
+ std::unique_ptr<DurationReporter> duration_reporter(new DurationReporter("DUMPSTATE"));
+ unsigned long timeout;
dump_dev_files("TRUSTY VERSION", "/sys/bus/platform/drivers/trusty", "trusty_version");
run_command("UPTIME", 10, "uptime", NULL);
@@ -808,6 +813,8 @@
}
}
+ print_header();
+
/* open the vibrator before dropping root */
std::unique_ptr<FILE, int(*)(FILE*)> vibrator(NULL, fclose);
if (do_vibrate) {
diff --git a/cmds/dumpstate/dumpstate.h b/cmds/dumpstate/dumpstate.h
index df9721d..1719090 100644
--- a/cmds/dumpstate/dumpstate.h
+++ b/cmds/dumpstate/dumpstate.h
@@ -142,11 +142,32 @@
/* Takes a screenshot and save it to the given file */
void take_screenshot(const std::string& path);
+/* dump eMMC Extended CSD data */
+void dump_emmc_ecsd(const char *ext_csd_path);
+
+/*
+ * Helper class used to report how long it takes for a section to finish.
+ *
+ * Typical usage:
+ *
+ * DurationReporter duration_reporter(title);
+ *
+ */
+class DurationReporter {
+public:
+ DurationReporter(const char *title);
+
+ ~DurationReporter();
+
+ static uint64_t nanotime();
+
+private:
+ const char* title_;
+ uint64_t started_;
+};
+
#ifdef __cplusplus
}
#endif
-/* dump eMMC Extended CSD data */
-void dump_emmc_ecsd(const char *ext_csd_path);
-
#endif /* _DUMPSTATE_H_ */
diff --git a/cmds/dumpstate/utils.cpp b/cmds/dumpstate/utils.cpp
index d448c74..da5632d 100644
--- a/cmds/dumpstate/utils.cpp
+++ b/cmds/dumpstate/utils.cpp
@@ -59,10 +59,26 @@
NULL,
};
-static uint64_t nanotime() {
+DurationReporter::DurationReporter(const char *title) {
+ title_ = title;
+ if (title) {
+ started_ = DurationReporter::nanotime();
+ }
+}
+
+DurationReporter::~DurationReporter() {
+ if (title_) {
+ uint64_t elapsed = DurationReporter::nanotime() - started_;
+ // Use "Yoda grammar" to make it easier to grep|sort sections.
+ printf("------ %.3fs was the duration of '%s' ------\n",
+ (float) elapsed / NANOS_PER_SEC, title_);
+ }
+}
+
+uint64_t DurationReporter::DurationReporter::nanotime() {
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
- return (uint64_t)ts.tv_sec * NANOS_PER_SEC + ts.tv_nsec;
+ return (uint64_t) ts.tv_sec * NANOS_PER_SEC + ts.tv_nsec;
}
void for_each_userid(void (*func)(int), const char *header) {
@@ -217,7 +233,10 @@
}
void do_dmesg() {
- printf("------ KERNEL LOG (dmesg) ------\n");
+ const char *title = "KERNEL LOG (dmesg)";
+ DurationReporter duration_reporter(title);
+ printf("------ %s ------\n", title);
+
ON_DRY_RUN_RETURN();
/* Get size of kernel buffer */
int size = klogctl(KLOG_SIZE_BUFFER, NULL, 0);
@@ -280,14 +299,14 @@
/* Timeout if no data is read for 30 seconds. */
tm.tv_sec = 30;
tm.tv_usec = 0;
- uint64_t elapsed = nanotime();
+ uint64_t elapsed = DurationReporter::nanotime();
int ret = TEMP_FAILURE_RETRY(select(fd + 1, &read_set, NULL, NULL, &tm));
if (ret == -1) {
printf("*** %s: select failed: %s\n", path, strerror(errno));
newline = true;
break;
} else if (ret == 0) {
- elapsed = nanotime() - elapsed;
+ elapsed = DurationReporter::nanotime() - elapsed;
printf("*** %s: Timed out after %.3fs\n", path,
(float) elapsed / NANOS_PER_SEC);
newline = true;
@@ -317,6 +336,7 @@
/* prints the contents of a file */
int dump_file(const char *title, const char *path) {
+ DurationReporter duration_reporter(title);
int fd = TEMP_FAILURE_RETRY(open(path, O_RDONLY | O_NONBLOCK | O_CLOEXEC));
if (fd < 0) {
int err = errno;
@@ -336,6 +356,7 @@
int dump_files(const char *title, const char *dir,
bool (*skip)(const char *path),
int (*dump_from_fd)(const char *title, const char *path, int fd)) {
+ DurationReporter duration_reporter(title);
DIR *dirp;
struct dirent *d;
char *newpath = NULL;
@@ -460,6 +481,7 @@
}
int run_command(const char *title, int timeout_seconds, const char *command, ...) {
+ DurationReporter duration_reporter(title);
fflush(stdout);
const char *args[1024] = {command};
@@ -490,7 +512,7 @@
int weight = timeout_seconds;
const char *command = args[0];
- uint64_t start = nanotime();
+ uint64_t start = DurationReporter::nanotime();
pid_t pid = fork();
/* handle error case */
@@ -520,7 +542,7 @@
/* handle parent case */
int status;
bool ret = waitpid_with_timeout(pid, timeout_seconds, &status);
- uint64_t elapsed = nanotime() - start;
+ uint64_t elapsed = DurationReporter::nanotime() - start;
if (!ret) {
if (errno == ETIMEDOUT) {
printf("*** %s: Timed out after %.3fs (killing pid %d)\n", command,
@@ -586,7 +608,9 @@
/* prints all the system properties */
void print_properties() {
- printf("------ SYSTEM PROPERTIES ------\n");
+ const char* title = "SYSTEM PROPERTIES";
+ DurationReporter duration_reporter(title);
+ printf("------ %s ------\n", title);
ON_DRY_RUN_RETURN();
size_t i;
num_props = 0;
@@ -666,6 +690,7 @@
/* dump Dalvik and native stack traces, return the trace file location (NULL if none) */
const char *dump_traces() {
+ DurationReporter duration_reporter("DUMP TRACES");
ON_DRY_RUN_RETURN(NULL);
const char* result = NULL;
@@ -749,7 +774,7 @@
}
++dalvik_found;
- uint64_t start = nanotime();
+ uint64_t start = DurationReporter::nanotime();
if (kill(pid, SIGQUIT)) {
fprintf(stderr, "kill(%d, SIGQUIT): %s\n", pid, strerror(errno));
continue;
@@ -771,7 +796,7 @@
fprintf(stderr, "lseek: %s\n", strerror(errno));
} else {
dprintf(fd, "[dump dalvik stack %d: %.3fs elapsed]\n",
- pid, (float)(nanotime() - start) / NANOS_PER_SEC);
+ pid, (float)(DurationReporter::nanotime() - start) / NANOS_PER_SEC);
}
} else if (should_dump_native_traces(data)) {
/* dump native process if appropriate */
@@ -779,7 +804,7 @@
fprintf(stderr, "lseek: %s\n", strerror(errno));
} else {
static uint16_t timeout_failures = 0;
- uint64_t start = nanotime();
+ uint64_t start = DurationReporter::nanotime();
/* If 3 backtrace dumps fail in a row, consider debuggerd dead. */
if (timeout_failures == 3) {
@@ -791,7 +816,7 @@
timeout_failures = 0;
}
dprintf(fd, "[dump native stack %d: %.3fs elapsed]\n",
- pid, (float)(nanotime() - start) / NANOS_PER_SEC);
+ pid, (float)(DurationReporter::nanotime() - start) / NANOS_PER_SEC);
}
}
}
@@ -820,6 +845,7 @@
}
void dump_route_tables() {
+ DurationReporter duration_reporter("DUMP ROUTE TABLES");
ON_DRY_RUN_RETURN();
const char* const RT_TABLES_PATH = "/data/misc/net/rt_tables";
dump_file("RT_TABLES", RT_TABLES_PATH);