New issue
Advanced search Search tips
Starred by 2 users

Issue metadata

Status: Started
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug

Blocked on:
issue 810437



Sign in to add a comment

ast/events/hr-timestamp/input-events.html is flaky

Project Member Reported by majidvp@chromium.org, May 25

Issue description


https://test-results.appspot.com/dashboards/flakiness_dashboard.html#testType=webkit_layout_tests&tests=fast%2Fevents%2Fhr-timestamp

There are at least two issues:

a) FAILURE which happens on all platforms
b) TIMEOUT which seems to be limited to Mac.
 
Blocking: 810437
Cc: skyos...@chromium.org
Case A seems to be due to changes in behavior of how we clamp time values in blink. 
The clamping logic was revamped recently. 

Previously we were clamping to 5us but we are now clamping to 100us with some
additional psuedorandom jitter. [1] introduced the change and updates the test
however I think the news clamping logic can introduce up to 200us difference
for event time stamp.

[1] https://chromium-review.googlesource.com/c/chromium/src/+/849993/4/third_party/WebKit/Source/core/timing/PerformanceBase.cpp


I think the 200us max clamping difference is related to a change in how we
clamp time values that need to be relative to time origin. The new logic
clamps both the time origin and time value before computing the difference
while the old logic computed the difference first and then clamped once. 


simplified old logic:
double clamped_time_in_seconds = ClampTimeResolution(monotonic_time - time_origin);

simplified new logic:
double clamped_time_in_seconds =
      ClampTimeResolution(TimeTicksInSeconds(monotonic_time)) -
      ClampTimeResolution(TimeTicksInSeconds(time_origin));


I think dpending on the random jitter applied, the new logic can lead to clamped
version to be different by 200us from original unclamped version.

The test was only updated assuming a 100us max difference which is why it is failing
occasionally.


There are two possible simple fixes:
1. Update the test to reflect this change by having it expect a 200us clamp difference.
2. Change clamping logic to be similar to the old version.


I assume we want 1 since the chance in [1] was intentional. skyostil@ wdyt?


Example of case A:

https://test-results.appspot.com/data/layout_results/WebKit_Linux_Trusty/45532/layout-test-results/results.html

Output:
PASS Event timestamp should be equal to the timestamp provided by the platform for mousedown
FAIL Event timestamp should be equal to the timestamp provided by the platform for keydown assert_approx_equals: expected 29.200000000000003 +/- 0.100001 but got 29.399999999441206
PASS Event timestamp should be equal to the timestamp provided by the platform for touchstart
FAIL Event timestamp should be equal to the timestamp provided by the platform for click assert_approx_equals: expected 31.200000000000003 +/- 0.100001 but got 31.39999999984866
PASS Event timestamp should be equal to the timestamp provided by the platform for contextmenu
PASS Event timestamp should be equal to the timestamp provided by the platform for wheel

Project Member

Comment 3 by bugdroid1@chromium.org, May 29

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/4e103290aaecba63db670aead636ee8733e10e35

commit 4e103290aaecba63db670aead636ee8733e10e35
Author: Majid Valipour <majidvp@chromium.org>
Date: Tue May 29 15:22:53 2018

Fix flakiness in hr-timestamp/input-events.html test

Update the test to expect the difference between expected
unclamped time with observed time to be at most 200us instead of 100us.


A recent change [1] made it so that the clamping can lead to up to 200us
of adjustment for when we are computing a time values that is relative
to time origin. The new logic, first clamps both the time origin and time value
and then computes their delta while the old logic computed the delta first and
then clamped it once.

## simplified old logic
double clamped_time_in_seconds = ClampTimeResolution(monotonic_time - time_origin);

## simplified new logic

double clamped_time_in_seconds =
      ClampTimeResolution(TimeTicksInSeconds(monotonic_time)) -
      ClampTimeResolution(TimeTicksInSeconds(time_origin));


Flakiness dashboard link: https://test-results.appspot.com/dashboards/flakiness_dashboard.html#testType=webkit_layout_tests&tests=fast%2Fevents%2Fhr-timestamp

[1] https://chromium-review.googlesource.com/c/chromium/src/+/849993/4/third_party/WebKit/Source/core/timing/PerformanceBase.cpp

TEST= locally ran the test 1000 times which all passed. run-webkit-tests --repeat-each=1000  fast/events/hr-timestamp/input-events.html

