1233831 - Nursery collections (aka minor GCs) do not show up in the waterfall

Status: RESOLVED FIXED

(DevTools :: Performance Tools (Profiler/Timeline), defect)

Description

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

STR:

* https://bgrins.github.io/devtools-demos/perf/editor.html
* record
* click 100mb button
* wait for jank to stop
* stop recording

ER:

Waterfall and call tree make sense with respect to each other.

AR:

One of them is wrong, not 100% sure which, suspect waterfall is wrong.

Comment 1

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: codemirrorprofile.json

Comment 2

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Ok, so the issue is we don't have markers for nursery collections.

Comment 3

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Unfortunately, because our timeline markers are implemented in gecko, we don't have a nice way to trace events inside spidermonkey. We would need to pull the timeline markers (and maybe also the timeline consumers?) into spidermonkey, similar to what is done with JS::ProfilerEntry. This seems a little difficult given how interweaved they are with docshells...

Victor, any ideas?

Comment 4

[Terrence Cole [:terrence]]

Could you maybe just hand us a function pointer to call when we do a nursery GC?

Comment 5

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

(In reply to Terrence Cole [:terrence] from comment #4)
> Could you maybe just hand us a function pointer to call when we do a nursery
> GC?

Yes, we could do a pair of functions for start and stop (or give a start/stop enum parameter).

It isn't exactly pretty, though. :-/

Comment 6

[Terrence Cole [:terrence]]

Yeah, I've actually been thinking about that -- we need a better way to expose hooks to embedders. Right now we're plumbing everything manually: each new hook needs a JS_{Add,Remove}Hook and a couple layers to pass the hook down, store it in a list or a member variable, etc, where the only interesting code is where we actually call it. It would be nice to have a way to just say expose this hook with name Blah.

Comment 7

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Yeah, exactly. We likely want to trace more operations inside SM in the future (eg main thread parses or something) and it would be a shame if we had to add a new JSAPI hook for embedders for every single operation we wanted to trace.

Comment 8

[Victor Porof [:vporof][:vp]]

(In reply to Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8] from comment #3)
> Unfortunately, because our timeline markers are implemented in gecko, we
> don't have a nice way to trace events inside spidermonkey. We would need to
> pull the timeline markers (and maybe also the timeline consumers?) into
> spidermonkey, similar to what is done with JS::ProfilerEntry. This seems a
> little difficult given how interweaved they are with docshells...
> 
> Victor, any ideas?

Meh, docshells aren't really interweaved at all anymore with markers. They're simply a means to filter out markers that a particular timeline isn't interested in at some point ("is your docshell reference equal to this timeline's, and do we care about that? great, thou shalt pass"). We could easily imagine any other kind of filtering mechanism. There can exist markers which aren't tied to a particular docshell, and since there's no other filter mechanism in place, they'll show up in all timelines. See markers.md in the tree and the OperationInstrument wiki.

You could just create a custom marker by subclassing AbstractTimelineMarker and use TimelineConsumers::AddMarkerForAllObservedDocShells right now if you don't care about filtering. There's no burden of having to know what a "dochsell" is on your end when doing this. If you care about filtering, then we could create a new method that filters appropriately when there's multiple timelines open for different tabs.

Comment 9

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

(In reply to Victor Porof [:vporof][:vp] from comment #8)
> You could just create a custom marker by subclassing AbstractTimelineMarker
> and use TimelineConsumers::AddMarkerForAllObservedDocShells right now if you
> don't care about filtering. There's no burden of having to know what a
> "dochsell" is on your end when doing this. If you care about filtering, then
> we could create a new method that filters appropriately when there's
> multiple timelines open for different tabs.

We can't subclass AbstractTimelineMarker or use any of that because it is all in Gecko, not SpiderMonkey or MFBT or something.

I think I will just add another special-case hook to JSAPI. As I was thinking of other operations we would like to trace in SpiderMonkey, I came up fairly short, so I don't think we need something more generic/extensible for the future.

Comment 10

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: Part 0: JSAPI plumbing for nursery collection callbacks

This commit adds the relatively boring plumbing needed to expose methods to set
callbacks that get fired on nursery collection start and end, as well as storing
said callbacks internally.

Comment 11

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: Part 1: Call the callback on nursery collections

This commit adds the `js::gcstats::Statistics::{begin,end}NurseryCollection`
methods which calls the nursery collection callback, if present, and
additionally handles counting minor GCs (which used to be inline in
js::Nursery::collect).

Comment 12

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: Part 2: Install a callback to trace nursery collections

This commit makes CycleCollectedJSRuntime install a nursery collection callback
which traces nursery collections with AutoGlobalTimelineMarker.

Comment 13

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: Part 3: Add metadata for the minor GC markers

This commit adds the necessary metadata for the performance tool to render the
new minor gc markers.

Comment 14

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: Part 4: Test the minor GC markers

Comment 15

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=91a154eea287

Comment 16

[Andrew McCreight [:mccr8]]

Comment on attachment 8707645 [details] [diff] [review]
Part 2: Install a callback to trace nursery collections

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

::: xpcom/base/CycleCollectedJSRuntime.cpp
@@ +749,5 @@
>      self->mPrevGCSliceCallback(aRuntime, aProgress, aDesc);
>    }
>  }
>  
> +static mozilla::Maybe<mozilla::AutoGlobalTimelineMarker> sNurseryCollectionMarker;

