Open Bug 1400153 Opened 7 years ago Updated 2 years ago

Intermittent Assertion failure: ok (Inconsistent time data), at z:/build/build/src/js/src/gc/Statistics.cpp:830

Categories

(Core :: JavaScript: GC, defect, P5)

defect

Tracking

()

REOPENED

People

(Reporter: intermittent-bug-filer, Assigned: sfink, NeedInfo)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(3 files)

Component: web-platform-tests → JavaScript: GC
Product: Testing → Core
Version: Version 3 → unspecified
I wrote up a long explanation here of how this *has* to be due to a monotonic clock, explaining the sample output line

    Parent Sweep Compartments time = 172.199ms with 0.006ms remaining, child Sweep type information time 7.752ms

...except that "Sweep Compartments" is a child of "Sweep", not the other way around, so this is just totally messed up.

The only caller of the printout code is

    for (auto i : AllPhases()) {
        Phase parent = phases[i].parent;
        if (parent != Phase::NONE)
            bool ok = CheckSelfTime(parent, i, times, selfTimes, times[i]);
        }
    }

More outputs:

    Parent Mark During Sweeping time = 344.000ms with 343.835ms remaining, child Mark Gray time 344.000ms
    Parent Mark During Sweeping time = 281.000ms with 280.923ms remaining, child Mark Gray time 281.000ms
    Parent Sweep time = 62.000ms with 61.997ms remaining, child Sweep Compartments time 62.250ms
    Parent Mark During Sweeping time = 405.458ms with 404.982ms remaining, child Mark Gray time 405.007ms

Hm... all of those are at least valid according to the hierarchy. The sole weirdo, that first line, is also from the only 64-bit failure listed in this bug. Ummm... okay. I'll ignore that for a bit.

This assertion should only happen if time is nonmonotonic.

The code computes the time of nested phases of processing. So the parent starts a timer, then a child starts and stops its timer, possibly for multiple children, and finally the parent stops its timer. ("timer" here means recording TimeStamp::Now() values.) We assert if the parent's time is less than the sum of the childrens' time.

All of the failures appear to be on win32, except for that weird invalid-hierarchy failure on windows10-64-ccov.

Note that when this problem is detected, we log the problem. Sadly, it's in a somewhat weird way: we start out with the parent's elapsed time in a "self time" field and then subtract out the children times, emitting a log message when we run out of time to take away. So for example, using:

    Parent Mark During Sweeping time = 344.000ms with 343.835ms remaining, child Mark Gray time 344.000ms

That means the elapsed time for the parent ("Mark During Sweeping") is 344.000ms, we've gone through its children subtracting out their elapsed times, and at one point the parent only has 343.835ms remaining but it has a child ("Mark Gray") that took 344ms. The portion of the hierarchy here is from

        PhaseKind("SWEEP_MARK", "Mark During Sweeping", 10, [
            PhaseKind("UNMARK_GRAY", "Unmark gray", 56)
            PhaseKind("SWEEP_MARK_INCOMING_BLACK", "Mark Incoming Black Pointers", 12, [...]),
            PhaseKind("SWEEP_MARK_WEAK", "Mark Weak", 13, [...]),
            PhaseKind("SWEEP_MARK_INCOMING_GRAY", "Mark Incoming Gray Pointers", 14),
            PhaseKind("SWEEP_MARK_GRAY", "Mark Gray", 15),
            PhaseKind("SWEEP_MARK_GRAY_WEAK", "Mark Gray and Weak", 16)
        ]),

which is a little hard to read, but it means we've subtracted out UNMARK_GRAY, SWEEP_MARK_INCOMING_BLACK, SWEEP_MARK_WEAK, and SWEEP_MARK_INCOMING_GRAY (which were all quite fast, 0.145ms total for all of them). In this case, it is very suspicious that the total parent time was exactly equal to one of its children (Mark Gray) -- but not all of them were like that, eg

    Parent Mark During Sweeping time = 405.458ms with 404.982ms remaining, child Mark Gray time 405.007ms

It would be nice to report the phase start/end times too. But note that when a phase ends, we do

    MOZ_ASSERT(now >= phaseStartTimes[phase]);

which we should have hit *before* this assertion if it were true. Which means that time is never observed to go backwards between the start and end of any phase, though it appears that the end of the child phase has an end time after the end time of its parent, which should not be possible. Perhaps that's what I should be MOZ_ASSERTing next...

