Histogram how much time we spend for UI/IO thread hopping during SW startup

Not expecting to see a large value in major cases, but want to see how
much.

Bug: 824858
Change-Id: Ifacdd1d651f6512eb5fad4c45346d579f16eda2f
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1627271
Reviewed-by: Robert Kaplow (slow) <rkaplow@chromium.org>
Reviewed-by: Matt Falkenhagen <falken@chromium.org>
Commit-Queue: Kinuko Yasuda <kinuko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#663368}
diff --git a/content/browser/service_worker/embedded_worker_instance.cc b/content/browser/service_worker/embedded_worker_instance.cc
index 4ec39078..f747a13 100644
--- a/content/browser/service_worker/embedded_worker_instance.cc
+++ b/content/browser/service_worker/embedded_worker_instance.cc
@@ -106,7 +106,9 @@
         blink::URLLoaderFactoryBundleInfo> /* factory_bundle_for_new_scripts */,
     std::unique_ptr<
         blink::URLLoaderFactoryBundleInfo> /* factory_bundle_for_renderer */,
-    blink::mojom::CacheStoragePtrInfo)>;
+    blink::mojom::CacheStoragePtrInfo,
+    base::TimeDelta thread_hop_time,
+    base::Time ui_post_time)>;
 
 // Allocates a renderer process for starting a worker and does setup like
 // registering with DevTools. Called on the UI thread. Calls |callback| on the
@@ -124,8 +126,10 @@
                      blink::mojom::EmbeddedWorkerInstanceClientRequest request,
                      ServiceWorkerContextCore* context,
                      base::WeakPtr<ServiceWorkerContextCore> weak_context,
+                     base::Time io_post_time,
                      SetupProcessCallback callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  base::TimeDelta thread_hop_time = base::Time::Now() - io_post_time;
   auto process_info =
       std::make_unique<ServiceWorkerProcessManager::AllocatedProcessInfo>();
   std::unique_ptr<EmbeddedWorkerInstance::DevToolsProxy> devtools_proxy;
@@ -137,13 +141,13 @@
   if (!process_manager) {
     base::PostTaskWithTraits(
         FROM_HERE, {BrowserThread::IO},
-        base::BindOnce(std::move(callback),
-                       blink::ServiceWorkerStatusCode::kErrorAbort,
-                       std::move(params), std::move(process_info),
-                       std::move(devtools_proxy),
-                       std::move(factory_bundle_for_new_scripts),
-                       std::move(factory_bundle_for_renderer),
-                       nullptr /* cache_storage */));
+        base::BindOnce(
+            std::move(callback), blink::ServiceWorkerStatusCode::kErrorAbort,
+            std::move(params), std::move(process_info),
+            std::move(devtools_proxy),
+            std::move(factory_bundle_for_new_scripts),
+            std::move(factory_bundle_for_renderer), nullptr /* cache_storage */,
+            thread_hop_time, base::Time::Now()));
     return;
   }
 
@@ -159,7 +163,8 @@
                        std::move(process_info), std::move(devtools_proxy),
                        std::move(factory_bundle_for_new_scripts),
                        std::move(factory_bundle_for_renderer),
-                       nullptr /* cache_storage */));
+                       nullptr /* cache_storage */, thread_hop_time,
+                       base::Time::Now()));
     return;
   }
   const int process_id = process_info->process_id;
@@ -248,7 +253,8 @@
                      std::move(process_info), std::move(devtools_proxy),
                      std::move(factory_bundle_for_new_scripts),
                      std::move(factory_bundle_for_renderer),
-                     cache_storage.PassInterface()));
+                     cache_storage.PassInterface(), thread_hop_time,
+                     base::Time::Now()));
 }
 
 bool HasSentStartWorker(EmbeddedWorkerInstance::StartingPhase phase) {
@@ -483,6 +489,7 @@
   base::TimeTicks start_worker_sent_time() const {
     return start_worker_sent_time_;
   }
+  base::TimeDelta thread_hop_time() const { return thread_hop_time_; }
 
   void set_skip_recording_startup_time() {
     skip_recording_startup_time_ = true;
@@ -518,7 +525,7 @@
         base::BindOnce(
             &SetupOnUIThread, instance_->embedded_worker_id(), process_manager,
             can_use_existing_process, std::move(params), std::move(request_),
-            context.get(), context,
+            context.get(), context, base::Time::Now(),
             base::BindOnce(&StartTask::OnSetupCompleted,
                            weak_factory_.GetWeakPtr(), process_manager)));
   }
