848665 - Enormous amounts of CPU time spent in ScriptFrameIter

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Katelyn Gadd (:kael)]

Attachment: Profile screenshot

I'm trying to debug something that's broken in Nightly but works in Aurora. Unfortunately, having Firebug or the built-in Debugger active causes performance to degrade ENORMOUSLY and also hides the issue I'm trying to debug. This bug report is about the performance degradation.

A SPS profile shows that with either Firebug or the built-in Debugger active, over 60% of CPU time in my recording was spent in ScriptFrameIter. Not only is this eating up CPU time, but it causes really long pauses where the UI thread is unresponsive.

I had to upload the profile to my own server because for some reason the normal service wouldn't let me upload it (it failed with 'error 0', whatever that means), so let me know if you can't get to it for some reason.

I've attached a screenshot of the relevant bit of the profile.

Comment 1

[Jeff Walden [:Waldo]]

Any possibility some operation like pcQuadratic is being called, that results in this non-linear perf?  We'd probably do well adding "linear" or whatever order of complexity to the name of the method(s) in play, if it's something like that.

Comment 2

[Boris Zbarsky [:bzbarsky]]

The callstack looks something like this:

ScriptFrameIter
js::Debugger::slowPathOnLeave/EnterFrame
js::Debugger::onLeave/EnterFrame
js::ScriptDebugPrologue/Epilogue
js::mjit::stubs::ScriptDebugPrologue/Epiloge
page script

Comment 3

[Katelyn Gadd (:kael)]

I don't know what pcQuadratic is. How would I check whether it's being called?
My best theory is that since this code gets pretty deeply recursive in some initialization code, some really bad scaling in the stack walking is causing that deep recursion to turn into really long hangs in the debugger.

Also, I occasionally get 'slow script' warnings for some .js file that seems to be related to debugger RPC.

Comment 4

[Jeff Walden [:Waldo]]

If you're not seeing it as eating up time, it's not being called.

js::Debugger::slowPathOnLeaveFrame has two linear FrameRange loops over all script frames, front to end, using ScriptFrameIter.  That's O(2 * stack frame count).  The first such loop also builds up an AutoObjectVector of Debugger.Frame objects.  There's a loop over that vector.  That's another O(stack frame count).  So every leave-frame is going to have O(3 * stack frame count) complexity, at least.  If you have a deep stack, leaving a frame takes time proportional to stack frame depth, and leaving every frame is quadratic.

Does leaving a frame really require walking all frames a bunch of times?  Could that be done lazily if necessary somehow?  *handwaves* *jazz hands*

Comment 5

[Jeff Walden [:Waldo]]

Or no, Luke tells me I'm misreading this horribly, and really the problem is ScriptFrameIter is not the right thing to use here, if you want just the top frame or something.

Comment 6

[Jeff Walden [:Waldo]]

...and jandem knows what the right thing is.  :-)

Comment 7

[Jim Blandy :jimb]

That function uses ScriptFrameIter only to find the top frame of the stack: we want to extract and possibly change the return value; find out which script is being executed; get an AbstractFramePtr value that we can use to look up our Debugger.Frame instances, and so on.

However, Luke pointed out that ScriptFrameIter's constructor calls ExpandAllInlineFrames (for JaegerMonkey), which is hugely expensive. So we're paying to affect other stack frames when we only need info about the one that's in the process of exiting.

We use the ScriptFrameIter for the following things:

- We call iter.abstractFramePtr, and use that value to look up Debugger.Frame instances.

- We use iter.returnValue() and iter.setReturnValue(), because Debugger wants to tell onPop handlers what value the frame returned, and let the handler change that value.

