Closed Bug 557406 Opened 14 years ago Closed 14 years ago

Intermittent xpcshell failure in test_bookmarks.js | false == true

Categories

(Firefox :: Bookmarks & History, defect)

Product:
Firefox
Component:
Bookmarks & History
Platform:
x86
Windows Server 2003
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 3.7a5

People

(Reporter: philor, Assigned: mak)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

v1.1 [Checkin: Comment 93]
4.33 KB, patch
Details | Diff | Splinter Review
patch v1.0 [Checkin: Comment 112]
39.05 KB, patch
dietrich
: review+
Details | Diff | Splinter Review 
http://tinderbox.mozilla.org/Firefox/1270514698.1270515874.6073.gz
WINNT 5.2 mozilla-central opt test xpcshell on 2010/04/05 17:44:58
s: win32-slave05

*** PLACES TESTS: check that the separator was created with a valid dateAdded
*** PLACES TESTS: beforeInsert = 1270515477834999
*** PLACES TESTS: dateAdded = 1270515477825000
TEST-UNEXPECTED-FAIL | e:/builds/moz2_slave/mozilla-central-win32-opt-unittest-xpcshell/build/xpcshell/tests/test_places/bookmarks/test_bookmarks.js | false == true - See following stack:
JS frame :: e:\builds\moz2_slave\mozilla-central-win32-opt-unittest-xpcshell\build\xpcshell\head.js :: do_throw :: line 257
JS frame :: e:\builds\moz2_slave\mozilla-central-win32-opt-unittest-xpcshell\build\xpcshell\head.js :: do_check_eq :: line 287
JS frame :: e:\builds\moz2_slave\mozilla-central-win32-opt-unittest-xpcshell\build\xpcshell\head.js :: do_check_true :: line 299
JS frame :: e:/builds/moz2_slave/mozilla-central-win32-opt-unittest-xpcshell/build/xpcshell/tests/test_places/bookmarks/test_bookmarks.js :: testSimpleFolderResult :: line 675
JS frame :: e:/builds/moz2_slave/mozilla-central-win32-opt-unittest-xpcshell/build/xpcshell/tests/test_places/bookmarks/test_bookmarks.js :: run_test :: line 645
JS frame :: e:\builds\moz2_slave\mozilla-central-win32-opt-unittest-xpcshell\build\xpcshell\head.js :: _execute_test :: line 151
JS frame :: -e :: <TOP_LEVEL> :: line 1
TEST-INFO | (xpcshell/head.js) | exiting test

And previously, the one I mistakenly called bug 530687:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270496052.1270498444.19544.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/05 12:34:12
s: win32-slave27
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270520707.1270523506.24048.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/05 19:25:07
s: win32-slave18
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270526567.1270527857.2032.gz
WINNT 5.2 mozilla-central opt test xpcshell on 2010/04/05 21:02:47
s: mw32-ix-slave15
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270531123.1270533463.15825.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/05 22:18:43
s: win32-slave36
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270535308.1270538437.28769.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/05 23:28:28
s: win32-slave42
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270562287.1270565691.1481.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/06 06:58:07
s: win32-slave20
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270563939.1270566218.3329.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/06 07:25:39
s: mw32-ix-slave06
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270543310.1270546077.23755.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/06 01:41:50
s: win32-slave26
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270592012.1270593744.28273.gz
WINNT 5.2 mozilla-central opt test xpcshell on 2010/04/06 15:13:32
s: win32-slave12
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270590569.1270593965.28851.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/06 14:49:29
s: win32-slave07
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270624787.1270626980.18748.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/07 00:19:47
s: win32-slave16

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270629837.1270630984.30268.gz
WINNT 5.2 mozilla-central opt test xpcshell on 2010/04/07 01:43:57
s: win32-slave36

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270626821.1270629680.24900.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/07 00:53:41
s: win32-slave07
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270752493.1270753729.17927.gz
WINNT 5.2 mozilla-central opt test xpcshell on 2010/04/08 11:48:13
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270767313.1270769876.4610.gz
WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/08 15:55:13
s: win32-slave32
Depends on: 558745
It looks like we have a full millisecond of skew in the separator test.  The other tests (or many of them, at least) have been adjusted by a millisecond, but the separator case adjusts by a *microsecond*, and from the log we see that it's a bit later...except for the millisecond skew.