@@ -537,9 +544,13 @@
           factory_bundle_for_new_scripts,
       std::unique_ptr<blink::URLLoaderFactoryBundleInfo>
           factory_bundle_for_renderer,
-      blink::mojom::CacheStoragePtrInfo cache_storage) {
+      blink::mojom::CacheStoragePtrInfo cache_storage,
+      base::TimeDelta thread_hop_time,
+      base::Time ui_post_time) {
     DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
+    thread_hop_time_ = thread_hop_time + (base::Time::Now() - ui_post_time);
+
     std::unique_ptr<WorkerProcessHandle> process_handle;
     if (status == blink::ServiceWorkerStatusCode::kOk) {
       // If we allocated a process, WorkerProcessHandle has to be created before
@@ -625,6 +636,7 @@
   bool skip_recording_startup_time_;
   base::TimeTicks start_time_;
   base::TimeTicks start_worker_sent_time_;
+  base::TimeDelta thread_hop_time_;
 
   base::WeakPtrFactory<StartTask> weak_factory_;
 
@@ -894,6 +906,7 @@
     times.remote_script_evaluation_end =
         start_timing->script_evaluation_end_time;
     times.local_end = base::TimeTicks::Now();
+    times.thread_hop_time = inflight_start_task_->thread_hop_time();
 
     ServiceWorkerMetrics::RecordStartWorkerTiming(times, start_situation_);
   }
diff --git a/content/browser/service_worker/service_worker_metrics.cc b/content/browser/service_worker/service_worker_metrics.cc
index f2ac9fe..c6421308 100644
--- a/content/browser/service_worker/service_worker_metrics.cc
+++ b/content/browser/service_worker/service_worker_metrics.cc
@@ -638,6 +638,14 @@
 
 void ServiceWorkerMetrics::RecordStartWorkerTiming(const StartTimes& times,
                                                    StartSituation situation) {
+  // This is in-process timing, so process consistency doesn't matter.
+  constexpr base::TimeDelta kMinTime = base::TimeDelta::FromMicroseconds(1);
+  constexpr base::TimeDelta kMaxTime = base::TimeDelta::FromMilliseconds(100);
+  constexpr int kBuckets = 50;
+  UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
+      "ServiceWorker.StartTiming.BrowserThreadHopTime", times.thread_hop_time,
+      kMinTime, kMaxTime, kBuckets);
+
   // Bail if the timings across processes weren't consistent.
   if (!base::TimeTicks::IsHighResolution() ||
       !base::TimeTicks::IsConsistentAcrossProcesses()) {
diff --git a/content/browser/service_worker/service_worker_metrics.h b/content/browser/service_worker/service_worker_metrics.h
index 4bae11f..e09b037 100644
--- a/content/browser/service_worker/service_worker_metrics.h
+++ b/content/browser/service_worker/service_worker_metrics.h
@@ -270,6 +270,9 @@
 
     // The browser received the worker started IPC.
     base::TimeTicks local_end;
+
+    // Counts the time overhead of UI/IO thread hops during startup.
+    base::TimeDelta thread_hop_time;
   };
 
   // Records worker activities. Currently this only records
diff --git a/tools/metrics/histograms/histograms.xml b/tools/metrics/histograms/histograms.xml
index 0308867..985995e 100644
--- a/tools/metrics/histograms/histograms.xml
+++ b/tools/metrics/histograms/histograms.xml
@@ -115902,6 +115902,24 @@
   </summary>
 </histogram>
 
+<histogram name="ServiceWorker.StartTiming.BrowserThreadHopTime"
+    units="microseconds" expires_after="M80">
+  <owner>kinuko@chromium.org</owner>
+  <summary>
+    The sum of all the times spent posting tasks between the UI and IO threads
+    during ServiceWorker startup. Recorded on a successful startup and when
+    DevTools was not attached.
+
+    Note: This metric drops reports on clients with low-resolution clocks, which
+    means these reports will be biased against a portion of the population on
+    Windows. See Windows.HasHighResolutionTimeTicks for the affected sample.
+
+    Also note that this one's recorded slightly different from others as it's
+    recorded even if the inter-process timings were inconsistent (see
+    ServiceWorker.StartTiming.ClockConsistency).
+  </summary>
+</histogram>
+
 <histogram name="ServiceWorker.StartTiming.ClockConsistency"
     enum="CrossProcessTimeDelta" expires_after="2019-07-30">
   <owner>falken@chromium.org</owner>