- We use iter.script(), to take the script the frame was running out of single-step mode, and to remove breakpoints set on eval scripts (while you'd expect them to get deleted, they actually get cached, so a subsequent eval of identical code might resurrect dead breakpoints).

- We use iter.isEvalFrame() to decide whether to remove breakpoints, as described above.

There are probably alternate ways to get each of these pieces of information; for example, we could use cx->stack.currentScript() instead of iter.script().

Comment 8

[Jan de Mooij [:jandem]]

I guess my StackFrame -> ScriptFrameIter/AbstractFramePtr conversion caused this. Taking.

Comment 9

[Jan de Mooij [:jandem]]

Attachment: Patch

Debugger.Frame objects store a pointer-to-StackIter::Data, because there are methods where we can't use AbstractFramePtr: getting the current pc, previous frame, etc requires a StackIter.

Fortunately though, the onEnterFrame/onLeaveFrame hooks don't really need a ScriptFrameIter: we can just pass the AbstractFramePtr from the caller.

Comment 10

[Jan de Mooij [:jandem]]

Jim, review ping. It's a simple patch and I'd like to land it on Aurora.

Comment 11

[Jim Blandy :jimb]

Comment on attachment 722729 [details] [diff] [review]
Patch

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

This looks great --- a lot of simplifications in there.

I would want to make sure this works on both DEBUG and non-DEBUG builds, to catch any stray references to 'iter'; a clean Try push would suffice.

::: js/src/vm/Debugger.cpp
@@ +497,3 @@
>      ScriptFrameIter iter(cx);
> +    JS_ASSERT(iter.abstractFramePtr() == frame);
> +#endif

This means we'll still get the horrible performance in DEBUG builds, right?

::: js/src/vm/Stack-inl.h
@@ +604,5 @@
> +AbstractFramePtr::returnValue() const
> +{
> +    if (isStackFrame())
> +        return asStackFrame()->returnValue();
> +    JS_NOT_REACHED("Invalid frame");

Could this be written more directly as:
JS_ASSERT(isStackFrame());
up on entry to the function?

Comment 12

[Jan de Mooij [:jandem]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/898c83ea7b06

(In reply to Jim Blandy :jimb from comment #11)
> This means we'll still get the horrible performance in DEBUG builds, right?

Yeah though only in debug mode, so I don't think it matters much.

> Could this be written more directly as:
> JS_ASSERT(isStackFrame());
> up on entry to the function?

This matches the other AbstractFramePtr methods and when this change merges to the BC branch we can just replace the JS_NOT_REACHED with a "return asBaselineFrame()->returnValue();"

Comment 13

[Boris Zbarsky [:bzbarsky]]

As long as it's not horrible enough to make debugging debug mode impossible...

Comment 14

[Jan de Mooij [:jandem]]

Comment on attachment 722729 [details] [diff] [review]
Patch

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Bug 827258
User impact if declined: Slow debugging with Firebug or builtin debugger. 
Testing completed (on m-c, etc.): On inbound
Risk to taking this patch (and alternatives if risky): Low, affects only debug mode
String or UUID changes made by this patch: None

Comment 15

[Jim Blandy :jimb]

(In reply to Boris Zbarsky (:bz) from comment #13)
> As long as it's not horrible enough to make debugging debug mode
> impossible...

If I'm reading right, this patch will leave performance essentially unchanged when using the JS debugger on a DEBUG build: the problem reported by the original poster remains, in that configuration.

I approved the patch because it will help our releases, since they're not DEBUG builds. But frankly, I think those assertions should just come out.

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/898c83ea7b06

Comment 17

[bhavana bajaj [:bajaj]]

Comment on attachment 722729 [details] [diff] [review]
Patch

low risk , helps with faster debugging with Firebug or builtin debugger . Please go ahead with the landing

Comment 18

[Jim Blandy :jimb]

Filed as follow-up bug 852773.

Comment 19

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/bb20a6500778

Comment 20

[u279076]

Kevin, can you please confirm if this is fixed for you now? It should be fixed in today's Firefox Nightly and Aurora builds.

Comment 21

[Katelyn Gadd (:kael)]

I'm seeing samples for various debugger machinery (like enter/leaveframe) in SPS profiles with the latest nightly, but definitely not seeing ScriptFrameIter. The perf hit for the debugger looks to be about 3-4x right now, which is a lot better than what it was before. Looks like it's more or less fixed.

Comment 22

[Jim Blandy :jimb]

(In reply to Kevin Gadd (:kael) from comment #21)
> I'm seeing samples for various debugger machinery (like enter/leaveframe) in
> SPS profiles with the latest nightly, but definitely not seeing
> ScriptFrameIter. The perf hit for the debugger looks to be about 3-4x right
> now, which is a lot better than what it was before. Looks like it's more or
> less fixed.

I agree this bug seems fixed - but that's still a lot more impact than I'd like. What benchmark are you using?

Comment 23

[Katelyn Gadd (:kael)]

I'm comparing the framerate in escape goat with the debugger active versus the framerate normally. It's possible the hit will go down once things 'settle'. You can run an automated test by hitting

http://www.playescapegoat.com/?replayURI=/stages2and3.replay&disableSound

It will dump the overall mean/median performance stats into the log at the end of the replay, but it also shows you the current effective framerate if you mouse over the little colored dot in the corner labelled 'performance' (that's what I was using to guess at the perf hit, based on the framerate).

Beyond the reported framerate I also observed lots of jank with the debugger active, though that could have just been unlucky GC/CC timing and not a problem caused by the debugger.

Still, it was getting over 60fps, so it's good enough for basic debugging even if it's not consistently realtime and it janks some. Chrome has really severe performance consequences for having the debugger open, so I don't expect miracles :) I'm certainly willing to help if you want to keep digging into issues with debugger performance.

Comment 24

[Jim Blandy :jimb]

Filed follow-up bug 854078.

Comment 25

[Mihai Morar, (:MihaiMorar)]

How can QA verify this fix?

Comment 26

[Jim Blandy :jimb]

(In reply to MarioMi (:MarioMi) from comment #25)
> How can QA verify this fix?

Is comment #21 enough? Or the instructions in comment #23?