*** PLACES TESTS: check that the separator was created with a valid dateAdded
*** PLACES TESTS: beforeInsert = 1271186556881999
*** PLACES TESTS: dateAdded = 1271186556873000

I think we should change

  var beforeInsert = Date.now() * 1000 - 1;

to

  var beforeInsert = (Date.now() - 1) * 1000;

if we have some reason to believe that we'll only ever get adjusted by a single ms.  (Can we just keep the VMs from getting their time adjusted during a test run, and have them resync with NTP between runs?  I guess this goes away when we move to the talos hardware, though?)

As an aside, if we could write the tests like:

LOG("check that...").
LOG("beforeInsert...").
LOG("dateAdded...").
do_check_same_or_ordered(beforeInsert, dateAdded);

then the log message could be more useful in the summary, TBPLrobot could excerpt it better, and we would see something more useful than "false == true" in the summary as well.
Attached patch v1 (obsolete) — — Splinter Review 
per shaver's comment.
Assignee: nobody → dietrich
s/us/ms/
Attachment #438899 - Attachment is obsolete: true
tree is tumultuous. i'll do a test landing of this once it's a bit clearer.
Landed, will keep an eye on it to see if it helps.

http://hg.mozilla.org/mozilla-central/rev/a02d1f25ce68
Status: NEW → ASSIGNED
(And, cruelly enough, that was on your push.)
I think we need to solve this with either:

* a fix to the time sync on these VMs so that we preserve causality order during test execution (it's interesting that it only seems to happen on Windows!)

* a revisiting of the tests that rely on tight timing order, to make sure that they're really checking what they want to be checking and that they are not excessively precise.  For most of the cases we're really, I think, checking that the timestamp is set to something at all recent: if the separator creation time were even a *second* off, I don't think we would consider it a big problem.  Especially since we're doing so much stuff async here, and in the presence of Weave you have multi-computer clock issues.

The easiest fix is probably to make the slop here be a full second, and encapsulate it in a check_time_after(before, after) test call that hides the offset amount and can give us better diagnostics.
i think this happens on Windows due to what i posted here: https://bugzilla.mozilla.org/show_bug.cgi?id=558745#c2

the 2 timers used by pr_now and js date.now() have a really large difference in precision as Drew pointed at, this difference can be up to 11ms (but looks like it can go up to about 16ms).
I think we should try with the 11ms and 16ms values, to try finding the edge.
Clearly what I'd really like is having PR_Now use the same code of Date.now(), we don't need much precision out of PR_Now i think, there is PRIntervalNow() for that.
i meant PRIntervalTime, clearly :\
looking at last logs, i can't find any skew going over 16ms, that is about Windows timers precision.
Yes, duh, of course.  So I propose check_time_ordered(before, after) and that we bake a 20ms fudge into it for mismatched timer use.  I don't think we have any cases where we care about timestamps with a tighter tolerance than that, do we?

Well-spotted!
(In reply to comment #105)
> Yes, duh, of course.  So I propose check_time_ordered(before, after) and that
> we bake a 20ms fudge into it for mismatched timer use.

Well, the awesome part about this is that now we can put this util in head_common.js and use it in any Places xpcshell test, this is a nice solution.
Blocks: 559354
test disabled till we implement the above thing.
http://hg.mozilla.org/mozilla-central/rev/a085a040a6bd
Assignee: dietrich → mak77
The patch is practically the head_common.js change, you can skip most of the changes to test_bookmarks.js, that's just some naming cleanup. I reverted you previous patch, and used is_date_ordered in all date comparisons between cpp and js.
Attachment #439680 - Flags: review?(dietrich)
Attachment #439680 - Flags: review?(dietrich) → review+
sounds like i forgot to close the bug
http://hg.mozilla.org/mozilla-central/rev/f6a16df040b2
Status: ASSIGNED → RESOLVED
Closed: 14 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 3.7a5
Attachment #438903 - Attachment description: v1.1 → v1.1 [Checkin: Comment 93]
Attachment #439680 - Attachment description: patch v1.0 → patch v1.0 [Checkin: Comment 112]
Flags: in-testsuite+
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: