Skip EventLatency metrics if event time stamp is after cc stages

Ideally, if an event is associated with a compositor frame, it means
that the event was created before the compositor frame is submitted to
viz for presentation. So, the time stamp of the event should be smaller
than the start time of viz stage in CompositorFrameReporter. However, it
seems that it's not the case all the time (see the associated bug). For
now, let's silently ignore such cases instead of a DCHECK. Hopefully,
our work on investigating discrepancies between the new EventLatency and
the old Event.Latency would reveal the cause of the issue. If not, we
should reconsider this case.

Bug: 1093698
Change-Id: I4ce943fe2c9ed69caba82b34b652fa14e027d549
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2252678Reviewed-by: Sadrul Chowdhury <sadrul@chromium.org>
Commit-Queue: Mohsen Izadi <mohsen@chromium.org>
Cr-Commit-Position: refs/heads/master@{#779997}

cc/metrics/compositor_frame_reporter.cc

@@ -613,7 +613,15 @@ void CompositorFrameReporter::ReportEventLatencyHistograms() const {
                      [&event_metrics](const StageData& stage) {
                        return stage.start_time > event_metrics.time_stamp();
                      });
-    DCHECK(stage_it != stage_history_.end());
+    // TODO(crbug.com/1079116): Ideally, at least the start time of
+    // SubmitCompositorFrameToPresentationCompositorFrame stage should be
+    // greater than the event time stamp, but apparently, this is not always the
+    // case (see crbug.com/1093698). For now, skip to the next event in such
+    // cases. Hopefully, the work to reduce discrepancies between the new
+    // EventLatency and the old Event.Latency metrics would fix this issue. If
+    // not, we need to reconsider investigating this issue.
+    if (stage_it == stage_history_.end())
+      continue;
 
     const base::TimeDelta b2r_latency =
         stage_it->start_time - event_metrics.time_stamp();
@@ -789,7 +797,15 @@ void CompositorFrameReporter::ReportEventLatencyTraceEvents() const {
                      [&event_metrics](const StageData& stage) {
                        return stage.start_time > event_metrics.time_stamp();
                      });
-    DCHECK(stage_it != stage_history_.end());
+    // TODO(crbug.com/1079116): Ideally, at least the start time of
+    // SubmitCompositorFrameToPresentationCompositorFrame stage should be
+    // greater than the event time stamp, but apparently, this is not always the
+    // case (see crbug.com/1093698). For now, skip to the next event in such
+    // cases. Hopefully, the work to reduce discrepancies between the new
+    // EventLatency and the old Event.Latency metrics would fix this issue. If
+    // not, we need to reconsider investigating this issue.
+    if (stage_it == stage_history_.end())
+      continue;
 
     TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
         "cc,input", "BrowserToRendererCompositor", trace_id,

cc/trees/ukm_manager.cc

@@ -325,7 +325,16 @@ void UkmManager::RecordEventLatencyUKM(
         [&event_metrics](const CompositorFrameReporter::StageData& stage) {
           return stage.start_time > event_metrics.time_stamp();
         });
-    DCHECK(stage_it != stage_history.end());
+    // TODO(crbug.com/1079116): Ideally, at least the start time of
+    // SubmitCompositorFrameToPresentationCompositorFrame stage should be
+    // greater than the event time stamp, but apparently, this is not always the
+    // case (see crbug.com/1093698). For now, skip to the next event in such
+    // cases. Hopefully, the work to reduce discrepancies between the new
+    // EventLatency and the old Event.Latency metrics would fix this issue. If
+    // not, we need to reconsider investigating this issue.
+    if (stage_it == stage_history.end())
+      continue;
+
     builder.SetBrowserToRendererCompositor(
         (stage_it->start_time - event_metrics.time_stamp()).InMicroseconds());