bootstat: Disambiguate boot time on encrypted devices.

This change introduces new metrics to discern boot time on encrypted devices:
* post_decrypt_time_elapsed
* boot_decryption_complete
* boot_complete_post_decrypt
* boot_complete_no_encryption

Bug: 27497357
Change-Id: I8d3a411029bd6a45f80589ff67c408593e133a87

7 files changed, 127 insertions, 31 deletions

diff --git a/bootstat/Android.mk b/bootstat/Android.mk
index c6349c1d6..3d027527f 100644
--- a/bootstat/Android.mk
+++ b/bootstat/Android.mk
@@ -20,32 +20,33 @@ bootstat_c_includes := external/gtest/include
 
 bootstat_lib_src_files := \
         boot_event_record_store.cpp \
-        event_log_list_builder.cpp
+        event_log_list_builder.cpp \
+        uptime_parser.cpp \
 
 bootstat_src_files := \
-        bootstat.cpp
+        bootstat.cpp \
 
 bootstat_test_src_files := \
         boot_event_record_store_test.cpp \
         event_log_list_builder_test.cpp \
-        testrunner.cpp
+        testrunner.cpp \
 
 bootstat_shared_libs := \
         libbase \
         libcutils \
-        liblog
+        liblog \
 
 bootstat_cflags := \
         -Wall \
         -Wextra \
-        -Werror
+        -Werror \
 
 bootstat_cppflags := \
-        -Wno-non-virtual-dtor
+        -Wno-non-virtual-dtor \
 
 bootstat_debug_cflags := \
         $(bootstat_cflags) \
-        -UNDEBUG
+        -UNDEBUG \
 
 # 524291 corresponds to sysui_histogram, from
 # frameworks/base/core/java/com/android/internal/logging/EventLogTags.logtags
diff --git a/bootstat/boot_event_record_store.cpp b/bootstat/boot_event_record_store.cpp
index 8282b406b..40254f866 100644
--- a/bootstat/boot_event_record_store.cpp
+++ b/bootstat/boot_event_record_store.cpp
@@ -24,6 +24,7 @@
 #include <utility>
 #include <android-base/file.h>
 #include <android-base/logging.h>
