932837 - Optimize JSStackFrame::CreateStack

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Jan de Mooij [:jandem]]

See discussion in bug 929950.

JSStackFrame::CreateStack calls DescribeStack to get a stack trace from JS, then it allocates a JSStackFrame for every frame and does a bunch of other slow stuff like strlen(filename) and calling some JS API functions.

It would be nice if we could avoid the copying completely and had methods on JSStackFrame to get the line number, file name etc only when we actually need them.

Comment 1

[Boris Zbarsky [:bzbarsky]]

I agree that if we could do it lazily that would rock.  How can we keep the relevant JS data structures alive and in the right state?

The filenames are not too bad: we can just keep and trace the JSScripts involved.  Similar for the function name bits, if we just keep the functions alive.  But what about line numbers?  That is, can we avoid the DescribeStack call somehow, or should we still do it but then pretty much try to do nothing else?

Comment 2

[Jan de Mooij [:jandem]]

(In reply to Boris Zbarsky [:bz] from comment #1)
> The filenames are not too bad: we can just keep and trace the JSScripts
> involved.  Similar for the function name bits, if we just keep the functions
> alive.  But what about line numbers?

If we store the JSScript anyway, we might as well store the jsbytecode *pc (or "uint32_t offset" if we don't want to expose jsbytecode). Then it's just a matter of calling PCToLineNumber(script, offset) once we add that function to the API.

Comment 3

[Jan de Mooij [:jandem]]

(In reply to Boris Zbarsky [:bz] from comment #1)
> That is, can we avoid the
> DescribeStack call somehow, or should we still do it but then pretty much
> try to do nothing else?

I think we still need it. But DescribeStack itself could also be a bit smarter, for instance we probably don't need that js_new<JS::StackDescription>() and the frames Vector could malloc/realloc less...

Comment 4

[Boris Zbarsky [:bzbarsky]]

OK.  So in an ideal world, I think this would look like so:

1)  We still call DescribeStack.
2)  This hands back some data structure we can just trace or whatnot to keep the relevant
    bits alive.
3)  The data structure stores whatever it needs to store to produce the stack information
    on demand.
4)  When we need the stack information, we ask this data structure.

right?  So if the exception is caught and then ignored we only do the DescribeStack work.

Comment 5

[Boris Zbarsky [:bzbarsky]]

So I just did a profile of the testcase in bug 922048, or rather one particular selector in it that throws.  I did that with the patch in bug 932870 applied.

About 21.8% of the time was spent under DocumebtBinding::genericMethod.  20.4% was under DocumentBinding::querySelectorAll.  Of that, 19.1% was under dom::Throw.  If I focus on dom::Throw, so that all percentages are of the time spent under there, I see:

 50% JS::DescribeStack.  This breaks down as:
  19% js::PCToLineNumber (almost entirely self time, and in particular at least half
      the SN_DELTA(), SN_IS_TERMINATOR(), SN_NEXT() bits).
  16% js::ScriptFrameIter::operator++ (mostly under InlineFrameIteratorMaybeGC::resetOn
      doing osiIndex, findNextFrame, ionScript(), etc).
  10% VectorBase::growStorageBy (looks like malloc and free; Vector never uses
      realloc???).

So yeah, nixing the malloc/realloc costs and the eager line number computations would help a good bit with that part.

We also have:

 8% malloc calls from JSStackFrame::CreateStack.
 5% nsMemory::Clone calls from the same.
 2% free() calls from the same.
 2% JS::FreeStackDescription calls from same.

Overall, 74% of the time under Throw() is under JSStackFrame::CreateStack.

Outside of that:

 6% the GetService call for nsXPConnect in dom::GetCurrentJSStack(!).  Filed bug 932886.
 1% NS_IsMainThread calls in the same place.
 2% dom::Exception::Initialize (mostly a GetFileName call on the JSStackFrame; why?).
    We should be able to do this stuff (getting the filename and lineno) lazily, I
    think.
 5-6% various call overhead, since the C++ stack here ends up 4-5 levels deep.
 8% under dom::ThrowExceptionObject.  This has 2% checks for system principal,
    3% creating the JS reflector for the C++ DOMException object, some more mainthread
    checks, etc.

We'll definitely want to at least change Initialize to not eagerly grab the filename/lineno if we make all that computation lazy.

Comment 6

[Boris Zbarsky [:bzbarsky]]

Some patches coming up that make the testcase in bug about 100ms faster for me.

They're not done yet, and in particular the tracing of the stack bits is not hooked up.  I'd appreciate it if someone more familiar with CC and Heap and such took a look at that part and made whatever changes we need to JS::StackDescription here.

Comment 7

[Boris Zbarsky [:bzbarsky]]

Attachment: part 1. Make FrameDescription compute the line number lazily.

Comment 8

[Boris Zbarsky [:bzbarsky]]

Attachment: part 2. Create a refcounted object to manage the lifetime of a JS::StackDescription.

Comment 9

[Boris Zbarsky [:bzbarsky]]

