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

@@ -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");
 

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.

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};

init/init.cpp

@@ -35,6 +35,7 @@
 #include <android-base/chrono_utils.h>
 #include <android-base/file.h>
 #include <android-base/logging.h>
+#include <android-base/parseint.h>
 #include <android-base/properties.h>
 #include <android-base/stringprintf.h>
 #include <android-base/strings.h>
@@ -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");
 

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<char**>(args));

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