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=MozillaTry/1270575074.1270587668.5623.gz WINNT 5.2 try hg unit test on 2010/04/06 10:31:14

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

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1270776470.1270779573.30531.gz WINNT 5.2 mozilla-central debug test xpcshell on 2010/04/08 18:27:50 s: win32-slave20

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.

per shaver's comment.

s/us/ms/

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

(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.

test disabled till we implement the above thing. http://hg.mozilla.org/mozilla-central/rev/a085a040a6bd

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.

sounds like i forgot to close the bug http://hg.mozilla.org/mozilla-central/rev/f6a16df040b2