+#include "uptime_parser.h"
 
 namespace {
 
@@ -51,14 +52,7 @@ BootEventRecordStore::BootEventRecordStore() {
 }
 
 void BootEventRecordStore::AddBootEvent(const std::string& event) {
-  std::string uptime_str;
-  if (!android::base::ReadFileToString("/proc/uptime", &uptime_str)) {
-    LOG(ERROR) << "Failed to read /proc/uptime";
-  }
-
-  // Cast intentionally rounds down.
-  int32_t uptime = static_cast<int32_t>(strtod(uptime_str.c_str(), NULL));
-  AddBootEventWithValue(event, uptime);
+  AddBootEventWithValue(event, bootstat::ParseUptime());
 }
 
 // The implementation of AddBootEventValue makes use of the mtime file
diff --git a/bootstat/boot_event_record_store_test.cpp b/bootstat/boot_event_record_store_test.cpp
index 0d7bbb0b8..343f9d00b 100644
--- a/bootstat/boot_event_record_store_test.cpp
+++ b/bootstat/boot_event_record_store_test.cpp
@@ -25,6 +25,7 @@
 #include <android-base/test_utils.h>
 #include <gtest/gtest.h>
 #include <gmock/gmock.h>
+#include "uptime_parser.h"
 
 using testing::UnorderedElementsAreArray;
 
@@ -38,17 +39,6 @@ bool FuzzUptimeEquals(int32_t a, int32_t b) {
   return (abs(a - b) <= FUZZ_SECONDS);
 }
 
-// Returns the uptime as read from /proc/uptime, rounded down to an integer.
-int32_t ReadUptime() {
-  std::string uptime_str;
-  if (!android::base::ReadFileToString("/proc/uptime", &uptime_str)) {
-    return -1;
-  }
-
-  // Cast to int to round down.
-  return static_cast<int32_t>(strtod(uptime_str.c_str(), NULL));
-}
-
 // Recursively deletes the directory at |path|.
 void DeleteDirectory(const std::string& path) {
   typedef std::unique_ptr<DIR, decltype(&closedir)> ScopedDIR;
@@ -110,7 +100,7 @@ TEST_F(BootEventRecordStoreTest, AddSingleBootEvent) {
   BootEventRecordStore store;
   store.SetStorePath(GetStorePathForTesting());
 
-  int32_t uptime = ReadUptime();
+  time_t uptime = bootstat::ParseUptime();
   ASSERT_NE(-1, uptime);
 
   store.AddBootEvent("cenozoic");
@@ -125,7 +115,7 @@ TEST_F(BootEventRecordStoreTest, AddMultipleBootEvents) {
   BootEventRecordStore store;
   store.SetStorePath(GetStorePathForTesting());
 
-  int32_t uptime = ReadUptime();
+  time_t uptime = bootstat::ParseUptime();
   ASSERT_NE(-1, uptime);
 
   store.AddBootEvent("cretaceous");
diff --git a/bootstat/bootstat.cpp b/bootstat/bootstat.cpp
index c59a191dc..9214e6ddf 100644
--- a/bootstat/bootstat.cpp
+++ b/bootstat/bootstat.cpp
@@ -32,6 +32,7 @@
 #include <log/log.h>
 #include "boot_event_record_store.h"
 #include "event_log_list_builder.h"
+#include "uptime_parser.h"
 
 namespace {
 
@@ -174,6 +175,37 @@ int32_t BootReasonStrToEnum(const std::string& boot_reason) {
   return kUnknownBootReason;
 }
 
+// Records several metrics related to the time it takes to boot the device,
+// including disambiguating boot time on encrypted or non-encrypted devices.
+void RecordBootComplete() {
+  BootEventRecordStore boot_event_store;
+  time_t uptime = bootstat::ParseUptime();
+
+  BootEventRecordStore::BootEventRecord record;
+
+  // post_decrypt_time_elapsed is only logged on encrypted devices.
+  if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) {
+    // Log the amount of time elapsed until the device is decrypted, which
+    // includes the variable amount of time the user takes to enter the
+    // decryption password.
+    boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime);
+
+    // Subtract the decryption time to normalize the boot cycle timing.
+    time_t boot_complete = uptime - record.second;
+    boot_event_store.AddBootEventWithValue("boot_complete_post_decrypt",
+                                           boot_complete);
+
+
+  } else {
+    boot_event_store.AddBootEventWithValue("boot_complete_no_encryption",
+                                           uptime);
+  }
+
+  // Record the total time from device startup to boot complete, regardless of
+  // encryption state.
+  boot_event_store.AddBootEventWithValue("boot_complete", uptime);
+}
+
 // Records the boot_reason metric by querying the ro.boot.bootreason system
 // property.
 void RecordBootReason() {
@@ -229,6 +261,7 @@ int main(int argc, char **argv) {
   LOG(INFO) << "Service started: " << cmd_line;
 
   int option_index = 0;
+  static const char boot_complete_str[] = "record_boot_complete";
   static const char boot_reason_str[] = "record_boot_reason";
   static const char factory_reset_str[] = "record_time_since_factory_reset";
   static const struct option long_options[] = {
@@ -236,6 +269,7 @@ int main(int argc, char **argv) {
     { "log",             no_argument,       NULL,   'l' },
     { "print",           no_argument,       NULL,   'p' },
     { "record",          required_argument, NULL,   'r' },
+    { boot_complete_str, no_argument,       NULL,   0 },
     { boot_reason_str,   no_argument,       NULL,   0 },
     { factory_reset_str, no_argument,       NULL,   0 },
     { NULL,              0,                 NULL,   0 }
@@ -247,7 +281,9 @@ int main(int argc, char **argv) {
       // This case handles long options which have no single-character mapping.
       case 0: {
         const std::string option_name = long_options[option_index].name;
-        if (option_name == boot_reason_str) {
+        if (option_name == boot_complete_str) {
+          RecordBootComplete();
+        } else if (option_name == boot_reason_str) {
           RecordBootReason();
         } else if (option_name == factory_reset_str) {
           RecordFactoryReset();
diff --git a/bootstat/bootstat.rc b/bootstat/bootstat.rc
index 3c20fc826..ba8f81c9d 100644
--- a/bootstat/bootstat.rc
+++ b/bootstat/bootstat.rc
@@ -3,6 +3,14 @@
 on post-fs-data
     mkdir /data/misc/bootstat 0700 root root
 
+# Record the time at which the user has successfully entered the pin to decrypt
+# the device, /data is decrypted, and the system is entering the main boot phase.
+#
+# post-fs-data: /data is writable
+# property:init.svc.bootanim=running: The boot animation is running
+on post-fs-data && property:init.svc.bootanim=running
+    exec - root root -- /system/bin/bootstat -r post_decrypt_time_elapsed
+
 # The first marker, boot animation stopped, is considered the point at which
 # the user may interact with the device, so it is a good proxy for the boot
 # complete signal.
@@ -10,8 +18,8 @@ on post-fs-data
 # The second marker ensures an encrypted device is decrypted before logging
 # boot time data.
 on property:init.svc.bootanim=stopped && property:vold.decrypt=trigger_restart_framework
-    # Record boot_complete timing event.
-    exec - root root -- /system/bin/bootstat -r boot_complete
+    # Record boot_complete and related stats (decryption, etc).
+    exec - root root -- /system/bin/bootstat --record_boot_complete
 
     # Record the boot reason.
     exec - root root -- /system/bin/bootstat --record_boot_reason
diff --git a/bootstat/uptime_parser.cpp b/bootstat/uptime_parser.cpp
new file mode 100644
index 000000000..7c2034c3d
--- /dev/null
+++ b/bootstat/uptime_parser.cpp
@@ -0,0 +1,38 @@
+/*
+ * Copyright (C) 2016 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "uptime_parser.h"
+
+#include <time.h>
+#include <cstdlib>
+#include <string>
+#include <android-base/file.h>
+#include <android-base/logging.h>
+
+namespace bootstat {
+
+time_t ParseUptime() {
+  std::string uptime_str;
+  if (!android::base::ReadFileToString("/proc/uptime", &uptime_str)) {
+    PLOG(ERROR) << "Failed to read /proc/uptime";
+    return -1;
+  }
+
+  // Cast intentionally rounds down.
+  return static_cast<time_t>(strtod(uptime_str.c_str(), NULL));
+}
+
+}  // namespace bootstat
\ No newline at end of file
diff --git a/bootstat/uptime_parser.h b/bootstat/uptime_parser.h
new file mode 100644
index 000000000..756ae9b7c
--- /dev/null
+++ b/bootstat/uptime_parser.h
@@ -0,0 +1,29 @@
+/*
+ * Copyright (C) 2016 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef UPTIME_PARSER_H_
+#define UPTIME_PARSER_H_
+
+#include <time.h>
+
+namespace bootstat {
+
+// Returns the number of seconds the system has been on since reboot.
+time_t ParseUptime();
+
+}  // namespace bootstat
+
+#endif  // UPTIME_PARSER_H_
\ No newline at end of file