1088831 - Nursery accounting

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Steve Fink [:sfink] [:s:]]

Series of patches for adding additional statistics collection. We don't have to take all of this.

Comment 1

[Steve Fink [:sfink] [:s:]]

Attachment: Count storebuffer compactions

Comment 2

[Steve Fink [:sfink] [:s:]]

Attachment: Account for the storebuffer compaction time

Storebuffer compaction is a little tricky because it can happen both inside and outside of GC. So we need to move the stats clearing to endGC instead of beginGC (to avoid erasing the time spent during the mutator), and it has to have multiple parent phases.

The latter could be done more simply, by requiring the caller to pass in the right subphase. But that would require inferring the appropriate phase from... uh, gcDepth or something? That would make this patch simpler, though it would not provide as generic a mechanism. (Are other users likely? Is there anything that should *already* be multiparented, but right now we ignore it? eg waiting on a background thread for something.)

Comment 3

[Steve Fink [:sfink] [:s:]]

Attachment: Track mutator vs GC time in specified intervals

More craziness -- implement {start,stop}TimingMutator to record how much time is spent in the mutator vs the GC.

Here's the output from adding this to an Octane run (mutator timings are displayed before each test result):

Mutator: 1002.262ms (100.0%), GC: 0.000ms (0.0%)
Richards: 1244
Mutator: 928.335ms (92.7%), GC: 73.345ms (7.3%)
DeltaBlue: 1848
Mutator: 941.264ms (94.1%), GC: 59.258ms (5.9%)
Mutator: 1021.098ms (99.8%), GC: 1.693ms (0.2%)
Mutator: 1015.995ms (99.7%), GC: 3.447ms (0.3%)
Crypto: 3269
Mutator: 726.384ms (72.1%), GC: 280.512ms (27.9%)
RayTrace: 3454
Mutator: 926.164ms (92.6%), GC: 74.448ms (7.4%)
Mutator: 1030.040ms (96.8%), GC: 34.061ms (3.2%)
Mutator: 978.313ms (95.9%), GC: 42.205ms (4.1%)
Mutator: 1021.235ms (97.8%), GC: 22.760ms (2.2%)
Mutator: 1038.959ms (96.9%), GC: 33.300ms (3.1%)
Mutator: 978.851ms (96.0%), GC: 41.199ms (4.0%)
Mutator: 1024.168ms (97.9%), GC: 22.168ms (2.1%)
Mutator: 1040.737ms (97.0%), GC: 32.689ms (3.0%)
EarleyBoyer: 1349
Mutator: 1209.307ms (95.5%), GC: 57.401ms (4.5%)
Mutator: 995.087ms (93.8%), GC: 65.742ms (6.2%)
Mutator: 1053.454ms (90.7%), GC: 108.102ms (9.3%)
RegExp: 496
Mutator: 666.091ms (65.6%), GC: 348.580ms (34.4%)
Splay: 1485
SplayLatency: 2146
Mutator: 1002.731ms (100.0%), GC: 0.000ms (0.0%)
NavierStokes: 29591
Mutator: 1198.106ms (97.9%), GC: 25.076ms (2.1%)
Mutator: 1193.385ms (85.5%), GC: 201.896ms (14.5%)
PdfJS: 1934
Mutator: 1044.162ms (100.0%), GC: 0.000ms (0.0%)
Mutator: 1285.192ms (100.0%), GC: 0.000ms (0.0%)
Mandreel: 4334
MandreelLatency: 9031
Mutator: 1151.037ms (99.7%), GC: 3.925ms (0.3%)
Mutator: 1016.614ms (69.2%), GC: 452.840ms (30.8%)
Gameboy: 6011
Mutator: 868.524ms (86.8%), GC: 131.974ms (13.2%)
Mutator: 892.921ms (88.0%), GC: 121.199ms (12.0%)
CodeLoad: 8988
Mutator: 1029.284ms (99.2%), GC: 8.419ms (0.8%)
Mutator: 1052.780ms (100.0%), GC: 0.239ms (0.0%)
Box2D: 2858
Mutator: 2207.208ms (93.6%), GC: 150.613ms (6.4%)
zlib: 64807
Mutator: 35377.770ms (84.3%), GC: 6605.170ms (15.7%)
Typescript: 3037
----
Score (version 9): 3658

So RayTrace, Splay, and Gameboy seem to be our most GC-intensive Octane tests.

Comment 4

[Jon Coppeard (:jonco)]

Comment on attachment 8512210 [details] [diff] [review]
Account for the storebuffer compaction time

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

The other time something like this comes up is in GCRuntime::endMarkingZoneGroup() for weak/gray marking where markWeakReferencesInCurrentGroup() takes a phase as a parameter.

I think it would be better to do something similar and have StoreBuffer::compact() take a phase parameter too.

