Use better histogram parameters for duration metrics
In the current code this is capped at 20 minutes which is not helpful
as we're interested in data for devices that take much longer to
update. Instead, use one year for UpdateDuration and one month for
UpdateDurationUptime. Also move the code that sends the metric into
PayloadState to better conform with newly added code.
Also rename the metrics to they have the suffix Minutes. E.g. the new
metric names are
Installer.UpdateDurationMinutes
Installer.UpdateDurationUptimeMinutes
Also add unit test for utils::FormatTimeDelta().
BUG=None
TEST=Unit tests, look at chrome://histogram
Change-Id: I8581ec111f9833bdd72f10888c9626f40779f8b9
Reviewed-on: https://gerrit.chromium.org/gerrit/48558
Commit-Queue: David Zeuthen <zeuthen@chromium.org>
Reviewed-by: David Zeuthen <zeuthen@chromium.org>
Tested-by: David Zeuthen <zeuthen@chromium.org>
diff --git a/payload_state.cc b/payload_state.cc
index bae21b9..77652a7 100644
--- a/payload_state.cc
+++ b/payload_state.cc
@@ -143,6 +143,7 @@
ReportBytesDownloadedMetrics();
ReportUpdateUrlSwitchesMetric();
ReportRebootMetrics();
+ ReportDurationMetrics();
}
void PayloadState::UpdateFailed(ActionExitCode error) {
@@ -668,8 +669,8 @@
LOG(ERROR) << "The UpdateTimestampStart value ("
<< utils::ToString(stored_time)
<< ") in persisted state is "
- << duration_according_to_stored_time.InSeconds()
- << " seconds in the future. Resetting.";
+ << utils::FormatTimeDelta(duration_according_to_stored_time)
+ << " in the future. Resetting.";
stored_time = now;
}
@@ -717,10 +718,10 @@
TimeDelta diff = GetUpdateDuration() - stored_delta;
if (diff < -kDurationSlack) {
LOG(ERROR) << "The UpdateDurationUptime value ("
- << stored_delta.InSeconds() << " seconds"
+ << utils::FormatTimeDelta(stored_delta)
<< ") in persisted state is "
- << diff.InSeconds()
- << " seconds larger than the wall-clock delta. Resetting.";
+ << utils::FormatTimeDelta(diff)
+ << " larger than the wall-clock delta. Resetting.";
stored_delta = update_duration_current_;
}
@@ -741,8 +742,7 @@
update_duration_uptime_.ToInternalValue());
if (use_logging) {
LOG(INFO) << "Update Duration Uptime = "
- << update_duration_uptime_.InSeconds()
- << " seconds";
+ << utils::FormatTimeDelta(update_duration_uptime_);
}
}
@@ -758,6 +758,35 @@
SetUpdateDurationUptimeExtended(new_uptime, now, false);
}
+void PayloadState::ReportDurationMetrics() {
+ TimeDelta duration = GetUpdateDuration();
+ TimeDelta duration_uptime = GetUpdateDurationUptime();
+ string metric;
+
+ metric = "Installer.UpdateDurationMinutes";
+ system_state_->metrics_lib()->SendToUMA(
+ metric,
+ static_cast<int>(duration.InMinutes()),
+ 1, // min: 1 minute
+ 365*24*60, // max: 1 year (approx)
+ kNumDefaultUmaBuckets);
+ LOG(INFO) << "Uploading " << utils::FormatTimeDelta(duration)
+ << " for metric " << metric;
+
+ metric = "Installer.UpdateDurationUptimeMinutes";
+ system_state_->metrics_lib()->SendToUMA(
+ metric,
+ static_cast<int>(duration_uptime.InMinutes()),
+ 1, // min: 1 minute
+ 30*24*60, // max: 1 month (approx)
+ kNumDefaultUmaBuckets);
+ LOG(INFO) << "Uploading " << utils::FormatTimeDelta(duration_uptime)
+ << " for metric " << metric;
+
+ prefs_->Delete(kPrefsUpdateTimestampStart);
+ prefs_->Delete(kPrefsUpdateDurationUptime);
+}
+
string PayloadState::GetPrefsKey(const string& prefix, DownloadSource source) {
return prefix + "-from-" + utils::ToString(source);
}
diff --git a/payload_state.h b/payload_state.h
index 43fe5cc..b12e6b0 100644
--- a/payload_state.h
+++ b/payload_state.h
@@ -120,6 +120,9 @@
// Reports the various metrics related to rebooting during an update.
void ReportRebootMetrics();
+ // Reports the various metrics related to update duration.
+ void ReportDurationMetrics();
+
// Resets all the persisted state values which are maintained relative to the
// current response signature. The response signature itself is not reset.
void ResetPersistedState();
diff --git a/payload_state_unittest.cc b/payload_state_unittest.cc
index 2be5896..e7b7ed2 100644
--- a/payload_state_unittest.cc
+++ b/payload_state_unittest.cc
@@ -668,6 +668,12 @@
EXPECT_CALL(*mock_system_state.mock_metrics_lib(), SendToUMA(
"Installer.UpdateURLSwitches",
2, _, _, _));
+ EXPECT_CALL(*mock_system_state.mock_metrics_lib(), SendToUMA(
+ "Installer.UpdateDurationMinutes",
+ _, _, _, _));
+ EXPECT_CALL(*mock_system_state.mock_metrics_lib(), SendToUMA(
+ "Installer.UpdateDurationUptimeMinutes",
+ _, _, _, _));
payload_state.UpdateSucceeded();
diff --git a/update_attempter.cc b/update_attempter.cc
index 9f01ab9..60276dd 100644
--- a/update_attempter.cc
+++ b/update_attempter.cc
@@ -606,25 +606,6 @@
system_state_->payload_state()->UpdateSucceeded();
- if (!fake_update_success_) {
- // Get the time it took to update the system
- TimeDelta duration = system_state_->payload_state()->GetUpdateDuration();
- TimeDelta duration_uptime =
- system_state_->payload_state()->GetUpdateDurationUptime();
- system_state_->metrics_lib()->SendToUMA(
- "Installer.UpdateDuration",
- static_cast<int>(duration.InSeconds()), // sample
- 1, // min = 1 second
- 20 * 60, // max = 20 minutes
- 50); // buckets
- system_state_->metrics_lib()->SendToUMA(
- "Installer.UpdateDurationUptime",
- static_cast<int>(duration_uptime.InSeconds()), // sample
- 1, // min = 1 second
- 20 * 60, // max = 20 minutes
- 50); // buckets
- }
-
// Since we're done with scattering fully at this point, this is the
// safest point delete the state files, as we're sure that the status is
// set to reboot (which means no more updates will be applied until reboot)
@@ -637,9 +618,6 @@
prefs_->Delete(kPrefsUpdateCheckCount);
prefs_->Delete(kPrefsWallClockWaitPeriod);
prefs_->Delete(kPrefsUpdateFirstSeenAt);
- prefs_->Delete(kPrefsUpdateTimestampStart);
- prefs_->Delete(kPrefsUpdateDurationUptime);
- LOG(INFO) << "Update successfully applied, waiting to reboot.";
SetStatusAndNotify(UPDATE_STATUS_UPDATED_NEED_REBOOT,
kUpdateNoticeUnspecified);
diff --git a/utils_unittest.cc b/utils_unittest.cc
index ec58046..3d2feaa 100644
--- a/utils_unittest.cc
+++ b/utils_unittest.cc
@@ -286,4 +286,42 @@
g_main_loop_unref(loop);
}
+TEST(UtilsTest, FormatTimeDeltaTest) {
+ // utils::FormatTimeDelta() is not locale-aware (it's only used for logging
+ // which is not localized) so we only need to test the C locale
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromMilliseconds(100)),
+ "0.1s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(0)),
+ "0s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(1)),
+ "1s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(59)),
+ "59s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(60)),
+ "1m0s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(61)),
+ "1m1s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(90)),
+ "1m30s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(1205)),
+ "20m5s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(3600)),
+ "1h0m0s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(3601)),
+ "1h0m1s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(3661)),
+ "1h1m1s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(7261)),
+ "2h1m1s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(86400)),
+ "1d0h0m0s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(86401)),
+ "1d0h0m1s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(200000)),
+ "2d7h33m20s");
+ EXPECT_EQ(utils::FormatTimeDelta(base::TimeDelta::FromSeconds(200000) +
+ base::TimeDelta::FromMilliseconds(1)),
+ "2d7h33m20.001s");
+}
+
} // namespace chromeos_update_engine