Merge "init: ro.boottime.init.first_stage"temp_b_131756210_stage-aosp-master

am: a6e6c7d966

Change-Id: Ib622f2277a1f38df31e3a3cd1ae08d699abf3475

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 <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");
 
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<char**>(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"},