From 331cf2fb7c16b5b25064f8d2f00284105a9b413f Mon Sep 17 00:00:00 2001 From: Elliott Hughes Date: Tue, 29 Nov 2016 19:20:58 +0000 Subject: [PATCH] Replace the "coldboot" timeout with a property. Also rename init's existing boot-time related properties so they're all "ro.*" properties. Example result: # Three properties showing when init started... [ro.boottime.init]: [5294587604] # ...how long it waited for ueventd... [ro.boottime.init.cold_boot_wait]: [646956470] # ...and how long SELinux initialization took... [ro.boottime.init.selinux]: [45742921] # Plus one property for each service, showing when it first started. [ro.boottime.InputEventFind]: [10278767840] [ro.boottime.adbd]: [8359267180] [ro.boottime.atfwd]: [10338554773] [ro.boottime.audioserver]: [10298157478] [ro.boottime.bootanim]: [9323670089] [ro.boottime.cameraserver]: [10299402321] [ro.boottime.cnd]: [10335931856] [ro.boottime.debuggerd]: [7001352774] [ro.boottime.debuggerd64]: [7002261785] [ro.boottime.drm]: [10301082113] [ro.boottime.fingerprintd]: [10331443314] [ro.boottime.flash-nanohub-fw]: [6995265534] [ro.boottime.gatekeeperd]: [10340355242] [ro.boottime.healthd]: [7856893380] [ro.boottime.hwservicemanager]: [7856051088] [ro.boottime.imscmservice]: [10290530758] [ro.boottime.imsdatadaemon]: [10358136702] [ro.boottime.imsqmidaemon]: [10289084872] [ro.boottime.installd]: [10303296020] [ro.boottime.irsc_util]: [10279807632] [ro.boottime.keystore]: [10305034093] [ro.boottime.lmkd]: [7863506714] [ro.boottime.loc_launcher]: [10324525241] [ro.boottime.logd]: [6526221633] [ro.boottime.logd-reinit]: [7850662702] [ro.boottime.mcfg-sh]: [10337268315] [ro.boottime.media]: [10312152687] [ro.boottime.mediacodec]: [10306852530] [ro.boottime.mediadrm]: [10308707999] [ro.boottime.mediaextractor]: [10310681177] [ro.boottime.msm_irqbalance]: [7862451974] [ro.boottime.netd]: [10313523104] [ro.boottime.netmgrd]: [10285009351] [ro.boottime.oem_qmi_server]: [10293329092] [ro.boottime.per_mgr]: [7857915776] [ro.boottime.per_proxy]: [8335121605] [ro.boottime.perfd]: [10283443101] [ro.boottime.qcamerasvr]: [10329644772] [ro.boottime.qmuxd]: [10282346643] [ro.boottime.qseecomd]: [6855708593] [ro.boottime.qti]: [10286196851] [ro.boottime.ril-daemon]: [10314933677] [ro.boottime.rmt_storage]: [7859105047] [ro.boottime.servicemanager]: [7864555881] [ro.boottime.ss_ramdump]: [8337634938] [ro.boottime.ssr_setup]: [8336268324] [ro.boottime.surfaceflinger]: [7866921402] [ro.boottime.thermal-engine]: [10281249924] [ro.boottime.time_daemon]: [10322006542] [ro.boottime.ueventd]: [5618663938] [ro.boottime.vold]: [7003493920] [ro.boottime.wificond]: [10316641073] [ro.boottime.wpa_supplicant]: [18959816881] [ro.boottime.zygote]: [10295295029] [ro.boottime.zygote_secondary]: [10296637269] Bug: http://b/31800756 Test: boots Change-Id: I094cce0c1bab9406d950ca94212689dc2e15dba5 --- init/action.cpp | 2 +- init/builtins.cpp | 10 +++---- init/devices.cpp | 4 +-- init/init.cpp | 35 +++++++++++++++--------- init/init_parser.cpp | 2 +- init/property_service.cpp | 56 +++++++++++++++++++-------------------- init/readme.txt | 23 +++++++++++----- init/service.cpp | 11 +++----- init/signal_handler.cpp | 1 - init/util.cpp | 21 +++++++++++++++ init/util.h | 15 +++++++++-- 11 files changed, 114 insertions(+), 66 deletions(-) diff --git a/init/action.cpp b/init/action.cpp index 0ea7e1479..65bf29277 100644 --- a/init/action.cpp +++ b/init/action.cpp @@ -121,7 +121,7 @@ void Action::ExecuteCommand(const Command& command) const { Timer t; int result = command.InvokeFunc(); - double duration_ms = t.duration() * 1000; + double duration_ms = t.duration_s() * 1000; // Any action longer than 50ms will be warned to user as slow operation if (duration_ms > 50.0 || android::base::GetMinimumLogSeverity() <= android::base::DEBUG) { diff --git a/init/builtins.cpp b/init/builtins.cpp index 6d58754a7..76e3d6e33 100644 --- a/init/builtins.cpp +++ b/init/builtins.cpp @@ -146,8 +146,7 @@ static int wipe_data_via_recovery(const std::string& reason) { LOG(ERROR) << "failed to set bootloader message: " << err; return -1; } - android_reboot(ANDROID_RB_RESTART2, 0, "recovery"); - while (1) { pause(); } // never reached + reboot("recovery"); } static void unmount_and_fsck(const struct mntent *entry) { @@ -727,7 +726,7 @@ static int do_powerctl(const std::vector& args) { ServiceManager::GetInstance().ForEachService( [] (Service* s) { s->Terminate(); }); - while (t.duration() < delay) { + while (t.duration_s() < delay) { ServiceManager::GetInstance().ReapAnyOutstandingChildren(); int service_count = 0; @@ -751,11 +750,10 @@ static int do_powerctl(const std::vector& args) { // Wait a bit before recounting the number or running services. std::this_thread::sleep_for(50ms); } - LOG(VERBOSE) << "Terminating running services took " << t.duration() << " seconds"; + LOG(VERBOSE) << "Terminating running services took " << t; } - return android_reboot_with_callback(cmd, 0, reboot_target, - callback_on_ro_remount); + return android_reboot_with_callback(cmd, 0, reboot_target, callback_on_ro_remount); } static int do_trigger(const std::vector& args) { diff --git a/init/devices.cpp b/init/devices.cpp index 2db24b700..6af237cf9 100644 --- a/init/devices.cpp +++ b/init/devices.cpp @@ -868,7 +868,7 @@ static void handle_firmware_event(uevent* uevent) { if (pid == 0) { Timer t; process_firmware_event(uevent); - LOG(INFO) << "loading " << uevent->path << " took " << t.duration() << "s"; + LOG(INFO) << "loading " << uevent->path << " took " << t; _exit(EXIT_SUCCESS); } else if (pid == -1) { PLOG(ERROR) << "could not fork to process firmware event for " << uevent->firmware; @@ -1043,7 +1043,7 @@ void device_init() { coldboot("/sys/block"); coldboot("/sys/devices"); close(open(COLDBOOT_DONE, O_WRONLY|O_CREAT|O_CLOEXEC, 0000)); - LOG(INFO) << "Coldboot took " << t.duration() << "s."; + LOG(INFO) << "Coldboot took " << t; } int get_device_fd() { diff --git a/init/init.cpp b/init/init.cpp index ef6f37c0e..95cb62fea 100644 --- a/init/init.cpp +++ b/init/init.cpp @@ -43,7 +43,6 @@ #include #include #include -#include #include #include #include @@ -163,14 +162,21 @@ static int wait_for_coldboot_done_action(const std::vector& args) { Timer t; LOG(VERBOSE) << "Waiting for " COLDBOOT_DONE "..."; - // Any longer than 1s is an unreasonable length of time to delay booting. - // If you're hitting this timeout, check that you didn't make your - // sepolicy regular expressions too expensive (http://b/19899875). - if (wait_for_file(COLDBOOT_DONE, 1s)) { + + // Historically we had a 1s timeout here because we weren't otherwise + // tracking boot time, and many OEMs made their sepolicy regular + // expressions too expensive (http://b/19899875). + + // Now we're tracking boot time, just log the time taken to a system + // property. We still panic if it takes more than a minute though, + // because any build that slow isn't likely to boot at all, and we'd + // rather any test lab devices fail back to the bootloader. + if (wait_for_file(COLDBOOT_DONE, 60s) < 0) { LOG(ERROR) << "Timed out waiting for " COLDBOOT_DONE; + panic(); } - LOG(VERBOSE) << "Waiting for " COLDBOOT_DONE " took " << t.duration() << "s."; + property_set("ro.boottime.init.cold_boot_wait", std::to_string(t.duration_ns()).c_str()); return 0; } @@ -409,9 +415,8 @@ static int audit_callback(void *data, security_class_t /*cls*/, char *buf, size_ } static void security_failure() { - LOG(ERROR) << "Security failure; rebooting into recovery mode..."; - android_reboot(ANDROID_RB_RESTART2, 0, "recovery"); - while (true) { pause(); } // never reached + LOG(ERROR) << "Security failure..."; + panic(); } static void selinux_initialize(bool in_kernel_domain) { @@ -443,8 +448,8 @@ static void selinux_initialize(bool in_kernel_domain) { security_failure(); } - LOG(INFO) << "(Initializing SELinux " << (is_enforcing ? "enforcing" : "non-enforcing") - << " took " << t.duration() << "s.)"; + // init's first stage can't set properties, so pass the time to the second stage. + setenv("INIT_SELINUX_TOOK", std::to_string(t.duration_ns()).c_str(), 1); } else { selinux_init_all_handles(); } @@ -650,7 +655,13 @@ int main(int argc, char** argv) { export_kernel_boot_props(); // Make the time that init started available for bootstat to log. - property_set("init.start", getenv("INIT_STARTED_AT")); + property_set("ro.boottime.init", getenv("INIT_STARTED_AT")); + property_set("ro.boottime.init.selinux", getenv("INIT_SELINUX_TOOK")); + + // Clean up our environment. + unsetenv("INIT_SECOND_STAGE"); + unsetenv("INIT_STARTED_AT"); + unsetenv("INIT_SELINUX_TOOK"); // Now set up SELinux for second stage. selinux_initialize(false); diff --git a/init/init_parser.cpp b/init/init_parser.cpp index d017390ce..406b33914 100644 --- a/init/init_parser.cpp +++ b/init/init_parser.cpp @@ -110,7 +110,7 @@ bool Parser::ParseConfigFile(const std::string& path) { // Nexus 9 boot time, so it's disabled by default. if (false) DumpState(); - LOG(VERBOSE) << "(Parsing " << path << " took " << t.duration() << "s.)"; + LOG(VERBOSE) << "(Parsing " << path << " took " << t << ".)"; return true; } diff --git a/init/property_service.cpp b/init/property_service.cpp index e19829765..aed84386d 100644 --- a/init/property_service.cpp +++ b/init/property_service.cpp @@ -169,11 +169,18 @@ bool is_legal_property_name(const std::string &name) return true; } -static int property_set_impl(const char* name, const char* value) { +int property_set(const char* name, const char* value) { size_t valuelen = strlen(value); - if (!is_legal_property_name(name)) return -1; - if (valuelen >= PROP_VALUE_MAX) return -1; + if (!is_legal_property_name(name)) { + LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: bad name"; + return -1; + } + if (valuelen >= PROP_VALUE_MAX) { + LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: " + << "value too long"; + return -1; + } if (strcmp("selinux.restorecon_recursive", name) == 0 && valuelen > 0) { if (restorecon(value, SELINUX_ANDROID_RESTORECON_RECURSE) != 0) { @@ -182,49 +189,42 @@ static int property_set_impl(const char* name, const char* value) { } prop_info* pi = (prop_info*) __system_property_find(name); - - if(pi != 0) { - /* ro.* properties may NEVER be modified once set */ - if(!strncmp(name, "ro.", 3)) return -1; + if (pi != nullptr) { + // ro.* properties are actually "write-once". + if (!strncmp(name, "ro.", 3)) { + LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: " + << "property already set"; + return -1; + } __system_property_update(pi, value, valuelen); } else { int rc = __system_property_add(name, strlen(name), value, valuelen); if (rc < 0) { + LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed: " + << "__system_property_add failed"; return rc; } } - /* If name starts with "net." treat as a DNS property. */ + + // If name starts with "net." treat as a DNS property. if (strncmp("net.", name, strlen("net.")) == 0) { if (strcmp("net.change", name) == 0) { return 0; } - /* - * The 'net.change' property is a special property used track when any - * 'net.*' property name is updated. It is _ONLY_ updated here. Its value - * contains the last updated 'net.*' property. - */ + // The 'net.change' property is a special property used track when any + // 'net.*' property name is updated. It is _ONLY_ updated here. Its value + // contains the last updated 'net.*' property. property_set("net.change", name); - } else if (persistent_properties_loaded && - strncmp("persist.", name, strlen("persist.")) == 0) { - /* - * Don't write properties to disk until after we have read all default properties - * to prevent them from being overwritten by default values. - */ + } else if (persistent_properties_loaded && strncmp("persist.", name, strlen("persist.")) == 0) { + // Don't write properties to disk until after we have read all default properties + // to prevent them from being overwritten by default values. write_persistent_property(name, value); } property_changed(name, value); return 0; } -int property_set(const char* name, const char* value) { - int rc = property_set_impl(name, value); - if (rc == -1) { - LOG(ERROR) << "property_set(\"" << name << "\", \"" << value << "\") failed"; - } - return rc; -} - static void handle_property_set_fd() { prop_msg msg; @@ -388,7 +388,7 @@ static void load_properties_from_file(const char* filename, const char* filter) } data.push_back('\n'); load_properties(&data[0], filter); - LOG(VERBOSE) << "(Loading properties from " << filename << " took " << t.duration() << "s.)"; + LOG(VERBOSE) << "(Loading properties from " << filename << " took " << t << ".)"; } static void load_persistent_properties() { diff --git a/init/readme.txt b/init/readme.txt index 7e9d21b69..7549e3c03 100644 --- a/init/readme.txt +++ b/init/readme.txt @@ -440,16 +440,27 @@ Properties Init provides information about the services that it is responsible for via the below properties. -init.start - Time after boot in ns (via the CLOCK_BOOTTIME clock) at which the first - stage of init started. - init.svc. State of a named service ("stopped", "stopping", "running", "restarting") -init.svc..start + +Boot timing +----------- +Init records some boot timing information in system properties. + +ro.boottime.init + Time after boot in ns (via the CLOCK_BOOTTIME clock) at which the first + stage of init started. + +ro.boottime.init.selinux + How long it took the first stage to initialize SELinux. + +ro.boottime.init.cold_boot_wait + How long init waited for ueventd's coldboot phase to end. + +ro.boottime. Time after boot in ns (via the CLOCK_BOOTTIME clock) that the service was - most recently started. + first started. Bootcharting diff --git a/init/service.cpp b/init/service.cpp index 1f53a1ba3..4b9724ddf 100644 --- a/init/service.cpp +++ b/init/service.cpp @@ -36,7 +36,6 @@ #include #include #include -#include #include #include @@ -190,9 +189,9 @@ void Service::NotifyStateChange(const std::string& new_state) const { property_set(prop_name.c_str(), new_state.c_str()); if (new_state == "running") { - prop_name += ".start"; uint64_t start_ns = time_started_.time_since_epoch().count(); - property_set(prop_name.c_str(), StringPrintf("%" PRIu64, start_ns).c_str()); + property_set(StringPrintf("ro.boottime.%s", name_.c_str()).c_str(), + StringPrintf("%" PRIu64, start_ns).c_str()); } } @@ -283,10 +282,8 @@ bool Service::Reap() { if ((flags_ & SVC_CRITICAL) && !(flags_ & SVC_RESTART)) { if (now < time_crashed_ + 4min) { if (++crash_count_ > 4) { - LOG(ERROR) << "critical process '" << name_ << "' exited 4 times in 4 minutes; " - << "rebooting into recovery mode"; - android_reboot(ANDROID_RB_RESTART2, 0, "recovery"); - return false; + LOG(ERROR) << "critical process '" << name_ << "' exited 4 times in 4 minutes"; + panic(); } } else { time_crashed_ = now; diff --git a/init/signal_handler.cpp b/init/signal_handler.cpp index 0dea3e065..1041b82d0 100644 --- a/init/signal_handler.cpp +++ b/init/signal_handler.cpp @@ -24,7 +24,6 @@ #include #include -#include #include #include diff --git a/init/util.cpp b/init/util.cpp index 5205ea094..38e3b8d82 100644 --- a/init/util.cpp +++ b/init/util.cpp @@ -41,6 +41,8 @@ #include #include #include + +#include /* for ANDROID_SOCKET_* */ #include @@ -472,3 +474,22 @@ bool expand_props(const std::string& src, std::string* dst) { return true; } + +void reboot(const char* destination) { + android_reboot(ANDROID_RB_RESTART2, 0, destination); + // We're init, so android_reboot will actually have been a syscall so there's nothing + // to wait for. If android_reboot returns, just abort so that the kernel will reboot + // itself when init dies. + PLOG(FATAL) << "reboot failed"; + abort(); +} + +void panic() { + LOG(ERROR) << "panic: rebooting to bootloader"; + reboot("bootloader"); +} + +std::ostream& operator<<(std::ostream& os, const Timer& t) { + os << t.duration_s() << " seconds"; + return os; +} diff --git a/init/util.h b/init/util.h index d56da39b5..4b5436145 100644 --- a/init/util.h +++ b/init/util.h @@ -21,8 +21,9 @@ #include #include -#include #include +#include +#include #define COLDBOOT_DONE "/dev/.coldboot_done" @@ -51,15 +52,21 @@ class Timer { Timer() : start_(boot_clock::now()) { } - double duration() { + double duration_s() const { typedef std::chrono::duration double_duration; return std::chrono::duration_cast(boot_clock::now() - start_).count(); } + int64_t duration_ns() const { + return (boot_clock::now() - start_).count(); + } + private: boot_clock::time_point start_; }; +std::ostream& operator<<(std::ostream& os, const Timer& t); + unsigned int decode_uid(const char *s); int mkdir_recursive(const char *pathname, mode_t mode); @@ -72,4 +79,8 @@ int restorecon(const char *pathname, int flags = 0); std::string bytes_to_hex(const uint8_t *bytes, size_t bytes_len); bool is_dir(const char* pathname); bool expand_props(const std::string& src, std::string* dst); + +void reboot(const char* destination) __attribute__((__noreturn__)); +void panic() __attribute__((__noreturn__)); + #endif