403345 - DTrace js_calltime.d output includes functions not defined in JS file

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Myk Melez [:myk] [@mykmelez]]

The DTrace Toolkit 0.99 script js_calltime.d generates output that includes functions that aren't defined in the JS file the output says they're in.  For example, a recent trace included the following entry:

Count,
   FILE                 TYPE       NAME                                COUNT
...
   nsContentPrefService func       step                                   80
...
Exclusive function elapsed times (us),
   FILE                 TYPE       NAME                                TOTAL
...
   nsContentPrefService func       step                                 6750
...
Inclusive function elapsed times (us),
   FILE                 TYPE       NAME                                TOTAL
...
   nsContentPrefService func       step                                10207

But "step" isn't defined anywhere in nsContentPrefService.js (although code in that file does call the function).  It's not even a JS function.  It's part of the mozIStorageStatementWrapper interface and is implemented by mozStorageStatementWrapper::Step:

http://lxr.mozilla.org/mozilla/source/storage/src/mozStorageStatementWrapper.cpp#193

Seems like the DTrace script shouldn't be reporting this function at all.

Comment 1

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

I know this bug is old, but I'm hitting this now too trying to do some performance analysis using DTrace.

I'm 99% sure this isn't really a problem with the DTrace script, but with the probes. I'm trying to look into it but my C skills are not so top notch & I don't know the JS code at all.

Some additional observations (looking at the function-info probe):
arg0 = filename - filename the function is currently executing (not the one where funcname actually exists)
arg1 = classname - (I'm not using)
arg2 = funcname - function name being called
arg3 = lineno - line number of the function we're currently in (not funcname, not the line we're on)
arg4 = runfilename - often the same as arg0, but not always
arg5 = runlineno - line number function is called (current line)

I tried making changes to see if we're passing the wrong JSStackFrame to jsdtrace_function_info but changes either give wrong info or not much change. I'll keep investigating though.

Comment 2

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

On further investigation it looks like there's a distinct difference between the output from inlines vs non-inlines.