Attachment: part 3. Make JSStackFrame get information from the JS stack lazily.

Comment 10

[Boris Zbarsky [:bzbarsky]]

Attachment: part 4. Allocate the caller JSStackFrames lazily.

Comment 11

[Boris Zbarsky [:bzbarsky]]

Attachment: part 5. Don't eagerly grab file/line info when constructing an Exception.

Kyle, is it ok to start using the filename/lineno of the location we picked up off the stack in the case when aLocation was null in Initialize?  If not, we can just add a boolean that tracks which codepath we took

Comment 12

[Boris Zbarsky [:bzbarsky]]

Also, we should seriously think about converting this stuff to nsString and away from char*!

With the above patches, if I do something like comment 5 and focus on dom::Throw, we're up to 57% of the time under JS::DescriptStack and overall time has dropped by about 12%.

Comment 13

[Jan de Mooij [:jandem]]

Comment on attachment 8347903 [details] [diff] [review]
part 1.  Make FrameDescription compute the line number lazily.

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

Looks great, just some JS style nits. Thanks for doing this.

::: js/public/OldDebugAPI.h
@@ +33,2 @@
>  {
> +public:

Nit: indent the "public:" and "private:" labels in this class with two spaces.

@@ +40,5 @@
> +    {
> +    }
> +
> +    unsigned lineno()
> +    {

Nit: { can go after lineno(), so "unsigned lineno() {", same for script() and fun() below.

@@ +49,5 @@
> +        return lineno_;
> +    }
> +
> +    JSScript * script() const
> +    {

Nit: no space after *, same for fun() below.

@@ +60,5 @@
> +    }
> +
> +private:
> +    JSScript* script_;
> +    JSFunction* fun_;

Nit: * goes before script_ and fun_, like pc_ below.

Comment 14

[Terrence Cole [:terrence]]

Comment on attachment 8347904 [details] [diff] [review]
part 2.  Create a refcounted object to manage the lifetime of a JS::StackDescription.

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

f=me We discussed on IRC and this strategy seems totally reasonable.

Comment 15

[Boris Zbarsky [:bzbarsky]]

Attachment: part 2. Create a refcounted object to manage the lifetime of a JS::StackDescription. terrence

Comment 16

[Terrence Cole [:terrence]]

Comment on attachment 8348307 [details] [diff] [review]
part 2.  Create a refcounted object to manage the lifetime of a JS::StackDescription.   terrence

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

This looks awesome! r=me

Comment 17

[Andrew McCreight [:mccr8]]

Comment on attachment 8348307 [details] [diff] [review]
part 2.  Create a refcounted object to manage the lifetime of a JS::StackDescription.   terrence

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

::: dom/bindings/Exceptions.cpp
@@ +205,5 @@
>  
> +class StackDescriptionOwner {
> +public:
> +  StackDescriptionOwner(JS::StackDescription* aDescription)
> +    : mDescription(aDescription)

You need mozilla::HoldJSObjects(this) in the ctor and mozilla::DropJSObjects(this) in the dtor, so these DescriptionOwners will actually get registered as JS holders, which will make them get traced by the GC and CC.

This probably doesn't show up in testing because the lifetime of these objects is stack-limited.  The CC probably won't even run unless you get a nested event loop in there somehow.

I mean, really, you probably want some kind of Rooted<JS::StackDescription> class because this is stack-scoped, but that's going to be a whole other pile of macros to learn so this is fine with me.

::: js/src/vm/OldDebugAPI.cpp
@@ +990,5 @@
>  JS_PUBLIC_API(void)
>  JS::FreeStackDescription(JSContext *cx, JS::StackDescription *desc)
>  {
> +    for (size_t i = 0; i < desc->nframes; ++i)
> +        desc->frames[i].~FrameDescription();

Lovely. I guess this is what you get when you combine C and C++ code.

::: xpcom/glue/nsCycleCollectionParticipant.cpp
@@ +99,5 @@
>    mCallback(p->get(), name, closure);
>  }
> +
> +void
> +TraceCallbackFunc::Trace(JS::Heap<JSFunction*>* p, const char* name, void* closure) const

maybe put this next to the case for JSObject because it is also a JSObject and thus their definitions will look the same?

Comment 18

[Andrew McCreight [:mccr8]]

Comment on attachment 8348307 [details] [diff] [review]
part 2.  Create a refcounted object to manage the lifetime of a JS::StackDescription.   terrence

I'm not sure what happened there.

Comment 19

[Boris Zbarsky [:bzbarsky]]

> mozilla::HoldJSObjects(this) in the ctor and mozilla::DropJSObjects(this) in the dtor

Aha!  I knew I was missing something.

> because this is stack-scoped

The whole point of this bug is to stop it being stack-scoped.

> maybe put this next to the case for JSObject

Will do.

Comment 20

[Andrew McCreight [:mccr8]]

(In reply to Boris Zbarsky [:bz] from comment #19)
> The whole point of this bug is to stop it being stack-scoped.
Ah, great!  Sorry, for some reason I didn't notice this was only patch 2 and not the last patch.

Comment 21

[Boris Zbarsky [:bzbarsky]]

Attachment: Part 2 updated to review comments

Comment 22

[Boris Zbarsky [:bzbarsky]]

Attachment: part 3. Make JSStackFrame get information from the JS stack lazily.

Comment 23

[Boris Zbarsky [:bzbarsky]]

Attachment: Part 2 updated with some null-checks try caught

Comment 24

[Boris Zbarsky [:bzbarsky]]

Attachment: Part 1 updated to review comments

Comment 25

[Boris Zbarsky [:bzbarsky]]

Attachment: part 3. Make JSStackFrame get information from the JS stack lazily.

Comment 26

[Boris Zbarsky [:bzbarsky]]

Attachment: part 4. Allocate the caller JSStackFrames lazily.

Comment 27

[Boris Zbarsky [:bzbarsky]]

Attachment: Performance testcase

Comment 28

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 8348899 [details] [diff] [review]
part 3.  Make JSStackFrame get information from the JS stack lazily.

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

::: dom/bindings/Exceptions.cpp
@@ +308,5 @@
> +  size_t mIndex;
> +
> +  bool mFilenameValid;
> +  bool mFunnameValid;
> +  bool mLinenoValid;

nullptr and 0 are valid values.  I would call these mFooInitialized.

@@ +392,5 @@
> +      }
> +    }
> +    mFilenameValid = true;
> +  }
> +  return mFilename;

super-nit: \n before return

@@ +462,5 @@
> +    JS::FrameDescription& desc = mStackDescription->FrameAt(mIndex);
> +    mLineno = desc.lineno();
> +    mLinenoValid = true;
> +  }
> +  return mLineno;

