From a3641af22fdb0f1b3127e4d56e65c13ad108d74a Mon Sep 17 00:00:00 2001 From: Elliott Hughes Date: Thu, 10 Nov 2016 17:43:47 -0800 Subject: [PATCH] Improve init bootcharting. Most notably, there's no longer any need to guess an end time. Bug: http://b/23478578 Bug: http://b/33450491 Test: rebooted with bootcharting on/off Change-Id: Icb7d6859581da5526d77dfc5aa4d57c9bfbfd7e2 --- init/bootchart.cpp | 220 ++++++++++++++++------------------------- init/bootchart.h | 2 +- init/builtins.cpp | 2 +- init/grab-bootchart.sh | 2 +- init/readme.txt | 21 ++-- rootdir/init.rc | 5 +- 6 files changed, 99 insertions(+), 153 deletions(-) diff --git a/init/bootchart.cpp b/init/bootchart.cpp index 8fb55f03f..7a8a3d53f 100644 --- a/init/bootchart.cpp +++ b/init/bootchart.cpp @@ -34,29 +34,25 @@ #include #include +#include -#define LOG_ROOT "/data/bootchart" -#define LOG_STAT LOG_ROOT"/proc_stat.log" -#define LOG_PROCS LOG_ROOT"/proc_ps.log" -#define LOG_DISK LOG_ROOT"/proc_diskstats.log" -#define LOG_HEADER LOG_ROOT"/header" -#define LOG_ACCT LOG_ROOT"/kernel_pacct" +using android::base::StringPrintf; -#define LOG_STARTFILE LOG_ROOT"/start" -#define LOG_STOPFILE LOG_ROOT"/stop" +static constexpr const char* LOG_STAT = "/data/bootchart/proc_stat.log"; +static constexpr const char* LOG_PROC = "/data/bootchart/proc_ps.log"; +static constexpr const char* LOG_DISK = "/data/bootchart/proc_diskstats.log"; +static constexpr const char* LOG_HEADER = "/data/bootchart/header"; // Polling period in ms. -static const int BOOTCHART_POLLING_MS = 200; - -// Max polling time in seconds. -static const int BOOTCHART_MAX_TIME_SEC = 10*60; +static constexpr int BOOTCHART_POLLING_MS = 200; static long long g_last_bootchart_time; -static int g_remaining_samples; -static FILE* log_stat; -static FILE* log_procs; -static FILE* log_disks; +static bool g_bootcharting = false; + +static FILE* g_stat_log; +static FILE* g_proc_log; +static FILE* g_disk_log; static long long get_uptime_jiffies() { std::string uptime; @@ -99,12 +95,12 @@ static void log_header() { fclose(out); } -static void do_log_uptime(FILE* log) { +static void log_uptime(FILE* log) { fprintf(log, "%lld\n", get_uptime_jiffies()); } -static void do_log_file(FILE* log, const char* procfile) { - do_log_uptime(log); +static void log_file(FILE* log, const char* procfile) { + log_uptime(log); std::string content; if (android::base::ReadFileToString(procfile, &content)) { @@ -112,161 +108,115 @@ static void do_log_file(FILE* log, const char* procfile) { } } -static void do_log_procs(FILE* log) { - do_log_uptime(log); +static void log_processes() { + log_uptime(g_proc_log); std::unique_ptr dir(opendir("/proc"), closedir); struct dirent* entry; while ((entry = readdir(dir.get())) != NULL) { // Only match numeric values. - char* end; - int pid = strtol(entry->d_name, &end, 10); - if (end != NULL && end > entry->d_name && *end == 0) { - char filename[32]; + int pid = atoi(entry->d_name); + if (pid == 0) continue; - // /proc//stat only has truncated task names, so get the full - // name from /proc//cmdline. - snprintf(filename, sizeof(filename), "/proc/%d/cmdline", pid); - std::string cmdline; - android::base::ReadFileToString(filename, &cmdline); - const char* full_name = cmdline.c_str(); // So we stop at the first NUL. - - // Read process stat line. - snprintf(filename, sizeof(filename), "/proc/%d/stat", pid); - std::string stat; - if (android::base::ReadFileToString(filename, &stat)) { - if (!cmdline.empty()) { - // Substitute the process name with its real name. - size_t open = stat.find('('); - size_t close = stat.find_last_of(')'); - if (open != std::string::npos && close != std::string::npos) { - stat.replace(open + 1, close - open - 1, full_name); - } - } - fputs(stat.c_str(), log); - } - } - } - - fputc('\n', log); -} - -static int bootchart_init() { - int timeout = 0; - - std::string start; - android::base::ReadFileToString(LOG_STARTFILE, &start); - if (!start.empty()) { - timeout = atoi(start.c_str()); - } else { - // When running with emulator, androidboot.bootchart= - // might be passed by as kernel parameters to specify the bootchart - // timeout. this is useful when using -wipe-data since the /data - // partition is fresh. + // /proc//stat only has truncated task names, so get the full + // name from /proc//cmdline. std::string cmdline; - const char* s; - android::base::ReadFileToString("/proc/cmdline", &cmdline); -#define KERNEL_OPTION "androidboot.bootchart=" - if ((s = strstr(cmdline.c_str(), KERNEL_OPTION)) != NULL) { - timeout = atoi(s + sizeof(KERNEL_OPTION) - 1); + android::base::ReadFileToString(StringPrintf("/proc/%d/cmdline", pid), &cmdline); + const char* full_name = cmdline.c_str(); // So we stop at the first NUL. + + // Read process stat line. + std::string stat; + if (android::base::ReadFileToString(StringPrintf("/proc/%d/stat", pid), &stat)) { + if (!cmdline.empty()) { + // Substitute the process name with its real name. + size_t open = stat.find('('); + size_t close = stat.find_last_of(')'); + if (open != std::string::npos && close != std::string::npos) { + stat.replace(open + 1, close - open - 1, full_name); + } + } + fputs(stat.c_str(), g_proc_log); } } - if (timeout == 0) + + fputc('\n', g_proc_log); +} + +static int do_bootchart_start() { + // We don't care about the content, but we do care that /data/bootchart/enabled actually exists. + std::string start; + if (!android::base::ReadFileToString("/data/bootchart/enabled", &start)) { + LOG(VERBOSE) << "Not bootcharting"; return 0; + } - if (timeout > BOOTCHART_MAX_TIME_SEC) - timeout = BOOTCHART_MAX_TIME_SEC; - - int count = (timeout*1000 + BOOTCHART_POLLING_MS-1)/BOOTCHART_POLLING_MS; - - log_stat = fopen(LOG_STAT, "we"); - if (log_stat == NULL) { + // Open log files. + std::unique_ptr stat_log(fopen(LOG_STAT, "we"), fclose); + if (!stat_log) { + PLOG(ERROR) << "Bootcharting couldn't open " << LOG_STAT; return -1; } - log_procs = fopen(LOG_PROCS, "we"); - if (log_procs == NULL) { - fclose(log_stat); + std::unique_ptr proc_log(fopen(LOG_PROC, "we"), fclose); + if (!proc_log) { + PLOG(ERROR) << "Bootcharting couldn't open " << LOG_PROC; return -1; } - log_disks = fopen(LOG_DISK, "we"); - if (log_disks == NULL) { - fclose(log_stat); - fclose(log_procs); + std::unique_ptr disk_log(fopen(LOG_DISK, "we"), fclose); + if (!disk_log) { + PLOG(ERROR) << "Bootcharting couldn't open " << LOG_DISK; return -1; } - // Create kernel process accounting file. - close(open(LOG_ACCT, O_WRONLY | O_CREAT | O_TRUNC | O_CLOEXEC, 0644)); - acct(LOG_ACCT); - + LOG(INFO) << "Bootcharting started"; + g_stat_log = stat_log.release(); + g_proc_log = proc_log.release(); + g_disk_log = disk_log.release(); + g_bootcharting = true; log_header(); - return count; -} - -int do_bootchart_init(const std::vector& args) { - g_remaining_samples = bootchart_init(); - if (g_remaining_samples < 0) { - PLOG(ERROR) << "Bootcharting initialization failed"; - } else if (g_remaining_samples > 0) { - LOG(INFO) << "Bootcharting started (will run for " - << ((g_remaining_samples * BOOTCHART_POLLING_MS) / 1000) << " s)."; - } else { - LOG(VERBOSE) << "Not bootcharting."; - } - return 0; -} - -static int bootchart_step() { - do_log_file(log_stat, "/proc/stat"); - do_log_file(log_disks, "/proc/diskstats"); - do_log_procs(log_procs); - - // Stop if /data/bootchart/stop contains 1. - std::string stop; - if (android::base::ReadFileToString(LOG_STOPFILE, &stop) && stop == "1") { - return -1; - } return 0; } -/* called to get time (in ms) used by bootchart */ -static long long bootchart_gettime() { - return 10LL*get_uptime_jiffies(); +static void do_bootchart_step() { + log_file(g_stat_log, "/proc/stat"); + log_file(g_disk_log, "/proc/diskstats"); + log_processes(); } -static void bootchart_finish() { - unlink(LOG_STOPFILE); - fclose(log_stat); - fclose(log_disks); - fclose(log_procs); - acct(NULL); +static int do_bootchart_stop() { + if (!g_bootcharting) return 0; + LOG(INFO) << "Bootcharting finished"; + g_bootcharting = false; + fclose(g_stat_log); + fclose(g_disk_log); + fclose(g_proc_log); + return 0; +} + +int do_bootchart(const std::vector& args) { + if (args[1] == "start") return do_bootchart_start(); + return do_bootchart_stop(); } void bootchart_sample(int* timeout) { // Do we have any more bootcharting to do? - if (g_remaining_samples <= 0) { - return; - } + if (!g_bootcharting) return; - long long current_time = bootchart_gettime(); + long long current_time = 10LL * get_uptime_jiffies(); int elapsed_time = current_time - g_last_bootchart_time; if (elapsed_time >= BOOTCHART_POLLING_MS) { - // Count missed samples. while (elapsed_time >= BOOTCHART_POLLING_MS) { elapsed_time -= BOOTCHART_POLLING_MS; - g_remaining_samples--; } - // Count may be negative, take a sample anyway. + g_last_bootchart_time = current_time; - if (bootchart_step() < 0 || g_remaining_samples <= 0) { - bootchart_finish(); - g_remaining_samples = 0; - } + do_bootchart_step(); } - if (g_remaining_samples > 0) { + + // Schedule another? + if (g_bootcharting) { int remaining_time = BOOTCHART_POLLING_MS - elapsed_time; if (*timeout < 0 || *timeout > remaining_time) { *timeout = remaining_time; diff --git a/init/bootchart.h b/init/bootchart.h index 47eda7abe..1e8d0f865 100644 --- a/init/bootchart.h +++ b/init/bootchart.h @@ -20,7 +20,7 @@ #include #include -int do_bootchart_init(const std::vector& args); +int do_bootchart(const std::vector& args); void bootchart_sample(int* timeout); #endif /* _BOOTCHART_H */ diff --git a/init/builtins.cpp b/init/builtins.cpp index 76e3d6e33..fc0459c13 100644 --- a/init/builtins.cpp +++ b/init/builtins.cpp @@ -1023,7 +1023,7 @@ static int do_init_user0(const std::vector& args) { BuiltinFunctionMap::Map& BuiltinFunctionMap::map() const { constexpr std::size_t kMax = std::numeric_limits::max(); static const Map builtin_functions = { - {"bootchart_init", {0, 0, do_bootchart_init}}, + {"bootchart", {1, 1, do_bootchart}}, {"chmod", {2, 2, do_chmod}}, {"chown", {2, 3, do_chown}}, {"class_reset", {1, 1, do_class_reset}}, diff --git a/init/grab-bootchart.sh b/init/grab-bootchart.sh index d6082aaad..c4ff6dfaf 100755 --- a/init/grab-bootchart.sh +++ b/init/grab-bootchart.sh @@ -11,7 +11,7 @@ mkdir -p $TMPDIR LOGROOT=/data/bootchart TARBALL=bootchart.tgz -FILES="header proc_stat.log proc_ps.log proc_diskstats.log kernel_pacct" +FILES="header proc_stat.log proc_ps.log proc_diskstats.log" for f in $FILES; do adb "${@}" pull $LOGROOT/$f $TMPDIR/$f 2>&1 > /dev/null diff --git a/init/readme.txt b/init/readme.txt index 7549e3c03..7f2bb532c 100644 --- a/init/readme.txt +++ b/init/readme.txt @@ -256,9 +256,10 @@ at three times, Commands -------- -bootchart_init - Start bootcharting if configured (see below). - This is included in the default init.rc. +bootchart [start|stop] + Start/stop bootcharting. These are present in the default init.rc files, + but bootcharting is only active if the file /data/bootchart/enabled exists; + otherwise bootchart start/stop are no-ops. chmod Change file access permissions. @@ -471,19 +472,11 @@ files that can be later processed by the tools provided by www.bootchart.org. On the emulator, use the -bootchart option to boot with bootcharting activated for seconds. -On a device, create /data/bootchart/start with a command like the following: +On a device: - adb shell 'echo $TIMEOUT > /data/bootchart/start' + adb shell 'touch /data/bootchart/enabled' -Where the value of $TIMEOUT corresponds to the desired bootcharted period in -seconds. Bootcharting will stop after that many seconds have elapsed. -You can also stop the bootcharting at any moment by doing the following: - - adb shell 'echo 1 > /data/bootchart/stop' - -Note that /data/bootchart/stop is deleted automatically by init at the end of -the bootcharting. This is not the case with /data/bootchart/start, so don't -forget to delete it when you're done collecting data. +Don't forget to delete this file when you're done collecting data! The log files are written to /data/bootchart/. A script is provided to retrieve them and create a bootchart.tgz file that can be used with the diff --git a/rootdir/init.rc b/rootdir/init.rc index ecc3ccdee..9a1fb2353 100644 --- a/rootdir/init.rc +++ b/rootdir/init.rc @@ -349,7 +349,7 @@ on post-fs-data # Start bootcharting as soon as possible after the data partition is # mounted to collect more data. mkdir /data/bootchart 0755 shell shell - bootchart_init + bootchart start # Avoid predictable entropy pool. Carry over entropy from previous boot. copy /data/system/entropy.dat /dev/urandom @@ -598,6 +598,9 @@ on property:vold.decrypt=trigger_shutdown_framework on property:sys.powerctl=* powerctl ${sys.powerctl} +on property:sys.boot_completed=1 + bootchart stop + # system server cannot write to /proc/sys files, # and chown/chmod does not work for /proc/sys/ entries. # So proxy writes through init.