Inlines (http://mxr.mozilla.org/mozilla-central/source/js/src/jsinterp.cpp#5106) seem to be (more) correct, and 2 different JSStackFrames are being passed in.

Non-inlines (http://mxr.mozilla.org/mozilla-central/source/js/src/jsinterp.cpp#5129) aren't correct - the same JSStackFrame is being passed in twice. My theory is that this is the problem here. However, when I try to get the "up" frame, it doesn't really work. A lot of the contexts only have 1 frame, (which to me doesn't make any sense, but I don't know the JS API).

That's my brain dump ATM. I would love to have somebody who knows the JS API better to have a look at this.

Comment 3

[Mike Shaver (:shaver emeritus)]

This is hampering some front-end perf investigations; a spare cycle or three on it would be very welcome.

Comment 4

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Attachment: quick patch from mrbkap

This compiles but crashes. I know part of the problem (http://mxr.mozilla.org/mozilla-central/source/js/src/jsdtracef.cpp#224 should be using jsdtrace_linenumber instead of going straight to fp->script->lineno), but haven't had a chance to do more inspection yet.

Comment 5

[Brendan Eich [:brendan]]

Probably want js_FramePCToLineNumber, not js_PCToLineNumber, too -- unless dtrace only ever runs while not recording a trace for the JIT.

/be

Comment 6

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Pretty sure it'll run while recording (though in this case, we're worried about chrome, so the jit is turned off).

Comment 7

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Attachment: updated patch

mrbkap and I debugged this and fixed a bunch of problems.  Major changes:

- anonymous functions have null as their name; we don't try to guess their property/variable name any more, because that's fragile and painful, and there's an easy workaround (name your anon functions)

- we correctly handle calls into js_Invoke, to capture calling into JS code from native code

- we figure out the correct filename and line number, reporting null:0 if we don't have them available (e.g. when calling a native function)

Comment 8

[Brendan Eich [:brendan]]

Comment on attachment 382600 [details] [diff] [review]
updated patch

>+jsdtrace_linenumber(JSContext *cx, JSStackFrame *fp, JSFunction *fun)
> {
>+    /*
>+     * js_FramePCToLineNumber will be more accurate if we have a fp,
>+     * but when we have a fun, GetScriptBaseLineNumber will give us
>+     * a line number that's more in line with what the user expects.
>+     */
>+    if (fun && FUN_INTERPRETED(fun))
>+        return (int) JS_GetScriptBaseLineNumber(cx, FUN_SCRIPT(fun));
>+
>+    if (fp && fp->regs)
>+        return (int) js_FramePCToLineNumber(cx, fp);
>+
>+    return 0;

This is really two separate functions, one taking fun (which can assert that it's interpreted, AFAICT) which wants the starting line of the function, and one taking fp which wants the current pc's line. Separate into two functions?

/be

Comment 9

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Attachment: updated

Good point; separated them out.

Comment 10

[Brendan Eich [:brendan]]

Comment on attachment 382608 [details] [diff] [review]
updated

r=me, thanks.

/be

Comment 11

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Attachment: crashing backtrace

I got this to crash (early in browser startup) using my dtrace script. Here's the backtrace from gdb.

my .d script is just doing:

javascript*:::function-info {
  printf("%4d:%30s:%-40s --> %4d:%s\n",
         arg3, basename(copyinstr(arg0)),
         copyinstr(arg2),
         arg5, basename(copyinstr(arg4)));
}

Comment 12

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

Attachment: additional patch, fix crash

I didn't have the internet yesterday when I found this; should fix that crash.

Comment 13

[Brendan Eich [:brendan]]

Comment on attachment 383102 [details] [diff] [review]
additional patch, fix crash

I don't mind extra null checks in jsdtracef.cpp, but who was calling with null fun? If that's always going to happen and there's a single place to null-defend higher in the control flow, yet still within jsdtracef.cpp code, do that. Thanks,

/be

Comment 14

[Paul O'Shannessy [:zpao] (not bugmail, email directly)]

Mrbkap gave me a patch that just did a null check in jsinterp before calling any of the dtrace probes in js_Invoke FWIW

Comment 15

[Blake Kaplan (:mrbkap) (inactive)]

Yeah, I think it's weird to call a function-based API if we're not entering a function... But if this shows the right thing for entries into global code, then that seems good to me!

Comment 16

[Mike Beltzner [:beltzner, not reading bugmail]]

This is marked relnote, but I'm not sure what the note would be. That people using DTrace to develop Firefox may run into problems?

Comment 17

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

(In reply to comment #15)
> Yeah, I think it's weird to call a function-based API if we're not entering a
> function... But if this shows the right thing for entries into global code,
> then that seems good to me!

It seems to show accurate results for global code, so it's probably worth keeping the null checks lower in instead of just not calling the function.

(In reply to comment #16)
> This is marked relnote, but I'm not sure what the note would be. That people
> using DTrace to develop Firefox may run into problems?

No idea why it's marked; if anything "dtrace probes will now give correct results" :-)

Comment 18

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

http://hg.mozilla.org/mozilla-central/rev/f443daaa6923

We should take this for 1.9.1.x, IMO; we build with dtrace probes enabled by default on OSX, right?

Comment 19

[Robert Sayre]

(In reply to comment #18)
> http://hg.mozilla.org/mozilla-central/rev/f443daaa6923
> 
> We should take this for 1.9.1.x, IMO; we build with dtrace probes enabled by
> default on OSX, right?

I don't think we do.

Comment 20

[Damon Sicore (:damons)]

We want this in 1.9.2, so, we're assigning to sayre to get this merged.  This doesn't block 1.9.2.  Also adding needs-1.9.2-patch.  We need to go back and find other patches that need to be updated for 1.9.2 that were wanted+ as well.