Virtual A/B report metrics from update_engine. (1/2)

Test: apply OTA and look at log
Bug: 138817833
Bug: 147696014
Change-Id: I12331a272028e4a21a14604e1e7e48cb2c5ef55c
Merged-In: I12331a272028e4a21a14604e1e7e48cb2c5ef55c
diff --git a/cleanup_previous_update_action.cc b/cleanup_previous_update_action.cc
index 169f6bd..f6838f9 100644
--- a/cleanup_previous_update_action.cc
+++ b/cleanup_previous_update_action.cc
@@ -15,16 +15,22 @@
 //
 #include "update_engine/cleanup_previous_update_action.h"
 
+#include <chrono>  // NOLINT(build/c++11) -- for merge times
 #include <functional>
 #include <string>
 
 #include <android-base/properties.h>
 #include <base/bind.h>
 
+#ifndef __ANDROID_RECOVERY__
+#include <statslog.h>
+#endif
+
 #include "update_engine/common/utils.h"
 #include "update_engine/payload_consumer/delta_performer.h"
 
 using android::snapshot::SnapshotManager;
+using android::snapshot::SnapshotMergeStats;
 using android::snapshot::UpdateState;
 using brillo::MessageLoop;
 
@@ -50,7 +56,8 @@
       delegate_(delegate),
       running_(false),
       cancel_failed_(false),
-      last_percentage_(0) {}
+      last_percentage_(0),
+      merge_stats_(SnapshotMergeStats::GetInstance(*snapshot)) {}
 
 void CleanupPreviousUpdateAction::PerformAction() {
   ResumeAction();
@@ -76,6 +83,7 @@
 
 void CleanupPreviousUpdateAction::ActionCompleted(ErrorCode error_code) {
   running_ = false;
+  ReportMergeStats();
 }
 
 std::string CleanupPreviousUpdateAction::Type() const {
@@ -135,6 +143,11 @@
   if (!boot_control_->IsSlotMarkedSuccessful(boot_control_->GetCurrentSlot())) {
     ScheduleWaitMarkBootSuccessful();
   }
+  if (!merge_stats_->Start()) {
+    // Not an error because CleanupPreviousUpdateAction may be paused and
+    // resumed while kernel continues merging snapshots in the background.
+    LOG(WARNING) << "SnapshotMergeStats::Start failed.";
+  }
   LOG(INFO) << "Waiting for any previous merge request to complete. "
             << "This can take up to several minutes.";
   WaitForMergeOrSchedule();
@@ -154,8 +167,8 @@
   auto state = snapshot_->ProcessUpdateState(
       std::bind(&CleanupPreviousUpdateAction::OnMergePercentageUpdate, this),
       std::bind(&CleanupPreviousUpdateAction::BeforeCancel, this));
+  merge_stats_->set_state(state);
 
-  // TODO(elsk): log stats
   switch (state) {
     case UpdateState::None: {
       LOG(INFO) << "Can't find any snapshot to merge.";
@@ -271,6 +284,7 @@
 
   LOG(WARNING) << "InitiateMerge failed.";
   auto state = snapshot_->GetUpdateState();
+  merge_stats_->set_state(state);
   if (state == UpdateState::Unverified) {
     // We are stuck at unverified state. This can happen if the update has
     // been applied, but it has not even been attempted yet (in libsnapshot,
@@ -296,4 +310,34 @@
   return;
 }
 
+void CleanupPreviousUpdateAction::ReportMergeStats() {
+  auto result = merge_stats_->Finish();
+  if (result == nullptr) {
+    LOG(WARNING) << "Not reporting merge stats because "
+                    "SnapshotMergeStats::Finish failed.";
+    return;
+  }
+
+#ifdef __ANDROID_RECOVERY__
+  LOG(INFO) << "Skip reporting merge stats in recovery.";
+#else
+  const auto& report = result->report();
+
+  if (report.state() == UpdateState::None ||
+      report.state() == UpdateState::Initiated ||
+      report.state() == UpdateState::Unverified) {
+    LOG(INFO) << "Not reporting merge stats because state is "
+              << android::snapshot::UpdateState_Name(report.state());
+    return;
+  }
+
+  auto passed_ms = std::chrono::duration_cast<std::chrono::milliseconds>(
+      result->merge_time());
+  LOG(INFO) << "Reporting merge stats: "
+            << android::snapshot::UpdateState_Name(report.state()) << " in "
+            << passed_ms.count() << "ms (resumed " << report.resume_count()
+            << " times)";
+#endif
+}
+
 }  // namespace chromeos_update_engine