Add UMA histograms to MHTML save operations.

content/browser/download/mhtml_generation_manager.cc

Index: content/browser/download/mhtml_generation_manager.cc
diff --git a/content/browser/download/mhtml_generation_manager.cc b/content/browser/download/mhtml_generation_manager.cc
index 18403f78cb18082884a6fb283a0d67b9859eafa4..4fc6d797b7679d963c2e7bab84ce4a27b9496bbd 100644
--- a/content/browser/download/mhtml_generation_manager.cc
+++ b/content/browser/download/mhtml_generation_manager.cc
@@ -12,9 +12,11 @@
 #include "base/files/file.h"
 #include "base/guid.h"
 #include "base/macros.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/scoped_observer.h"
 #include "base/stl_util.h"
 #include "base/strings/stringprintf.h"
+#include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "content/browser/bad_message.h"
 #include "content/browser/frame_host/frame_tree_node.h"
@@ -42,6 +44,7 @@ class MHTMLGenerationManager::Job : public RenderProcessHostObserver {
 
   int id() const { return job_id_; }
   void set_browser_file(base::File file) { browser_file_ = std::move(file); }
+  const base::TimeTicks creation_time() { return creation_time_; }

[Łukasz Anforowicz, 2016/09/28 19:38:40]

The |const| in |const T field() { return field_)| above looks weird.  Did you
mean to use

1) const T& field() ...

and/or

2) T field() const { ... } 

?

[carlosk, 2016/09/28 21:07:49]

Done #2.

 
   const GenerateMHTMLCallback& callback() const { return callback_; }
 
@@ -82,6 +85,8 @@ class MHTMLGenerationManager::Job : public RenderProcessHostObserver {
 
   void MarkAsFinished();
 
+  void ReportRendererMainThreadTime(base::TimeDelta renderer_main_thread_time);
+
  private:
   static int64_t CloseFileOnFileThread(base::File file);
   void AddFrame(RenderFrameHost* render_frame_host);
@@ -94,7 +99,13 @@ class MHTMLGenerationManager::Job : public RenderProcessHostObserver {
 
   // Id used to map renderer responses to jobs.
   // See also MHTMLGenerationManager::id_to_job_ map.
-  int job_id_;
+  const int job_id_;
+
+  // Time tracking for performance metrics reporting.
+  const base::TimeTicks creation_time_;
+  base::TimeTicks wait_on_renderer_start_time_;
+  base::TimeDelta all_renderers_wait_time_;
+  base::TimeDelta all_renderers_main_thread_time_;
 
   // User-configurable parameters. Includes the file location, binary encoding
   // choices, and whether to skip storing resources marked
@@ -143,6 +154,7 @@ MHTMLGenerationManager::Job::Job(int job_id,
                                  const MHTMLGenerationParams& params,
                                  const GenerateMHTMLCallback& callback)
     : job_id_(job_id),
+      creation_time_(base::TimeTicks::Now()),
       params_(params),
       frame_tree_node_id_of_busy_frame_(FrameTreeNode::kFrameTreeNodeInvalidId),
       mhtml_boundary_marker_(net::GenerateMimeMultipartBoundary()),
@@ -227,6 +239,8 @@ bool MHTMLGenerationManager::Job::SendToNextRenderFrame() {
   TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("page-serialization", "WaitingOnRenderer",
                                     this, "frame tree node id",
                                     frame_tree_node_id);
+  DCHECK(wait_on_renderer_start_time_.is_null());
+  wait_on_renderer_start_time_ = base::TimeTicks::Now();
   return true;
 }
 
@@ -244,11 +258,40 @@ void MHTMLGenerationManager::Job::MarkAsFinished() {
   TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("page-serialization", "JobFinished",
                                       this);
 
+  // End of job timing reports.
+  if (!wait_on_renderer_start_time_.is_null()) {
+    base::TimeDelta renderer_wait_time =
+        base::TimeTicks::Now() - wait_on_renderer_start_time_;
+    UMA_HISTOGRAM_TIMES(
+        "PageSerialization.MhtmlGeneration.BrowserWaitForRendererTime."
+        "SingleFrame",
+        renderer_wait_time);
+    all_renderers_wait_time_ += renderer_wait_time;

[Łukasz Anforowicz, 2016/09/28 19:38:40]

Would it make sense to null-out/zero-out |wait_on_renderer_start_time_| here?  I
think there were cases when MarkAsFinished could be called twice (in some kind
of a race between 1) a real job completion IPC and 2) renderer exit
notification).  I think these races are fixed, but zeroing-out the value should
improve resiliency of the new code to such duplicate completion notifications.

[carlosk, 2016/09/28 21:07:49]

Done, but checking |is_finished_| instead.

+  }
+  if (!all_renderers_wait_time_.is_zero()) {
+    UMA_HISTOGRAM_TIMES(
+        "PageSerialization.MhtmlGeneration.BrowserWaitForRendererTime."
+        "FrameTree",
+        all_renderers_wait_time_);
+  }
+  if (!all_renderers_main_thread_time_.is_zero()) {
+    UMA_HISTOGRAM_TIMES(
+        "PageSerialization.MhtmlGeneration.RendererMainThreadTime.FrameTree",
+        all_renderers_main_thread_time_);

[Łukasz Anforowicz, 2016/09/28 19:38:40]

Same suggestion (zeroing out the fields) as above here and in the other places.

[carlosk, 2016/09/28 21:07:49]

Ditto.

+  }
+
   // Stopping RenderProcessExited notifications is needed to avoid calling
   // JobFinished twice.  See also https://crbug.com/612098.
   observed_renderer_process_host_.RemoveAll();
 }
 