Bug: 846750,  810437 
Change-Id: I69547484838c3b21bc3c15441baec287db0f5e8e
Reviewed-on: https://chromium-review.googlesource.com/1072466
Commit-Queue: Majid Valipour <majidvp@chromium.org>
Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
Cr-Commit-Position: refs/heads/master@{#562430}
[modify] https://crrev.com/4e103290aaecba63db670aead636ee8733e10e35/third_party/WebKit/LayoutTests/fast/events/hr-timestamp/input-events.html

FWIW, I cannot reproduce the timeout locally on MacOS 10.13 High Sierra. I am using the following with both release and debug builds:

 ./third_party/blink/tools/run_web_tests.py -t default --repeat-each=100 --iterations=10  fast/events/hr-timestamp

My suspicion is that sometimes the event generators do not result in expected event so the callback is never called for some event types which causes time out. I am not sure why that will be but if I can narrow this down to a specific event type then it may help.

Project Member

Comment 5 by bugdroid1@chromium.org, Jun 13

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/583b8a18aaef8bb463193cec014b12c9fdb40879

commit 583b8a18aaef8bb463193cec014b12c9fdb40879
Author: Majid Valipour <majidvp@chromium.org>
Date: Wed Jun 13 17:46:35 2018

Speculative fix for timeout flakiness of hr-timestamp/input-events.html

Now call prevent default in event handler to ensure context menu does
not show up which can potentially hijack other events.

Added an explicit timeout to help produce more detailed picture when
timeout happens and hopefully help us identify the root cause if the
above fix is not working.

Also updated expectation to only expect timeout on Mac.


Bug: 846750, 846726
Change-Id: Ica117c5cd7eafc559c3e457af008d1a1043deff6
Reviewed-on: https://chromium-review.googlesource.com/1099039
Commit-Queue: Majid Valipour <majidvp@chromium.org>
Reviewed-by: Navid Zolghadr <nzolghadr@chromium.org>
Cr-Commit-Position: refs/heads/master@{#566891}
[modify] https://crrev.com/583b8a18aaef8bb463193cec014b12c9fdb40879/third_party/WebKit/LayoutTests/TestExpectations
[modify] https://crrev.com/583b8a18aaef8bb463193cec014b12c9fdb40879/third_party/WebKit/LayoutTests/fast/events/hr-timestamp/input-events.html

Blocking: -810437
Blockedon: 810437
Now I can see specific tests timing out. Here is a few examples:

- https://test-results.appspot.com/data/layout_results/Mac10_12_Tests/13920/layout-test-results/results.html
- https://test-results.appspot.com/data/layout_results/Mac10_12_Tests/13902/layout-test-results/results.html
- https://test-results.appspot.com/data/layout_results/Mac10_13_Tests/3657/layout-test-results/results.html
- https://test-results.appspot.com/data/layout_results/Mac10_10_Tests/33279/layout-test-results/results.html


In every case the output looks like below. Thanks to the new logging I can see that the failure is caused by 
not receiving the expected click and wheel events. It so happens that these two are just before and after the 
contextmenu. I think this strongly suggests that on Mac we are still somehow showing the context menu
which is absorbing the other two adjacent events.

My next step is to move the contextmenu test to its own test and see if that fixes the issue.



--- Typical output ----
PASS Event timestamp should be equal to the timestamp provided by the platform for mousedown
PASS Event timestamp should be equal to the timestamp provided by the platform for keydown
PASS Event timestamp should be equal to the timestamp provided by the platform for touchstart
FAIL Event timestamp should be equal to the timestamp provided by the platform for click assert_unreached: timeout with received events: mousedown, keydown, touchstart, contextmenu Reached unreachable code
PASS Event timestamp should be equal to the timestamp provided by the platform for contextmenu
FAIL Event timestamp should be equal to the timestamp provided by the platform for wheel assert_unreached: timeout with received events: mousedown, keydown, touchstart, contextmenu Reached unreachable code







Project Member

Comment 9 by bugdroid1@chromium.org, Jul 12

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/8696fc59786065ffc8a2e06f2db8f9e9ebc772a1

commit 8696fc59786065ffc8a2e06f2db8f9e9ebc772a1
Author: Majid Valipour <majidvp@chromium.org>
Date: Thu Jul 12 15:46:20 2018

[testing] Move context menu ever timestamp test to a separate test

ContextMenu interaction with other events is a suspected cause of
flakiness of the original test. This CL is separating it from the
rest as a potential fix.

Bug: 846750
Change-Id: I3d452388be65984ca82238d55a938d7a273fcf3f
Reviewed-on: https://chromium-review.googlesource.com/1134180
Reviewed-by: Navid Zolghadr <nzolghadr@chromium.org>
Commit-Queue: Majid Valipour <majidvp@chromium.org>
Cr-Commit-Position: refs/heads/master@{#574573}
[add] https://crrev.com/8696fc59786065ffc8a2e06f2db8f9e9ebc772a1/third_party/WebKit/LayoutTests/fast/events/hr-timestamp/context-menu-event.html
[modify] https://crrev.com/8696fc59786065ffc8a2e06f2db8f9e9ebc772a1/third_party/WebKit/LayoutTests/fast/events/hr-timestamp/input-events.html

So I still see timeouts in the dashboard. My next step is to make tests run in a sequence removing all possible avenue for potential interference. 

Sign in to add a comment