Event Timing - Handle modal dialog interference
* Previous undesired outcome: event timing could measure the arbitrarily
long user input waiting time on synchronous javascript modal dialogs
and report it as part of the presentation delay.
* Root cause: synchronous modal dialogs paused the event-damaged frame
to be presented until after user close the dialog.
* This CL address it by: treating modal dialogs showing as another way
of page responding and report the dialog showing timestamp as an
alternative end time for duration measurement to any events that was
interfered by the modal dialog in event timing.
Bug: 1435448
Change-Id: I8f48c0292e45b01ea51ac5134096a08f584fdcfb
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/5258894
Commit-Queue: Aoyuan Zuo <[email protected]>
Reviewed-by: Michal Mocny <[email protected]>
Reviewed-by: Dmitry Gozman <[email protected]>
Cr-Commit-Position: refs/heads/main@{#1259367}
diff --git a/testing/variations/fieldtrial_testing_config.json b/testing/variations/fieldtrial_testing_config.json
index e75eff1..582738cf 100644
--- a/testing/variations/fieldtrial_testing_config.json
+++ b/testing/variations/fieldtrial_testing_config.json
@@ -7231,6 +7231,29 @@
]
}
],
+ "EventTimingFallbackToModalDialogStart": [
+ {
+ "platforms": [
+ "android",
+ "chromeos",
+ "chromeos_lacros",
+ "fuchsia",
+ "linux",
+ "mac",
+ "windows",
+ "android_webview",
+ "android_weblayer"
+ ],
+ "experiments": [
+ {
+ "name": "Enabled",
+ "enable_features": [
+ "EventTimingFallbackToModalDialogStart"
+ ]
+ }
+ ]
+ }
+ ],
"EvictionUnlocksResources": [
{
"platforms": [
diff --git a/third_party/blink/common/features.cc b/third_party/blink/common/features.cc
index 0e71cc3..50f54fb 100644
--- a/third_party/blink/common/features.cc
+++ b/third_party/blink/common/features.cc
@@ -830,6 +830,12 @@
"EnableMojoJSProtectedMemory",
base::FEATURE_DISABLED_BY_DEFAULT);
+// Enable reporting the modal dialog start time as an alternative end time for
+// duration measurement in performance event timing.
+BASE_FEATURE(kEventTimingFallbackToModalDialogStart,
+ "EventTimingFallbackToModalDialogStart",
+ base::FEATURE_DISABLED_BY_DEFAULT);
+
// Controls whether LCP calculations should exclude low-entropy images. If
// enabled, then the associated parameter sets the cutoff, expressed as the
// minimum number of bits of encoded image data used to encode each rendered
diff --git a/third_party/blink/public/common/features.h b/third_party/blink/public/common/features.h
index 98f95a3b..f21a82e 100644
--- a/third_party/blink/public/common/features.h
+++ b/third_party/blink/public/common/features.h
@@ -434,6 +434,9 @@
BLINK_COMMON_EXPORT BASE_DECLARE_FEATURE(kEnableMojoJSProtectedMemory);
+BLINK_COMMON_EXPORT BASE_DECLARE_FEATURE(
+ kEventTimingFallbackToModalDialogStart);
+
BLINK_COMMON_EXPORT BASE_DECLARE_FEATURE(kExcludeLowEntropyImagesFromLCP);
BLINK_COMMON_EXPORT extern const base::FeatureParam<double>
kMinimumEntropyForLCP;
diff --git a/third_party/blink/renderer/core/page/chrome_client.cc b/third_party/blink/renderer/core/page/chrome_client.cc
index 665da92..5c55389 100644
--- a/third_party/blink/renderer/core/page/chrome_client.cc
+++ b/third_party/blink/renderer/core/page/chrome_client.cc
@@ -38,6 +38,7 @@
#include "third_party/blink/renderer/core/page/page.h"
#include "third_party/blink/renderer/core/page/scoped_page_pauser.h"
#include "third_party/blink/renderer/core/probe/core_probes.h"
+#include "third_party/blink/renderer/core/timing/dom_window_performance.h"
#include "third_party/blink/renderer/platform/heap/garbage_collected.h"
#include "third_party/blink/renderer/platform/runtime_enabled_features.h"
#include "ui/display/screen_info.h"
@@ -94,6 +95,7 @@
static bool OpenJavaScriptDialog(LocalFrame* frame,
const String& message,
const Delegate& delegate) {
+ DOMWindowPerformance::performance(*frame->DomWindow())->WillShowModalDialog();
// Suspend pages in case the client method runs a new event loop that would
// otherwise cause the load to continue while we're in the middle of
// executing JavaScript.
@@ -269,6 +271,8 @@
return false;
}
+ DOMWindowPerformance::performance(*frame->DomWindow())->WillShowModalDialog();
+
// Suspend pages in case the client method runs a new event loop that would
// otherwise cause the load to continue while we're in the middle of
// executing JavaScript.
diff --git a/third_party/blink/renderer/core/timing/window_performance.cc b/third_party/blink/renderer/core/timing/window_performance.cc
index 5521592..58193a7 100644
--- a/third_party/blink/renderer/core/timing/window_performance.cc
+++ b/third_party/blink/renderer/core/timing/window_performance.cc
@@ -511,35 +511,13 @@
std::optional<int> key_code = event_data->GetKeyCode();
std::optional<PointerId> pointer_id = event_data->GetPointerId();
- const bool is_artificial_pointerup_or_click =
- (entry->name() == event_type_names::kPointerup ||
- entry->name() == event_type_names::kClick) &&
- entry->startTime() == pending_pointer_down_start_time_;
-
- if (is_artificial_pointerup_or_click) {
- UseCounter::Count(GetExecutionContext(),
- WebFeature::kEventTimingArtificialPointerupOrClick);
- }
-
- // The page visibility was changed, or this is an artificial event. We
- // fallback entry's end time to its processingEnd (as if there was no next
- // paint needed).
- const bool fallback_end_time_to_processing_end =
- (last_visibility_change_timestamp_ > event_timestamp &&
- last_visibility_change_timestamp_ < presentation_timestamp)
-#if BUILDFLAG(IS_MAC)
- || is_artificial_pointerup_or_click
-#endif // BUILDFLAG(IS_MAC)
- ;
+ absl::optional<base::TimeTicks> fallback_time =
+ GetFallbackTime(entry, event_timestamp, presentation_timestamp);
base::TimeTicks entry_end_timetick =
- fallback_end_time_to_processing_end
- ? GetTimeOriginInternal() + base::Milliseconds(entry->processingEnd())
- : presentation_timestamp;
+ fallback_time.has_value() ? *fallback_time : presentation_timestamp;
DOMHighResTimeStamp entry_end_time =
- fallback_end_time_to_processing_end
- ? entry->processingEnd()
- : MonotonicTimeToDOMHighResTimeStamp(presentation_timestamp);
+ MonotonicTimeToDOMHighResTimeStamp(entry_end_timetick);
base::TimeDelta processing_time =
base::Milliseconds(entry->processingEnd() - entry->processingStart());
@@ -633,6 +611,70 @@
}
}
+absl::optional<base::TimeTicks> WindowPerformance::GetFallbackTime(
+ PerformanceEventTiming* entry,
+ base::TimeTicks event_timestamp,
+ base::TimeTicks presentation_timestamp) {
+ // For artificial events on MacOS, we will fallback entry's end time to its
+ // processingEnd (as if there was no next paint needed). crbug.com/1321819.
+ const bool is_artificial_pointerup_or_click =
+ (entry->name() == event_type_names::kPointerup ||
+ entry->name() == event_type_names::kClick) &&
+ entry->startTime() == pending_pointer_down_start_time_;
+
+ if (is_artificial_pointerup_or_click) {
+ UseCounter::Count(GetExecutionContext(),
+ WebFeature::kEventTimingArtificialPointerupOrClick);
+ }
+
+ // If the page visibility was changed. We fallback entry's end time to its
+ // processingEnd (as if there was no next paint needed). crbug.com/1312568.
+ const bool was_page_visibility_changed =
+ last_visibility_change_timestamp_ > event_timestamp &&
+ last_visibility_change_timestamp_ < presentation_timestamp;
+
+ // An javascript synchronous modal dialog showed before the event frame
+ // got presented. User could wait for arbitrarily long on the dialog. Thus
+ // we fall back presentation time to the pre dialog showing time.
+ // crbug.com/1435448.
+ bool fallback_end_time_to_dialog_time = false;
+ base::TimeTicks first_modal_dialog_timestamp;
+
+ // Clean up stale dialog times.
+ while (!show_modal_dialog_timestamps_.empty() &&
+ show_modal_dialog_timestamps_.front() < event_timestamp) {
+ show_modal_dialog_timestamps_.pop_front();
+ }
+
+ if (!show_modal_dialog_timestamps_.empty() &&
+ show_modal_dialog_timestamps_.front() < presentation_timestamp) {
+ if (base::FeatureList::IsEnabled(
+ features::kEventTimingFallbackToModalDialogStart)) {
+ fallback_end_time_to_dialog_time = true;
+ }
+ first_modal_dialog_timestamp = show_modal_dialog_timestamps_.front();
+ }
+
+ const bool fallback_end_time_to_processing_end =
+ was_page_visibility_changed
+#if BUILDFLAG(IS_MAC)
+ || is_artificial_pointerup_or_click
+#endif // BUILDFLAG(IS_MAC)
+ ;
+
+ // Return minimum fallback time.
+ base::TimeTicks processing_end_timetick =
+ GetTimeOriginInternal() + base::Milliseconds(entry->processingEnd());
+ if (fallback_end_time_to_dialog_time && fallback_end_time_to_processing_end) {
+ return std::min(first_modal_dialog_timestamp, processing_end_timetick);
+ } else if (fallback_end_time_to_dialog_time) {
+ return first_modal_dialog_timestamp;
+ } else if (fallback_end_time_to_processing_end) {
+ return processing_end_timetick;
+ }
+ return absl::nullopt;
+}
+
bool WindowPerformance::SetInteractionIdAndRecordLatency(
PerformanceEventTiming* entry,
std::optional<int> key_code,
@@ -755,6 +797,10 @@
last_visibility_change_timestamp_);
}
+void WindowPerformance::WillShowModalDialog() {
+ show_modal_dialog_timestamps_.push_back(base::TimeTicks::Now());
+}
+
EventCounts* WindowPerformance::eventCounts() {
if (!event_counts_)
event_counts_ = MakeGarbageCollected<EventCounts>();
diff --git a/third_party/blink/renderer/core/timing/window_performance.h b/third_party/blink/renderer/core/timing/window_performance.h
index 1ba7976..7c4703c 100644
--- a/third_party/blink/renderer/core/timing/window_performance.h
+++ b/third_party/blink/renderer/core/timing/window_performance.h
@@ -130,6 +130,8 @@
bool FirstInputDetected() const { return !!first_input_timing_; }
+ void WillShowModalDialog();
+
// This method creates a PerformanceEventTiming and if needed creates a
// presentation promise to calculate the |duration| attribute when such
// promise is resolved.
@@ -226,9 +228,20 @@
// timing buffer if needed.
void NotifyAndAddEventTimingBuffer(PerformanceEventTiming* entry);
+ // Return a valid fallback time in event timing if there's one; otherwise
+ // return nullopt.
+ absl::optional<base::TimeTicks> GetFallbackTime(
+ PerformanceEventTiming* entry,
+ base::TimeTicks event_timestamp,
+ base::TimeTicks presentation_timestamp);
+
// The last time the page visibility was changed.
base::TimeTicks last_visibility_change_timestamp_;
+ // A list of timestamps that javascript modal dialogs was showing. These are
+ // timestamps right before start showing each dialog.
+ Deque<base::TimeTicks> show_modal_dialog_timestamps_;
+
// Controls if we register a new presentation promise upon events arrival.
bool need_new_promise_for_event_presentation_time_ = true;
// Counts the total number of presentation promises we've registered for
diff --git a/third_party/blink/renderer/core/timing/window_performance_test.cc b/third_party/blink/renderer/core/timing/window_performance_test.cc
index c4694fef3..3bfb14f 100644
--- a/third_party/blink/renderer/core/timing/window_performance_test.cc
+++ b/third_party/blink/renderer/core/timing/window_performance_test.cc
@@ -1083,7 +1083,7 @@
// as event duration ending time.
// See crbug.com/1321819
TEST_F(WindowPerformanceTest, ArtificialPointerupOrClick) {
- // Arbitrary keycode picked for testing
+ // Arbitrary pointerId picked for testing
PointerId pointer_id = 4;
// Pointerdown
diff --git a/third_party/blink/web_tests/external/wpt/event-timing/modal-dialog-interrupt-paint.html b/third_party/blink/web_tests/external/wpt/event-timing/modal-dialog-interrupt-paint.html
new file mode 100644
index 0000000..011311a0
--- /dev/null
+++ b/third_party/blink/web_tests/external/wpt/event-timing/modal-dialog-interrupt-paint.html
@@ -0,0 +1,38 @@
+<!DOCTYPE html>
+<html>
+<meta charset=utf-8 />
+<title>Event Timing: Modal Dialog Interrupt Paint</title>
+<button id='testButtonId'>Click me.</button>
+<script src=/https/chromium.googlesource.com/resources/testharness.js></script>
+<script src=/https/chromium.googlesource.com/resources/testharnessreport.js></script>
+<script src=/https/chromium.googlesource.com/resources/testdriver.js></script>
+<script src=/https/chromium.googlesource.com/resources/testdriver-actions.js></script>
+<script src=/https/chromium.googlesource.com/resources/testdriver-vendor.js></script>
+<script src=resources/event-timing-test-utils.js></script>
+
+<script>
+ let observedEntries = [];
+ const map = new Map();
+ const events = ['click'];
+ const showModalDialog = () => {
+ alert();
+ };
+ document.getElementById('testButtonId').addEventListener("click", showModalDialog);
+
+ promise_test(async t => {
+ assert_implements(window.PerformanceEventTiming, 'Event Timing is not supported.');
+
+ const callback = (entryList) => { observedEntries = observedEntries.concat(entryList.getEntries().filter(filterAndAddToMap(events, map))); };
+ const readyToResolve = () => { return observedEntries.length >= 1; };
+ const observerPromise = createPerformanceObserverPromise(['event'], callback, readyToResolve);
+
+ await interactAndObserve('click', document.getElementById('testButtonId'), observerPromise);
+
+ const clickEntry = observedEntries[0];
+ assert_less_than(clickEntry.startTime + clickEntry.duration, clickEntry.processingEnd, 'Event duration measurement should stop at the modal dialog showing time, which should be before processingEnd.');
+ assert_greater_than(clickEntry.interactionId, 0, 'Should have a non-trivial interactionId for click event');
+ }, "Event Timing: showing modal dialogs is an alternative end point.");
+
+</script>
+
+</html>
