[autofill] Ingore mouse move on Windows for the first 50ms.

[autofill] Ingore mouse move on Windows for the first 50ms.

BUG=458300
Committed: https://crrev.com/aa41e91e7ef29cd6d73666e9ad930cdc88a366d6
Cr-Commit-Position: refs/heads/master@{#321845}

[please use gerrit instead, 2015-03-19 17:40:53]

rouslan@chromium.org changed reviewers:
+ estade@chromium.org

[please use gerrit instead, 2015-03-19 17:40:53]

Evan, PTAL.

[Evan Stade, 2015-03-19 20:16:30]

https://codereview.chromium.org/1018393002/diff/20001/chrome/browser/ui/views...
File chrome/browser/ui/views/autofill/autofill_popup_base_view.cc (right):

https://codereview.chromium.org/1018393002/diff/20001/chrome/browser/ui/views...
chrome/browser/ui/views/autofill/autofill_popup_base_view.cc:150: if
((base::Time::Now() - show_time_).InMilliseconds() <= kMouseMoveIngoreMs)
if (base::Time::Now() < show_time_ + TimeDelta::FromMilliseconds(50))

but I feel like we should be using some timestamp on |event| rather than |now|
(there can be a big difference if Chrome is bogged down)

[please use gerrit instead, 2015-03-20 17:36:43]

PTAL Patch Set 4.

https://codereview.chromium.org/1018393002/diff/20001/chrome/browser/ui/views...
File chrome/browser/ui/views/autofill/autofill_popup_base_view.cc (right):

https://codereview.chromium.org/1018393002/diff/20001/chrome/browser/ui/views...
chrome/browser/ui/views/autofill/autofill_popup_base_view.cc:150: if
((base::Time::Now() - show_time_).InMilliseconds() <= kMouseMoveIngoreMs)
On 2015/03/19 20:16:30, Evan Stade wrote:
> if (base::Time::Now() < show_time_ + TimeDelta::FromMilliseconds(50))
> 
> but I feel like we should be using some timestamp on |event| rather than |now|
> (there can be a big difference if Chrome is bogged down)

Done.

[please use gerrit instead, 2015-03-20 19:13:19]

Note: a better approach is to use the time_stamp() from user's keyboard event
instead of system time. However, that would require a lot of plumbing throughout
Chrome and maybe even Blink.

[Evan Stade, 2015-03-20 19:27:52]

https://codereview.chromium.org/1018393002/diff/60001/chrome/browser/ui/views...
File chrome/browser/ui/views/autofill/autofill_popup_base_view.cc (right):

https://codereview.chromium.org/1018393002/diff/60001/chrome/browser/ui/views...
chrome/browser/ui/views/autofill/autofill_popup_base_view.cc:16: #include
<mmsystem.h>
ewww

can you use TimeTicks or something?

[please use gerrit instead, 2015-03-20 20:55:53]

https://codereview.chromium.org/1018393002/diff/60001/chrome/browser/ui/views...
File chrome/browser/ui/views/autofill/autofill_popup_base_view.cc (right):

https://codereview.chromium.org/1018393002/diff/60001/chrome/browser/ui/views...
chrome/browser/ui/views/autofill/autofill_popup_base_view.cc:16: #include
<mmsystem.h>
On 2015/03/20 19:27:52, Evan Stade wrote:
> ewww
> 
> can you use TimeTicks or something?

event.time_stamp() is comparable to GetTickCount() and timeGetTime(), because it
uses the 32-bit timer provided by the Get­Tick­Count() function:

http://blogs.msdn.com/b/oldnewthing/archive/2014/01/22/10491576.aspx

timeGetTime() is pretty much the same thing as, but sometimes more accurate
than, GetTickCount():

http://blogs.msdn.com/b/larryosterman/archive/2009/09/02/what-s-the-differenc...

If you don't like the include, we can use Get­Tick­Count(), which is a Win32 API
function that's somehow magically available without an include.

I tried using base::TickCount as you suggested, but somehow it always lags by
~200 ms behind the event.time_stamp(). So we cannot use TimeTicks to compare to
event.time_stamp().

[please use gerrit instead, 2015-03-20 21:16:31]

On 2015/03/20 20:55:53, Rouslan Solomakhin wrote:
> I tried using base::TickCount as you suggested, but somehow it always lags by
> ~200 ms behind the event.time_stamp(). So we cannot use TimeTicks to compare
to
> event.time_stamp().

s/TickCount/TimeTicks/

[Evan Stade, 2015-03-20 21:29:00]

On 2015/03/20 21:16:31, Rouslan Solomakhin wrote:
> On 2015/03/20 20:55:53, Rouslan Solomakhin wrote:
> > I tried using base::TickCount as you suggested, but somehow it always lags
by
> > ~200 ms behind the event.time_stamp(). So we cannot use TimeTicks to compare
> to
> > event.time_stamp().
> 
> s/TickCount/TimeTicks/

https://code.google.com/p/chromium/codesearch#chromium/src/ui/events/event_ut...

[please use gerrit instead, 2015-03-20 21:56:42]

On 2015/03/20 21:29:00, Evan Stade wrote:
> On 2015/03/20 21:16:31, Rouslan Solomakhin wrote:
> > On 2015/03/20 20:55:53, Rouslan Solomakhin wrote:
> > > I tried using base::TickCount as you suggested, but somehow it always lags
> by
> > > ~200 ms behind the event.time_stamp(). So we cannot use TimeTicks to
compare
> > to
> > > event.time_stamp().
> > 
> > s/TickCount/TimeTicks/
> 
>
https://code.google.com/p/chromium/codesearch#chromium/src/ui/events/event_ut...

Unfortunately, ui::EventTimeForNow() also suffers the offset from
event.time_stamp(). Here's a log of events:

Show time: 100925142
Event time: 100924812 - skip
Event time: 100924828 - skip
Event time: 100924828 - skip
Event time: 100924843 - skip
Event time: 100924843 - skip
Event time: 100924859 - skip
Event time: 100924859 - skip
Event time: 100924875 - skip
Event time: 100924968 - skip
Event time: 100924984 - skip
Event time: 100925000 - skip
Event time: 100925046 - skip
Event time: 100925062 - skip
Event time: 100925078 - skip
Event time: 100925093 - skip
Event time: 100925109 - skip
Event time: 100925109 - skip
Event time: 100925125 - skip
Event time: 100925125 - skip
Event time: 100925140 - skip
Event time: 100925140 - skip
Event time: 100925156 - skip
Event time: 100925156 - skip
Event time: 100925171 - skip
Event time: 100925203 - handle

That's a 391ms lag for handling mouse-move event, because ui::EventTimeForNow()
returns time that's 330ms in the future.

[Evan Stade, 2015-03-21 01:00:17]

Perhaps rvargas or cpu can help demystify the situation.

tl;dr: we want to compare an event timestamp to the time a certain function was
called. Is this possible? See problems above.

[please use gerrit instead, 2015-03-21 01:15:00]

When I print EventTimeForNow inside of the AutofillPopupBaseView::OnMouseMoved
handler, it is 491ms in the future from the MouseEvent time stamp. (Exact
difference varies.)

MouseEvent time stamp: 112839781
      EventTimeForNow: 112840272
         GetTickCount: 112839781
          timeGetTime: 112839776

GetTickCount matches MouseEvent time stamp exactly. timeGetTime is off by 5ms.

[please use gerrit instead, 2015-03-21 01:23:30]

Here's me printing the delta in Event constructor for a while:

ERROR	9264	12252	18:17:40-892	c:\src\chrome\src\ui\events\event.cc	225	Event
delta: 488
ERROR	9264	12252	18:17:40-900	c:\src\chrome\src\ui\events\event.cc	225	Event
delta: 496
ERROR	9264	12252	18:17:40-908	c:\src\chrome\src\ui\events\event.cc	225	Event
delta: 488
ERROR	9264	12252	18:17:40-915	c:\src\chrome\src\ui\events\event.cc	225	Event
delta: 496
ERROR	9264	12252	18:17:40-924	c:\src\chrome\src\ui\events\event.cc	225	Event
delta: 489
ERROR	9264	12252	18:17:40-933	c:\src\chrome\src\ui\events\event.cc	225	Event
delta: 498

[please use gerrit instead, 2015-03-21 01:24:12]

Better formatting.

Event delta: 488
Event delta: 496
Event delta: 488
Event delta: 496
Event delta: 489
Event delta: 498

(That was me moving the mouse around the page.)

[rvargas (doing something else), 2015-03-21 01:30:58]

On 2015/03/21 01:15:00, Rouslan Solomakhin wrote:
> When I print EventTimeForNow inside of the AutofillPopupBaseView::OnMouseMoved
> handler, it is 491ms in the future from the MouseEvent time stamp. (Exact
> difference varies.)
> 
> MouseEvent time stamp: 112839781
>       EventTimeForNow: 112840272
>          GetTickCount: 112839781
>           timeGetTime: 112839776
> 
> GetTickCount matches MouseEvent time stamp exactly. timeGetTime is off by 5ms.

Ideally we should not be using direct OS calls to get a timestamp anywhere
(that's what TimeTicks::Now is for). I don't follow where the other timestamp
comes from, as I only see EventTimeForNow() which uses TimeTicks::Now().
Comparing things that come from the OS against things that come form base:: will
result in drifts.

Semi-unrelated to this CL, EventTimeForNow seems conceptually wrong... as
TimeDelta is not a type that is supposed to be used to store a timestamp. That
would be a TimeTicks (or Time of course).

[Evan Stade, 2015-03-21 01:33:29]

On 2015/03/21 01:30:58, rvargas wrote:
> On 2015/03/21 01:15:00, Rouslan Solomakhin wrote:
> > When I print EventTimeForNow inside of the
AutofillPopupBaseView::OnMouseMoved
> > handler, it is 491ms in the future from the MouseEvent time stamp. (Exact
> > difference varies.)
> > 
> > MouseEvent time stamp: 112839781
> >       EventTimeForNow: 112840272
> >          GetTickCount: 112839781
> >           timeGetTime: 112839776
> > 
> > GetTickCount matches MouseEvent time stamp exactly. timeGetTime is off by
5ms.
> 
> Ideally we should not be using direct OS calls to get a timestamp anywhere
> (that's what TimeTicks::Now is for). I don't follow where the other timestamp
> comes from, as I only see EventTimeForNow() which uses TimeTicks::Now().
> Comparing things that come from the OS against things that come form base::
will
> result in drifts.

Doesn't TimeTicks::Now() gets its time from the OS? It seems to be using
timeGetTime()

> 
> Semi-unrelated to this CL, EventTimeForNow seems conceptually wrong... as
> TimeDelta is not a type that is supposed to be used to store a timestamp. That
> would be a TimeTicks (or Time of course).

Yep, as pointed out here:
https://code.google.com/p/chromium/issues/detail?id=453559

[rvargas (doing something else), 2015-03-21 02:02:58]

On 2015/03/21 01:33:29, Evan Stade wrote:
> On 2015/03/21 01:30:58, rvargas wrote:
> > On 2015/03/21 01:15:00, Rouslan Solomakhin wrote:
> > > When I print EventTimeForNow inside of the
> AutofillPopupBaseView::OnMouseMoved
> > > handler, it is 491ms in the future from the MouseEvent time stamp. (Exact
> > > difference varies.)
> > > 
> > > MouseEvent time stamp: 112839781
> > >       EventTimeForNow: 112840272
> > >          GetTickCount: 112839781
> > >           timeGetTime: 112839776
> > > 
> > > GetTickCount matches MouseEvent time stamp exactly. timeGetTime is off by
> 5ms.
> > 
> > Ideally we should not be using direct OS calls to get a timestamp anywhere
> > (that's what TimeTicks::Now is for). I don't follow where the other
timestamp
> > comes from, as I only see EventTimeForNow() which uses TimeTicks::Now().
> > Comparing things that come from the OS against things that come form base::
> will
> > result in drifts.
> 
> Doesn't TimeTicks::Now() gets its time from the OS? It seems to be using
> timeGetTime()

It can use QueryPerformanceCounter... I thought it also had something to correct
drift but I don't see it now; maybe it was Time::Now.


> 
> > 
> > Semi-unrelated to this CL, EventTimeForNow seems conceptually wrong... as
> > TimeDelta is not a type that is supposed to be used to store a timestamp.
That
> > would be a TimeTicks (or Time of course).
> 
> Yep, as pointed out here:
> https://code.google.com/p/chromium/issues/detail?id=453559

[please use gerrit instead, 2015-03-21 15:20:14]

On 2015/03/21 01:30:58, rvargas wrote:
> On 2015/03/21 01:15:00, Rouslan Solomakhin wrote:
> > When I print EventTimeForNow inside of the
AutofillPopupBaseView::OnMouseMoved
> > handler, it is 491ms in the future from the MouseEvent time stamp. (Exact
> > difference varies.)
> > 
> > MouseEvent time stamp: 112839781
> >       EventTimeForNow: 112840272
> >          GetTickCount: 112839781
> >           timeGetTime: 112839776
> > 
> > GetTickCount matches MouseEvent time stamp exactly. timeGetTime is off by
5ms.
> 
> Ideally we should not be using direct OS calls to get a timestamp anywhere
> (that's what TimeTicks::Now is for). I don't follow where the other timestamp
> comes from

event.time_stamp() comes from EventTimeFromNative() in events_win.cc:

https://code.google.com/p/chromium/codesearch#chromium/src/ui/events/win/even...

base::TimeDelta EventTimeFromNative(const base::NativeEvent& native_event) {
  return base::TimeDelta::FromMilliseconds(native_event.time);
}

base::NativeEvent on windows is MSG. MSG.time gets its time from GetTickCount():

http://blogs.msdn.com/b/oldnewthing/archive/2014/01/22/10491576.aspx

That's why GetTickCount() and timeGetTime() appears to work better than
base::TimeTicks::Now() or ui::EventTimeForNow().

> , as I only see EventTimeForNow() which uses TimeTicks::Now().
> Comparing things that come from the OS against things that come form base::
will
> result in drifts.
> 
> Semi-unrelated to this CL, EventTimeForNow seems conceptually wrong... as
> TimeDelta is not a type that is supposed to be used to store a timestamp. That
> would be a TimeTicks (or Time of course).

[spang, 2015-03-22 17:14:02]

spang@chromium.org changed reviewers:
+ spang@chromium.org

[spang, 2015-03-22 17:14:03]

https://codereview.chromium.org/1018393002/diff/60001/chrome/browser/ui/views...
File chrome/browser/ui/views/autofill/autofill_popup_base_view.cc (right):

https://codereview.chromium.org/1018393002/diff/60001/chrome/browser/ui/views...
chrome/browser/ui/views/autofill/autofill_popup_base_view.cc:16: #include
<mmsystem.h>
On 2015/03/20 20:55:53, Rouslan Solomakhin wrote:
> On 2015/03/20 19:27:52, Evan Stade wrote:
> > ewww
> > 
> > can you use TimeTicks or something?
> 
> event.time_stamp() is comparable to GetTickCount() and timeGetTime(), because
it
> uses the 32-bit timer provided by the Get­Tick­Count() function:
> 
> http://blogs.msdn.com/b/oldnewthing/archive/2014/01/22/10491576.aspx
> 
> timeGetTime() is pretty much the same thing as, but sometimes more accurate
> than, GetTickCount():
> 
>
http://blogs.msdn.com/b/larryosterman/archive/2009/09/02/what-s-the-differenc...
> 
> If you don't like the include, we can use Get­Tick­Count(), which is a Win32
API
> function that's somehow magically available without an include.
> 
> I tried using base::TickCount as you suggested, but somehow it always lags by
> ~200 ms behind the event.time_stamp(). So we cannot use TimeTicks to compare
to
> event.time_stamp().

Please don't put this kind of workaround here with out some kind of TODO or
comment.

If what you say is true, then there is a bug in the events implementation where
the timestamp can be populated from 1 of 2 clocks. Sometimes it is
base::TimeTicks(), and sometimes it is GetTickCount().

You cannot completely fix the issue by simply changing the choice of clock.

[Evan Stade, 2015-03-23 17:18:21]

spang: do you know what the correct fix is?

rouslan: perhaps we can go with patchset 1 for now with a TODO to use event
timestamps/EventTimeForNow after the bugs have been fixed

[spang, 2015-03-23 18:18:46]

On 2015/03/23 17:18:21, Evan Stade wrote:
> spang: do you know what the correct fix is?

T
> 
> rouslan: perhaps we can go with patchset 1 for now with a TODO to use event
> timestamps/EventTimeForNow after the bugs have been fixed

[spang, 2015-03-23 18:22:17]

On 2015/03/23 18:18:46, spang wrote:
> On 2015/03/23 17:18:21, Evan Stade wrote:
> > spang: do you know what the correct fix is?

The correct fix is to decide on one of the 2 clocks and use it consistently,
everywhere. We can't use one clock for native events and a different one for
synthetic ones. I'm not sure which choice is best.

I do think this workaround is defensible until we fix the larger issue but it
should be marked as such.

[please use gerrit instead, 2015-03-23 18:26:29]

Evan, PTAL Patch Set 6.

[Evan Stade, 2015-03-23 18:57:12]

lgtm

https://codereview.chromium.org/1018393002/diff/100001/chrome/browser/ui/view...
File chrome/browser/ui/views/autofill/autofill_popup_base_view.cc (right):

https://codereview.chromium.org/1018393002/diff/100001/chrome/browser/ui/view...
chrome/browser/ui/views/autofill/autofill_popup_base_view.cc:150: // become
comparable.
link to bug

[please use gerrit instead, 2015-03-23 19:52:06]

Sending to cq.

https://codereview.chromium.org/1018393002/diff/100001/chrome/browser/ui/view...
File chrome/browser/ui/views/autofill/autofill_popup_base_view.cc (right):

https://codereview.chromium.org/1018393002/diff/100001/chrome/browser/ui/view...
chrome/browser/ui/views/autofill/autofill_popup_base_view.cc:150: // become
comparable.
On 2015/03/23 18:57:11, Evan Stade wrote:
> link to bug

Done.

[please use gerrit instead, 2015-03-23 19:52:11]

The CQ bit was checked by rouslan@chromium.org

[please use gerrit instead, 2015-03-23 19:52:11]

The patchset sent to the CQ was uploaded after l-g-t-m from estade@chromium.org
Link to the patchset: https://codereview.chromium.org/1018393002/#ps120001
(title: "Link to bug in todo.")

[commit-bot: I haz the power, 2015-03-23 19:53:15]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1018393002/120001

[commit-bot: I haz the power, 2015-03-23 21:00:11]

Committed patchset #7 (id:120001)

[commit-bot: I haz the power, 2015-03-23 21:01:30]

Patchset 7 (id:??) landed as
https://crrev.com/aa41e91e7ef29cd6d73666e9ad930cdc88a366d6
Cr-Commit-Position: refs/heads/master@{#321845}