1212102 - Assertion failure: mReferenceTimeStamp <= aTimeStamp (Got a negative timestamp delta), SystemTimeConverter.h:206

Status: RESOLVED FIXED

(Core :: DOM: Events, defect)

Description

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

While trying to reproduce bug 1211706 on my desktop machine under rr, I crashed with the assertion:

Assertion failure: mReferenceTimeStamp <= aTimeStamp (Got a negative timestamp delta), .../mozilla/widget/SystemTimeConverter.h:206

I have the recording of this under rr, though that only lasts until I next rebuild.

Comment 1

[Brian Birtles (:birtles, Feb 26~ parental leave)]

I'm afraid I can't run rr here (I only have linux running as a VM) but is it possible to get a stack trace?

If the call site is GetTimeStampFromSystemTime (as opposed to CompensateForBackwardsSkew) then I suppose it's possible that the system time attached to an event is ahead of TimeStamp::NowLoRes() because system times could potentially be anything (they might be vsync-aligned for example). If this were Windows then I suppose using TimeStamp::NowLoRes() could also cause this to be false but I believe that on Linux TimeStamp::NowLoRes() is identical to TimeStamp::Now().

So I suspect this assertion is not valid and we should be doing some kind of clamping instead. I'd like to understand better what is going on, however.

Comment 2

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: gdb session with stack and some other data

I can get more information if you need it (and ask soon, i.e., before I rebuild anything); it's an rr recording.

Comment 3

[Brian Birtles (:birtles, Feb 26~ parental leave)]

