Closed Bug 1274704 Opened 8 years ago Closed 8 years ago

Intermittent browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should work - Got false, expected true

Categories

(DevTools :: Responsive Design Mode, defect, P1)

Product:
DevTools
Component:
Responsive Design Mode
Version:
49 Branch
Type:
defect

Tracking

(firefox49 fixed, firefox50 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 50
Tracking Flags:
Tracking Status
firefox49 --- fixed
firefox50 --- fixed

People

(Reporter: KWierso, Assigned: danhuang)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

setTimeout exevute callback before the delay
380.58 KB, image/png
Details
Bug 1274704 - update Date.now() to performance.now() for getting accurate time diffence.
58 bytes, text/x-review-board-request
jryans
: review+
Details
The opposite: https://treeherder.mozilla.org/logviewer.html#?job_id=28363840&repo=mozilla-inbound
Summary: Intermittent browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should work - Got false, expected true → Intermittent browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should work - Got false, expected true | should not work - Got true, expected false
:danhuang, would you be able to investigate this? It looks related to bug 920956.
Blocks: 920956
Flags: needinfo?(dhuang)
Priority: -- → P1
Assignee: nobody → dhuang
Status: NEW → ASSIGNED
Flags: needinfo?(dhuang)
As far as getting WinXP builds working, it should be possible in a VM, though I no longer have an XP one myself. Looking at the Windows setup guide[1], it seems like it could be tricky, since VS2015 apparently requires at least Windows 7? I am not sure about this. Another option is to request RelEng to loan you a machine[2]. It should be possible to then build on that machine as needed[3], though I have not done this myself before. If we still can't figure out the issue, then we should probably disable the test on WinXP. [1]: https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Build_Instructions/Windows_Prerequisites [2]: https://wiki.mozilla.org/ReleaseEngineering/How_To/Request_a_slave [3]: https://wiki.mozilla.org/ReleaseEngineering/How_To/Run_a_build_on_a_loaner
This is the 12th top intermittent. Looks like the first of devtools. Note that it also happen much less frequently on linux. Here is some try push with additional debug statements: https://treeherder.mozilla.org/#/jobs?repo=try&revision=8d0218933fde You can see the try syntax to get to run on Windows XP.
Reproduced the intermittent once: 07:04:59 INFO - 657 INFO TEST-START | devtools/client/responsivedesign/test/browser_responsiveui_touch.js 07:04:59 INFO - 658 INFO Entering test bound 07:04:59 INFO - 659 INFO Adding a new tab with URL: 'http://mochi.test:8888/browser/devtools/client/responsivedesign/test/touch.html' 07:04:59 INFO - 660 INFO Waiting for event: 'load' on [object XULElement]. 07:04:59 INFO - 661 INFO Got event: 'load' on [object XULElement]. 07:04:59 INFO - 662 INFO URL 'http://mochi.test:8888/browser/devtools/client/responsivedesign/test/touch.html' loading complete 07:04:59 INFO - 663 INFO Waiting for event: 'on' on [object Object]. 07:04:59 INFO - 664 INFO Waiting for event: 'contentResize' on [object Object]. 07:04:59 INFO - 665 INFO Got event: 'contentResize' on [object Object]. 07:04:59 INFO - 666 INFO Got event: 'on' on [object Object]. 07:04:59 INFO - 667 INFO testWithNoTouch: Initial test parameter and mouse mouse outside div element 07:04:59 INFO - 668 INFO testWithNoTouch: Move mouse into the div element 07:04:59 INFO - updatedpreviousEvent(mouseover) at 1464707099441 07:04:59 INFO - updatedpreviousEvent(mouseenter) at 1464707099441 07:04:59 INFO - updatedpreviousEvent(mousemove) at 1464707099441 07:04:59 INFO - 669 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | mouseenter or mouseover should work - 07:04:59 INFO - 670 INFO testWithNoTouch: Drag the div element 07:04:59 INFO - onMouseDown, previousEvent:mousemove touchEndTime:0 elapsed:1464707099442 07:04:59 INFO - updatedpreviousEvent(mousedown) at 1464707099443 07:04:59 INFO - updatedpreviousEvent(mousemove) at 1464707099443 07:04:59 INFO - 671 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | touchmove shouldn't work - 07:04:59 INFO - updatedpreviousEvent(mouseup) at 1464707099445 07:04:59 INFO - updatedpreviousEvent(click) at 1464707099445 07:04:59 INFO - 672 INFO testWithNoTouch: Move mouse out of the div element 07:04:59 INFO - updatedpreviousEvent(mouseout) at 1464707099448 07:04:59 INFO - updatedpreviousEvent(mouseleave) at 1464707099448 07:04:59 INFO - 673 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | mouseout or mouseleave should work - 07:04:59 INFO - 674 INFO testWithNoTouch: Click the div element 07:04:59 INFO - onMouseDown, previousEvent:mouseleave touchEndTime:0 elapsed:1464707099452 07:04:59 INFO - updatedpreviousEvent(mousedown) at 1464707099452 07:04:59 INFO - updatedpreviousEvent(mouseup) at 1464707099453 07:04:59 INFO - updatedpreviousEvent(click) at 1464707099453 07:04:59 INFO - 675 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should not work - 07:04:59 INFO - 676 INFO testWithTouch: Initial test parameter and mouse mouse outside div element 07:04:59 INFO - 677 INFO testWithTouch: Move mouse into the div element 07:04:59 INFO - 678 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | mouseenter or mouseover should not work - 07:04:59 INFO - 679 INFO testWithTouch: Drag the div element 07:04:59 INFO - updatedpreviousEvent(touchstart) at 1464707099465 07:04:59 INFO - updatedpreviousEvent(touchmove) at 1464707099471 07:04:59 INFO - 680 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | touchmove should work - 07:04:59 INFO - updatedpreviousEvent(touchend) at 1464707099474 07:04:59 INFO - 681 INFO testWithTouch: Move mouse out of the div element 07:04:59 INFO - 682 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | mouseout or mouseleave should not work - 07:04:59 INFO - 683 INFO testWithMetaViewportEnabled: click the div element with <meta name='viewport'> 07:04:59 INFO - updatedpreviousEvent(touchstart) at 1464707099483 07:04:59 INFO - updatedpreviousEvent(touchend) at 1464707099484 07:04:59 INFO - onMouseDown, previousEvent:touchend touchEndTime:1464707099484 elapsed:302 07:04:59 INFO - updatedpreviousEvent(mousedown) at 1464707099786 07:04:59 INFO - updatedpreviousEvent(mouseover) at 1464707099787 07:04:59 INFO - updatedpreviousEvent(mouseenter) at 1464707099787 07:04:59 INFO - updatedpreviousEvent(mousemove) at 1464707099787 07:04:59 INFO - updatedpreviousEvent(mouseup) at 1464707099788 07:04:59 INFO - updatedpreviousEvent(click) at 1464707099788 07:04:59 INFO - 684 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should work - 07:04:59 INFO - 685 INFO testWithMetaViewportEnabled: click the div element with <meta name='viewport' content='user-scalable=no'> 07:04:59 INFO - updatedpreviousEvent(touchstart) at 1464707099791 07:04:59 INFO - updatedpreviousEvent(touchend) at 1464707099792 07:04:59 INFO - onMouseDown, previousEvent:touchend touchEndTime:1464707099792 elapsed:1 07:04:59 INFO - updatedpreviousEvent(mousedown) at 1464707099793 07:04:59 INFO - updatedpreviousEvent(mousemove) at 1464707099793 07:04:59 INFO - updatedpreviousEvent(mouseup) at 1464707099794 07:04:59 INFO - updatedpreviousEvent(click) at 1464707099794 07:04:59 INFO - 686 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should not work - 07:04:59 INFO - 687 INFO testWithMetaViewportEnabled: click the div element with <meta name='viewport' content='minimum-scale=maximum-scale'> 07:04:59 INFO - updatedpreviousEvent(touchstart) at 1464707099797 07:04:59 INFO - updatedpreviousEvent(touchend) at 1464707099798 07:04:59 INFO - onMouseDown, previousEvent:touchend touchEndTime:1464707099798 elapsed:2 07:04:59 INFO - updatedpreviousEvent(mousedown) at 1464707099800 07:04:59 INFO - updatedpreviousEvent(mousemove) at 1464707099801 07:04:59 INFO - updatedpreviousEvent(mouseup) at 1464707099801 07:04:59 INFO - updatedpreviousEvent(click) at 1464707099801 07:04:59 INFO - 688 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should not work - 07:04:59 INFO - 689 INFO testWithMetaViewportEnabled: click the div element with <meta name='viewport' content='width=device-width'> 07:04:59 INFO - updatedpreviousEvent(touchstart) at 1464707099805 07:04:59 INFO - updatedpreviousEvent(touchend) at 1464707099806 07:04:59 INFO - onMouseDown, previousEvent:touchend touchEndTime:1464707099806 elapsed:0 07:04:59 INFO - updatedpreviousEvent(mousedown) at 1464707099806 07:04:59 INFO - updatedpreviousEvent(mousemove) at 1464707099807 07:04:59 INFO - updatedpreviousEvent(mouseup) at 1464707099808 07:04:59 INFO - updatedpreviousEvent(click) at 1464707099808 07:04:59 INFO - 690 INFO TEST-PASS | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should not work - 07:04:59 INFO - 691 INFO testWithMetaViewportDisabled: click the div element with <meta name='viewport'> 07:04:59 INFO - updatedpreviousEvent(touchstart) at 1464707099814 07:04:59 INFO - updatedpreviousEvent(touchend) at 1464707099815 07:05:00 INFO - onMouseDown, previousEvent:touchend touchEndTime:1464707099814 elapsed:285 07:05:00 INFO - updatedpreviousEvent(mousedown) at 1464707100099 07:05:00 INFO - updatedpreviousEvent(mousemove) at 1464707100100 07:05:00 INFO - updatedpreviousEvent(mouseup) at 1464707100100 07:05:00 INFO - updatedpreviousEvent(click) at 1464707100101 07:05:00 INFO - TEST-INFO | started process screenshot 07:05:00 INFO - TEST-INFO | screenshot: exit 0 07:05:00 INFO - 692 INFO checking window state 07:05:00 INFO - 693 INFO TEST-UNEXPECTED-FAIL | devtools/client/responsivedesign/test/browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should work - Got false, expected true 07:05:00 INFO - Stack trace: 07:05:00 INFO - chrome://mochikit/content/browser-test.js:test_is:967 07:05:00 INFO - chrome://mochitests/content/browser/devtools/client/responsivedesign/test/browser_responsiveui_touch.js:testWithMetaViewportDisabled:132 Does that ring any bell?
Base on the above log, I add more dump() in getDelayBeforeMouseEvent()[1], and run on the try server[2]. And finds that when the setTimeout duration between touchend and mousedown set to 300ms, sometimes it's seems the time interval between these two events is less than 300ms. [1] https://dxr.mozilla.org/mozilla-central/source/devtools/shared/touch/simulator-content.js#324 [2] https://treeherder.mozilla.org/#/jobs?repo=try&revision=ab6c2819600c&selectedJob=21881860 [3] Error log: 12:01:36 INFO - 688 INFO testWithMetaViewportDisabled: click the div element with <meta name='viewport'> 12:01:36 INFO - updatedpreviousEvent(touchstart) at 1464897696699 12:01:36 INFO - updatedpreviousEvent(touchend) at 1464897696702 >>>>> 12:01:36 INFO - getDelayBeforeMouseEvent: viewport not enable, delay 300ms <<<<< 12:01:36 INFO - onMouseDown, previousEvent:touchend touchEndTime:1464897696702 elapsed:287 12:01:36 INFO - updatedpreviousEvent(mousedown) at 1464897696989 12:01:36 INFO - updatedpreviousEvent(mousemove) at 1464897696990 12:01:36 INFO - updatedpreviousEvent(mouseup) at 1464897696992 12:01:36 INFO - updatedpreviousEvent(click) at 1464897696992 12:01:37 INFO - TEST-INFO | started process screenshot 12:01:37 INFO - TEST-INFO | screenshot: exit 0 12:01:37 INFO - 689 INFO checking window state 12:01:37 INFO - 690 INFO TEST-UNEXPECTED-FAIL | devtools/client/responsivedesign /test/browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should work - Got false, expected true
Attached image setTimeout didn't work correct (obsolete) —
Attachment #8762494 - Attachment is obsolete: true
Sorry about didn't have much progress here, I still can't successfully reproduce on WinXP slave. But sometimes the setTimeout() actually execute the callback before the delay, see attach attachment 8762504 [details][1]. When setTimeout() calls, the SetTimeoutOrInterval()[2] would be called to set the delay and callback information in to mTimer[3]. I didn't find out the root cause why the TimerThread[4] execute the callback early than the delay. Do you have any suggestion about this, or which part should I look more deeper to find out the root cause? Thanks. [1] https://jsfiddle.net/e0cmn2fy/ [2] https://dxr.mozilla.org/mozilla-beta/source/dom/base/nsGlobalWindow.cpp#11691 [3] https://dxr.mozilla.org/mozilla-beta/source/dom/base/nsGlobalWindow.cpp#550 [4] https://dxr.mozilla.org/mozilla-beta/source/xpcom/threads/nsTimerImpl.cpp#267
Flags: needinfo?(jryans)
(Sorry for the delay, I did not see this until after the work week.) :bz, do you know the details of our setTimeout implementation, or can you redirect to someone who does? Is it expected that setTimeout's callback might be called _before_ the delay time has passed? I was already aware that it can be delayed _longer_ than the delay value, but I am a little surprised to see a _shorter_ delay. Comment 18 includes a test case (https://jsfiddle.net/e0cmn2fy/) for this.
Flags: needinfo?(jryans) → needinfo?(bzbarsky)
> Is it expected that setTimeout's callback might be called _before_ the delay time has passed? Well, there's this comment and code in nsGlobalWindow::RunTimeout: if (aTimeout && aTimeout->mWhen > now) { // The OS timer fired early (which can happen due to the timers // having lower precision than TimeStamp does). Set |deadline| to // be the time when the OS timer *should* have fired so that any // timers that *should* have fired before aTimeout *will* be fired // now. deadline = aTimeout->mWhen; and we then proceed to run everything that has an mWhen <= deadline. That said, firing 14ms early as in that screenshot in attachment 8762504 [details] would be somewhat unlikely to be caused by timer precision issues. Except maybe on some Windows versions where iirc timers are only accurate to 16ms at best.... On the other hand, this general form of testcase: var start = Date.now(); var delay = 300; setTimeout(function() { if (Date.now() - start < delay) { alert("fail"); } }, delay); can certainly alert "fail" in a world of perfect setTimeout behavior. And the reason for that is that in such a world the function will run 300ms after the setTimeout call. But the elapsed time according to Date.now() need not be 300ms, because Date.now() returns wall-clock time. This can be affected by various things: settimeofday() calls, the user changing the clock, NTP suddenly discovering that the clock is way off and doing a step, that sort of thing. A good first step is rewriting the testcase as follows: var start = performance.now(); var delay = 300; setTimeout(function() { if (performance.now() - start < delay) { alert("fail"); } }, delay); and seeing if _that_ ever alerts. If it does not, the problem was presumably wall-clock adjustment while the timeout was pending, and hence Date.now() lying to you about how much time had passed. Looks to me like the actual test at devtools/client/responsivedesign/test/touch.html uses JS Date for timing as well, so another option is to just move that to performance.now() and see if this bug goes away...
Flags: needinfo?(bzbarsky)
:bz, thanks for your suggestion. After update Date.now() to performance.now() in the testcase, the alert didn't pop up again!
Yes, thanks for the help :bz, it all makes more sense now.
Comment on attachment 8764189 [details] Bug 1274704 - update Date.now() to performance.now() for getting accurate time diffence. https://reviewboard.mozilla.org/r/60214/#review57108 Thanks for investigating this!
Attachment #8764189 - Flags: review?(jryans) → review+
Keywords: checkin-needed
Pushed by ryanvm@gmail.com: https://hg.mozilla.org/integration/fx-team/rev/a640fd9a849c Update Date.now() to performance.now() for getting accurate time diffence. r=jryans
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/a640fd9a849c
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
status-firefox50: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 50
are we sure this is fixed ? seems still to happen ?
Status: RESOLVED → REOPENED
Flags: needinfo?(dhuang)
Resolution: FIXED → ---
If it helps, we could loosen the time check a bit. Like we could check that it's at least 200 ms instead of starting with 300 ms or larger.
I would decrease the time check duration from 300ms to 200ms to see if it can pass try server.
Flags: needinfo?(dhuang)
I spent some time to check to the OrangeFactor Robot's report[1], and found out that the intermittent errors occur in mozilla-aurora tree is caused by the mochitest.tests.zip in the test packages url[2] is referenced to firefox-49.0a2. This means the devtools/client/responsivedesign/test/touch.html in the mochitest.tests.zip still uses javascript Date for timing, not using the performance.now(). I think using performance.now() is actually fix the intermittent error[3]. But there are still other intermittent error[4] sometimes happened in fx-team and mozilla-inbound tree. These two intermittent errors[3][4] are causing by different reasons. So I suggest that this bug is only use to fix the intermittent error[3]. And we should open the other bug for tracing the intermittent error[4]. Do you think it is proper to open another bug to fix intermittent error[4]? [1] https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1274704&startday=2016-06-27&endday=2016-07-03&tree=all [2] https://public-artifacts.taskcluster.net/Efd2LInYSB-d5HVi1RF6WQ/0/public/build/firefox-49.0a2.en-US.win64.test_packages.json [3] 300ms delay between touch events and mouse events should work - Got false, expected true [4] 300ms delay between touch events and mouse events should not work - Got true, expected false
Flags: needinfo?(jryans)
(In reply to Dan Huang[:danhuang] from comment #35) > I spent some time to check to the OrangeFactor Robot's report[1], and found > out that the intermittent errors occur in mozilla-aurora tree is caused by > the mochitest.tests.zip in the test packages url[2] is referenced to > firefox-49.0a2. This means the > devtools/client/responsivedesign/test/touch.html in the mochitest.tests.zip > still uses javascript Date for timing, not using the performance.now(). Yes, I think I agree. When I alter the orangefactor search to only include days after the perf.now() fix was uplifted to aurora in comment 30, then there are no more reports for aurora. > I think using performance.now() is actually fix the intermittent error[3]. > But there are still other intermittent error[4] sometimes happened in > fx-team and mozilla-inbound tree. These two intermittent errors[3][4] are > causing by different reasons. > > So I suggest that this bug is only use to fix the intermittent error[3]. And > we should open the other bug for tracing the intermittent error[4]. > > Do you think it is proper to open another bug to fix intermittent error[4]? Yes, let's file a new bug for the "300ms delay between touch events and mouse events should not work - Got true, expected false" case so it can be tracked separately. It looks like we can mark this one resolved again, since all cases in the last 7 days are for message [4] which we'll file a new bug for.
Flags: needinfo?(jryans)
Summary: Intermittent browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should work - Got false, expected true | should not work - Got true, expected false → Intermittent browser_responsiveui_touch.js | 300ms delay between touch events and mouse events should work - Got false, expected true
I filed bug 1284654 for the case "300ms delay between touch events and mouse events should not work - Got true, expected false".
Status: REOPENED → RESOLVED
Closed: 8 years ago → 8 years ago
Resolution: --- → FIXED
See Also: → 1284654
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: