1316150 - Profiler hangs when interrupting malloc in JS::ProfilingFrameIterator::extractStack

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Alon Zakai (:azakai)]

STR:

1. Load http://assets.metacade.com/emulators/jaguar-wasm.html , which is the Jaguar game emulated in JSMESS, compiled to wasm. This is a fairly large wasm application.

2. Start the profiler.

The profiler appears to run, it updates its own display, but the frame rate it shows the app as having is either 0 or decreases to 0, and the app does not render. The browser itself is no longer responsive, stopping the profiler is impossible. Other tabs show the spinner forever, even if I close this tab. The only option to shut down the browser.

Comment 1

[Luke Wagner [:luke]]

I'm able to reproduce: the content process seems hung (spinner) and when I break into it with GDB I think I see why: we're doing a malloc from within the signal handler which tries to take a lock which we've already taken further down the stack (frame #19) because we've interrupted malloc.

Hg indicates that this malloc copy was introduced by bug 1297360.  Kannan/Jon: Could we instead move the duplication of labels stored in Frames to the points at which labels can be freed (presumably, during GC)?

Comment 2

[Luke Wagner [:luke]]

Attachment: backtrace.txt

Backtrace of hang.  I should add that this is wasm, but I see a DuplicateStack() for non-wasm as well.

Comment 3

[Kannan Vijayan [:djvj]]

That should be possible, but might cause longer pause times during GC if profiling is enabled.

During GC of the jitcode map table, the collector can save the to-be-freed labels to a temporary set.  After the scan of the jitcode map table, the GC would then need to scan the profile sample buffer for entries with pointers from the set, and do the duplication then.  Then it frees all the labels in the set.  This should be safe since sampling is suppressed during GC of the profiler jitcodemap tables.

Comment 4

[Jon Coppeard (:jonco)]

Attachment: bug1316150-hold-jit-strings

How about this: we add a flag to delay freeing of any of these strings until we know the client doesn't have any references to them any more.  This patch applies on top of a backout of the patch in bug 1297360.

Comment 5

[Luke Wagner [:luke]]

Comment on attachment 8810459 [details] [diff] [review]
bug1316150-hold-jit-strings

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

That sounds great, thanks Jon!  I think wasm now has the same problem as Ion (labels can be cleared either when profiling is disabled (js::wasm::Code::ensureProfilingState) or when a Code object is destroyed by its owning wasm::Instance).  Could we hoist frameLabelsToFree_ and keepFrameLabels_ bool up to the JSRuntime so wasm could use too?

::: js/src/jit/JitcodeMap.h
@@ +1010,5 @@
>      JitcodeGlobalEntry* freeEntries_;
>      uint32_t rand_;
>      uint32_t skiplistSize_;
> +    bool keepFrameLabels_;
> +    Vector<const char*, 0, SystemAllocPolicy> frameLabelsToFree_;

Perhaps a Vector<UniqueChars>?

::: tools/profiler/core/GeckoSampler.cpp
@@ +763,5 @@
>    }
>    uint32_t jsCount = 0;
>  #ifndef SPS_STANDALONE
>    JS::ProfilingFrameIterator::Frame jsFrames[1000];
> +  mozilla::Maybe<JS::AutoKeepFrameLabels> keepLabels;

This might be my own misunderstanding of how SPS works, but I'd assume that we need to start keeping labels as soon as profiling starts (when const char*s go into the buffer) and stop keeping when profiling stops.  Unfortunately, this would mean never freeing labels for people who run with profiling always-on, which is why I was suggesting the admittedly more complicated scheme that attaches generations to labels (you get stamped with a generation when your module/jitcode dies and you can't be freed until 2 generations  later).

Comment 6

[Jon Coppeard (:jonco)]

(In reply to Luke Wagner [:luke] from comment #5)

Thanks for the comments, I'll update the patch.

> This might be my own misunderstanding of how SPS works, but I'd assume that
> we need to start keeping labels as soon as profiling starts (when const
> char*s go into the buffer) and stop keeping when profiling stops.

If I'm understanding this correctly this label string is only used here, where it's passed to addDynamicTag which memcpys the contents:

http://searchfox.org/mozilla-central/source/tools/profiler/core/GeckoSampler.cpp#904

This is after the ProfilingFrameIterator loop but still in the same function.

Comment 7

[Luke Wagner [:luke]]

(In reply to Jon Coppeard (:jonco) from comment #6)
Ah hah, thanks for explaining.  I had assumed that the reason for the DuplicateString() was because we wanted to embed string pointers into the circular buffer (so we didn't chew through it so quickly).  But I see now that the problem was just GCs during the stack walk itself.

So in this case, if we are walking the stack and find a wasm module, that module is definitely rooted by the callstack, and so no GC should be able to invalidate its labels, so I think your patch is fine from a wasm pov.

Comment 8

[Jon Coppeard (:jonco)]

Attachment: bug1316150-profiler-gc-hazard

So after digging into this some more, it seems that the gecko profiler doesn't use these label strings after anything that could trigger a GC, so we don't really need to do any of this.  The testing function ReadSPSProfilingStack does but that can be changed.

Here's a patch that fixes that and makes the hazard analysis check that ProfilingFrameIterator::Frame is not used after GC (this is not ideal since we could copy the pointer somewhere but is better than nothing).

This is on top of a backout of bug 1297360 which removes the malloc.

Comment 9

[Kannan Vijayan [:djvj]]

Comment on attachment 8811684 [details] [diff] [review]
bug1316150-profiler-gc-hazard

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

::: js/src/builtin/TestingFunctions.cpp
@@ +1744,3 @@
>            : kind(kind), label(label) {}
>          const char* kind;
> +        char* label;

Since this label is now a duped string, I don't see where it's getting freed.

@@ +1774,5 @@
>                default:
>                  frameKindStr = "unknown";
>              }
>  
> +            char* label = JS_strdup(cx, frames[i].label);

Duped here.

Comment 10

[Jon Coppeard (:jonco)]

(In reply to Kannan Vijayan [:djvj] from comment #9)
NewString() takes owenership of the malloced chars, but I do need to make this a UniqueChars so that it gets freed if we fail before that point.

Comment 11

[Jon Coppeard (:jonco)]

Attachment: bug1316150-profiler-gc-hazard v2

Updated patch.

Comment 12

[Kannan Vijayan [:djvj]]

Comment on attachment 8812176 [details] [diff] [review]
bug1316150-profiler-gc-hazard v2

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

Cool.

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/f35a745eff4c
Make profiler frame labels a GC hazard and make shell profiling function copy them r=djvj

Comment 14

[Carsten Book [:Tomcat]]

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

Comment 16

[Luke Wagner [:luke]]

I retested comment 0 and can confirm no more hang.  Thanks guys!