EQT: Record the max queueing time from navigation start to navigation away

third_party/WebKit/Source/platform/scheduler/renderer/renderer_scheduler_impl.cc

 // Copyright 2014 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 "platform/scheduler/renderer/renderer_scheduler_impl.h"
 
 #include "base/bind.h"
 #include "base/debug/stack_trace.h"
 #include "base/logging.h"
 #include "base/memory/ptr_util.h"
 #include "base/metrics/histogram.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/trace_event/trace_event.h"
 #include "base/trace_event/trace_event_argument.h"
 #include "cc/output/begin_frame_args.h"
+#include "components/metrics/single_sample_metrics_factory_impl.h"
 #include "platform/RuntimeEnabledFeatures.h"
 #include "platform/scheduler/base/real_time_domain.h"
 #include "platform/scheduler/base/task_queue_impl.h"
 #include "platform/scheduler/base/task_queue_selector.h"
 #include "platform/scheduler/base/time_converter.h"
 #include "platform/scheduler/base/trace_helper.h"
 #include "platform/scheduler/base/virtual_time_domain.h"
 #include "platform/scheduler/child/scheduler_tqm_delegate.h"
 #include "platform/scheduler/renderer/auto_advancing_virtual_time_domain.h"
 #include "platform/scheduler/renderer/task_queue_throttler.h"
@@ skipping 185 matching lines @@
       timer_tasks_seem_expensive(false),
       touchstart_expected_soon(false),
       have_seen_a_begin_main_frame(false),
       have_reported_blocking_intervention_in_current_policy(false),
       have_reported_blocking_intervention_since_navigation(false),
       has_visible_render_widget_with_touch_handler(false),
       begin_frame_not_expected_soon(false),
       in_idle_period_for_testing(false),
       use_virtual_time(false),
       is_audio_playing(false),
+      has_navigated(false),
       rail_mode_observer(nullptr),
       wake_up_budget_pool(nullptr),
       task_duration_per_queue_type_histogram(base::Histogram::FactoryGet(
           "RendererScheduler.TaskDurationPerQueueType2",
           1,
           static_cast<int>(TaskQueue::QueueType::COUNT),
           static_cast<int>(TaskQueue::QueueType::COUNT) + 1,
           base::HistogramBase::kUmaTargetedHistogramFlag)) {
   foreground_main_thread_load_tracker.Resume(now);
 }
@@ skipping 1392 matching lines @@
 void RendererSchedulerImpl::RemovePendingNavigation(NavigatingFrameType type) {
   helper_.CheckOnValidThread();
   DCHECK_GT(GetMainThreadOnly().navigation_task_expected_count, 0);
   if (type == NavigatingFrameType::kMainFrame &&
       GetMainThreadOnly().navigation_task_expected_count > 0) {
     GetMainThreadOnly().navigation_task_expected_count--;
     UpdatePolicy();
   }
 }
 
+void RendererSchedulerImpl::OnCommitProvisionalLoad() {
+  // Initialize |max_queueing_time_metric| lazily so that
+  // |SingleSampleMetricsFactory::SetFactory()| is called before
+  // |SingleSampleMetricsFactory::Get()|
+  if (!GetMainThreadOnly().max_queueing_time_metric) {
+    GetMainThreadOnly().max_queueing_time_metric =
+        GetOrCreateMaxQueueingTimeMetric();
+  }
+  GetMainThreadOnly().max_queueing_time_metric.reset();
+  GetMainThreadOnly().max_queueing_time = base::TimeDelta();
+  GetMainThreadOnly().has_navigated = true;
+}
+
+std::unique_ptr<base::SingleSampleMetric>
+RendererSchedulerImpl::GetOrCreateMaxQueueingTimeMetric() {
+  return base::SingleSampleMetricsFactory::Get()->CreateCustomCountsMetric(

[Sami, 2017/05/31 10:30:34]

Based on the method name I would expect this to cache the result in
max_queueing_time_metric. Or do we need the second level cache at all if the
metrics factory handles everything for us?

[Liquan (Max) Gu, 2017/06/01 14:39:39]

There is a difference between caching it in max_queueing_time_metric or not. If
not caching, the single sample metric will destruct every time when we create or
get the metric to set value or reset the pointer. If caching, the metric won't
destruct when we want to set value only, and this is a necessary property for
the implementation. That's why we need this caching.

The singe sample metric is designed in a way that it inserts a sample to the
histogram when it destructs, so destruction should be used only when necessary.

[Sami, 2017/06/01 18:29:40]

I see. This function seems to create a new metric every time it's called so I
think the name GetOrCreate... is a little confusing, right?

[Liquan (Max) Gu, 2017/06/01 18:36:05]

Whoops, you are right. 

+      "RendererScheduler.MaxQueueingTime", 1, 10000, 50);
+}
+
 void RendererSchedulerImpl::OnNavigationStarted() {
   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("renderer.scheduler"),
                "RendererSchedulerImpl::OnNavigationStarted");
   base::AutoLock lock(any_thread_lock_);
   ResetForNavigationLocked();
 }
 
 void RendererSchedulerImpl::OnFirstMeaningfulPaint() {
   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("renderer.scheduler"),
                "RendererSchedulerImpl::OnFirstMeaningfulPaint");
@@ skipping 256 matching lines @@
 }
 
 void RendererSchedulerImpl::RemoveTaskTimeObserver(
     TaskTimeObserver* task_time_observer) {
   helper_.RemoveTaskTimeObserver(task_time_observer);
 }
 
 void RendererSchedulerImpl::OnQueueingTimeForWindowEstimated(
     base::TimeDelta queueing_time,
     base::TimeTicks window_start_time) {
+  if (GetMainThreadOnly().has_navigated) {
+    if (GetMainThreadOnly().max_queueing_time < queueing_time) {
+      if (!GetMainThreadOnly().max_queueing_time_metric) {
+        GetMainThreadOnly().max_queueing_time_metric =
+            GetOrCreateMaxQueueingTimeMetric();
+      }
+      GetMainThreadOnly().max_queueing_time_metric->SetSample(
+          queueing_time.InMilliseconds());
+      GetMainThreadOnly().max_queueing_time = queueing_time;
+    }
+  }
+
   // RendererScheduler reports the queueing time once per window's duration.
   //          |stepEQT|stepEQT|stepEQT|stepEQT|stepEQT|stepEQT|
   // Report:  |-------window EQT------|
   // Discard:         |-------window EQT------|
   // Discard:                 |-------window EQT------|
   // Report:                          |-------window EQT------|
   if (window_start_time -
           GetMainThreadOnly().uma_last_queueing_time_report_window_start_time <
       kQueueingTimeWindowDuration) {
     return;
@@ skipping 137 matching lines @@
     case TimeDomainType::VIRTUAL:
       return "virtual";
     default:
       NOTREACHED();
       return nullptr;
   }
 }
 
 }  // namespace scheduler
 }  // namespace blink