here too

@@ +491,5 @@
>  NS_IMETHODIMP JSStackFrame::ToString(char** _retval)
>  {
>    const char* frametype = IsJSFrame() ? "JS" : "native";
> +  const char* filename = GetFilename() ? GetFilename() : "<unknown filename>";
> +  const char* funname = GetFunname() ? GetFunname() : "<TOP_LEVEL>";

Calling the function twice is kind of ugly.  Can we do

const char* foo = GetFoo();
if (!foo) {
  foo = "<default foo>";
}
?

@@ +521,4 @@
>  
> +  // We create one dummy frame at the end (why?), so go up through
> +  // desc->nframes+1
> +  for (size_t i = 0; i < desc->nframes+1; i++) {

super-nit: spaces around +

@@ +532,2 @@
>      }
> +    last.swap(frame);

\n after }

Comment 29

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 8348900 [details] [diff] [review]
part 4.  Allocate the caller JSStackFrames lazily.

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

nice.

Comment 30

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 8347907 [details] [diff] [review]
part 5.  Don't eagerly grab file/line info when constructing an Exception.

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

::: dom/base/DOMException.cpp
@@ +567,1 @@
>    return mLineNumber;

\n after }

Comment 31

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Some of the comments on part 3 are in code that is removed in part 4, so I guess you can just ignore those.

Comment 32

[Boris Zbarsky [:bzbarsky]]

   https://hg.mozilla.org/integration/mozilla-inbound/rev/db68ac22b042
   https://hg.mozilla.org/integration/mozilla-inbound/rev/a3427a45608d
   https://hg.mozilla.org/integration/mozilla-inbound/rev/e0de03b97222
   https://hg.mozilla.org/integration/mozilla-inbound/rev/b6d1eaed0807
   https://hg.mozilla.org/integration/mozilla-inbound/rev/8e95a6fcee23

with the comments addressed.

Comment 33

[Boris Zbarsky [:bzbarsky]]

Attachment: Followup fix for an issue that somehow got missed in the try runs I did

Comment 34

[Boris Zbarsky [:bzbarsky]]

I pushed that followup as https://hg.mozilla.org/integration/mozilla-inbound/rev/1ff331377910 to get the tree less orange and open.

Comment 35

[Bobby Holley (:bholley)]

Comment on attachment 8356995 [details] [diff] [review]
Followup fix for an issue that somehow got missed in the try runs I did

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

As discussed on IRC, this is ok for the interim, but we really should make sure that our pushing semantics are preserved.

bz is going to add a ThreadsafeAutoJSContext and ThreadsafeAutoSafeJSContext tomorrow.

Comment 36

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/db68ac22b042
https://hg.mozilla.org/mozilla-central/rev/a3427a45608d
https://hg.mozilla.org/mozilla-central/rev/e0de03b97222
https://hg.mozilla.org/mozilla-central/rev/b6d1eaed0807
https://hg.mozilla.org/mozilla-central/rev/8e95a6fcee23
https://hg.mozilla.org/mozilla-central/rev/1ff331377910

Comment 37

[Boris Zbarsky [:bzbarsky]]

> bz is going to add a ThreadsafeAutoJSContext and ThreadsafeAutoSafeJSContext tomorrow.

What's a few weeks between friends?  Bug 963895.