| /* |
| * Copyright (C) 2016 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. |
| */ |
| |
| // The bootstat command provides options to persist boot events with the current |
| // timestamp, dump the persisted events, and log all events to EventLog to be |
| // uploaded to Android log storage via Tron. |
| |
| #include <getopt.h> |
| #include <unistd.h> |
| |
| #include <chrono> |
| #include <cmath> |
| #include <cstddef> |
| #include <cstdio> |
| #include <ctime> |
| #include <map> |
| #include <memory> |
| #include <string> |
| #include <vector> |
| |
| #include <android-base/chrono_utils.h> |
| #include <android-base/logging.h> |
| #include <android-base/parseint.h> |
| #include <android-base/strings.h> |
| #include <android/log.h> |
| #include <cutils/properties.h> |
| #include <metricslogger/metrics_logger.h> |
| |
| #include "boot_event_record_store.h" |
| |
| namespace { |
| |
| // Scans the boot event record store for record files and logs each boot event |
| // via EventLog. |
| void LogBootEvents() { |
| BootEventRecordStore boot_event_store; |
| |
| auto events = boot_event_store.GetAllBootEvents(); |
| for (auto i = events.cbegin(); i != events.cend(); ++i) { |
| android::metricslogger::LogHistogram(i->first, i->second); |
| } |
| } |
| |
| // Records the named boot |event| to the record store. If |value| is non-empty |
| // and is a proper string representation of an integer value, the converted |
| // integer value is associated with the boot event. |
| void RecordBootEventFromCommandLine( |
| const std::string& event, const std::string& value_str) { |
| BootEventRecordStore boot_event_store; |
| if (!value_str.empty()) { |
| int32_t value = 0; |
| if (android::base::ParseInt(value_str, &value)) { |
| boot_event_store.AddBootEventWithValue(event, value); |
| } |
| } else { |
| boot_event_store.AddBootEvent(event); |
| } |
| } |
| |
| void PrintBootEvents() { |
| printf("Boot events:\n"); |
| printf("------------\n"); |
| |
| BootEventRecordStore boot_event_store; |
| auto events = boot_event_store.GetAllBootEvents(); |
| for (auto i = events.cbegin(); i != events.cend(); ++i) { |
| printf("%s\t%d\n", i->first.c_str(), i->second); |
| } |
| } |
| |
| void ShowHelp(const char *cmd) { |
| fprintf(stderr, "Usage: %s [options]\n", cmd); |
| fprintf(stderr, |
| "options include:\n" |
| " -h, --help Show this help\n" |
| " -l, --log Log all metrics to logstorage\n" |
| " -p, --print Dump the boot event records to the console\n" |
| " -r, --record Record the timestamp of a named boot event\n" |
| " --value Optional value to associate with the boot event\n" |
| " --record_boot_reason Record the reason why the device booted\n" |
| " --record_time_since_factory_reset Record the time since the device was reset\n"); |
| } |
| |
| // Constructs a readable, printable string from the givencommand line |
| // arguments. |
| std::string GetCommandLine(int argc, char **argv) { |
| std::string cmd; |
| for (int i = 0; i < argc; ++i) { |
| cmd += argv[i]; |
| cmd += " "; |
| } |
| |
| return cmd; |
| } |
| |
| // Convenience wrapper over the property API that returns an |
| // std::string. |
| std::string GetProperty(const char* key) { |
| std::vector<char> temp(PROPERTY_VALUE_MAX); |
| const int len = property_get(key, &temp[0], nullptr); |
| if (len < 0) { |
| return ""; |
| } |
| return std::string(&temp[0], len); |
| } |
| |
| constexpr int32_t kUnknownBootReason = 1; |
| |
| // A mapping from boot reason string, as read from the ro.boot.bootreason |
| // system property, to a unique integer ID. Viewers of log data dashboards for |
| // the boot_reason metric may refer to this mapping to discern the histogram |
| // values. |
| const std::map<std::string, int32_t> kBootReasonMap = { |
| {"unknown", kUnknownBootReason}, |
| {"normal", 2}, |
| {"recovery", 3}, |
| {"reboot", 4}, |
| {"PowerKey", 5}, |
| {"hard_reset", 6}, |
| {"kernel_panic", 7}, |
| {"rpm_err", 8}, |
| {"hw_reset", 9}, |
| {"tz_err", 10}, |
| {"adsp_err", 11}, |
| {"modem_err", 12}, |
| {"mba_err", 13}, |
| {"Watchdog", 14}, |
| {"Panic", 15}, |
| {"power_key", 16}, |
| {"power_on", 17}, |
| {"Reboot", 18}, |
| {"rtc", 19}, |
| {"edl", 20}, |
| {"oem_pon1", 21}, |
| {"oem_powerkey", 22}, |
| {"oem_unknown_reset", 23}, |
| {"srto: HWWDT reset SC", 24}, |
| {"srto: HWWDT reset platform", 25}, |
| {"srto: bootloader", 26}, |
| {"srto: kernel panic", 27}, |
| {"srto: kernel watchdog reset", 28}, |
| {"srto: normal", 29}, |
| {"srto: reboot", 30}, |
| {"srto: reboot-bootloader", 31}, |
| {"srto: security watchdog reset", 32}, |
| {"srto: wakesrc", 33}, |
| {"srto: watchdog", 34}, |
| {"srto:1-1", 35}, |
| {"srto:omap_hsmm", 36}, |
| {"srto:phy0", 37}, |
| {"srto:rtc0", 38}, |
| {"srto:touchpad", 39}, |
| {"watchdog", 40}, |
| {"watchdogr", 41}, |
| {"wdog_bark", 42}, |
| {"wdog_bite", 43}, |
| {"wdog_reset", 44}, |
| }; |
| |
| // Converts a string value representing the reason the system booted to an |
| // integer representation. This is necessary for logging the boot_reason metric |
| // via Tron, which does not accept non-integer buckets in histograms. |
| int32_t BootReasonStrToEnum(const std::string& boot_reason) { |
| auto mapping = kBootReasonMap.find(boot_reason); |
| if (mapping != kBootReasonMap.end()) { |
| return mapping->second; |
| } |
| |
| LOG(INFO) << "Unknown boot reason: " << boot_reason; |
| return kUnknownBootReason; |
| } |
| |
| // Returns the appropriate metric key prefix for the boot_complete metric such |
| // that boot metrics after a system update are labeled as ota_boot_complete; |
| // otherwise, they are labeled as boot_complete. This method encapsulates the |
| // bookkeeping required to track when a system update has occurred by storing |
| // the UTC timestamp of the system build date and comparing against the current |
| // system build date. |
| std::string CalculateBootCompletePrefix() { |
| static const std::string kBuildDateKey = "build_date"; |
| std::string boot_complete_prefix = "boot_complete"; |
| |
| std::string build_date_str = GetProperty("ro.build.date.utc"); |
| int32_t build_date; |
| if (!android::base::ParseInt(build_date_str, &build_date)) { |
| return std::string(); |
| } |
| |
| BootEventRecordStore boot_event_store; |
| BootEventRecordStore::BootEventRecord record; |
| if (!boot_event_store.GetBootEvent(kBuildDateKey, &record)) { |
| boot_complete_prefix = "factory_reset_" + boot_complete_prefix; |
| boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date); |
| } else if (build_date != record.second) { |
| boot_complete_prefix = "ota_" + boot_complete_prefix; |
| boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date); |
| } |
| |
| return boot_complete_prefix; |
| } |
| |
| // Records the value of a given ro.boottime.init property in milliseconds. |
| void RecordInitBootTimeProp( |
| BootEventRecordStore* boot_event_store, const char* property) { |
| std::string value = GetProperty(property); |
| |
| int32_t time_in_ms; |
| if (android::base::ParseInt(value, &time_in_ms)) { |
| boot_event_store->AddBootEventWithValue(property, time_in_ms); |
| } |
| } |
| |
| // A map from bootloader timing stage to the time that stage took during boot. |
| typedef std::map<std::string, int32_t> BootloaderTimingMap; |
| |
| // Returns a mapping from bootloader stage names to the time those stages |
| // took to boot. |
| const BootloaderTimingMap GetBootLoaderTimings() { |
| BootloaderTimingMap timings; |
| |
| // |ro.boot.boottime| is of the form 'stage1:time1,...,stageN:timeN', |
| // where timeN is in milliseconds. |
| std::string value = GetProperty("ro.boot.boottime"); |
| if (value.empty()) { |
| // ro.boot.boottime is not reported on all devices. |
| return BootloaderTimingMap(); |
| } |
| |
| auto stages = android::base::Split(value, ","); |
| for (const auto& stageTiming : stages) { |
| // |stageTiming| is of the form 'stage:time'. |
| auto stageTimingValues = android::base::Split(stageTiming, ":"); |
| DCHECK_EQ(2U, stageTimingValues.size()); |
| |
| std::string stageName = stageTimingValues[0]; |
| int32_t time_ms; |
| if (android::base::ParseInt(stageTimingValues[1], &time_ms)) { |
| timings[stageName] = time_ms; |
| } |
| } |
| |
| return timings; |
| } |
| |
| // Parses and records the set of bootloader stages and associated boot times |
| // from the ro.boot.boottime system property. |
| void RecordBootloaderTimings(BootEventRecordStore* boot_event_store, |
| const BootloaderTimingMap& bootloader_timings) { |
| int32_t total_time = 0; |
| for (const auto& timing : bootloader_timings) { |
| total_time += timing.second; |
| boot_event_store->AddBootEventWithValue("boottime.bootloader." + timing.first, timing.second); |
| } |
| |
| boot_event_store->AddBootEventWithValue("boottime.bootloader.total", total_time); |
| } |
| |
| // Records the closest estimation to the absolute device boot time, i.e., |
| // from power on to boot_complete, including bootloader times. |
| void RecordAbsoluteBootTime(BootEventRecordStore* boot_event_store, |
| const BootloaderTimingMap& bootloader_timings, |
| std::chrono::milliseconds uptime) { |
| int32_t bootloader_time_ms = 0; |
| |
| for (const auto& timing : bootloader_timings) { |
| if (timing.first.compare("SW") != 0) { |
| bootloader_time_ms += timing.second; |
| } |
| } |
| |
| auto bootloader_duration = std::chrono::milliseconds(bootloader_time_ms); |
| auto absolute_total = |
| std::chrono::duration_cast<std::chrono::seconds>(bootloader_duration + uptime); |
| boot_event_store->AddBootEventWithValue("absolute_boot_time", absolute_total.count()); |
| } |
| |
| // Records several metrics related to the time it takes to boot the device, |
| // including disambiguating boot time on encrypted or non-encrypted devices. |
| void RecordBootComplete() { |
| BootEventRecordStore boot_event_store; |
| BootEventRecordStore::BootEventRecord record; |
| |
| auto time_since_epoch = android::base::boot_clock::now().time_since_epoch(); |
| auto uptime = std::chrono::duration_cast<std::chrono::seconds>(time_since_epoch); |
| time_t current_time_utc = time(nullptr); |
| |
| if (boot_event_store.GetBootEvent("last_boot_time_utc", &record)) { |
| time_t last_boot_time_utc = record.second; |
| time_t time_since_last_boot = difftime(current_time_utc, |
| last_boot_time_utc); |
| boot_event_store.AddBootEventWithValue("time_since_last_boot", |
| time_since_last_boot); |
| } |
| |
| boot_event_store.AddBootEventWithValue("last_boot_time_utc", current_time_utc); |
| |
| // The boot_complete metric has two variants: boot_complete and |
| // ota_boot_complete. The latter signifies that the device is booting after |
| // a system update. |
| std::string boot_complete_prefix = CalculateBootCompletePrefix(); |
| if (boot_complete_prefix.empty()) { |
| // The system is hosed because the build date property could not be read. |
| return; |
| } |
| |
| // post_decrypt_time_elapsed is only logged on encrypted devices. |
| if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) { |
| // Log the amount of time elapsed until the device is decrypted, which |
| // includes the variable amount of time the user takes to enter the |
| // decryption password. |
| boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime.count()); |
| |
| // Subtract the decryption time to normalize the boot cycle timing. |
| std::chrono::seconds boot_complete = std::chrono::seconds(uptime.count() - record.second); |
| boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_post_decrypt", |
| boot_complete.count()); |
| } else { |
| boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_no_encryption", |
| uptime.count()); |
| } |
| |
| // Record the total time from device startup to boot complete, regardless of |
| // encryption state. |
| boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime.count()); |
| |
| RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init"); |
| RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux"); |
| RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait"); |
| |
| const BootloaderTimingMap bootloader_timings = GetBootLoaderTimings(); |
| RecordBootloaderTimings(&boot_event_store, bootloader_timings); |
| |
| auto uptime_ms = std::chrono::duration_cast<std::chrono::milliseconds>(time_since_epoch); |
| RecordAbsoluteBootTime(&boot_event_store, bootloader_timings, uptime_ms); |
| } |
| |
| // Records the boot_reason metric by querying the ro.boot.bootreason system |
| // property. |
| void RecordBootReason() { |
| int32_t boot_reason = BootReasonStrToEnum(GetProperty("ro.boot.bootreason")); |
| BootEventRecordStore boot_event_store; |
| boot_event_store.AddBootEventWithValue("boot_reason", boot_reason); |
| } |
| |
| // Records two metrics related to the user resetting a device: the time at |
| // which the device is reset, and the time since the user last reset the |
| // device. The former is only set once per-factory reset. |
| void RecordFactoryReset() { |
| BootEventRecordStore boot_event_store; |
| BootEventRecordStore::BootEventRecord record; |
| |
| time_t current_time_utc = time(nullptr); |
| |
| if (current_time_utc < 0) { |
| // UMA does not display negative values in buckets, so convert to positive. |
| android::metricslogger::LogHistogram( |
| "factory_reset_current_time_failure", std::abs(current_time_utc)); |
| |
| // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram |
| // is losing records somehow. |
| boot_event_store.AddBootEventWithValue( |
| "factory_reset_current_time_failure", std::abs(current_time_utc)); |
| return; |
| } else { |
| android::metricslogger::LogHistogram("factory_reset_current_time", current_time_utc); |
| |
| // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram |
| // is losing records somehow. |
| boot_event_store.AddBootEventWithValue( |
| "factory_reset_current_time", current_time_utc); |
| } |
| |
| // The factory_reset boot event does not exist after the device is reset, so |
| // use this signal to mark the time of the factory reset. |
| if (!boot_event_store.GetBootEvent("factory_reset", &record)) { |
| boot_event_store.AddBootEventWithValue("factory_reset", current_time_utc); |
| |
| // Don't log the time_since_factory_reset until some time has elapsed. |
| // The data is not meaningful yet and skews the histogram buckets. |
| return; |
| } |
| |
| // Calculate and record the difference in time between now and the |
| // factory_reset time. |
| time_t factory_reset_utc = record.second; |
| android::metricslogger::LogHistogram("factory_reset_record_value", factory_reset_utc); |
| |
| // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram |
| // is losing records somehow. |
| boot_event_store.AddBootEventWithValue( |
| "factory_reset_record_value", factory_reset_utc); |
| |
| time_t time_since_factory_reset = difftime(current_time_utc, |
| factory_reset_utc); |
| boot_event_store.AddBootEventWithValue("time_since_factory_reset", |
| time_since_factory_reset); |
| } |
| |
| } // namespace |
| |
| int main(int argc, char **argv) { |
| android::base::InitLogging(argv); |
| |
| const std::string cmd_line = GetCommandLine(argc, argv); |
| LOG(INFO) << "Service started: " << cmd_line; |
| |
| int option_index = 0; |
| static const char value_str[] = "value"; |
| static const char boot_complete_str[] = "record_boot_complete"; |
| static const char boot_reason_str[] = "record_boot_reason"; |
| static const char factory_reset_str[] = "record_time_since_factory_reset"; |
| static const struct option long_options[] = { |
| { "help", no_argument, NULL, 'h' }, |
| { "log", no_argument, NULL, 'l' }, |
| { "print", no_argument, NULL, 'p' }, |
| { "record", required_argument, NULL, 'r' }, |
| { value_str, required_argument, NULL, 0 }, |
| { boot_complete_str, no_argument, NULL, 0 }, |
| { boot_reason_str, no_argument, NULL, 0 }, |
| { factory_reset_str, no_argument, NULL, 0 }, |
| { NULL, 0, NULL, 0 } |
| }; |
| |
| std::string boot_event; |
| std::string value; |
| int opt = 0; |
| while ((opt = getopt_long(argc, argv, "hlpr:", long_options, &option_index)) != -1) { |
| switch (opt) { |
| // This case handles long options which have no single-character mapping. |
| case 0: { |
| const std::string option_name = long_options[option_index].name; |
| if (option_name == value_str) { |
| // |optarg| is an external variable set by getopt representing |
| // the option argument. |
| value = optarg; |
| } else if (option_name == boot_complete_str) { |
| RecordBootComplete(); |
| } else if (option_name == boot_reason_str) { |
| RecordBootReason(); |
| } else if (option_name == factory_reset_str) { |
| RecordFactoryReset(); |
| } else { |
| LOG(ERROR) << "Invalid option: " << option_name; |
| } |
| break; |
| } |
| |
| case 'h': { |
| ShowHelp(argv[0]); |
| break; |
| } |
| |
| case 'l': { |
| LogBootEvents(); |
| break; |
| } |
| |
| case 'p': { |
| PrintBootEvents(); |
| break; |
| } |
| |
| case 'r': { |
| // |optarg| is an external variable set by getopt representing |
| // the option argument. |
| boot_event = optarg; |
| break; |
| } |
| |
| default: { |
| DCHECK_EQ(opt, '?'); |
| |
| // |optopt| is an external variable set by getopt representing |
| // the value of the invalid option. |
| LOG(ERROR) << "Invalid option: " << optopt; |
| ShowHelp(argv[0]); |
| return EXIT_FAILURE; |
| } |
| } |
| } |
| |
| if (!boot_event.empty()) { |
| RecordBootEventFromCommandLine(boot_event, value); |
| } |
| |
| return 0; |
| } |