I'm only looking into this because I was under the impression that our TimeStamp code took great pains to be monotonic, even on win32, and I thought I had a counterexample. But now I'm not entirely clear on what's going on.
Totally cosmetic, but I came back to this stuff after a long time, and stumbled over the name here.
Attachment #8969756 - Flags: review?(jcoppeard)
Assignee: nobody → sphink
Status: NEW → ASSIGNED
I've heard that we're depending on these timestamps being monotonic in other places, and this intermittent is the most solid evidence we have of problems. But it's not totally straightforward to infer what's going on from the existing printouts, so I'm adding some comparisons with end times.

I asked the sheriffs how to get assertion failures routed to a bug that I'm watching, and apavel said that the automated failure suggestions look for matching substrings. So I'm making all of the asserts related to this issue include the same, longer, substring. We'll see if it works; I notice several bugs that have been duped to this one. Hopefully this will help?
Attachment #8969759 - Flags: review?(jcoppeard)
Attachment #8969756 - Attachment is obsolete: true
Attachment #8969756 - Flags: review?(jcoppeard)
Comment on attachment 8969756 [details] [diff] [review]
Rename nextInPhase -> nextWithPhaseKind

Oops. I hit Ctrl-C during bzexport, and it looks like it left things in a weird state. There are two patches up for review.
Attachment #8969756 - Attachment is obsolete: false
Attachment #8969756 - Flags: review?(jcoppeard)
Comment on attachment 8969756 [details] [diff] [review]
Rename nextInPhase -> nextWithPhaseKind

Review of attachment 8969756 [details] [diff] [review]:
-----------------------------------------------------------------

Yeah, that's a better name.
Attachment #8969756 - Flags: review?(jcoppeard) → review+
Comment on attachment 8969759 [details] [diff] [review]
Add another check for timestamp problems, and attempt to get all the intermittents routed to one bug

Review of attachment 8969759 [details] [diff] [review]:
-----------------------------------------------------------------

::: js/src/gc/Statistics.cpp
@@ +1099,5 @@
>          auto mutatorStartTime = phaseStartTimes[Phase::MUTATOR];
>          auto mutatorTime = phaseTimes[Phase::MUTATOR];
>          PodZero(&phaseStartTimes);
> +#ifdef DEBUG
> +        PodZero(&phaseEndTimes);

TimeStamp has a default constructor that initialises it to zero.  I think you can remove this, and the one above.

@@ +1251,5 @@
> +                    t(now - TimeStamp::ProcessCreation()),
> +                    phases[kid].name,
> +                    t(phaseEndTimes[kid] - TimeStamp::ProcessCreation()));
> +        MOZ_ASSERT(phaseEndTimes[kid] <= now, "Inconsistent time data; see bug 1400153");
> +    }

Nice, hopefully this will give us more to go on.

@@ +1253,5 @@
> +                    t(phaseEndTimes[kid] - TimeStamp::ProcessCreation()));
> +        MOZ_ASSERT(phaseEndTimes[kid] <= now, "Inconsistent time data; see bug 1400153");
> +    }
> +#endif
> +    

