Nursery accounting

RESOLVED FIXED in mozilla36

Status

()

Core
JavaScript Engine
RESOLVED FIXED
4 years ago
3 years ago

People

(Reporter: sfink, Assigned: sfink)

Tracking

unspecified
mozilla36
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(3 attachments, 1 obsolete attachment)

(Assignee)

Description

4 years ago
Series of patches for adding additional statistics collection. We don't have to take all of this.
(Assignee)

Comment 1

4 years ago
Created attachment 8511228 [details] [diff] [review]
Count storebuffer compactions
Attachment #8511228 - Flags: review?(terrence)
Attachment #8511228 - Flags: review?(terrence) → review+
(Assignee)

Comment 2

4 years ago
Created attachment 8512210 [details] [diff] [review]
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.)
Attachment #8512210 - Flags: review?(jcoppeard)
(Assignee)

Comment 3

4 years ago
Created attachment 8512217 [details] [diff] [review]
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.
Attachment #8512217 - Flags: review?(jcoppeard)
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.
Attachment #8512210 - Flags: review?(jcoppeard)
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.
Attachment #8512217 - Flags: review?(jcoppeard) → review+
(Assignee)

Comment 6

4 years ago
Created attachment 8514582 [details] [diff] [review]
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.
Attachment #8514582 - Flags: review?(jcoppeard)
(Assignee)

Updated

4 years ago
Attachment #8512210 - Attachment is obsolete: true
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.
Attachment #8514582 - Flags: review?(jcoppeard) → review+
(Assignee)

Comment 8

4 years ago
(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.
(Assignee)

Comment 12

4 years ago
(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.
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
Flags: needinfo?(sphink)
This also appears to have started failing from this push: https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3588525&repo=mozilla-inbound
There were two different ones involved here. Neither was caused by shu.
Flags: needinfo?(sphink)
Keywords: checkin-needed
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
Keywords: checkin-needed
(Assignee)

Comment 18

4 years ago
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
(Assignee)

Updated

4 years ago
Depends on: 1099463
(Assignee)

Comment 20

4 years ago
This patch is truly cursed. It managed to trigger another unrelated assertion with the cgc run, through no fault of its own.
Depends on: 1102498
https://hg.mozilla.org/mozilla-central/rev/b261745c586a
Status: ASSIGNED → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
Depends on: 1104162
You need to log in before you can comment on or make changes to this bug.