(In reply to David Baron [:dbaron] ⌚UTC-7 from comment #2)
> Created attachment 8670643 [details]
> gdb session with stack and some other data
> 
> I can get more information if you need it (and ask soon, i.e., before I
> rebuild anything); it's an rr recording.

Thanks David! That's great. I think that has the information I need. In particular, it tells me we're getting called from CompensateForBackwardsSkew, not from GetTimeStampFromSystemTime.

Comment 4

[Brian Birtles (:birtles, Feb 26~ parental leave)]

So basically mAsyncStart is less than mReferenceTimeStamp when called
from CompensateForBackwardsSkew.

I think what happens is this:

1. We get a call to GetTimeStampFromSystemTime
2. We record the current timestamp as roughlyNow = TimeStamp::NowLoRes
3. We call:
   IsTimeNewerThanTimestamp(aTime, roughlyNow, &deltaFromNow)
   and the assertion that compares roughlyNow with mReferenceTimeStamp
   does *not* fail.
   i.e. mReferenceTimeStamp <= roughlyNow
4. We detect possible backwards-skew and call:
   aCurrentTimeGetter.GetTimeAsyncForPossibleBackwardsSkew(roughlyNow);
5. GetTimeStampFromSystemTime sets mAsyncUpdateStart to roughlyNow.
6. GetTimeStampFromSystemTime triggers an asynchronous request for the
   current time.
7. The async request returns and calls:
   TimeConverter().CompensateForBackwardsSkew(eventTime, lowerBound);
   where lowerBound is initialized to mAsyncUpdateStart.
8. In CompensateForBackwardsSkew we call:
   IsTimeNewerThanTimestamp(aReferenceTime, aLowerBound, &delta)
   where aLowerBound is lowerBound, i.e. mAsyncUpdateStart from before.
9. In IsTimeNewerThanTimestamp mReferenceTimeStamp > aLowerBound, i.e.
   mAsyncUpdateStart, i.e. roughlyNow from before.

So in step 3 mReferenceTimeStamp <= roughlyNow but in step 9 it is not.

Given that we appear to be correctly detecting and ignoring calls to
GetTimeStampFromSystemTime while an async request is in flight, it would
seem that mReferenceTimeStamp is being updated while the async request
is in progress (i.e. between steps 6 and 7).

I think that could happen if we detected possible backwards skew but
in a subsequent call to GetTimeStampFromSystemTime (before the async
request completed) triggered the forwards skew code and updated the
reference time stamp.

If that's the case, I think we could do a couple of different things:

a. Explicitly cancel any in-flight test for backwards skew whenever we
   detect forwards skew.

   e.g. add a CancelGetTimeAsync method to CurrentX11TimeGetter that
   nulls out mAsyncUpdateStart and then check for
   mAsyncUpdateStart.IsNull() in PropertyNotifyHandler and abort the
   call. That would probably produce the wrong results, however, if we
   then made another async request before the first one returned and is
   probably just going to become more and more complex so I suspect we
   should not do this.

b. In CompensateForBackwardsSkew check if aLowerBound is less than
   mReferenceTimeStamp at the start of the function and bail in that
   case.

Karl, does that seem reasonable to you?

Comment 5

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: gdb session with some watchpoints

To try to confirm your theory (though I didn't really take the time to fully understand it), I set some watchpoints in my rr replay.  Here's the gdb session, going forward with the watchpoints (after previously reversing).

(I'm going to clobber the rr replay shortly, so this is probably the last info I'll be able to give you; should have asked sooner if there was something you wanted me to confirm from the replay.)

Comment 6

[Karl Tomlinson (:karlt)]

(In reply to Brian Birtles (:birtles) from comment #4)
> I think that could happen if we detected possible backwards skew but
> in a subsequent call to GetTimeStampFromSystemTime (before the async
> request completed) triggered the forwards skew code and updated the
> reference time stamp.

Yes, that seems consistent with the trace in comment 5.

> If that's the case, I think we could do a couple of different things:
> 
> a. Explicitly cancel any in-flight test for backwards skew whenever we
>    detect forwards skew.
> 
>    e.g. add a CancelGetTimeAsync method to CurrentX11TimeGetter that
>    nulls out mAsyncUpdateStart and then check for
>    mAsyncUpdateStart.IsNull() in PropertyNotifyHandler and abort the
>    call. That would probably produce the wrong results, however, if we
>    then made another async request before the first one returned and is
>    probably just going to become more and more complex so I suspect we
>    should not do this.

Agreed.

> 
> b. In CompensateForBackwardsSkew check if aLowerBound is less than
>    mReferenceTimeStamp at the start of the function and bail in that
>    case.
> 
> Karl, does that seem reasonable to you?

I think 'b' would be OK, but unnecessary.
AFAICS removing the failing assertion should be fine.

Assuming the system timestamps are sane, the system time on the property
notify event (steps 7 to 9) will be newer than the system time value in
mReferenceTime from the second motion-notify event (between steps 6 and 7).
Given that and aLowerBound is less than < mReferenceTimeStamp,
IsTimeNewerThanTimestamp() will return true and so 
CompensateForBackwardsSkew() will return early anyway.

Comment 7

[Brian Birtles (:birtles, Feb 26~ parental leave)]

So, to check I follow here, in IsNewerThanTimestamp:

* aTime = aReferenceTime = eventTime
* aTimeStamp = aLowerBound = mAsyncStart

* Time timeDelta = aTime - mReferenceTime which, as I understand it, in this
  case will not underflow since the eventTime from the async time request will
  be greater than the last time we updated mReferenceTime.
* Time timeStampDelta =
    static_cast<int64_t>((aTimeStamp - mReferenceTimeStamp).ToMilliseconds());
  which, in this case, will underflow and give us a very large number
* Time timeToTimeStamp = timeStampDelta - timeDelta
  which leaves us with a very large number (i.e. greater than kTimeHalfRange)
* Hence isNewer will be set to true and *aDelta will be set to the difference
  (I think this will actually end up being a sensible result but it doesn't
  matter in this case because we don't use the delta in
  CompensateForBackwardsSkew).

So I think you're right. I feel a little bit uncomfortable about just dropping
the assertion however. It seems like this depends a little too much on system
event times being sensible and on the particular implementation of
IsNewerThanTimestamp? Also, for someone reading the code, it's not clear
that this is supposed to work.

I'll prepare a patch for (b) from comment 4 for now, but if you still think
dropping the assertion is preferable I'm happy to do that.

Comment 8

[Brian Birtles (:birtles, Feb 26~ parental leave)]

Attachment: Check for an updated reference timestamp before adjusting for backwards skew

Comment 9

[Karl Tomlinson (:karlt)]

(In reply to Brian Birtles (:birtles) from comment #7)
> I feel a little bit uncomfortable about just
> dropping
> the assertion however. It seems like this depends a little too much on system
> event times being sensible and on the particular implementation of
> IsNewerThanTimestamp?

If the event times seem out of order because of bad Time values then
CompensateForBackwardsSkew() will probably have the more reliable Time,
because we know its source is reliable (it is generated from our request
rather than a foreign client sending an event) and because it is the most
recent event.

> Also, for someone reading the code, it's not clear
> that this is supposed to work.

I not clear what you mean by that.  Time types in this code in general must
be read as using modulo 2^N arithmetic because that is how the system Time
values work.

Comment 10

[Brian Birtles (:birtles, Feb 26~ parental leave)]

(In reply to Karl Tomlinson (ni?:karlt) from comment #9)
> > Also, for someone reading the code, it's not clear
> > that this is supposed to work.
> 
> I not clear what you mean by that.  Time types in this code in general must
> be read as using modulo 2^N arithmetic because that is how the system Time
> values work.

Right, but this is to do with timestamp subtraction here, not system times. And, in fact TimeStamps don't wrap on underflow (as of bug 1202556), so my analysis in comment 7 is wrong.

Comment 11

[Karl Tomlinson (:karlt)]

Comment on attachment 8674017 [details] [diff] [review]
Check for an updated reference timestamp before adjusting for backwards skew

(In reply to Brian Birtles (:birtles) from comment #10)
> (In reply to Karl Tomlinson (ni?:karlt) from comment #9)
> > (In reply to Brian Birtles (:birtles) from comment #7)
> > > Also, for someone reading the code, it's not clear
> > > that this is supposed to work.
> > 
> > I not clear what you mean by that.

> this is to do with timestamp subtraction here, not system times.

Ah, thanks.  I'm assuming your concern is with the TimeDuration from a - b
where a and b are TimeStamps such that b > a.

> And, in fact TimeStamps don't wrap on underflow (as of bug 1202556), so my
> analysis in comment 7 is wrong.

Adding/subtracting TimeDuration to/from TimeStamp so as to generate something
that cannot be represented in the TimeStamp result type is different from
using the TimeStamp difference operator to generate something that can be
represented by the TimeDuration result type.

BaseTimeDuration docs say "Negative durations are allowed, meaning the end is
before the start", which sounds like the situation here.  The TimeDuration
docs also hint at the possibility of negative durations.

TimeStamp docs say it is possible to "compute a difference between two
TimeStamps to get a TimeDuration" and the documentation of
operation-(const TimeStamp) says "Compute the difference between two
timestamps. Both must be non-null."  I think the intention is and it is
reasonable to expect that this behave sensibly when b > a.  The code depends
on implementation-defined behavior (bug 1216714) but the compiler implementations define the required behavior.

I gather that you chose this solution aiming to make the code clearer, but I
find it misleading and unnecessary to have an assertion and code to guard
against a situation which IsTimeNewerThanTimestamp() can handle without
problem.

(In reply to Brian Birtles (:birtles) from comment #7)
>  if you still think
> dropping the assertion is preferable I'm happy to do that.

Yes, please.

Comment 12

[Brian Birtles (:birtles, Feb 26~ parental leave)]

Yes, you're right. I was thinking of the TimeStamp arithmetic operators that take a TimeDuration. I'll take the last part of comment 11 as equivalent to an r+ for a patch to simply drop the assertion.

Comment 13

[Karl Tomlinson (:karlt)]

(In reply to Brian Birtles (:birtles) from comment #12)
> I'll take the last part of comment 11 as equivalent to
> an r+ for a patch to simply drop the assertion.

Sure, thanks.

Comment 14

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/806ccfb8d1dd

Comment 15

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/806ccfb8d1dd