::: js/src/gc/StoreBuffer.cpp
@@ +112,5 @@
>  void
>  StoreBuffer::MonoTypeBuffer<T>::compactRemoveDuplicates(StoreBuffer *owner)
>  {
>      Statistics& stats = owner->stats();
> +    gcstats::AutoPhase ap(stats, stats.resolveMultiParentPhase(gcstats::PHASE_COMPACT_STOREBUFFER));

I guess we want this in RelocatableMonoTypeBuffer::compactMoved() too.

Comment 5

[Jon Coppeard (:jonco)]

Comment on attachment 8512217 [details] [diff] [review]
Track mutator vs GC time in specified intervals

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

Nice, it will be useful to get the mutator vs. GC timings easily.

Comment 6

[Steve Fink [:sfink] [:s:]]

Attachment: Account for the storebuffer compaction time

I may be adding in too much cruft, but the additional stats turned out to be useful in tracking down where some compaction time was going, so perhaps they are useful. Overflow-triggered compaction *can* sometimes use up a decent amount of time (I was seeing hundreds of ms occasionally, though that's for a debug build.)

The compaction overflow counters are the least likely to be useful. I was using them to debug the other stuff.

Comment 7

[Jon Coppeard (:jonco)]

Comment on attachment 8514582 [details] [diff] [review]
Account for the storebuffer compaction time

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

Looks good to me.

::: js/src/gc/StoreBuffer.cpp
@@ +139,5 @@
>      }
>      storage_->release(insert.mark());
>  
>      duplicates.clear();
> +    owner->stats().count(gcstats::STAT_COMPACT_STOREBUFFER);

Moving this into maybeCompact() might be clearer.

Comment 8

[Steve Fink [:sfink] [:s:]]

(In reply to Jon Coppeard (:jonco) from comment #7)
> Comment on attachment 8514582 [details] [diff] [review]
> Account for the storebuffer compaction time
> 
> Review of attachment 8514582 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good to me.
> 
> ::: js/src/gc/StoreBuffer.cpp
> @@ +139,5 @@
> >      }
> >      storage_->release(insert.mark());
> >  
> >      duplicates.clear();
> > +    owner->stats().count(gcstats::STAT_COMPACT_STOREBUFFER);
> 
> Moving this into maybeCompact() might be clearer.

Not that this would ever matter, but there is an early return in compactRemoveDuplicates, and I didn't want to count those. Even if that particular one doesn't matter (it's an OOM), I was thinking that there could conceivably be other ways for that to avoid doing anything in the future.

Comment 9

[Steve Fink [:sfink] [:s:]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/70a7f15c30fb
https://hg.mozilla.org/integration/mozilla-inbound/rev/15e064492127
https://hg.mozilla.org/integration/mozilla-inbound/rev/5156cefdad51

Comment 10

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/3439514abf7b

static: https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3554901&repo=mozilla-inbound
hazard: https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3554899&repo=mozilla-inbound
shell: https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3554921&repo=mozilla-inbound

Comment 11

[Phil Ringnalda (:philor)]

And some test asserting, https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3555970&repo=mozilla-inbound

Comment 12

[Steve Fink [:sfink] [:s:]]

(In reply to Phil Ringnalda (:philor) from comment #10)
> Backed out in
> https://hg.mozilla.org/integration/mozilla-inbound/rev/3439514abf7b
> 
> static:
> https://treeherder.mozilla.org/ui/logviewer.
> html#?job_id=3554901&repo=mozilla-inbound
> hazard:
> https://treeherder.mozilla.org/ui/logviewer.
> html#?job_id=3554899&repo=mozilla-inbound
> shell:
> https://treeherder.mozilla.org/ui/logviewer.
> html#?job_id=3554921&repo=mozilla-inbound

Non-unified breakage.

(In reply to Phil Ringnalda (:philor) from comment #11)
> And some test asserting,
> https://treeherder.mozilla.org/ui/logviewer.
> html#?job_id=3555970&repo=mozilla-inbound

Something else. Ugh.

Comment 13

[Steve Fink [:sfink] [:s:]]

Re-landed:

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/7a9f3b3b3006
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/d6aceb31282a
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/5cbe9fc3c2ff

(jit-tests problem was very real.)

Comment 14

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

That assert is still intermittently happening:  https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3590396&repo=mozilla-inbound

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/d95e85773aa6

Comment 15

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

This also appears to have started failing from this push: https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3588525&repo=mozilla-inbound

Comment 16

[Ryan VanderMeulen [:RyanVM]]

There were two different ones involved here. Neither was caused by shu.

Comment 17

[Ryan VanderMeulen [:RyanVM]]

dammit, that comment went to the wrong bug. This did cause SM(ggc) failures.
https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3588525&repo=mozilla-inbound

Then Hannes landed more bustage on top of that with bug 1052839:
https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3591649&repo=mozilla-inbound

Comment 18

[Steve Fink [:sfink] [:s:]]

Why push once when I can push the same thing 3 times?

https://hg.mozilla.org/integration/mozilla-inbound/rev/bfedb105396e
https://hg.mozilla.org/integration/mozilla-inbound/rev/dbec0bed9bf5
https://hg.mozilla.org/integration/mozilla-inbound/rev/06c511b6093e

It doesn't include everything, but it does have SM(ggc). I don't think this was to blame for the previous backout, though.

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=31853eee1d45

Comment 19

[Ryan VanderMeulen [:RyanVM]]

Backed out for various assertions.
https://hg.mozilla.org/integration/mozilla-inbound/rev/44ba0c1d88cb

https://treeherder.mozilla.org/logviewer.html#?job_id=3882582&repo=mozilla-inbound
https://treeherder.mozilla.org/logviewer.html#?job_id=3884141&repo=mozilla-inbound

Comment 20

[Steve Fink [:sfink] [:s:]]

This patch is truly cursed. It managed to trigger another unrelated assertion with the cgc run, through no fault of its own.

Comment 21

[Steve Fink [:sfink] [:s:]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b261745c586a

Comment 22

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/b261745c586a