This is a little ugly, but I guess it is okay. Maybe rename it to something like sMainThreadNurseryCollectionMarker?

@@ +756,5 @@
> +CycleCollectedJSRuntime::GCNurseryCollectionCallback(JSRuntime* aRuntime,
> +                                                     JS::GCNurseryProgress aProgress,
> +                                                     JS::gcreason::Reason aReason)
> +{
> +  CycleCollectedJSRuntime* self = CycleCollectedJSRuntime::Get();

How performance sensitive are minor GCs? You are going to be hitting TLS at least twice in this function. (for the Get() and for the IsMainThread()).

@@ +763,5 @@
> +  if (NS_IsMainThread()) {
> +    // We would like to support all threads here, but AutoGlobalTimelineMarker
> +    // only supports the main thread. If/when that changes, we should switch
> +    // from storing the auto-marker in a static to putting it in TLS or on the
> +    // CycleCollectedJSRuntime itself.

Generally, if you want something that is mainthread only, you should put it on XPCJSRuntime. I guess maybe this is okay here because the plan is for it to "eventually" support all threads.

Comment 17

[Terrence Cole [:terrence]]

Comment on attachment 8707643 [details] [diff] [review]
Part 0: JSAPI plumbing for nursery collection callbacks

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

Looks good. Thanks for the doc comments.

Comment 18

[Terrence Cole [:terrence]]

Comment on attachment 8707644 [details] [diff] [review]
Part 1: Call the callback on nursery collections

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

LGTM.

Comment 19

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

(In reply to Andrew McCreight [:mccr8] from comment #16)
> @@ +756,5 @@
> > +CycleCollectedJSRuntime::GCNurseryCollectionCallback(JSRuntime* aRuntime,
> > +                                                     JS::GCNurseryProgress aProgress,
> > +                                                     JS::gcreason::Reason aReason)
> > +{
> > +  CycleCollectedJSRuntime* self = CycleCollectedJSRuntime::Get();
> 
> How performance sensitive are minor GCs? You are going to be hitting TLS at
> least twice in this function. (for the Get() and for the IsMainThread()).

I ran octane in the browser (so we would hit this callback) and found that the difference was noise. Some runs were faster with this patch, some runs were slower.

Comment 20

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: Part 2: Expose JS::gcreason::ExplainReason to embedders

This renames the internal function `js::gcstats::ExplainReason` to
`JS::gcreason::ExplainReason` and publicly exposes it to embedders.

Comment 21

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: Part 3: Install a callback to trace nursery collections

:mccr8, to fix the static bustage in the try push, I had to stop using the Auto
class and construct start/end markers explicitly. This code changed enough that
I feel I should get re-review. The upside, however, is that we can now properly
pass along the GC reason information and display it in the UI down the line.

Comment 22

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: Part 4: Add metadata for the minor GC markers

This commit adds the necessary metadata for the performance tool to render the
new minor gc markers.

Comment 23

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: Part 5: Test the minor GC markers

Comment 24

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

New try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ec0a167e410d

Comment 25

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Attachment: screen shot w/ gc reason

Comment 26

[Terrence Cole [:terrence]]

Comment on attachment 8708097 [details] [diff] [review]
Part 2: Expose JS::gcreason::ExplainReason to embedders

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

::: js/public/GCAPI.h
@@ +132,5 @@
>  
> +/**
> + * Get a statically allocated C string explaining the given GC reason.
> + */
> +const char* ExplainReason(JS::gcreason::Reason reason);

In order to link on windows, this needs to be:

extern JS_PUBLIC_API(const char*)
ExplainReason(...);

Also, put the return type on the line above to match the existing style. Side Node: The rationale is that this way you can grep for the decl using "^Decl".

::: js/src/gc/Statistics.cpp
@@ +48,5 @@
>      else
>           return "Shrinking";
>  }
>  
>  const char*

JS_PUBLIC_API(const char*)

Comment 27

[Andrew McCreight [:mccr8]]

Comment on attachment 8708098 [details] [diff] [review]
Part 3: Install a callback to trace nursery collections

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

Nathan, could you look at the UniquePointer/Move stuff in this patch? I'm not too clear on how that is supposed to work. Thanks.

::: xpcom/base/CycleCollectedJSRuntime.cpp
@@ +441,5 @@
>    }
>    JS_SetGrayGCRootsTracer(mJSRuntime, TraceGrayJS, this);
>    JS_SetGCCallback(mJSRuntime, GCCallback, this);
>    mPrevGCSliceCallback = JS::SetGCSliceCallback(mJSRuntime, GCSliceCallback);
> +  mPrevGCNurseryCollectionCallback = JS::SetGCNurseryCollectionCallback(

Now that I've thought about this some more, it seems like it would make sense to only set this on the main thread, rather than doing the check every time we have the callback, so please do that.

@@ +751,5 @@
>      self->mPrevGCSliceCallback(aRuntime, aProgress, aDesc);
>    }
>  }
>  
> +class MinorGCMarker : public mozilla::TimelineMarker

This class is pretty boilerplate-y, but I guess that's unavoidable.

@@ +756,5 @@
> +{
> +private:
> +  JS::gcreason::Reason mReason;
> +
> +  explicit MinorGCMarker(mozilla::MarkerTracingType aTracingType,

Do you need explicit with two arguments? (likewise with the next ctor)

@@ +788,5 @@
> +    auto reason = JS::gcreason::ExplainReason(mReason);
> +    auto length = strlen(reason);
> +    if (GetTracingType() == mozilla::MarkerTracingType::START) {
> +      aMarker.mCauseName.Construct(
> +        NS_ConvertUTF8toUTF16(nsDependentCString(reason, length)));

I think you don't need the |length| argument here.

@@ +796,5 @@
> +  virtual mozilla::UniquePtr<AbstractTimelineMarker>
> +  Clone() override
> +  {
> +    mozilla::UniquePtr<MinorGCMarker> clone(
> +      new MinorGCMarker(GetTracingType(), mReason));

Should this use MakeUnique?

@@ +797,5 @@
> +  Clone() override
> +  {
> +    mozilla::UniquePtr<MinorGCMarker> clone(
> +      new MinorGCMarker(GetTracingType(), mReason));
> +    if (clone) {

Isn't this allocation infallible?

@@ +814,5 @@
> +  MOZ_ASSERT(self->Runtime() == aRuntime);
> +
> +  if (NS_IsMainThread()) {
> +    // We would like to support all threads here, but the way timeline consumers
> +    // is set up currently, you can either add a marker for one specific

nit: is -> are

@@ +816,5 @@
> +  if (NS_IsMainThread()) {
> +    // We would like to support all threads here, but the way timeline consumers
> +    // is set up currently, you can either add a marker for one specific
> +    // docshell, or for every consumer globally. We would like to add a marker
> +    // for every consumer observing anything on a this thread, but that is not

nit: "a this" should be "this"?

@@ +819,5 @@
> +    // docshell, or for every consumer globally. We would like to add a marker
> +    // for every consumer observing anything on a this thread, but that is not
> +    // currently possible. For now, add global markers only when we are on the
> +    // main thread, since the UI for this tracing data only displays data
> +    // relevant to the main-thread at the moment.

nit: you don't need the "at the moment".

@@ +824,5 @@
> +
> +    RefPtr<TimelineConsumers> timelines = TimelineConsumers::Get();
> +    if (timelines && !timelines->IsEmpty()) {
> +      auto marker = mozilla::MakeUnique<MinorGCMarker>(aProgress, aReason);
> +      if (marker) {

Can marker ever be null? Isn't this using infallible new?

@@ +826,5 @@
> +    if (timelines && !timelines->IsEmpty()) {
> +      auto marker = mozilla::MakeUnique<MinorGCMarker>(aProgress, aReason);
> +      if (marker) {
> +        mozilla::UniquePtr<AbstractTimelineMarker> abstractMarker(
> +          mozilla::Move(marker));

It looks odd to me to make something unique, and then immediately move it, but maybe that's just the way you are supposed to do it.

Comment 28

[Nathan Froyd [:froydnj]]

Comment on attachment 8708098 [details] [diff] [review]
Part 3: Install a callback to trace nursery collections

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

CycleCollectedJSRuntime.cpp has |using namespace mozilla;|, so we ought to be able to drop a lot of the mozilla:: prefixes from things.  A few comments on top of Andrew's comments:

::: xpcom/base/CycleCollectedJSRuntime.cpp
@@ +788,5 @@
> +    auto reason = JS::gcreason::ExplainReason(mReason);
> +    auto length = strlen(reason);
> +    if (GetTracingType() == mozilla::MarkerTracingType::START) {
> +      aMarker.mCauseName.Construct(
> +        NS_ConvertUTF8toUTF16(nsDependentCString(reason, length)));

Just NS_ConvertUTF8toUTF16(reason) works, and then you can drop the strlen call, as Andrew suggested.

@@ +796,5 @@
> +  virtual mozilla::UniquePtr<AbstractTimelineMarker>
> +  Clone() override
> +  {
> +    mozilla::UniquePtr<MinorGCMarker> clone(
> +      new MinorGCMarker(GetTracingType(), mReason));

I vote for auto clone = MakeUnique<MinorGCMarker>(...);

@@ +797,5 @@
> +  Clone() override
> +  {
> +    mozilla::UniquePtr<MinorGCMarker> clone(
> +      new MinorGCMarker(GetTracingType(), mReason));
> +    if (clone) {

If you really mean to use fallible allocations here and throughout, you want to use MakeUniqueFallible from UniquePtrExtensions.h.

@@ +800,5 @@
> +      new MinorGCMarker(GetTracingType(), mReason));
> +    if (clone) {
> +      clone->SetCustomTime(GetTime());
> +    }
> +    return mozilla::UniquePtr<AbstractTimelineMarker>(mozilla::Move(clone));

I assume the compiler complains if you just try to |return clone;|?

@@ +826,5 @@
> +    if (timelines && !timelines->IsEmpty()) {
> +      auto marker = mozilla::MakeUnique<MinorGCMarker>(aProgress, aReason);
> +      if (marker) {
> +        mozilla::UniquePtr<AbstractTimelineMarker> abstractMarker(
> +          mozilla::Move(marker));

Nick's problem here is that he can't do:

timelines->AddMarkerForAllObservedDocShells(MakeUnique<MinorGCMarker>(aProgress, aReason));

because AddMarkerForAllObservedDocShells takes a reference, not a const reference, and passing a temporary like that to a non-const reference isn't allowed.  So he has to have this temporary variable.  If we really don't need fallibility here, then:

UniquePtr<AbstractTimelineMarker> abstractMarker(MakeUnique<MinorGCMarker>(...));

ought to work, but that is a bit of a mouthful.

Comment 29

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

(In reply to Andrew McCreight [:mccr8] from comment #27)
> ::: xpcom/base/CycleCollectedJSRuntime.cpp
> @@ +441,5 @@
> >    }
> >    JS_SetGrayGCRootsTracer(mJSRuntime, TraceGrayJS, this);
> >    JS_SetGCCallback(mJSRuntime, GCCallback, this);
> >    mPrevGCSliceCallback = JS::SetGCSliceCallback(mJSRuntime, GCSliceCallback);
> > +  mPrevGCNurseryCollectionCallback = JS::SetGCNurseryCollectionCallback(
> 
> Now that I've thought about this some more, it seems like it would make
> sense to only set this on the main thread, rather than doing the check every
> time we have the callback, so please do that.

So, move this into XPCJSRuntime or only set the callback here if NS_IsMainThread() and assert NS_IsMainThred() in the callback?

> @@ +796,5 @@
> > +  virtual mozilla::UniquePtr<AbstractTimelineMarker>
> > +  Clone() override
> > +  {
> > +    mozilla::UniquePtr<MinorGCMarker> clone(
> > +      new MinorGCMarker(GetTracingType(), mReason));
> 
> Should this use MakeUnique?

This would force the constructor to be public, but I suppose that isn't a very big deal.

> @@ +826,5 @@
> > +    if (timelines && !timelines->IsEmpty()) {
> > +      auto marker = mozilla::MakeUnique<MinorGCMarker>(aProgress, aReason);
> > +      if (marker) {
> > +        mozilla::UniquePtr<AbstractTimelineMarker> abstractMarker(
> > +          mozilla::Move(marker));
> 
> It looks odd to me to make something unique, and then immediately move it,
> but maybe that's just the way you are supposed to do it.

IIRC, a UniquePtr<Derived> cannot be coerced into a UniquePtr<Base>, which is why I spelled everything out in painful detail here, but I admit I didn't test the coercion first.

(In reply to Nathan Froyd [:froydnj] from comment #28)
> @@ +796,5 @@
> > +  virtual mozilla::UniquePtr<AbstractTimelineMarker>
> > +  Clone() override
> > +  {
> > +    mozilla::UniquePtr<MinorGCMarker> clone(
> > +      new MinorGCMarker(GetTracingType(), mReason));
> 
> I vote for auto clone = MakeUnique<MinorGCMarker>(...);

Ok, I will make the constructor public.

> @@ +797,5 @@
> > +  Clone() override
> > +  {
> > +    mozilla::UniquePtr<MinorGCMarker> clone(
> > +      new MinorGCMarker(GetTracingType(), mReason));
> > +    if (clone) {
> 
> If you really mean to use fallible allocations here and throughout, you want
> to use MakeUniqueFallible from UniquePtrExtensions.h.

I don't really have a preference either way, I'm just used to hacking in SpiderMonkey where it is always fallible.

> @@ +800,5 @@
> > +      new MinorGCMarker(GetTracingType(), mReason));
> > +    if (clone) {
> > +      clone->SetCustomTime(GetTime());
> > +    }
> > +    return mozilla::UniquePtr<AbstractTimelineMarker>(mozilla::Move(clone));
> 
> I assume the compiler complains if you just try to |return clone;|?

See note earlier in this comment about UniquePtr<Base> and UniquePtr<Derived>.

> @@ +826,5 @@
> > +    if (timelines && !timelines->IsEmpty()) {
> > +      auto marker = mozilla::MakeUnique<MinorGCMarker>(aProgress, aReason);
> > +      if (marker) {
> > +        mozilla::UniquePtr<AbstractTimelineMarker> abstractMarker(
> > +          mozilla::Move(marker));
> 
> Nick's problem here is that he can't do:
> 
> timelines-
> >AddMarkerForAllObservedDocShells(MakeUnique<MinorGCMarker>(aProgress,
> aReason));
> 
> because AddMarkerForAllObservedDocShells takes a reference, not a const
> reference, and passing a temporary like that to a non-const reference isn't
> allowed.

AFAICT, there is not a good reason why it takes a non-const reference and not a && reference, since it is taking ownership of the UniquePtr internally anyways, but I didn't want to start rewriting APIs just to add a new marker.

Comment 30

[Andrew McCreight [:mccr8]]

(In reply to Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8] from comment #29)
> So, move this into XPCJSRuntime or only set the callback here if
> NS_IsMainThread() and assert NS_IsMainThred() in the callback?

The latter. It seems like that should be simpler over all. Thanks!

> I don't really have a preference either way, I'm just used to hacking in
> SpiderMonkey where it is always fallible.

Gecko style is to always use infallible allocation unless web content can make some object an unbounded size. This is safer because these OOM handling paths are hard to test. SpiderMonkey people have had to invest a decent chunk of time in OOM fuzzing and fixing, as you've probably seen if you follow the JS engine component.

Comment 31

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/59e221c0187c
https://hg.mozilla.org/integration/mozilla-inbound/rev/c345ee9e6201
https://hg.mozilla.org/integration/mozilla-inbound/rev/b6ac28307c87
https://hg.mozilla.org/integration/mozilla-inbound/rev/349ed8187489
https://hg.mozilla.org/integration/mozilla-inbound/rev/d3e9bcaeb725
https://hg.mozilla.org/integration/mozilla-inbound/rev/f68531b0c81d

Comment 32

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/75ad3c86b2ba

Comment 33

[Jim Blandy :jimb]

\o/

Comment 34

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/59e221c0187c
https://hg.mozilla.org/mozilla-central/rev/c345ee9e6201
https://hg.mozilla.org/mozilla-central/rev/b6ac28307c87
https://hg.mozilla.org/mozilla-central/rev/349ed8187489
https://hg.mozilla.org/mozilla-central/rev/d3e9bcaeb725
https://hg.mozilla.org/mozilla-central/rev/f68531b0c81d
https://hg.mozilla.org/mozilla-central/rev/75ad3c86b2ba

Comment 35

[Mayur Patil]

[bugday-20160323]

Status: RESOLVED,FIXED -> UNVERIFIED

Comments:
STR: Not clear.
Developer specific testing

Component: 
Name			Firefox
Version			46.0b9
Build ID		20160322075646
Update Channel	beta
User Agent		Mozilla/5.0 (Windows NT 6.1; WOW64; rv:46.0) Gecko/20100101 Firefox/46.0
OS				Windows 7 SP1 x86_64

Expected Results: 
Developer specific testing

Actual Results: 
As expected