commit 39f571439821118c9ee5b36131e851206b819074
author Lann Martin <lannm@chromium.org> Fri Jul 14 09:18:42 2017 -0600
committer chrome-bot <chrome-bot@chromium.org> Sun Jul 16 17:58:18 2017 -0700
tree 74ac2824ca26071fbaa30ae9af7929cc01846b93
parent 3584bce5a45f0c40b43385324bfc4a44f1960567

Log DeltaPerformer operation histogram after update

Record and log InstallOperation run durations in DeltaPerformer. Since
these operations block the single-threaded process they may be
responsible for dbus service timeouts.

BUG=chromium:578270
TEST=deploy to device, restart update-engine, perform update (e.g.
`cros flash ssh://...`), check logs for histogram.

Change-Id: Idb782c86a627b1738a29901edd5d3b45790f4bb9
Reviewed-on: https://chromium-review.googlesource.com/570997
Commit-Ready: Lann Martin <lannm@chromium.org>
Tested-by: Lann Martin <lannm@chromium.org>
Reviewed-by: Simon Glass <sjg@chromium.org>
Reviewed-by: Grant Grundler <grundler@chromium.org>

payload_consumer/delta_performer.cc

diff --git a/payload_consumer/delta_performer.cc b/payload_consumer/delta_performer.cc
index 9b7eea3..01db96a 100644
--- a/payload_consumer/delta_performer.cc
+++ b/payload_consumer/delta_performer.cc
@@ -29,9 +29,11 @@
 #include <base/files/file_util.h>
 #include <base/format_macros.h>
 #include <base/memory/ptr_util.h>
+#include <base/metrics/histogram_macros.h>
 #include <base/strings/string_number_conversions.h>
 #include <base/strings/string_util.h>
 #include <base/strings/stringprintf.h>
+#include <base/time/time.h>
 #include <brillo/data_encoding.h>
 #include <bsdiff/bspatch.h>
 #include <google/protobuf/repeated_field.h>
@@ -580,6 +582,15 @@
   return kMetadataParseSuccess;
 }
 
+#define OP_DURATION_HISTOGRAM(_op_name, _start_time)      \
+    LOCAL_HISTOGRAM_CUSTOM_TIMES(                         \
+        "UpdateEngine.DownloadAction.InstallOperation::"  \
+        _op_name ".Duration",                             \
+        base::TimeTicks::Now() - _start_time,             \
+        base::TimeDelta::FromMilliseconds(10),            \
+        base::TimeDelta::FromMinutes(5),                  \
+        20);
+
 // Wrapper around write. Returns true if all requested bytes
 // were written, or false on any error, regardless of progress
 // and stores an action exit code in |error|.
@@ -709,28 +720,36 @@
     ScopedTerminatorExitUnblocker exit_unblocker =
         ScopedTerminatorExitUnblocker();  // Avoids a compiler unused var bug.
 
+    base::TimeTicks op_start_time = base::TimeTicks::Now();
+
     bool op_result;
     switch (op.type()) {
       case InstallOperation::REPLACE:
       case InstallOperation::REPLACE_BZ:
       case InstallOperation::REPLACE_XZ:
         op_result = PerformReplaceOperation(op);
+        OP_DURATION_HISTOGRAM("REPLACE", op_start_time);
         break;
       case InstallOperation::ZERO:
       case InstallOperation::DISCARD:
         op_result = PerformZeroOrDiscardOperation(op);
+        OP_DURATION_HISTOGRAM("ZERO_OR_DISCARD", op_start_time);
         break;
       case InstallOperation::MOVE:
         op_result = PerformMoveOperation(op);
+        OP_DURATION_HISTOGRAM("MOVE", op_start_time);
         break;
       case InstallOperation::BSDIFF:
         op_result = PerformBsdiffOperation(op);
+        OP_DURATION_HISTOGRAM("BSDIFF", op_start_time);
         break;
       case InstallOperation::SOURCE_COPY:
         op_result = PerformSourceCopyOperation(op, error);
+        OP_DURATION_HISTOGRAM("SOURCE_COPY", op_start_time);
         break;
       case InstallOperation::SOURCE_BSDIFF:
         op_result = PerformSourceBsdiffOperation(op, error);
+        OP_DURATION_HISTOGRAM("SOURCE_BSDIFF", op_start_time);
         break;
       case InstallOperation::IMGDIFF:
         // TODO(deymo): Replace with PUFFIN operation.

payload_consumer/download_action.cc

diff --git a/payload_consumer/download_action.cc b/payload_consumer/download_action.cc
index 084848e..b2405ef 100644
--- a/payload_consumer/download_action.cc
+++ b/payload_consumer/download_action.cc
@@ -23,6 +23,7 @@
 #include <vector>
 
 #include <base/files/file_path.h>
+#include <base/metrics/statistics_recorder.h>
 #include <base/strings/stringprintf.h>
 
 #include "update_engine/common/action_pipe.h"
@@ -55,6 +56,7 @@
       bytes_received_(0),
       p2p_sharing_fd_(-1),
       p2p_visible_(true) {
+  base::StatisticsRecorder::Initialize();
 }
 
 DownloadAction::~DownloadAction() {}
@@ -305,7 +307,14 @@
   if (code == ErrorCode::kSuccess && delta_performer_.get()) {
     code = delta_performer_->VerifyPayload(install_plan_.payload_hash,
                                            install_plan_.payload_size);
-    if (code != ErrorCode::kSuccess) {
+    if (code == ErrorCode::kSuccess) {
+      // Log UpdateEngine.DownloadAction.* histograms to help diagnose
+      // long-blocking oeprations.
+      std::string histogram_output;
+      base::StatisticsRecorder::WriteGraph(
+          "UpdateEngine.DownloadAction.", &histogram_output);
+      LOG(INFO) << histogram_output;
+    } else {
       LOG(ERROR) << "Download of " << install_plan_.download_url
                  << " failed due to payload verification error.";
       // Delete p2p file, if applicable.