Metrics for document.write script blocking

chrome/browser/page_load_metrics/observers/document_write_page_load_metrics_observer.cc

Index: chrome/browser/page_load_metrics/observers/document_write_page_load_metrics_observer.cc
diff --git a/chrome/browser/page_load_metrics/observers/document_write_page_load_metrics_observer.cc b/chrome/browser/page_load_metrics/observers/document_write_page_load_metrics_observer.cc
index a26c8bad2a62f972d48d0c19460bb9ee02090aec..72a3f8fc8538fc32cf3d6eb68a99c5d1f6cac2ad 100644
--- a/chrome/browser/page_load_metrics/observers/document_write_page_load_metrics_observer.cc
+++ b/chrome/browser/page_load_metrics/observers/document_write_page_load_metrics_observer.cc
@@ -41,6 +41,49 @@ const char kBackgroundHistogramDocWriteParseBlockedOnScriptLoadDocumentWrite[] =
     "PageLoad.Clients.DocWrite.Evaluator.Timing2."
     "ParseBlockedOnScriptLoadFromDocumentWrite.Background";
 
+// document.write blocking histograms
+const char kHistogramDocWriteBlockDomLoadingToDomContentLoaded[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2."
+    "DOMLoadingToDOMContentLoadedEventFired";

[Bryan McQuade, 2016/04/26 19:35:44]

we're moving away from DOMLoadingToDOMContentLoadedEventFired to ParseDuration
instead. let's remove DOMLoadingToDOMContentLoadedEventFired which should be
essentially the same as ParseDuration.

I'll put together a CL to remove DOMLoading from our code soon.

[shivanisha, 2016/04/27 13:34:33]

done.

+const char kHistogramDocWriteBlockDomLoadingToFirstContentfulPaint[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2.DOMLoadingToFirstContentfulPaint";

[Bryan McQuade, 2016/04/26 19:35:44]

same - let's prefer ParseStartToFirstContentfulPaint and remove this one

[shivanisha, 2016/04/27 13:34:33]

done.

+const char kHistogramDocWriteBlockParseStartToFirstContentfulPaint[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2.ParseStartToFirstContentfulPaint";
+const char kHistogramDocWriteBlockParseBlockedOnScript[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2.ParseBlockedOnScriptLoad";
+const char kHistogramDocWriteBlockParseBlockedOnScriptLoadDocumentWrite[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2."
+    "ParseBlockedOnScriptLoadFromDocumentWrite";
+const char kHistogramDocWriteBlockParseDuration[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2.ParseDuration";
+const char kHistogramDocWriteBlockParseBlockedOnScriptParseComplete[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2.ParseBlockedOnScriptLoad."
+    "ParseComplete";
+const char
+    kHistogramDocWriteBlockParseBlockedOnScriptLoadDocumentWriteParseComplete
+        [] = "PageLoad.Clients.DocWrite.Block.Timing2."
+             "ParseBlockedOnScriptLoadFromDocumentWrite.ParseComplete";
+const char kHistogramDocWriteBlockReloads[] =
+    "PageLoad.Clients.DocWrite.Block.Reloads";
+
+const char kBackgroundHistogramDocWriteBlockParseBlockedOnScript[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2.ParseBlockedOnScriptLoad."
+    "Background";

[jkarlin, 2016/04/26 20:29:11]

Where are any of the .Background metrics recorded?

[shivanisha, 2016/04/26 20:40:13]

They are recorded in the same function as foreground metrics :
DocumentWritePageLoadMetricsObserver::LogDocumentWriteBlockData
when WasStartedInForegroundEventInForeground or ParseInForeground return false.

[Bryan McQuade, 2016/04/26 20:50:14]

We may see some pages that would have been backgrounded before an event to move
into the foreground bucket as a result of our work to speed up pages, so I
thought it'd be useful to log both fg and bg to see this effect directly (we may
expect to see a reduction in number of background events). It's a lot of
histograms and I'm mixed, but in general I think it's better to log more data
than to be wondering what a histogram might have looked like and wishing you'd
added it a month earlier.

[jkarlin, 2016/04/27 14:28:16]

Acknowledged.

[jkarlin, 2016/04/27 14:28:16]

My bad. I was searching for ParseBlockedOnScriptLoadBackground but Background is
at the beginning of the const name instead of the end. End of a long day :)

These const strings are odd for UMA. We don't typically do this. What's the
motivation?

[Bryan McQuade, 2016/04/27 14:32:48]

This has been the convention in page load metrics. It allows for avoiding
duplication of string constants between implementation in tests. We've taken the
approach of doing this for all histograms, rather than just the ones exposed to
tests, to be consistent and keep all name declarations in one place.

+const char kBackgroundHistogramDocWriteBlockParseBlockedOnScriptComplete[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2.ParseBlockedOnScriptLoad."
+    "ParseComplete."
+    "Background";

[Bryan McQuade, 2016/04/26 19:35:44]

looks like this can be pulled up onto the previous line

[shivanisha, 2016/04/27 13:34:33]

done.

+const char
+    kBackgroundHistogramDocWriteBlockParseBlockedOnScriptLoadDocumentWrite[] =
+        "PageLoad.Clients.DocWrite.Block.Timing2."
+        "ParseBlockedOnScriptLoadFromDocumentWrite.Background";
+const char
+    kBackgroundHistogramDocWriteBlockParseBlockedOnScriptLoadDocWriteComplete
+        [] = "PageLoad.Clients.DocWrite.Block.Timing2."
+             "ParseBlockedOnScriptLoadFromDocumentWrite.ParseComplete."
+             "Background";
+const char kBackgroundHistogramDocWriteBlockParseDuration[] =
+    "PageLoad.Clients.DocWrite.Block.Timing2.ParseDuration.Background";
 }  // namespace internal
 
 DocumentWritePageLoadMetricsObserver::DocumentWritePageLoadMetricsObserver() {}
@@ -54,6 +97,15 @@ void DocumentWritePageLoadMetricsObserver::OnComplete(
       blink::WebLoadingBehaviorFlag::WebLoadingBehaviorDocumentWriteEvaluator) {
     LogDocumentWriteEvaluatorData(timing, info);
   }
+  if (info.metadata.behavior_flags &
+      blink::WebLoadingBehaviorFlag::WebLoadingBehaviorDocumentWriteBlock) {
+    LogDocumentWriteBlockData(timing, info);
+  }
+  if (info.metadata.behavior_flags &
+      blink::WebLoadingBehaviorFlag::
+          WebLoadingBehaviorDocumentWriteBlockReload) {
+    UMA_HISTOGRAM_COUNTS(internal::kHistogramDocWriteBlockReloads, 1);
+  }
 }
 
 void DocumentWritePageLoadMetricsObserver::LogDocumentWriteEvaluatorData(
@@ -78,11 +130,7 @@ void DocumentWritePageLoadMetricsObserver::LogDocumentWriteEvaluatorData(
           timing.first_contentful_paint - timing.parse_start);
     }
 
-    const bool incomplete_parse_in_foreground =
-        timing.parse_stop.is_zero() && info.started_in_foreground &&
-        info.first_background_time.is_zero();
-    if (incomplete_parse_in_foreground ||
-        WasStartedInForegroundEventInForeground(timing.parse_stop, info)) {
+    if (ParseInForeground(timing.parse_start, timing.parse_stop, info)) {
       PAGE_LOAD_HISTOGRAM(internal::kHistogramDocWriteParseBlockedOnScript,
                           timing.parse_blocked_on_script_load_duration);
       PAGE_LOAD_HISTOGRAM(
@@ -118,3 +166,85 @@ void DocumentWritePageLoadMetricsObserver::LogDocumentWriteEvaluatorData(
     }
   }
 }
+
+void DocumentWritePageLoadMetricsObserver::LogDocumentWriteBlockData(
+    const page_load_metrics::PageLoadTiming& timing,
+    const page_load_metrics::PageLoadExtraInfo& info) {
+  // DOM Loading to DOM content loaded.
+  if (!timing.dom_content_loaded_event_start.is_zero()) {
+    if (WasStartedInForegroundEventInForeground(
+            timing.dom_content_loaded_event_start, info)) {
+      PAGE_LOAD_HISTOGRAM(
+          internal::kHistogramDocWriteBlockDomLoadingToDomContentLoaded,
+          timing.dom_content_loaded_event_start - timing.dom_loading);
+    }
+  }
+
+  // DOM Loading to First contentful paint.
+  if (!timing.first_contentful_paint.is_zero()) {
+    if (WasStartedInForegroundEventInForeground(timing.first_contentful_paint,
+                                                info)) {
+      if (WasStartedInForegroundEventInForeground(timing.first_contentful_paint,

[jkarlin, 2016/04/26 20:29:11]

Did you mean for this extra condition? It looks the same as above.

[shivanisha, 2016/04/26 20:40:13]

This is definitely a typing error. Thanks for catching this.

+                                                  info)) {
+        PAGE_LOAD_HISTOGRAM(
+            internal::kHistogramDocWriteBlockDomLoadingToFirstContentfulPaint,
+            timing.first_contentful_paint - timing.dom_loading);
+      }
+    }
+  }
+
+  // Parse started.
+  if (!timing.parse_start.is_zero()) {
+    if (WasStartedInForegroundEventInForeground(timing.first_contentful_paint,
+                                                info)) {
+      PAGE_LOAD_HISTOGRAM(
+          internal::kHistogramDocWriteBlockParseStartToFirstContentfulPaint,
+          timing.first_contentful_paint - timing.parse_start);
+    }
+
+    if (ParseInForeground(timing.parse_start, timing.parse_stop, info)) {
+      PAGE_LOAD_HISTOGRAM(internal::kHistogramDocWriteBlockParseBlockedOnScript,
+                          timing.parse_blocked_on_script_load_duration);
+      PAGE_LOAD_HISTOGRAM(
+          internal::
+              kHistogramDocWriteBlockParseBlockedOnScriptLoadDocumentWrite,
+          timing.parse_blocked_on_script_load_from_document_write_duration);
+    } else {
+      PAGE_LOAD_HISTOGRAM(
+          internal::kBackgroundHistogramDocWriteBlockParseBlockedOnScript,
+          timing.parse_blocked_on_script_load_duration);
+      PAGE_LOAD_HISTOGRAM(
+          internal::
+              kBackgroundHistogramDocWriteBlockParseBlockedOnScriptLoadDocumentWrite,
+          timing.parse_blocked_on_script_load_from_document_write_duration);
+    }
+
+    // Parse completed.
+    if (!timing.parse_stop.is_zero()) {
+      base::TimeDelta parse_duration = timing.parse_stop - timing.parse_start;
+      if (WasStartedInForegroundEventInForeground(timing.parse_stop, info)) {
+        PAGE_LOAD_HISTOGRAM(internal::kHistogramDocWriteBlockParseDuration,
+                            parse_duration);
+        PAGE_LOAD_HISTOGRAM(
+            internal::kHistogramDocWriteBlockParseBlockedOnScriptParseComplete,
+            timing.parse_blocked_on_script_load_duration);
+        PAGE_LOAD_HISTOGRAM(
+            internal::
+                kHistogramDocWriteBlockParseBlockedOnScriptLoadDocumentWriteParseComplete,
+            timing.parse_blocked_on_script_load_from_document_write_duration);
+      } else {
+        PAGE_LOAD_HISTOGRAM(
+            internal::kBackgroundHistogramDocWriteBlockParseDuration,
+            parse_duration);
+        PAGE_LOAD_HISTOGRAM(
+            internal::
+                kBackgroundHistogramDocWriteBlockParseBlockedOnScriptComplete,
+            timing.parse_blocked_on_script_load_duration);
+        PAGE_LOAD_HISTOGRAM(
+            internal::
+                kBackgroundHistogramDocWriteBlockParseBlockedOnScriptLoadDocWriteComplete,
+            timing.parse_blocked_on_script_load_from_document_write_duration);
+      }
+    }
+  }
+}