From 10377df9f88dcb6d5d1be9b1a989d677aa76ecc3 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 27 Mar 2019 08:10:41 -0700 Subject: [PATCH] init: ro.boottime.init.first_stage Add a property ro.boottime.init.first_stage to provide us a first stage init duration from start to exec completed in nanoseconds. For consistency, report nanoseconds duration for ro.boottime.init.selinux as well instead of milliseconds. Now also report consistently from start to exec completed instead of just the selinux load time. SideEffects: ro.boottime.init.selinux is reported to TRON and may alarm with the millionfold increase in precision. ro.boottime.init is now also consistent with ns precision. Test: inspect Bug: 124491153 Bug: 129780532 Change-Id: Iff4f1a3a1ab7ff0a309c278724c92da0832b9a69 --- bootstat/bootstat.cpp | 1 + init/README.md | 5 ++- init/first_stage_init.cpp | 5 +-- init/init.cpp | 37 ++++++++++++++++--- init/selinux.cpp | 9 ++--- .../property_info_serializer_test.cpp | 1 + 6 files changed, 44 insertions(+), 14 deletions(-) diff --git a/bootstat/bootstat.cpp b/bootstat/bootstat.cpp index 558e6c4b2..c091ff70a 100644 --- a/bootstat/bootstat.cpp +++ b/bootstat/bootstat.cpp @@ -1183,6 +1183,7 @@ void RecordBootComplete() { boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime_s.count()); RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init"); + RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.first_stage"); RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux"); RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait"); diff --git a/init/README.md b/init/README.md index 79c623720..c4505fe4c 100644 --- a/init/README.md +++ b/init/README.md @@ -695,8 +695,11 @@ Init records some boot timing information in system properties. > Time after boot in ns (via the CLOCK\_BOOTTIME clock) at which the first stage of init started. +`ro.boottime.init.first_stage` +> How long in ns it took to run first stage. + `ro.boottime.init.selinux` -> How long it took the first stage to initialize SELinux. +> How long in ns it took to run SELinux stage. `ro.boottime.init.cold_boot_wait` > How long init waited for ueventd's coldboot phase to end. diff --git a/init/first_stage_init.cpp b/init/first_stage_init.cpp index 8b95e3832..f069c5833 100644 --- a/init/first_stage_init.cpp +++ b/init/first_stage_init.cpp @@ -235,9 +235,8 @@ int FirstStageMain(int argc, char** argv) { SetInitAvbVersionInRecovery(); - static constexpr uint32_t kNanosecondsPerMillisecond = 1e6; - uint64_t start_ms = start_time.time_since_epoch().count() / kNanosecondsPerMillisecond; - setenv("INIT_STARTED_AT", std::to_string(start_ms).c_str(), 1); + setenv("FIRST_STAGE_STARTED_AT", std::to_string(start_time.time_since_epoch().count()).c_str(), + 1); const char* path = "/system/bin/init"; const char* args[] = {path, "selinux_setup", nullptr}; diff --git a/init/init.cpp b/init/init.cpp index c79e459eb..a18c2c8fb 100644 --- a/init/init.cpp +++ b/init/init.cpp @@ -35,6 +35,7 @@ #include #include #include +#include #include #include #include @@ -627,11 +628,40 @@ static void UmountDebugRamdisk() { } } +static void RecordStageBoottimes(const boot_clock::time_point& second_stage_start_time) { + int64_t first_stage_start_time_ns = -1; + static constexpr char first_stage_started_at[] = "FIRST_STAGE_STARTED_AT"; + if (auto first_stage_start_time_str = getenv(first_stage_started_at); + first_stage_start_time_str) { + property_set("ro.boottime.init", first_stage_start_time_str); + android::base::ParseInt(first_stage_start_time_str, &first_stage_start_time_ns); + } + unsetenv(first_stage_started_at); + + int64_t selinux_start_time_ns = -1; + static constexpr char selinux_started_at[] = "SELINUX_STARTED_AT"; + if (auto selinux_start_time_str = getenv(selinux_started_at); selinux_start_time_str) { + android::base::ParseInt(selinux_start_time_str, &selinux_start_time_ns); + } + unsetenv(selinux_started_at); + + if (selinux_start_time_ns == -1) return; + if (first_stage_start_time_ns == -1) return; + + property_set("ro.boottime.init.first_stage", + std::to_string(selinux_start_time_ns - first_stage_start_time_ns)); + property_set("ro.boottime.init.selinux", + std::to_string(second_stage_start_time.time_since_epoch().count() - + selinux_start_time_ns)); +} + int SecondStageMain(int argc, char** argv) { if (REBOOT_BOOTLOADER_ON_PANIC) { InstallRebootSignalHandlers(); } + boot_clock::time_point start_time = boot_clock::now(); + // We need to set up stdin/stdout/stderr again now that we're running in init's context. InitKernelLogging(argv, InitAborter); LOG(INFO) << "init second stage started!"; @@ -663,9 +693,8 @@ int SecondStageMain(int argc, char** argv) { // used by init as well as the current required properties. export_kernel_boot_props(); - // Make the time that init started available for bootstat to log. - property_set("ro.boottime.init", getenv("INIT_STARTED_AT")); - property_set("ro.boottime.init.selinux", getenv("INIT_SELINUX_TOOK")); + // Make the time that init stages started available for bootstat to log. + RecordStageBoottimes(start_time); // Set libavb version for Framework-only OTA match in Treble build. const char* avb_version = getenv("INIT_AVB_VERSION"); @@ -678,8 +707,6 @@ int SecondStageMain(int argc, char** argv) { } // Clean up our environment. - unsetenv("INIT_STARTED_AT"); - unsetenv("INIT_SELINUX_TOOK"); unsetenv("INIT_AVB_VERSION"); unsetenv("INIT_FORCE_DEBUGGABLE"); diff --git a/init/selinux.cpp b/init/selinux.cpp index c49dc9f60..f8971705d 100644 --- a/init/selinux.cpp +++ b/init/selinux.cpp @@ -431,8 +431,6 @@ bool LoadPolicy() { } void SelinuxInitialize() { - Timer t; - LOG(INFO) << "Loading SELinux policy"; if (!LoadPolicy()) { LOG(FATAL) << "Unable to load SELinux policy"; @@ -449,9 +447,6 @@ void SelinuxInitialize() { if (auto result = WriteFile("/sys/fs/selinux/checkreqprot", "0"); !result) { LOG(FATAL) << "Unable to write to /sys/fs/selinux/checkreqprot: " << result.error(); } - - // 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().count()).c_str(), 1); } } // namespace @@ -535,6 +530,8 @@ int SetupSelinux(char** argv) { InstallRebootSignalHandlers(); } + boot_clock::time_point start_time = boot_clock::now(); + // Set up SELinux, loading the SELinux policy. SelinuxSetupKernelLogging(); SelinuxInitialize(); @@ -547,6 +544,8 @@ int SetupSelinux(char** argv) { PLOG(FATAL) << "restorecon failed of /system/bin/init failed"; } + setenv("SELINUX_STARTED_AT", std::to_string(start_time.time_since_epoch().count()).c_str(), 1); + const char* path = "/system/bin/init"; const char* args[] = {path, "second_stage", nullptr}; execv(path, const_cast(args)); diff --git a/property_service/libpropertyinfoserializer/property_info_serializer_test.cpp b/property_service/libpropertyinfoserializer/property_info_serializer_test.cpp index f4845505c..33da1f132 100644 --- a/property_service/libpropertyinfoserializer/property_info_serializer_test.cpp +++ b/property_service/libpropertyinfoserializer/property_info_serializer_test.cpp @@ -585,6 +585,7 @@ TEST(propertyinfoserializer, RealProperties) { {"ro.boottime.imsdatadaemon", "u:object_r:boottime_prop:s0"}, {"ro.boottime.imsqmidaemon", "u:object_r:boottime_prop:s0"}, {"ro.boottime.init", "u:object_r:boottime_prop:s0"}, + {"ro.boottime.init.first_stage", "u:object_r:boottime_prop:s0"}, {"ro.boottime.init.cold_boot_wait", "u:object_r:boottime_prop:s0"}, {"ro.boottime.init.mount_all.default", "u:object_r:boottime_prop:s0"}, {"ro.boottime.init.selinux", "u:object_r:boottime_prop:s0"},