+void MHTMLGenerationManager::Job::ReportRendererMainThreadTime(
+    base::TimeDelta renderer_main_thread_time) {
+  DCHECK(renderer_main_thread_time > base::TimeDelta());
+  if (renderer_main_thread_time > base::TimeDelta())
+    all_renderers_main_thread_time_ += renderer_main_thread_time;
+}
+
 void MHTMLGenerationManager::Job::AddFrame(RenderFrameHost* render_frame_host) {
   auto* rfhi = static_cast<RenderFrameHostImpl*>(render_frame_host);
   int frame_tree_node_id = rfhi->frame_tree_node()->frame_tree_node_id();
@@ -297,6 +340,16 @@ bool MHTMLGenerationManager::Job::IsMessageFromFrameExpected(
 
 bool MHTMLGenerationManager::Job::OnSerializeAsMHTMLResponse(
     const std::set<std::string>& digests_of_uris_of_serialized_resources) {
+  DCHECK(!wait_on_renderer_start_time_.is_null());
+  base::TimeDelta renderer_wait_time =
+      base::TimeTicks::Now() - wait_on_renderer_start_time_;
+  UMA_HISTOGRAM_TIMES(
+      "PageSerialization.MhtmlGeneration.BrowserWaitForRendererTime."
+      "SingleFrame",
+      renderer_wait_time);
+  all_renderers_wait_time_ += renderer_wait_time;
+  wait_on_renderer_start_time_ = base::TimeTicks();
+
   // Renderer should be deduping resources with the same uris.
   DCHECK_EQ(0u, base::STLSetIntersection<std::set<std::string>>(
                     digests_of_already_serialized_uris_,
@@ -353,7 +406,8 @@ void MHTMLGenerationManager::OnSerializeAsMHTMLResponse(
     RenderFrameHostImpl* sender,
     int job_id,
     bool mhtml_generation_in_renderer_succeeded,
-    const std::set<std::string>& digests_of_uris_of_serialized_resources) {
+    const std::set<std::string>& digests_of_uris_of_serialized_resources,
+    base::TimeDelta renderer_main_thread_time) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
 
   Job* job = FindJob(job_id);
@@ -366,6 +420,7 @@ void MHTMLGenerationManager::OnSerializeAsMHTMLResponse(
 
   TRACE_EVENT_NESTABLE_ASYNC_END0("page-serialization", "WaitingOnRenderer",
                                   job);
+  job->ReportRendererMainThreadTime(renderer_main_thread_time);
 
   if (!mhtml_generation_in_renderer_succeeded) {
     JobFinished(job, JobStatus::FAILURE);
@@ -443,6 +498,8 @@ void MHTMLGenerationManager::OnFileClosed(int job_id,
       "page-serialization", "SavingMhtmlJob", job, "job result",
       job_status == JobStatus::SUCCESS ? "success" : "failure", "file size",
       file_size);
+  UMA_HISTOGRAM_TIMES("PageSerialization.MhtmlGeneration.FullPageSavingTime",
+                      base::TimeTicks::Now() - job->creation_time());
   job->callback().Run(job_status == JobStatus::SUCCESS ? file_size : -1);
   id_to_job_.erase(job_id);
   delete job;