Closed Bug 580055 Opened 11 years ago Closed 10 years ago

Log all JS function entry/exits

Categories

(Core :: JavaScript Engine, enhancement)

x86_64
Linux
enhancement
Not set
normal

Tracking

()

RESOLVED WONTFIX

People

(Reporter: sfink, Assigned: sfink)

References

Details

Attachments

(1 file, 6 obsolete files)

Split off from bug 507012. There should be a simple way to request a log of all function call entries/exits, using function tracking callback from bug 507012.
Here is a proposal. This goes through PR_LOGGING, so you use it by setting eg

NSPR_LOG_MODULES=JSDiagnostics:5
NSPR_LOG_FILE=/tmp/jscalls.log

This will intermix the function call reports with other JS logging, but it's easy enough to separate out.

I could have a separate log module if the intermixing bothers anyone.

The info logged is:

 - a thread identifier
 - the function pointer
 - the script filename and line number
 - the function name
 - whether JS_ON_TRACE is true while the function is being entered/exited
 - a boolean saying whether this is an enter or exit
 - timestamp

Any requests for additions/modifications?
Blocks: 507012
No longer blocks: 507012
Blocks: 507012
No longer blocks: 507012
Depends on: 507012
Severity: normal → enhancement
Adding mfinkle to the CC list, since I wrote this portion based on his request.

The original patch also logged isInterpreted for each function call. Is that useful? I could throw that in as well.
(In reply to comment #2)
> Adding mfinkle to the CC list, since I wrote this portion based on his request.
> 
> The original patch also logged isInterpreted for each function call. Is that
> useful? I could throw that in as well.

I was using isInterpreted to see if code was JIT'ed or not. JS_ON_TRACE is good enough for me.
That's what I thought it must mean, but unless I confused myself, I discovered that isInterpreted means something entirely different. The details, which I don't understand, are in jsfun.h. It's something like isInterpreted means it's implemented in JS as opposed to a native function call. If isInterpreted, you can get to the defining script. But that's orthogonal to whether you're on trace or not.

fwiw, watching JS_ON_TRACE while loading a gmail message is depressing. Hopefully that means that gmail functions are mostly high-level? I should see what tracevis tells me.
Attached patch Log all JS calls (obsolete) — Splinter Review
Updated on top of latest instrumentation. Currently requires tracemonkey branch + patches from bug 605330. This patch supersedes the one from bug 558200.

Current instructions are at https://wiki.mozilla.org/Using_SlowCalls
Just some feedback. I imported this patch into my local Fennec build and tried to do some JS profiling on N900 and Android. I noticed that there is no output for XPCOM JS components. Those are handled by mozJSComponentLoader.cpp

I also didn't see much of the chrome JS in the startup profiles either. The initial browser.xul onLoad handler, for example, was not in the profile.
Attachment #458442 - Attachment is obsolete: true
Attached patch Log all JS calls (obsolete) — Splinter Review
Briefly escaped from the hardblocker grind by updating this. Taras told me about a runtime-wide context creation callback, so I moved everything into xpconnect instead and used the callback.

This now appears to be catching way more stuff, although it now sees so much stuff that it overwhelms. It's just a mass of text. But anyone interested could give it a try and see if it catches what you're interested in.

I'll update the instructions on the wiki next (had to change PR_LOG sections), and upload a new processing script (slight tweaks; completely independent of this change.)

Wiki - https://wiki.mozilla.org/Using_SlowCalls
Processing script attached to bug 558200
Attachment #485465 - Attachment is obsolete: true
Attached patch Log all JS calls (obsolete) — Splinter Review
I had to un-bitrot this to use it, here's the updated patch.
Attachment #514105 - Attachment is obsolete: true
Attachment #530370 - Attachment is obsolete: true
Attached patch Log all JS calls (obsolete) — Splinter Review
Rebased again, but I haven't actually tested it.
Attachment #535062 - Attachment is obsolete: true
I had #defines/#includes out of order so the logging was disabled in non-DEBUG builds.

This patch also includes the functiontimer fix for GET_FUNCTION_PRIVATE, which doesn't really belong here.
Attachment #555900 - Attachment is obsolete: true
Steve, is it possible to get this landed, ifdef'd out? Who would need to review, etc?
Pinging again for Dietrich's question, I'd really like to see this landed.

On a somewhat unrelated note, when I try to rebuild with
--enable-trace-jscalls.
--enable-functiontimer

I get a build error:
In file included from /home/ahal/hg/mozilla-central/js/src/jsalloc.cpp:40:
/home/ahal/hg/mozilla-central/js/src/jscntxt.h:1153: error: ‘JSFunctionCallback’ does not name a type
/home/ahal/hg/mozilla-central/js/src/jscntxt.h: In member function ‘void JSContext::doFunctionCallback(const JSFunction*, const JSScript*, int) const’:
/home/ahal/hg/mozilla-central/js/src/jscntxt.h:1159: error: ‘functionCallback’ was not declared in this scope

Can anyone shed some light on this?
Depends on: 702740
Blocks: 706847
The new profiler work likely removes the need for this, so marking WONTFIX. See bug 713227. Re-open if this is still needed.
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → WONTFIX
No longer blocks: 653701
You need to log in before you can comment on or make changes to this bug.