Add Total Blocking Time to Time To Interactive's trace event

This CL adds TBT to TTI's trace event by keeping track of the longtasks
and using the list to compute TBT as soon as TTI is known. The
computation is done inside the trace event to avoid running the code
when tracing is disabled. An args param is added because there are no
macros supporting more than 2 args, so two of them are merged into a
single TracedValue param.

Bug: 1055806
Change-Id: Ided9c2378aff6d98cbdf5e88e99d46735b92e284
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2079616Reviewed-by: Steve Kobes <skobes@chromium.org>
Reviewed-by: Deep Roy <dproy@chromium.org>
Commit-Queue: Nicolás Peña Moreno <npm@chromium.org>
Cr-Commit-Position: refs/heads/master@{#745610}

third_party/blink/renderer/core/loader/interactive_detector.cc

@@ -87,7 +87,6 @@ void InteractiveDetector::SetNavigationStartTime(
   base::TimeTicks initial_timer_fire_time =
       navigation_start_time + kTimeToInteractiveWindow;
 
-  active_main_thread_quiet_window_start_ = navigation_start_time;
   active_network_quiet_window_start_ = navigation_start_time;
   StartOrPostponeCITimer(initial_timer_fire_time);
 }
@@ -345,13 +344,7 @@ void InteractiveDetector::OnLongTaskDetected(base::TimeTicks start_time,
   // We should not be receiving long task notifications after Time to
   // Interactive has already been reached.
   DCHECK(interactive_time_.is_null());
-  base::TimeDelta quiet_window_length =
-      start_time - active_main_thread_quiet_window_start_;
-  if (quiet_window_length >= kTimeToInteractiveWindow) {
-    main_thread_quiet_windows_.emplace_back(
-        active_main_thread_quiet_window_start_, start_time);
-  }
-  active_main_thread_quiet_window_start_ = end_time;
+  long_tasks_.emplace_back(start_time, end_time);
   StartOrPostponeCITimer(end_time + kTimeToInteractiveWindow);
 }
 
@@ -406,7 +399,7 @@ void InteractiveDetector::TimeToInteractiveTimerFired(TimerBase*) {
   CheckTimeToInteractiveReached();
 }
 
-void InteractiveDetector::AddCurrentlyActiveQuietIntervals(
+void InteractiveDetector::AddCurrentlyActiveNetworkQuietInterval(
     base::TimeTicks current_time) {
   // Network is currently quiet.
   if (!active_network_quiet_window_start_.is_null()) {
@@ -416,78 +409,81 @@ void InteractiveDetector::AddCurrentlyActiveQuietIntervals(
                                           current_time);
     }
   }
-
-  // Since this code executes on the main thread, we know that no task is
-  // currently running on the main thread. We can therefore skip checking.
-  // main_thread_quiet_window_being != 0.0.
-  if (current_time - active_main_thread_quiet_window_start_ >=
-      kTimeToInteractiveWindow) {
-    main_thread_quiet_windows_.emplace_back(
-        active_main_thread_quiet_window_start_, current_time);
-  }
 }
 
-void InteractiveDetector::RemoveCurrentlyActiveQuietIntervals() {
+void InteractiveDetector::RemoveCurrentlyActiveNetworkQuietInterval() {
   if (!network_quiet_windows_.IsEmpty() &&
       network_quiet_windows_.back().Low() ==
           active_network_quiet_window_start_) {
     network_quiet_windows_.pop_back();
   }
-
-  if (!main_thread_quiet_windows_.IsEmpty() &&
-      main_thread_quiet_windows_.back().Low() ==
-          active_main_thread_quiet_window_start_) {
-    main_thread_quiet_windows_.pop_back();
-  }
 }
 
 base::TimeTicks InteractiveDetector::FindInteractiveCandidate(
-    base::TimeTicks lower_bound) {
-  // Main thread iterator.
-  auto* it_mt = main_thread_quiet_windows_.begin();
+    base::TimeTicks lower_bound,
+    base::TimeTicks current_time) {
   // Network iterator.
   auto* it_net = network_quiet_windows_.begin();
+  // Long tasks iterator.
+  auto* it_lt = long_tasks_.begin();
+
+  base::TimeTicks main_quiet_start = page_event_times_.nav_start;
 
-  while (it_mt < main_thread_quiet_windows_.end() &&
+  while (main_quiet_start < current_time &&
          it_net < network_quiet_windows_.end()) {
-    if (it_mt->High() <= lower_bound) {
-      it_mt++;
+    base::TimeTicks main_quiet_end =
+        it_lt == long_tasks_.end() ? current_time : it_lt->Low();
+    base::TimeTicks next_main_quiet_start =
+        it_lt == long_tasks_.end() ? current_time : it_lt->High();
+    if (main_quiet_end - main_quiet_start < kTimeToInteractiveWindow) {
+      // The main thread quiet window is too short.
+      ++it_lt;
+      main_quiet_start = next_main_quiet_start;
+      continue;
+    }
+    if (main_quiet_end <= lower_bound) {
+      // The main thread quiet window is before |lower_bound|.
+      ++it_lt;
+      main_quiet_start = next_main_quiet_start;
       continue;
     }
     if (it_net->High() <= lower_bound) {
-      it_net++;
+      // The network quiet window is before |lower_bound|.
+      ++it_net;
       continue;
     }
 
     // First handling the no overlap cases.
     // [ main thread interval ]
     //                                     [ network interval ]
-    if (it_mt->High() <= it_net->Low()) {
-      it_mt++;
+    if (main_quiet_end <= it_net->Low()) {
+      ++it_lt;
+      main_quiet_start = next_main_quiet_start;
       continue;
     }
     //                                     [ main thread interval ]
     // [   network interval   ]
-    if (it_net->High() <= it_mt->Low()) {
-      it_net++;
+    if (it_net->High() <= main_quiet_start) {
+      ++it_net;
       continue;
     }
 
     // At this point we know we have a non-empty overlap after lower_bound.
     base::TimeTicks overlap_start =
-        std::max({it_mt->Low(), it_net->Low(), lower_bound});
-    base::TimeTicks overlap_end = std::min(it_mt->High(), it_net->High());
+        std::max({main_quiet_start, it_net->Low(), lower_bound});
+    base::TimeTicks overlap_end = std::min(main_quiet_end, it_net->High());
     base::TimeDelta overlap_duration = overlap_end - overlap_start;
     if (overlap_duration >= kTimeToInteractiveWindow) {
-      return std::max(lower_bound, it_mt->Low());
+      return std::max(lower_bound, main_quiet_start);
     }
 
     // The interval with earlier end time will not produce any more overlap, so
     // we move on from it.
-    if (it_mt->High() <= it_net->High()) {
-      it_mt++;
+    if (main_quiet_end <= it_net->High()) {
+      ++it_lt;
+      main_quiet_start = next_main_quiet_start;
     } else {
-      it_net++;
+      ++it_net;
     }
   }
 
@@ -512,10 +508,10 @@ void InteractiveDetector::CheckTimeToInteractiveReached() {
     return;
   }
 
-  AddCurrentlyActiveQuietIntervals(current_time);
-  const base::TimeTicks interactive_candidate =
-      FindInteractiveCandidate(page_event_times_.first_contentful_paint);
-  RemoveCurrentlyActiveQuietIntervals();
+  AddCurrentlyActiveNetworkQuietInterval(current_time);
+  const base::TimeTicks interactive_candidate = FindInteractiveCandidate(
+      page_event_times_.first_contentful_paint, current_time);
+  RemoveCurrentlyActiveNetworkQuietInterval();
 
   // No Interactive Candidate found.
   if (interactive_candidate.is_null())
@@ -529,19 +525,47 @@ void InteractiveDetector::CheckTimeToInteractiveReached() {
 
 void InteractiveDetector::OnTimeToInteractiveDetected() {
   LongTaskDetector::Instance().UnregisterObserver(this);
-  main_thread_quiet_windows_.clear();
   network_quiet_windows_.clear();
 
+  TRACE_EVENT_MARK_WITH_TIMESTAMP2(
+      "loading,rail", "InteractiveTime", interactive_time_, "frame",
+      ToTraceValue(GetSupplementable()->GetFrame()), "args",
+      ComputeTimeToInteractiveTraceArgs());
+
+  long_tasks_.clear();
+}
+
+std::unique_ptr<TracedValue>
+InteractiveDetector::ComputeTimeToInteractiveTraceArgs() {
+  // We log the trace event even if there is user input, but annotate the event
+  // with whether that happened.
   bool had_user_input_before_interactive =
       !page_event_times_.first_invalidating_input.is_null() &&
       page_event_times_.first_invalidating_input < interactive_time_;
 
-  // We log the trace event even if there is user input, but annotate the event
-  // with whether that happened.
-  TRACE_EVENT_MARK_WITH_TIMESTAMP2(
-      "loading,rail", "InteractiveTime", interactive_time_, "frame",
-      ToTraceValue(GetSupplementable()->GetFrame()),
-      "had_user_input_before_interactive", had_user_input_before_interactive);
+  auto dict = std::make_unique<TracedValue>();
+  dict->SetBoolean("had_user_input_before_interactive",
+                   had_user_input_before_interactive);
+  dict->SetDouble("total_blocking_time_ms",
+                  ComputeTotalBlockingTime().InMillisecondsF());
+  return dict;
+}
+
+base::TimeDelta InteractiveDetector::ComputeTotalBlockingTime() {
+  // We follow the same logic as the lighthouse computation in
+  // https://github.com/GoogleChrome/lighthouse/blob/f150573b5970cc90c8d0c2214f5738df5cde8a31/lighthouse-core/computed/metrics/total-blocking-time.js#L60-L74.
+  // In particular, tasks are clipped [FCP, TTI], and then all positive values
+  // of (task_length - 50) are added to the blocking time.
+  base::TimeDelta total_blocking_time;
+  for (const auto& long_task : long_tasks_) {
+    base::TimeTicks clipped_start =
+        std::max(long_task.Low(), page_event_times_.first_contentful_paint);
+    base::TimeTicks clipped_end = std::min(long_task.High(), interactive_time_);
+    total_blocking_time +=
+        std::max(base::TimeDelta(), clipped_end - clipped_start -
+                                        base::TimeDelta::FromMilliseconds(50));
+  }
+  return total_blocking_time;
 }
 
 void InteractiveDetector::ContextDestroyed() {

third_party/blink/renderer/core/loader/interactive_detector.h

@@ -14,6 +14,7 @@
 #include "third_party/blink/renderer/core/page/page_hidden_state.h"
 #include "third_party/blink/renderer/platform/heap/handle.h"
 #include "third_party/blink/renderer/platform/heap/persistent.h"
+#include "third_party/blink/renderer/platform/instrumentation/tracing/traced_value.h"
 #include "third_party/blink/renderer/platform/supplementable.h"
 #include "third_party/blink/renderer/platform/timer.h"
 #include "third_party/blink/renderer/platform/wtf/pod_interval.h"
@@ -160,22 +161,22 @@ class CORE_EXPORT InteractiveDetector
     bool was_hidden;
   };
 
-  // Stores sufficiently long quiet windows on main thread and network.
-  Vector<WTF::PODInterval<base::TimeTicks>> main_thread_quiet_windows_;
+  // Stores sufficiently long quiet windows on the network.
   Vector<WTF::PODInterval<base::TimeTicks>> network_quiet_windows_;
 
-  // Start times of currently active main thread and network quiet windows.
-  // Null base::TimeTicks values indicate main thread or network is not quiet at
-  // the moment.
-  base::TimeTicks active_main_thread_quiet_window_start_;
+  // Stores long tasks in order to compute Total Blocking Time (TBT) once Time
+  // To Interactive (TTI) is known.
+  Vector<WTF::PODInterval<base::TimeTicks>> long_tasks_;
+
+  // Start time of currently active network quiet windows.
+  // Null base::TimeTicks values indicate network is not quiet at the moment.
   base::TimeTicks active_network_quiet_window_start_;
 
-  // Adds currently active quiet main thread and network quiet windows to the
-  // vectors. Should be called before calling
-  // FindInteractiveCandidate.
-  void AddCurrentlyActiveQuietIntervals(base::TimeTicks current_time);
-  // Undoes AddCurrentlyActiveQuietIntervals.
-  void RemoveCurrentlyActiveQuietIntervals();
+  // Adds currently active quiet network quiet window to the
+  // vector. Should be called before calling FindInteractiveCandidate.
+  void AddCurrentlyActiveNetworkQuietInterval(base::TimeTicks current_time);
+  // Undoes AddCurrentlyActiveNetworkQuietInterval.
+  void RemoveCurrentlyActiveNetworkQuietInterval();
 
   std::unique_ptr<NetworkActivityChecker> network_activity_checker_;
   int ActiveConnections();
@@ -192,6 +193,8 @@ class CORE_EXPORT InteractiveDetector
   void TimeToInteractiveTimerFired(TimerBase*);
   void CheckTimeToInteractiveReached();
   void OnTimeToInteractiveDetected();
+  std::unique_ptr<TracedValue> ComputeTimeToInteractiveTraceArgs();
+  base::TimeDelta ComputeTotalBlockingTime();
 
   Vector<VisibilityChangeEvent> visibility_change_events_;
   bool initially_hidden_;
@@ -204,7 +207,8 @@ class CORE_EXPORT InteractiveDetector
   // long task before that quiet window, or lower_bound, whichever is bigger -
   // this is called the Interactive Candidate. Returns 0.0 if no such quiet
   // window is found.
-  base::TimeTicks FindInteractiveCandidate(base::TimeTicks lower_bound);
+  base::TimeTicks FindInteractiveCandidate(base::TimeTicks lower_bound,
+                                           base::TimeTicks current_time);
 
   // LongTaskObserver implementation
   void OnLongTaskDetected(base::TimeTicks start_time,

third_party/blink/renderer/core/loader/interactive_detector_test.cc

@@ -141,6 +141,14 @@ class InteractiveDetectorTest : public testing::Test {
 
   base::TimeTicks GetInteractiveTime() { return detector_->interactive_time_; }
 
+  void SetTimeToInteractive(base::TimeTicks interactive_time) {
+    detector_->interactive_time_ = interactive_time;
+  }
+
+  base::TimeDelta GetTotalBlockingTime() {
+    return detector_->ComputeTotalBlockingTime();
+  }
+
   ScopedTestingPlatformSupport<TestingPlatformSupportWithMockScheduler>
       platform_;
 
@@ -599,4 +607,78 @@ TEST_F(InteractiveDetectorTest, TotalInputDelay) {
             GetDetector()->GetTotalAdjustedInputDelay().InMilliseconds());
 }
 
+// In tests for Total Blocking Time (TBT) we call SetTimeToInteractive() instead
+// of allowing TimeToInteractive to occur because the computation is gated
+// behind tracing being enabled, which means that they won't run by default. In
+// addition, further complication stems from the fact that the vector of
+// longtasks is cleared at the end of OnTimeToInteractiveDetected(). Therefore,
+// the simplest solution is to manually set all of the relevant variables and
+// check the correctness of the method ComputeTotalBlockingTime(). This can be
+// revisited if we move TBT computations to occur outside of the trace event.
+TEST_F(InteractiveDetectorTest, TotalBlockingTimeZero) {
+  base::TimeTicks t0 = Now();
+  SimulateNavigationStart(t0);
+  // Set a high number of active connections, so that
+  // OnTimeToInteractiveDetected() is not called by accident.
+  SetActiveConnections(5);
+  SimulateFCPDetected(
+      /* fcp_time */ t0 + base::TimeDelta::FromMilliseconds(100),
+      /* detection_time */ t0 + base::TimeDelta::FromMilliseconds(100));
+
+  // Longtask of duration 51ms, but only 50ms occur after FCP.
+  SimulateLongTask(t0 + base::TimeDelta::FromMilliseconds(99),
+                   t0 + base::TimeDelta::FromMilliseconds(150));
+  // Longtask of duration 59ms, but only 49ms occur before TTI.
+  SimulateLongTask(t0 + base::TimeDelta::FromMilliseconds(201),
+                   t0 + base::TimeDelta::FromMilliseconds(260));
+  SetTimeToInteractive(t0 + base::TimeDelta::FromMilliseconds(250));
+  EXPECT_EQ(GetTotalBlockingTime(), base::TimeDelta());
+}
+
+TEST_F(InteractiveDetectorTest, TotalBlockingTimeNonZero) {
+  base::TimeTicks t0 = Now();
+  SimulateNavigationStart(t0);
+  // Set a high number of active connections, so that
+  // OnTimeToInteractiveDetected() is not called by accident.
+  SetActiveConnections(5);
+  SimulateFCPDetected(
+      /* fcp_time */ t0 + base::TimeDelta::FromMilliseconds(100),
+      /* detection_time */ t0 + base::TimeDelta::FromMilliseconds(100));
+
+  // Longtask fully before FCP.
+  SimulateLongTask(t0 + base::TimeDelta::FromMilliseconds(30),
+                   t0 + base::TimeDelta::FromMilliseconds(89));
+  // Longtask of duration 70ms, 60 ms of which occur after FCP. +10ms to TBT.
+  SimulateLongTask(t0 + base::TimeDelta::FromMilliseconds(90),
+                   t0 + base::TimeDelta::FromMilliseconds(160));
+  // Longtask of duration 80ms between FCP and TTI. +30ms to TBT.
+  SimulateLongTask(t0 + base::TimeDelta::FromMilliseconds(200),
+                   t0 + base::TimeDelta::FromMilliseconds(280));
+  // Longtask of duration 90ms, 70ms of which occur before TTI. +20ms to TBT.
+  SimulateLongTask(t0 + base::TimeDelta::FromMilliseconds(300),
+                   t0 + base::TimeDelta::FromMilliseconds(390));
+  // Longtask fully after TTI.
+  SimulateLongTask(t0 + base::TimeDelta::FromMilliseconds(371),
+                   t0 + base::TimeDelta::FromMilliseconds(472));
+  SetTimeToInteractive(t0 + base::TimeDelta::FromMilliseconds(370));
+  EXPECT_EQ(GetTotalBlockingTime(), base::TimeDelta::FromMilliseconds(60));
+}
+
+TEST_F(InteractiveDetectorTest, TotalBlockingSingleTask) {
+  base::TimeTicks t0 = Now();
+  SimulateNavigationStart(t0);
+  // Set a high number of active connections, so that
+  // OnTimeToInteractiveDetected() is not called by accident.
+  SetActiveConnections(5);
+  SimulateFCPDetected(
+      /* fcp_time */ t0 + base::TimeDelta::FromMilliseconds(100),
+      /* detection_time */ t0 + base::TimeDelta::FromMilliseconds(100));
+
+  // Longtask of duration 1s, from navigation start.
+  SimulateLongTask(t0, t0 + base::TimeDelta::FromSeconds(1));
+  SetTimeToInteractive(t0 + base::TimeDelta::FromMilliseconds(500));
+  // Truncated longtask is of length 400. So TBT is 400 - 50 = 350
+  EXPECT_EQ(GetTotalBlockingTime(), base::TimeDelta::FromMilliseconds(350));
+}
+
 }  // namespace blink