nit: trailing whitespace here.
Attachment #8969759 - Flags: review?(jcoppeard) → review+
(In reply to Jon Coppeard (:jonco) from comment #31)
> Comment on attachment 8969759 [details] [diff] [review]
> Add another check for timestamp problems, and attempt to get all the
> intermittents routed to one bug
> 
> Review of attachment 8969759 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: js/src/gc/Statistics.cpp
> @@ +1099,5 @@
> >          auto mutatorStartTime = phaseStartTimes[Phase::MUTATOR];
> >          auto mutatorTime = phaseTimes[Phase::MUTATOR];
> >          PodZero(&phaseStartTimes);
> > +#ifdef DEBUG
> > +        PodZero(&phaseEndTimes);
> 
> TimeStamp has a default constructor that initialises it to zero.  I think
> you can remove this, and the one above.

Wait, what? This is at the end of a slice, and needs to reset all of these to zero (the "null" time). The constructor itself already depends on the TimeStamp default constructor.

I *think* using PodZero here is correct (as opposed to looping and setting them all to TimeStamp(), for instance), because it looks like TimeStamp is POD. (Or in newer C++, I guess that's now "has a trivial type and is a standard layout type" or something.) It's a little wonky, since it depends on a binary zero pattern being the null pattern.

I plan to land whenever the tree reopens, will request forgiveness in place of permission if you tell me I'm wrong.
(In reply to Steve Fink [:sfink] [:s:] (PTO Apr9-12) from comment #32)
> (In reply to Jon Coppeard (:jonco) from comment #31)
> > Comment on attachment 8969759 [details] [diff] [review]
> > Add another check for timestamp problems, and attempt to get all the
> > intermittents routed to one bug
> > 
> > Review of attachment 8969759 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > ::: js/src/gc/Statistics.cpp
> > @@ +1099,5 @@
> > >          auto mutatorStartTime = phaseStartTimes[Phase::MUTATOR];
> > >          auto mutatorTime = phaseTimes[Phase::MUTATOR];
> > >          PodZero(&phaseStartTimes);
> > > +#ifdef DEBUG
> > > +        PodZero(&phaseEndTimes);
> > 
> > TimeStamp has a default constructor that initialises it to zero.  I think
> > you can remove this, and the one above.
> 
> Wait, what? This is at the end of a slice, and needs to reset all of these
> to zero (the "null" time). The constructor itself already depends on the
> TimeStamp default constructor.

I would feel better about this if we actually invoked the TimeStamp constructors, rather than assuming that PodZero does the right thing...
Pushed by sfink@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/7ce50d118d22
Rename nextInPhase -> nextWithPhaseKind, r=jonco
https://hg.mozilla.org/integration/mozilla-inbound/rev/5bfd3b3d6cc2
Add another check for timestamp problems, and attempt to get all the intermittents routed to one bug, r=jonco
Oops, sorry. I didn't see your comment before I pushed. That's a fair request. Hopefully the optimizers can DTRT.
Attachment #8970387 - Flags: review?(nfroyd)
Comment on attachment 8970387 [details] [diff] [review]
Stop using PodZero to initialize TimeStamps

Review of attachment 8970387 [details] [diff] [review]:
-----------------------------------------------------------------

Thank you!

FWIW, I don't think the optimizers can DTRT here: TimeStamp lives in mozglue, which is necessarily separate from this code, I think?  So if this really can't stand the overhead of that cross-library call, we may have to come up with something else...
Attachment #8970387 - Flags: review?(nfroyd) → review+
Pushed by sfink@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/63a48a0499b6
Stop using PodZero to initialize TimeStamps, r=nfroyd
(In reply to Nathan Froyd [:froydnj] (out until April 30) from comment #36)
> Thank you!
> 
> FWIW, I don't think the optimizers can DTRT here: TimeStamp lives in
> mozglue, which is necessarily separate from this code, I think?  So if this
> really can't stand the overhead of that cross-library call, we may have to
> come up with something else...

Isn't everything needed is in the header already? The constructor is

  constexpr TimeStamp() : mValue(0) {}

mValue is a TimeStampValue, which is uint64_t on non-Windows and on Windows is a weirdo struct with two uint64_t and two bools... oh crud. That PodZero looks like it *was* incorrect. The second bool is mIsNull, which is initialized to *true*. So you were right, we totally ought to be going through the constructor.

So what did my mutant timestamps do? The null check is

  bool IsNull() const { return mValue == 0; }

which constructs another TimeStampValue with

  struct _SomethingVeryRandomHere;
  constexpr MOZ_IMPLICIT TimeStampValue(_SomethingVeryRandomHere* aNullValue)
    : mGTC(0)
    , mQPC(0)
    , mHasQPC(false)
    , mIsNull(true)
  {
  }

so that it can call

  bool operator==(const TimeStampValue& aOther) const
  {
    return int64_t(*this - aOther) == 0;
  }

which goes through the mozglue library function :( declared

  MFBT_API uint64_t operator-(const TimeStampValue& aOther) const;

and defined

  MFBT_API uint64_t
  TimeStampValue::operator-(const TimeStampValue& aOther) const
  {
    if (mIsNull && aOther.mIsNull) {
      return uint64_t(0);
    }
  
    return CheckQPC(aOther);
  }

The mIsNull is incorrectly false, so it does

  uint64_t
  TimeStampValue::CheckQPC(const TimeStampValue& aOther) const
  {
    uint64_t deltaGTC = mGTC - aOther.mGTC;

    if (!mHasQPC || !aOther.mHasQPC) { // Both not holding QPC
      return deltaGTC;
    }
    ...complicated goop that we don't reach...
  }

and so it returns uint64_t(0), which back in operator==, returns true.

Ok, so my mangled timestamps will return true for IsNull(). Phew. froydnj, shouldn't that operator- be declared inline in TimeStamp_windows.h? It can call CheckQPC in the library for the complicated case, but it seems like the fast path for IsNull() == true could all be inlined with that change. I guess IsNull() == false would need more work.

Even better, change mIsNull to mIsNotNull so that the optimizer *can* bzero the memory.

(Note that I doubt any of this is relevant for my case; losing the optimization is unlikely to be significant.)

And yes, I should file a separate bug for this. Tell me I'm not being stupid first, please.
https://hg.mozilla.org/mozilla-central/rev/7ce50d118d22
https://hg.mozilla.org/mozilla-central/rev/5bfd3b3d6cc2
https://hg.mozilla.org/mozilla-central/rev/63a48a0499b6
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
(In reply to Steve Fink [:sfink] [:s:] (PTO June 31) from comment #32)
> Wait, what? This is at the end of a slice, and needs to reset all of these
> to zero (the "null" time). 

Sorry, you're right.  I misread this.  Assigning TimeStamp() is nicer too.
This does not appear to be fixed, thus reopening: https://treeherder.mozilla.org/logviewer.html#?job_id=177515203&repo=autoland&lineNumber=6302

17:51:44  WARNING -  PROCESS-CRASH | Main app process exited normally | application crashed [@ static js::gcstats::PhaseKind LongestPhaseSelfTimeInMajorGC(const class mozilla::EnumeratedArray<enum js::gcstats::Phase,105,mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator> > & const)]
17:51:44     INFO -  Crash dump filename: c:\users\task_1525800346\appdata\local\temp\tmpcmrjdo.mozrunner\minidumps\46b274ab-3bf7-4906-a959-47503ef98bed.dmp
17:51:44     INFO -  Operating system: Windows NT
17:51:44     INFO -                    10.0.15063
17:51:44     INFO -  CPU: amd64
17:51:44     INFO -       family 6 model 63 stepping 2
17:51:44     INFO -       8 CPUs
17:51:44     INFO -  GPU: UNKNOWN
17:51:44     INFO -  Crash reason:  EXCEPTION_BREAKPOINT
17:51:44     INFO -  Crash address: 0x7ffa890ffda5
17:51:44     INFO -  Assertion: Unknown assertion type 0x00000000
17:51:44     INFO -  Process uptime: 171 seconds
17:51:44     INFO -  Thread 0 (crashed)
17:51:44     INFO -   0  xul.dll!static js::gcstats::PhaseKind LongestPhaseSelfTimeInMajorGC(const class mozilla::EnumeratedArray<enum js::gcstats::Phase,105,mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator> > & const) [Statistics.cpp:3cd1fcae55debedd74333804b355b4aa20d1b58b : 873 + 0x19]
17:51:44     INFO -      rax = 0x0000000000000000   rdx = 0x0000000000000000
17:51:44     INFO -      rcx = 0x00000000ffffffff   rbx = 0x000000048a4a631c
17:51:44     INFO -      rsi = 0x000000000000001b   rdi = 0x000000000000001c
17:51:44     INFO -      rbp = 0x0000009e70bfe0a0   rsp = 0x0000009e70bfdfa0
17:51:44     INFO -       r8 = 0x0000009e70bfc958    r9 = 0x0000025605204154
17:51:44     INFO -      r10 = 0x0000000000000000   r11 = 0x0000009e70bfde20
17:51:44     INFO -      r12 = 0x7ff0000000000000   r13 = 0x0000000000000000
17:51:44     INFO -      r14 = 0x000002560a48f770   r15 = 0x00007ffa840d0000
17:51:44     INFO -      rip = 0x00007ffa890ffda5
17:51:44     INFO -      Found by: given as instruction pointer in context
17:51:44     INFO -   1  xul.dll!js::gcstats::Statistics::endSlice() [Statistics.cpp:3cd1fcae55debedd74333804b355b4aa20d1b58b : 1049 + 0x9]
17:51:44     INFO -      rbx = 0x000000048a4a631c   rbp = 0x0000009e70bfe0a0
17:51:44     INFO -      rsp = 0x0000009e70bfe570   r12 = 0x7ff0000000000000
17:51:44     INFO -      r13 = 0x0000000000000000   r14 = 0x000002560a48f770
17:51:44     INFO -      r15 = 0x00007ffa840d0000   rip = 0x00007ffa89109687
17:51:44     INFO -      Found by: call frame info
17:51:44     INFO -   2  xul.dll!js::gc::GCRuntime::gcCycle(bool,js::SliceBudget &,JS::gcreason::Reason) [GC.cpp:3cd1fcae55debedd74333804b355b4aa20d1b58b : 7484 + 0x19]
17:51:44     INFO -      rbx = 0x000000048a4a631c   rbp = 0x0000009e70bfe0a0
17:51:44     INFO -      rsp = 0x0000009e70bfe690   r12 = 0x7ff0000000000000
17:51:44     INFO -      r13 = 0x0000000000000000   r14 = 0x000002560a48f770
17:51:44     INFO -      r15 = 0x00007ffa840d0000   rip = 0x00007ffa88ff518d
17:51:44     INFO -      Found by: call frame info
17:51:44     INFO -   3  xul.dll!js::gc::GCRuntime::collect(bool,js::SliceBudget,JS::gcreason::Reason) [GC.cpp:3cd1fcae55debedd74333804b355b4aa20d1b58b : 7616 + 0x12]
17:51:44     INFO -      rbx = 0x000000048a4a631c   rbp = 0x0000009e70bfe0a0
17:51:44     INFO -      rsp = 0x0000009e70bfe7b0   r12 = 0x7ff0000000000000
17:51:44     INFO -      r13 = 0x0000000000000000   r14 = 0x000002560a48f770
17:51:44     INFO -      r15 = 0x00007ffa840d0000   rip = 0x00007ffa88fe5012
17:51:44     INFO -      Found by: call frame info
17:51:44     INFO -   4  xul.dll!js::gc::GCRuntime::gcSlice(JS::gcreason::Reason,__int64) [GC.cpp:3cd1fcae55debedd74333804b355b4aa20d1b58b : 7705 + 0x36]
17:51:44     INFO -      rbx = 0x000000048a4a631c   rbp = 0x0000009e70bfe0a0
17:51:44     INFO -      rsp = 0x0000009e70bfe860   r12 = 0x7ff0000000000000
17:51:44     INFO -      r13 = 0x0000000000000000   r14 = 0x000002560a48f770
17:51:44     INFO -      r15 = 0x00007ffa840d0000   rip = 0x00007ffa88ff569e
17:51:44     INFO -      Found by: call frame info
17:51:44     INFO -   5  xul.dll!nsJSContext::GarbageCollectNow(JS::gcreason::Reason,nsJSContext::IsIncremental,nsJSContext::IsShrinking,__int64) [nsJSEnvironment.cpp:3cd1fcae55debedd74333804b355b4aa20d1b58b : 1208 + 0xd]
17:51:44     INFO -      rbx = 0x000000048a4a631c   rbp = 0x0000009e70bfe0a0
17:51:44     INFO -      rsp = 0x0000009e70bfe8d0   r12 = 0x7ff0000000000000
17:51:44     INFO -      r13 = 0x0000000000000000   r14 = 0x000002560a48f770
17:51:44     INFO -      r15 = 0x00007ffa840d0000   rip = 0x00007ffa85fe9c9e
17:51:44     INFO -      Found by: call frame info
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Flags: needinfo?(sfink)
Flags: needinfo?(jcoppeard)
Target Milestone: mozilla61 → ---
The bug is that the OS doesn't always provide consistent time data.  There's not much we can really do about that.

Steve, what do you think about ignoring slices where the timestamps don't make sense and just printing a warning message instead of asserting?  Maybe we should add telemetry so we can tell this doesn't happen too often.
Flags: needinfo?(jcoppeard) → needinfo?(sphink)
(In reply to Andreea Pavel [:apavel] from comment #43)
> This does not appear to be fixed, thus reopening:

Sorry, I didn't mean for this to get closed. These are diagnostic patches only.

(In reply to Jon Coppeard (:jonco) from comment #45)
> The bug is that the OS doesn't always provide consistent time data.  There's
> not much we can really do about that.

Except that apparently a lot of work went into creating a consistent time source, and people (namely, Nathan) were unaware of any remaining issues. That's really the only reason I did anything here; I thought we were catching cases where time went backwards, but it turns out that in order to make sense of what our assertions meant, you'd have to step through a bunch of code logic. So I was just trying to get much more clear problem reports.

> Steve, what do you think about ignoring slices where the timestamps don't
> make sense and just printing a warning message instead of asserting?  Maybe
> we should add telemetry so we can tell this doesn't happen too often.

In terms of the final outcome, I agree that this would be fine. But someone like nfroyd might want to fix the underlying issue (if it's even possible), so I'd prefer to let him have a chance to take a look at the improved problem reports. (He might still be on PTO? Not sure.) I'll see if I can needinfo.
Flags: needinfo?(sphink) → needinfo?(nfroyd)
Hm... except comment 43 has the unimproved report in it. I want one that gives the "Parent %s ended at %.3fms, before child %s ended at %.3fms?" printout.
Flags: needinfo?(sfink)
Darn, I don't see any with the new report. Which I had at some point convinced myself would *have* to file first. So I don't have a smoking gun to point at the time source yet. Maybe I should make the CheckSelfTimes thing that *is* firing a lot fancier, by displaying all of the related start and end times.
Flags: needinfo?(sphink)
(In reply to Steve Fink [:sfink] [:s:] (PTO June 31) from comment #46)
> In terms of the final outcome, I agree that this would be fine. But someone
> like nfroyd might want to fix the underlying issue (if it's even possible),
> so I'd prefer to let him have a chance to take a look at the improved
> problem reports. (He might still be on PTO? Not sure.) I'll see if I can
> needinfo.

If there is non-monotonicity, I would want to get the issue fixed (though I might not be the one to do it).  But I've mostly-read through the non-bot comments above and I'm not even clear on what the problem is.  Can you provide a condensed summary?
Flags: needinfo?(nfroyd)
(In reply to Nathan Froyd [:froydnj] from comment #49)
> If there is non-monotonicity, I would want to get the issue fixed (though I
> might not be the one to do it).  But I've mostly-read through the non-bot
> comments above and I'm not even clear on what the problem is.  Can you
> provide a condensed summary?

I'll try.

This bug (and lots of other bugs that get duped to this) is collecting cases where we *think* we're seeing invalid timestamps reported.

The main assertion that gets hit is when we're computing the self-time of a parent phase, by subtracting out the elapsed times of its child phases. If we end up with negative time, something is wrong. (Either with the time source, or our logic; I'm no longer sure which.) It would mean that our parent took less time than its children did, which doesn't make sense because the children are nested within the parent.

One way this could happen is if we recorded the end time of a child, then the end time of a parent, and the latter end time was earlier than it should be (so it appeared to end before its child did.) But I have a separate assertion for that case, and it's not firing.

One wrinkle is that the parent and/or its children could run multiple times before the reporting and checking logic runs. So if we have a parent P1 with children C1, C2, and C3, and X[ represents a start event and ]X represents an end event, a valid sequence is

    P1[ C1[ ]C1 C2[ ]C2 ]P1 P1[ C1[ ]C1 ]P1

So in this case, P1 ran twice for this report cycle, C1 always ran, C2 was skipped the second time P1 ran, and C3 just never ran at all. In this case, we will only be able to see the most recent end times for P1, C1, and C2, a null end time for C3, and the durations will reflect 2, 1, or 0 actual instantiations. (Which is why I have other checks to catch the problem sooner, which sadly are not firing.)

Was that condensed or expanded? Bleh.
@sfink, is anything happening here? This seems to be hitting much more frequently in the last few days (see all the things duped to bug 1447643 which all have this assertion failure).

If no fix is forthcoming I think the assertion should be removed.
Summary: Intermittent PID 3288 | Assertion failure: ok (Inconsistent time data), at z:/build/build/src/js/src/gc/Statistics.cpp:830 → Intermittent Assertion failure: ok (Inconsistent time data), at z:/build/build/src/js/src/gc/Statistics.cpp:830

I've managed to hit this very easily by running jit-tests in a VM while the host system was heavily loaded. If the host system isn't loaded then it happens a lot less often. This makes me think that it might be an issue with the timebase.

Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.