Measure and send update duration (and corresponding uptime) to UMA
This patch introduces two new metrics, Installer.UpdateDuration and
Installer.UpdateDurationUptime. The former is the timespan from when
the update was first discovered until it has been downloaded and
applied (including the time the device is suspended or powered
off). The latter is similar, but without taking into account time
spent in suspend or powered off.
For example, if the device is suspended (or powered off) for N seconds
while updating, the Installer.UpdateDuration metric will be N seconds
bigger than Installer.UpdateDurationUptime metric:
Histogram: Installer.UpdateDuration recorded 1 samples, average = 313.0
Histogram: Installer.UpdateDurationUptime recorded 1 samples, average = 251.0
Also remove the existing Installer.UpdateTime metric as this didn't
take process restarts into account and is now superseeded by the
Installer.UpdateDuration metric.
This is done by using the CLOCK_MONOTONIC_RAW clock (available in
Linux 2.6.28 and later) since this clock indeed does not advance when
the system is sleeping.
We use the PayloadState class to persist recorded data across
update_engine process restart (including device reboots).
Since clock_gettime(2) and CLOCK_MONOTONIC_RAW requires linking to the
librt library do this and also request the system header files to
expose the required symbols and defines, i.e. define _POSIX_C_SOURCE
>= 199309L.
Also remove _POSIX_C_SOURCE mangling from update_attempter.cc since
it's actually not needed there and generally it's better to make the
environment the same across all translation units (by putting whatever
is needed in e.g. CCFLAGS).
BUG=chromium:226763
TEST=unit tests, force update, examine chrome://histograms
Change-Id: I883668564b5fa78ff3e19156bd77496ff929ca58
Signed-off-by: David Zeuthen <zeuthen@chromium.org>
Reviewed-on: https://gerrit.chromium.org/gerrit/47928
Reviewed-by: Jay Srinivasan <jaysri@chromium.org>
diff --git a/payload_state.cc b/payload_state.cc
index 585988a..1699f64 100644
--- a/payload_state.cc
+++ b/payload_state.cc
@@ -19,6 +19,8 @@
namespace chromeos_update_engine {
+const TimeDelta PayloadState::kDurationSlack = TimeDelta::FromSeconds(600);
+
// We want to upperbound backoffs to 16 days
static const uint32_t kMaxBackoffDays = 16;
@@ -33,6 +35,10 @@
LoadUrlIndex();
LoadUrlFailureCount();
LoadBackoffExpiryTime();
+ LoadUpdateTimestampStart();
+ // The LoadUpdateDurationUptime() method relies on LoadUpdateTimestampStart()
+ // being called before it. Don't reorder.
+ LoadUpdateDurationUptime();
return true;
}
@@ -75,6 +81,8 @@
if (count == 0)
return;
+ CalculateUpdateDurationUptime();
+
// We've received non-zero bytes from a recent download operation. Since our
// URL failure count is meant to penalize a URL only for consecutive
// failures, downloading bytes successfully means we should reset the failure
@@ -92,6 +100,11 @@
SetUrlFailureCount(0);
}
+void PayloadState::UpdateSucceeded() {
+ CalculateUpdateDurationUptime();
+ SetUpdateTimestampEnd(Time::Now());
+}
+
void PayloadState::UpdateFailed(ActionExitCode error) {
ActionExitCode base_error = utils::GetBaseErrorCode(error);
LOG(INFO) << "Updating payload state for error code: " << base_error
@@ -320,6 +333,9 @@
SetUrlIndex(0);
SetUrlFailureCount(0);
UpdateBackoffExpiryTime(); // This will reset the backoff expiry time.
+ SetUpdateTimestampStart(Time::Now());
+ SetUpdateTimestampEnd(Time()); // Set to null time
+ SetUpdateDurationUptime(TimeDelta::FromSeconds(0));
}
string PayloadState::CalculateResponseSignature() {
@@ -457,4 +473,124 @@
backoff_expiry_time_.ToInternalValue());
}
+TimeDelta PayloadState::GetUpdateDuration() {
+ Time end_time = update_timestamp_end_.is_null() ? Time::Now() :
+ update_timestamp_end_;
+ return end_time - update_timestamp_start_;
+}
+
+void PayloadState::LoadUpdateTimestampStart() {
+ int64_t stored_value;
+ Time stored_time;
+
+ CHECK(prefs_);
+
+ Time now = Time::Now();
+
+ if (!prefs_->Exists(kPrefsUpdateTimestampStart)) {
+ // The preference missing is not unexpected - in that case, just
+ // use the current time as start time
+ stored_time = now;
+ } else if (!prefs_->GetInt64(kPrefsUpdateTimestampStart, &stored_value)) {
+ LOG(ERROR) << "Invalid UpdateTimestampStart value. Resetting.";
+ stored_time = now;
+ } else {
+ stored_time = Time::FromInternalValue(stored_value);
+ }
+
+ // Sanity check: If the time read from disk is in the future
+ // (modulo some slack to account for possible NTP drift
+ // adjustments), something is fishy and we should report and
+ // reset.
+ TimeDelta duration_according_to_stored_time = now - stored_time;
+ if (duration_according_to_stored_time < -kDurationSlack) {
+ LOG(ERROR) << "The UpdateTimestampStart value ("
+ << utils::ToString(stored_time)
+ << ") in persisted state is "
+ << duration_according_to_stored_time.InSeconds()
+ << " seconds in the future. Resetting.";
+ stored_time = now;
+ }
+
+ SetUpdateTimestampStart(stored_time);
+}
+
+void PayloadState::SetUpdateTimestampStart(const Time& value) {
+ CHECK(prefs_);
+ update_timestamp_start_ = value;
+ prefs_->SetInt64(kPrefsUpdateTimestampStart,
+ update_timestamp_start_.ToInternalValue());
+ LOG(INFO) << "Update Timestamp Start = "
+ << utils::ToString(update_timestamp_start_);
+}
+
+void PayloadState::SetUpdateTimestampEnd(const Time& value) {
+ update_timestamp_end_ = value;
+ LOG(INFO) << "Update Timestamp End = "
+ << utils::ToString(update_timestamp_end_);
+}
+
+TimeDelta PayloadState::GetUpdateDurationUptime() {
+ return update_duration_uptime_;
+}
+
+void PayloadState::LoadUpdateDurationUptime() {
+ int64_t stored_value;
+ TimeDelta stored_delta;
+
+ CHECK(prefs_);
+
+ if (!prefs_->Exists(kPrefsUpdateDurationUptime)) {
+ // The preference missing is not unexpected - in that case, just
+ // we'll use zero as the delta
+ } else if (!prefs_->GetInt64(kPrefsUpdateDurationUptime, &stored_value)) {
+ LOG(ERROR) << "Invalid UpdateDurationUptime value. Resetting.";
+ stored_delta = TimeDelta::FromSeconds(0);
+ } else {
+ stored_delta = TimeDelta::FromInternalValue(stored_value);
+ }
+
+ // Sanity-check: Uptime can never be greater than the wall-clock
+ // difference (modulo some slack). If it is, report and reset
+ // to the wall-clock difference.
+ TimeDelta diff = GetUpdateDuration() - stored_delta;
+ if (diff < -kDurationSlack) {
+ LOG(ERROR) << "The UpdateDurationUptime value ("
+ << stored_delta.InSeconds() << " seconds"
+ << ") in persisted state is "
+ << diff.InSeconds()
+ << " seconds larger than the wall-clock delta. Resetting.";
+ stored_delta = update_duration_current_;
+ }
+
+ SetUpdateDurationUptime(stored_delta);
+}
+
+void PayloadState::SetUpdateDurationUptimeExtended(const TimeDelta& value,
+ const Time& timestamp,
+ bool use_logging) {
+ CHECK(prefs_);
+ update_duration_uptime_ = value;
+ update_duration_uptime_timestamp_ = timestamp;
+ prefs_->SetInt64(kPrefsUpdateDurationUptime,
+ update_duration_uptime_.ToInternalValue());
+ if (use_logging) {
+ LOG(INFO) << "Update Duration Uptime = "
+ << update_duration_uptime_.InSeconds()
+ << " seconds";
+ }
+}
+
+void PayloadState::SetUpdateDurationUptime(const TimeDelta& value) {
+ SetUpdateDurationUptimeExtended(value, utils::GetMonotonicTime(), true);
+}
+
+void PayloadState::CalculateUpdateDurationUptime() {
+ Time now = utils::GetMonotonicTime();
+ TimeDelta uptime_since_last_update = now - update_duration_uptime_timestamp_;
+ TimeDelta new_uptime = update_duration_uptime_ + uptime_since_last_update;
+ // We're frequently called so avoid logging this write
+ SetUpdateDurationUptimeExtended(new_uptime, now, false);
+}
+
} // namespace chromeos_update_engine