558745 - Remove all comparisons of Date.now to PR_Now

Status: RESOLVED WONTFIX

(Toolkit :: Places, defect)

Description

[Drew Willcoxon :adw]

A few hours with Ben and his record and replay box show that PR_Now and Date.now are incompatible.  Date.now uses high-resolution timers, but PR_Now does not.  This is true at least on some versions of Windows, including the VM we used and apparently the test machines/VMs where these failures occur.  They can return numbers with large differences, not just off by one.

This is the cause of bug 557406.  It might explain a large portion of our test failures.  I haven't checked if other failures are symptomatic.

test_bookmarks.js does this:

  // the time before we insert, in microseconds
  // Workaround possible VM timers issues subtracting 1us.
  var beforeInsert = Date.now() * 1000 - 1;
  do_check_true(beforeInsert > 0);

  // insert a separator
  var sep = bmsvc.insertSeparator(parent, bmsvc.DEFAULT_INDEX);

  var dateAdded = bmsvc.getItemDateAdded(sep);
  LOG("check that the separator was created with a valid dateAdded");
  LOG("beforeInsert = " + beforeInsert);
  LOG("dateAdded = " + dateAdded);
  do_check_true(dateAdded > beforeInsert);

The last assertion fails.  In the run that Ben and I did on this test, we saw these numbers:

Date.now:         1270752376583361
getItemDateAdded: 1270752376569000

(The Date.now number is not the actual return value of Date.now but the return value of one of the functions its impl uses, PRMJ_Now.)

We should either replace our uses of PR_Now with a function that's fully compatible with Date.now, if such a function exists, or try to fortify or remove our uses of Date.now in our tests or find some scriptable function somewhere that's compatible with PR_Now.

Comment 1

[Marco Bonardo [:mak]]

i think fixing tests won't fix the xpcom issue i see here. any xpcom user could call date.now and pr_now in js and cpp respectively, and have the same headache. Can't we have both codes use the same system timer impl? Or this could just be a "simple" rounding issue where we ceil instead of floor.
We should probably involve someone from platform and try to make impossible to get a past value if i call js now and then cpp now, or viceversa.

Comment 2

[Marco Bonardo [:mak]]

PR_Now on Windows uses
GetSystemTime(&st);
SystemTimeToFileTime(&st, &ft);
(not sure why it does not directly call GetSystemTimeAsFileTime)
it has a granularity of 100ns and a precision of about 11ms.

the js impl you pointed at sounds like using a low res timer, and recalibrates it though QueryPerformanceCounter that has a much higher precision (and cost) compared to GetSystemTime.

This is without taking in count:
- VM timers bugs (the timer can stay freeze for more than the expected ms, but in this case i'd expect two next calls to "now" to return same value")
- test machines updating their time while a test runs.

Comment 3

[Marco Bonardo [:mak]]

so, my current theory is that js impl corrects the time using windows timers precision that is about 16ms, when this happens it could subtract a value between 0 or 16ms and cause our issue. I've never seen a > 16ms difference in logs so far.

Comment 4

[Marco Bonardo [:mak]]

we'll just do this when we hit them.