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
diff --git a/init/README.md b/init/README.md
index 79c6237..c4505fe 100644
--- a/init/README.md
+++ b/init/README.md
@@ -695,8 +695,11 @@
> 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 8b95e38..f069c58 100644
--- a/init/first_stage_init.cpp
+++ b/init/first_stage_init.cpp
@@ -235,9 +235,8 @@
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 c79e459..a18c2c8 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 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 @@
// 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 @@
}
// 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 c49dc9f..f897170 100644
--- a/init/selinux.cpp
+++ b/init/selinux.cpp
@@ -431,8 +431,6 @@
}
void SelinuxInitialize() {
- Timer t;
-
LOG(INFO) << "Loading SELinux policy";
if (!LoadPolicy()) {
LOG(FATAL) << "Unable to load SELinux policy";
@@ -449,9 +447,6 @@
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 @@
InstallRebootSignalHandlers();
}
+ boot_clock::time_point start_time = boot_clock::now();
+
// Set up SELinux, loading the SELinux policy.
SelinuxSetupKernelLogging();
SelinuxInitialize();
@@ -547,6 +544,8 @@
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));