Add UMA histograms to MHTML save operations.

content/browser/download/mhtml_generation_manager.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "content/browser/download/mhtml_generation_manager.h"
 
 #include <map>
 #include <queue>
 #include <utility>
 
 #include "base/bind.h"
 #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"
 #include "content/browser/frame_host/render_frame_host_impl.h"
 #include "content/common/frame_messages.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/render_frame_host.h"
 #include "content/public/browser/render_process_host.h"
 #include "content/public/browser/render_process_host_observer.h"
 #include "content/public/browser/web_contents.h"
 #include "content/public/common/mhtml_generation_params.h"
 #include "net/base/mime_util.h"
 
 namespace content {
 
 // The class and all of its members live on the UI thread.  Only static methods
 // are executed on other threads.
 class MHTMLGenerationManager::Job : public RenderProcessHostObserver {
  public:
   Job(int job_id,
       WebContents* web_contents,
       const MHTMLGenerationParams& params,
       const GenerateMHTMLCallback& callback);
   ~Job() override;
 
   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_; }
 
   const GenerateMHTMLCallback& callback() const { return callback_; }
 
   // Indicates whether we expect a message from the |sender| at this time.
   // We expect only one message per frame - therefore calling this method
   // will always clear |frame_tree_node_id_of_busy_frame_|.
   bool IsMessageFromFrameExpected(RenderFrameHostImpl* sender);
 
   // Handler for FrameHostMsg_SerializeAsMHTMLResponse (a notification from the
   // renderer that the MHTML generation for previous frame has finished).
@@ skipping 20 matching lines @@
   void CloseFile(base::Callback<void(int64_t file_size)> callback);
 
   // RenderProcessHostObserver:
   void RenderProcessExited(RenderProcessHost* host,
                            base::TerminationStatus status,
                            int exit_code) override;
   void RenderProcessHostDestroyed(RenderProcessHost* host) override;
 
   void MarkAsFinished();
 
+  void ReportRendererMainThreadTime(base::TimeDelta renderer_main_thread_time);
+
  private:
   static int64_t CloseFileOnFileThread(base::File file);
   void AddFrame(RenderFrameHost* render_frame_host);
 
   // Creates a new map with values (content ids) the same as in
   // |frame_tree_node_to_content_id_| map, but with the keys translated from
   // frame_tree_node_id into a |site_instance|-specific routing_id.
   std::map<int, std::string> CreateFrameRoutingIdToContentId(
       SiteInstance* site_instance);
 
   // 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
   // Cache-Control: no-store.
   MHTMLGenerationParams params_;
 
   // The IDs of frames that still need to be processed.
   std::queue<int> pending_frame_tree_node_ids_;
 
   // Identifies a frame to which we've sent FrameMsg_SerializeAsMHTML but for
@@ skipping 28 matching lines @@
       observed_renderer_process_host_;
 
   DISALLOW_COPY_AND_ASSIGN(Job);
 };
 
 MHTMLGenerationManager::Job::Job(int job_id,
                                  WebContents* web_contents,
                                  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()),
       salt_(base::GenerateGUID()),
       callback_(callback),
       is_finished_(false),
       observed_renderer_process_host_(this) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   web_contents->ForEachFrame(base::Bind(
       &MHTMLGenerationManager::Job::AddFrame,
@@ skipping 64 matching lines @@
       CreateFrameRoutingIdToContentId(rfh->GetSiteInstance());
 
   // Send the IPC asking the renderer to serialize the frame.
   DCHECK_EQ(FrameTreeNode::kFrameTreeNodeInvalidId,
             frame_tree_node_id_of_busy_frame_);
   frame_tree_node_id_of_busy_frame_ = frame_tree_node_id;
   rfh->Send(new FrameMsg_SerializeAsMHTML(rfh->GetRoutingID(), ipc_params));
   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;
 }
 
 void MHTMLGenerationManager::Job::RenderProcessExited(
     RenderProcessHost* host,
     base::TerminationStatus status,
     int exit_code) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   MHTMLGenerationManager::GetInstance()->RenderProcessExited(this);
 }
 
 void MHTMLGenerationManager::Job::MarkAsFinished() {
   DCHECK(!is_finished_);
   is_finished_ = true;
   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);

[Ilya Sherman, 2016/09/28 00:42:16]

nit: One thing you could do to clean up the histogram names would be to define a
local macro like

#define RECORD_TIMING_HISTOGRAM(name, value) \
    UMA_HISTOGRAM_TIMES("PageSerialization.MhtmlGeneration." ## name, value);

and call this as

RECORD_TIMING_HISTOGRAM("BrowserWaitForRendererTime.SingleFrame",
renderer_wait_time);

I don't promise that the syntax is right, but hopefully the idea is clear =)

[carlosk, 2016/09/28 17:02:44]

The idea is clear but it doesn't solve my issue of leaving the whole name in
single string, what I find valuable when codesearch-ing for histograms.

+    all_renderers_wait_time_ += renderer_wait_time;
+  }
+  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_);
+  }
+
   // 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();
   pending_frame_tree_node_ids_.push(frame_tree_node_id);
 
   std::string guid = base::GenerateGUID();
   std::string content_id = base::StringPrintf("<frame-%d-%s@mhtml.blink>",
                                               frame_tree_node_id, guid.c_str());
   frame_tree_node_to_content_id_[frame_tree_node_id] = content_id;
 }
@@ skipping 28 matching lines @@
 
   // We only expect one message per frame - let's make sure subsequent messages
   // from the same |sender| will be rejected.
   frame_tree_node_id_of_busy_frame_ = FrameTreeNode::kFrameTreeNodeInvalidId;
 
   return true;
 }
 
 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_,
                     digests_of_uris_of_serialized_resources).size());
   digests_of_already_serialized_uris_.insert(
       digests_of_uris_of_serialized_resources.begin(),
       digests_of_uris_of_serialized_resources.end());
 
   if (pending_frame_tree_node_ids_.empty())
     return true;  // Report success - all frames have been processed.
@@ skipping 36 matching lines @@
       base::Bind(&MHTMLGenerationManager::CreateFile, params.file_path),
       base::Bind(&MHTMLGenerationManager::OnFileAvailable,
                  base::Unretained(this),  // Safe b/c |this| is a singleton.
                  job->id()));
 }
 
 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);
   if (!job || !job->IsMessageFromFrameExpected(sender)) {
     NOTREACHED();
     ReceivedBadMessage(sender->GetProcess(),
                        bad_message::DWNLD_INVALID_SERIALIZE_AS_MHTML_RESPONSE);
     return;
   }
 
   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);
     return;
   }
 
   if (!job->OnSerializeAsMHTMLResponse(
           digests_of_uris_of_serialized_resources)) {
     JobFinished(job, JobStatus::FAILURE);
     return;
@@ skipping 57 matching lines @@
 void MHTMLGenerationManager::OnFileClosed(int job_id,
                                           JobStatus job_status,
                                           int64_t file_size) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
 
   Job* job = FindJob(job_id);
   TRACE_EVENT_NESTABLE_ASYNC_END2(
       "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;
 }
 
 MHTMLGenerationManager::Job* MHTMLGenerationManager::NewJob(
     WebContents* web_contents,
     const MHTMLGenerationParams& params,
     const GenerateMHTMLCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
@@ skipping 14 matching lines @@
   return iter->second;
 }
 
 void MHTMLGenerationManager::RenderProcessExited(Job* job) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   DCHECK(job);
   JobFinished(job, JobStatus::FAILURE);
 }
 
 }  // namespace content