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
diff --git a/odrefresh/odr_metrics.cc b/odrefresh/odr_metrics.cc
index 33368b2..a2ce51f 100644
--- a/odrefresh/odr_metrics.cc
+++ b/odrefresh/odr_metrics.cc
@@ -64,16 +64,16 @@
}
}
-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 @@
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 cd80bef..7ebc148 100644
--- a/odrefresh/odr_metrics.h
+++ b/odrefresh/odr_metrics.h
@@ -126,7 +126,7 @@
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 @@
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 @@
~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 a5b4707..b8c2f80 100644
--- a/odrefresh/odr_metrics_record.cc
+++ b/odrefresh/odr_metrics_record.cc
@@ -84,14 +84,14 @@
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 @@
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 1bd7faa..fa95337 100644
--- a/odrefresh/odr_metrics_record.h
+++ b/odrefresh/odr_metrics_record.h
@@ -30,7 +30,7 @@
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 @@
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 d2cc59f..fbb5b99 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::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 @@
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 @@
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 @@
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 4f73aef..f222caa 100644
--- a/odrefresh/odr_metrics_test.cc
+++ b/odrefresh/odr_metrics_test.cc
@@ -159,10 +159,10 @@
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 @@
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 @@
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 831d1d1..ee173d4 100644
--- a/odrefresh/odr_statslog_android.cc
+++ b/odrefresh/odr_statslog_android.cc
@@ -146,16 +146,20 @@
// 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;