New issue
Advanced search Search tips

Issue 642714 link

Starred by 3 users

Issue metadata

Status: Fixed
Owner:
Closed: Feb 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug

Blocked on:
issue 616787



Sign in to add a comment

Event.timeStamp larger than performance.now() in some event handlers

Project Member Reported by majidvp@chromium.org, Aug 31 2016

Issue description

Based on report from Facebook usage of event.timeStamp for performance measurements they are seeing cases where event.timeStmap is ahead of performance.now() in event handler which should not be the case. Here are some more details:

> On about 5% of events we see that Event.timeStamp is a few milliseconds before performance.now in the event handler. This doesn’t seem to happen on  all kinds of events – the only events where this seems to happen are mouse*, key*, touch* and wheel events. For example we get a lot of samples of timeupdate events but none of them have a negative duration here.


Also 
> Looks like this issue is mostly Windows. 6% of all windows time stamps are negative. We do see a tiny number of Mac and Linux samples that are negative but it's less than 0.01%



 
Status: Started (was: Assigned)
Based on this information, I believe the Windows problem is a manifestation of issue 616787.

This explains why it happens for input events (timestamp coming from UI process) and never happens for timeupdate event (timestamp coming from renderer process).

After discussing with dtapuska@ and tdresser@ we think in cases where timeticks is not consistent cross processes we should use the input event's IPC message arrival time in renderer process as the event timestamp. This means that the event timestamp won't capture the UI process and IPC latency but this seems better than a timestamp that cannot be compared to performance.now. 
Blockedon: 616787

Comment 3 by n...@fb.com, Aug 31 2016

Labels: DevRel-Facebook
Project Member

Comment 4 by bugdroid1@chromium.org, Sep 6 2016

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

commit 5802f789601b88d99f72d8ed081651df4b3fdf4b
Author: majidvp <majidvp@chromium.org>
Date: Tue Sep 06 22:03:59 2016

Use IO thread time for event timestamp if TimeTicks isn't consistent x-process.

On some platforms (a subset of Windows) we don't have a monotonic clock that
is consistent across processes. On such platforms we cannot reliably compare
timeticks that are from different processes.

This is particularly problematic for WebInputEvent whose timestamp comes
from UI process but is consumed by the renderer process and eventually exposed
to the web as high-resolution timestamp.

This patch introduces a fallback where we use the message received time on the
renderer IO thread (i.e., the earliest time we get the message on the renderer)
as the event timestamp and sidestep the inconsistency.

BUG= 642714 

Review-Url: https://codereview.chromium.org/2289173003
Cr-Commit-Position: refs/heads/master@{#416737}

[modify] https://crrev.com/5802f789601b88d99f72d8ed081651df4b3fdf4b/content/renderer/input/input_event_filter.cc
[modify] https://crrev.com/5802f789601b88d99f72d8ed081651df4b3fdf4b/content/renderer/input/input_event_filter.h

Project Member

Comment 5 by bugdroid1@chromium.org, Oct 13 2016

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

commit 878e7bcf8646a318cae3cd38b3030f77ca7276b5
Author: majidvp <majidvp@chromium.org>
Date: Thu Oct 13 16:06:35 2016

Expand event timestamp timebase check to Ozone and Android.

For now we only collect UMA stats on such failures.

BUG= 642714 

Review-Url: https://codereview.chromium.org/2408063005
Cr-Commit-Position: refs/heads/master@{#425048}

[modify] https://crrev.com/878e7bcf8646a318cae3cd38b3030f77ca7276b5/ui/events/android/motion_event_android.cc
[modify] https://crrev.com/878e7bcf8646a318cae3cd38b3030f77ca7276b5/ui/events/ozone/evdev/event_converter_evdev.cc

Status: Fixed (was: Started)
According to our UMA stats for bad timestamps in browser process UMA (Event.TimestampHasValidTimebase.Browser):


Linux: 00.05%  => This is pretty large but we have expected it and in fact have a fallback option which corrects these bad timestamps.
Android: 0.001%
MacOs & ChromeOS: ~ 0%
Windows: we don't collect this stat as we don't use platform provided timestamp for events. See #4.

This is pretty good. Marking this as fixed. We are tracking few corner cases of bad timestamp elsewhere.


Sign in to add a comment