Report Odrefresh compilation times in milliseconds

Currently we are reporting the compilation times for the boot
classpath for primary/secondary architecture and system server
in seconds, but since the values we have observed so far are
4~8 seconds for the former and 8~16 for the latter, we might
benefit from having a finer granularity. Hence, this commit
is producing the compilation time in milliseconds (alongside
the previous values in seconds, for a transition period).

Bug: 243009337
Test: atest ArtGtestTargetChroot (especially art_odrefresh_tests)
Change-Id: Ib78a2e778d364653a5c29dd3430bf99274ca9a5a

7 files changed, 75 insertions, 65 deletions

diff --git a/odrefresh/odr_metrics.cc b/odrefresh/odr_metrics.cc
index 33368b2a1d..a2ce51f65b 100644
--- a/odrefresh/odr_metrics.cc
+++ b/odrefresh/odr_metrics.cc
@@ -64,16 +64,16 @@ OdrMetrics::~OdrMetrics() {
   }
 }
 
-void OdrMetrics::SetCompilationTime(int32_t seconds) {
+void OdrMetrics::SetCompilationTime(int32_t millis) {
   switch (stage_) {
     case Stage::kPrimaryBootClasspath:
-      primary_bcp_compilation_seconds_ = seconds;
+      primary_bcp_compilation_millis_ = millis;
       break;
     case Stage::kSecondaryBootClasspath:
-      secondary_bcp_compilation_seconds_ = seconds;
+      secondary_bcp_compilation_millis_ = millis;
       break;
     case Stage::kSystemServerClasspath:
-      system_server_compilation_seconds_ = seconds;
+      system_server_compilation_millis_ = millis;
       break;
     case Stage::kCheck:
     case Stage::kComplete:
@@ -124,11 +124,11 @@ bool OdrMetrics::ToRecord(/*out*/OdrMetricsRecord* record) const {
   record->trigger = static_cast<uint32_t>(trigger_.value());
   record->stage_reached = static_cast<uint32_t>(stage_);
   record->status = static_cast<uint32_t>(status_);
-  record->primary_bcp_compilation_seconds = primary_bcp_compilation_seconds_;
-  record->secondary_bcp_compilation_seconds = secondary_bcp_compilation_seconds_;
-  record->system_server_compilation_seconds = system_server_compilation_seconds_;
   record->cache_space_free_start_mib = cache_space_free_start_mib_;
   record->cache_space_free_end_mib = cache_space_free_end_mib_;
+  record->primary_bcp_compilation_millis = primary_bcp_compilation_millis_;
+  record->secondary_bcp_compilation_millis = secondary_bcp_compilation_millis_;
+  record->system_server_compilation_millis = system_server_compilation_millis_;
   return true;
 }
 
diff --git a/odrefresh/odr_metrics.h b/odrefresh/odr_metrics.h
index cd80beffc5..7ebc148684 100644
--- a/odrefresh/odr_metrics.h
+++ b/odrefresh/odr_metrics.h
@@ -126,7 +126,7 @@ class OdrMetrics final {
   static int32_t GetFreeSpaceMiB(const std::string& path);
   static void WriteToFile(const std::string& path, const OdrMetrics* metrics);
 
-  void SetCompilationTime(int32_t seconds);
+  void SetCompilationTime(int32_t millis);
 
   const std::string cache_directory_;
   const std::string metrics_file_;
@@ -137,11 +137,11 @@ class OdrMetrics final {
   Stage stage_ = Stage::kUnknown;
   Status status_ = Status::kUnknown;
 
-  int32_t primary_bcp_compilation_seconds_ = 0;
-  int32_t secondary_bcp_compilation_seconds_ = 0;
-  int32_t system_server_compilation_seconds_ = 0;
   int32_t cache_space_free_start_mib_ = 0;
   int32_t cache_space_free_end_mib_ = 0;
+  int32_t primary_bcp_compilation_millis_ = 0;
+  int32_t secondary_bcp_compilation_millis_ = 0;
+  int32_t system_server_compilation_millis_ = 0;
 
   friend class ScopedOdrCompilationTimer;
 };
@@ -155,8 +155,8 @@ class ScopedOdrCompilationTimer final {
 
   ~ScopedOdrCompilationTimer() {
     auto elapsed_time = std::chrono::steady_clock::now() - start_;
-    auto elapsed_seconds = std::chrono::duration_cast<std::chrono::seconds>(elapsed_time);
-    metrics_.SetCompilationTime(static_cast<int32_t>(elapsed_seconds.count()));
+    auto elapsed_millis = std::chrono::duration_cast<std::chrono::milliseconds>(elapsed_time);
+    metrics_.SetCompilationTime(static_cast<int32_t>(elapsed_millis.count()));
   }
 
  private:
diff --git a/odrefresh/odr_metrics_record.cc b/odrefresh/odr_metrics_record.cc
index a5b4707f17..b8c2f80fea 100644
--- a/odrefresh/odr_metrics_record.cc
+++ b/odrefresh/odr_metrics_record.cc
@@ -84,14 +84,14 @@ android::base::Result<void> OdrMetricsRecord::ReadFromFile(const std::string& fi
   trigger = OR_RETURN(ReadInt32(metrics, "trigger"));
   stage_reached = OR_RETURN(ReadInt32(metrics, "stage_reached"));
   status = OR_RETURN(ReadInt32(metrics, "status"));
-  primary_bcp_compilation_seconds = OR_RETURN(
-      ReadInt32(metrics, "primary_bcp_compilation_seconds"));
-  secondary_bcp_compilation_seconds = OR_RETURN(
-      ReadInt32(metrics, "secondary_bcp_compilation_seconds"));
-  system_server_compilation_seconds = OR_RETURN(
-      ReadInt32(metrics, "system_server_compilation_seconds"));
   cache_space_free_start_mib = OR_RETURN(ReadInt32(metrics, "cache_space_free_start_mib"));
   cache_space_free_end_mib = OR_RETURN(ReadInt32(metrics, "cache_space_free_end_mib"));
+  primary_bcp_compilation_millis = OR_RETURN(
+      ReadInt32(metrics, "primary_bcp_compilation_millis"));
+  secondary_bcp_compilation_millis = OR_RETURN(
+      ReadInt32(metrics, "secondary_bcp_compilation_millis"));
+  system_server_compilation_millis = OR_RETURN(
+      ReadInt32(metrics, "system_server_compilation_millis"));
   return {};
 }
 
@@ -106,11 +106,11 @@ android::base::Result<void> OdrMetricsRecord::WriteToFile(const std::string& fil
   AddMetric(metrics, "trigger", trigger);
   AddMetric(metrics, "stage_reached", stage_reached);
   AddMetric(metrics, "status", status);
-  AddMetric(metrics, "primary_bcp_compilation_seconds", primary_bcp_compilation_seconds);
-  AddMetric(metrics, "secondary_bcp_compilation_seconds", secondary_bcp_compilation_seconds);
-  AddMetric(metrics, "system_server_compilation_seconds", system_server_compilation_seconds);
   AddMetric(metrics, "cache_space_free_start_mib", cache_space_free_start_mib);
   AddMetric(metrics, "cache_space_free_end_mib", cache_space_free_end_mib);
+  AddMetric(metrics, "primary_bcp_compilation_millis", primary_bcp_compilation_millis);
+  AddMetric(metrics, "secondary_bcp_compilation_millis", secondary_bcp_compilation_millis);
+  AddMetric(metrics, "system_server_compilation_millis", system_server_compilation_millis);
 
   tinyxml2::XMLError result = xml_document.SaveFile(filename.data(), /*compact=*/true);
   if (result == tinyxml2::XML_SUCCESS) {
diff --git a/odrefresh/odr_metrics_record.h b/odrefresh/odr_metrics_record.h
index 1bd7faa0e0..fa953374e4 100644
--- a/odrefresh/odr_metrics_record.h
+++ b/odrefresh/odr_metrics_record.h
@@ -30,7 +30,7 @@ namespace odrefresh {
 constexpr const char* kOdrefreshMetricsFile = "/data/misc/odrefresh/odrefresh-metrics.xml";
 
 // Initial OdrefreshMetrics version
-static constexpr int32_t kOdrefreshMetricsVersion = 1;
+static constexpr int32_t kOdrefreshMetricsVersion = 2;
 
 // MetricsRecord is a simpler container for Odrefresh metric values reported to statsd. The order
 // and types of fields here mirror definition of `OdrefreshReported` in
@@ -41,11 +41,11 @@ struct OdrMetricsRecord {
   int32_t trigger;
   int32_t stage_reached;
   int32_t status;
-  int32_t primary_bcp_compilation_seconds;
-  int32_t secondary_bcp_compilation_seconds;
-  int32_t system_server_compilation_seconds;
   int32_t cache_space_free_start_mib;
   int32_t cache_space_free_end_mib;
+  int32_t primary_bcp_compilation_millis;
+  int32_t secondary_bcp_compilation_millis;
+  int32_t system_server_compilation_millis;
 
   // Reads a `MetricsRecord` from an XML file.
   // Returns an error if the XML document was not found or parsed correctly.
diff --git a/odrefresh/odr_metrics_record_test.cc b/odrefresh/odr_metrics_record_test.cc
index d2cc59f541..fbb5b99063 100644
--- a/odrefresh/odr_metrics_record_test.cc
+++ b/odrefresh/odr_metrics_record_test.cc
@@ -21,6 +21,7 @@
 #include <fstream>
 
 #include "android-base/result-gmock.h"
+#include "android-base/stringprintf.h"
 #include "base/common_art_test.h"
 
 namespace art {
@@ -33,16 +34,18 @@ using android::base::testing::HasError;
 using android::base::testing::WithMessage;
 
 TEST_F(OdrMetricsRecordTest, HappyPath) {
-  const OdrMetricsRecord expected{.odrefresh_metrics_version = 0x1,
-                                  .art_apex_version = 0x01233456'789abcde,
-                                  .trigger = 0x01020304,
-                                  .stage_reached = 0x11121314,
-                                  .status = 0x21222324,
-                                  .primary_bcp_compilation_seconds = 0x31323334,
-                                  .secondary_bcp_compilation_seconds = 0x41424344,
-                                  .system_server_compilation_seconds = 0x51525354,
-                                  .cache_space_free_start_mib = 0x61626364,
-                                  .cache_space_free_end_mib = 0x71727374};
+  const OdrMetricsRecord expected{
+    .odrefresh_metrics_version = art::odrefresh::kOdrefreshMetricsVersion,
+    .art_apex_version = 0x01233456'789abcde,
+    .trigger = 0x01020304,
+    .stage_reached = 0x11121314,
+    .status = 0x21222324,
+    .cache_space_free_start_mib = 0x61626364,
+    .cache_space_free_end_mib = 0x71727374,
+    .primary_bcp_compilation_millis = 0x31323334,
+    .secondary_bcp_compilation_millis = 0x41424344,
+    .system_server_compilation_millis = 0x51525354
+  };
 
   ScratchDir dir(/*keep_files=*/false);
   std::string file_path = dir.GetPath() + "/metrics-record.xml";
@@ -56,11 +59,11 @@ TEST_F(OdrMetricsRecordTest, HappyPath) {
   ASSERT_EQ(expected.trigger, actual.trigger);
   ASSERT_EQ(expected.stage_reached, actual.stage_reached);
   ASSERT_EQ(expected.status, actual.status);
-  ASSERT_EQ(expected.primary_bcp_compilation_seconds, actual.primary_bcp_compilation_seconds);
-  ASSERT_EQ(expected.secondary_bcp_compilation_seconds, actual.secondary_bcp_compilation_seconds);
-  ASSERT_EQ(expected.system_server_compilation_seconds, actual.system_server_compilation_seconds);
   ASSERT_EQ(expected.cache_space_free_start_mib, actual.cache_space_free_start_mib);
   ASSERT_EQ(expected.cache_space_free_end_mib, actual.cache_space_free_end_mib);
+  ASSERT_EQ(expected.primary_bcp_compilation_millis, actual.primary_bcp_compilation_millis);
+  ASSERT_EQ(expected.secondary_bcp_compilation_millis, actual.secondary_bcp_compilation_millis);
+  ASSERT_EQ(expected.system_server_compilation_millis, actual.system_server_compilation_millis);
   ASSERT_EQ(0, memcmp(&expected, &actual, sizeof(expected)));
 }
 
@@ -113,8 +116,11 @@ TEST_F(OdrMetricsRecordTest, UnexpectedOdrefreshMetricsVersion) {
   ofs.close();
 
   OdrMetricsRecord record{};
+  std::string expected_error = android::base::StringPrintf(
+      "odrefresh_metrics_version 0 is different than expected (%d)",
+      kOdrefreshMetricsVersion);
   ASSERT_THAT(record.ReadFromFile(file_path),
-              HasError(WithMessage("odrefresh_metrics_version 0 is different than expected (1)")));
+              HasError(WithMessage(expected_error)));
 }
 
 TEST_F(OdrMetricsRecordTest, UnexpectedType) {
@@ -129,11 +135,11 @@ TEST_F(OdrMetricsRecordTest, UnexpectedType) {
   ofs << "<trigger>16909060</trigger>";
   ofs << "<stage_reached>286397204</stage_reached>";
   ofs << "<status>abcd</status>";  // It should be an int32.
-  ofs << "<primary_bcp_compilation_seconds>825373492</primary_bcp_compilation_seconds>";
-  ofs << "<secondary_bcp_compilation_seconds>1094861636</secondary_bcp_compilation_seconds>";
-  ofs << "<system_server_compilation_seconds>1364349780</system_server_compilation_seconds>";
   ofs << "<cache_space_free_start_mib>1633837924</cache_space_free_start_mib>";
   ofs << "<cache_space_free_end_mib>1903326068</cache_space_free_end_mib>";
+  ofs << "<primary_bcp_compilation_millis>825373492</primary_bcp_compilation_millis>";
+  ofs << "<secondary_bcp_compilation_millis>1094861636</secondary_bcp_compilation_millis>";
+  ofs << "<system_server_compilation_millis>1364349780</system_server_compilation_millis>";
   ofs << "</odrefresh_metrics>";
   ofs.close();
 
diff --git a/odrefresh/odr_metrics_test.cc b/odrefresh/odr_metrics_test.cc
index 4f73aef0ce..f222caaf2e 100644
--- a/odrefresh/odr_metrics_test.cc
+++ b/odrefresh/odr_metrics_test.cc
@@ -159,10 +159,10 @@ TEST_F(OdrMetricsTest, TimeValuesAreRecorded) {
   EXPECT_TRUE(metrics.ToRecord(&record));
   EXPECT_EQ(OdrMetrics::Stage::kPrimaryBootClasspath,
             enum_cast<OdrMetrics::Stage>(record.stage_reached));
-  EXPECT_NE(0, record.primary_bcp_compilation_seconds);
-  EXPECT_GT(10, record.primary_bcp_compilation_seconds);
-  EXPECT_EQ(0, record.secondary_bcp_compilation_seconds);
-  EXPECT_EQ(0, record.system_server_compilation_seconds);
+  EXPECT_NE(0, record.primary_bcp_compilation_millis);
+  EXPECT_GT(10'000, record.primary_bcp_compilation_millis);
+  EXPECT_EQ(0, record.secondary_bcp_compilation_millis);
+  EXPECT_EQ(0, record.system_server_compilation_millis);
 
   // Secondary boot classpath compilation time.
   {
@@ -173,10 +173,10 @@ TEST_F(OdrMetricsTest, TimeValuesAreRecorded) {
   EXPECT_TRUE(metrics.ToRecord(&record));
   EXPECT_EQ(OdrMetrics::Stage::kSecondaryBootClasspath,
             enum_cast<OdrMetrics::Stage>(record.stage_reached));
-  EXPECT_NE(0, record.primary_bcp_compilation_seconds);
-  EXPECT_NE(0, record.secondary_bcp_compilation_seconds);
-  EXPECT_GT(10, record.secondary_bcp_compilation_seconds);
-  EXPECT_EQ(0, record.system_server_compilation_seconds);
+  EXPECT_NE(0, record.primary_bcp_compilation_millis);
+  EXPECT_NE(0, record.secondary_bcp_compilation_millis);
+  EXPECT_GT(10'000, record.secondary_bcp_compilation_millis);
+  EXPECT_EQ(0, record.system_server_compilation_millis);
 
   // system_server classpath compilation time.
   {
@@ -187,10 +187,10 @@ TEST_F(OdrMetricsTest, TimeValuesAreRecorded) {
   EXPECT_TRUE(metrics.ToRecord(&record));
   EXPECT_EQ(OdrMetrics::Stage::kSystemServerClasspath,
             enum_cast<OdrMetrics::Stage>(record.stage_reached));
-  EXPECT_NE(0, record.primary_bcp_compilation_seconds);
-  EXPECT_NE(0, record.secondary_bcp_compilation_seconds);
-  EXPECT_NE(0, record.system_server_compilation_seconds);
-  EXPECT_GT(10, record.system_server_compilation_seconds);
+  EXPECT_NE(0, record.primary_bcp_compilation_millis);
+  EXPECT_NE(0, record.secondary_bcp_compilation_millis);
+  EXPECT_NE(0, record.system_server_compilation_millis);
+  EXPECT_GT(10'000, record.system_server_compilation_millis);
 }
 
 TEST_F(OdrMetricsTest, CacheSpaceValuesAreUpdated) {
diff --git a/odrefresh/odr_statslog_android.cc b/odrefresh/odr_statslog_android.cc
index 831d1d1315..ee173d4b3d 100644
--- a/odrefresh/odr_statslog_android.cc
+++ b/odrefresh/odr_statslog_android.cc
@@ -146,16 +146,20 @@ bool UploadStatsIfAvailable(/*out*/std::string* error_msg) {
 
   // Write values to statsd. The order of values passed is the same as the order of the
   // fields in OdrMetricsRecord.
-  int bytes_written = art::metrics::statsd::stats_write(metrics::statsd::ODREFRESH_REPORTED,
-                                                        record.art_apex_version,
-                                                        record.trigger,
-                                                        record.stage_reached,
-                                                        record.status,
-                                                        record.primary_bcp_compilation_seconds,
-                                                        record.secondary_bcp_compilation_seconds,
-                                                        record.system_server_compilation_seconds,
-                                                        record.cache_space_free_start_mib,
-                                                        record.cache_space_free_end_mib);
+  int bytes_written = art::metrics::statsd::stats_write(
+      metrics::statsd::ODREFRESH_REPORTED,
+      record.art_apex_version,
+      record.trigger,
+      record.stage_reached,
+      record.status,
+      record.primary_bcp_compilation_millis / 1000,
+      record.secondary_bcp_compilation_millis / 1000,
+      record.system_server_compilation_millis / 1000,
+      record.cache_space_free_start_mib,
+      record.cache_space_free_end_mib,
+      record.primary_bcp_compilation_millis,
+      record.secondary_bcp_compilation_millis,
+      record.system_server_compilation_millis);
   if (bytes_written <= 0) {
     *error_msg = android::base::StringPrintf("stats_write returned %d", bytes_written);
     return false;