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"},