1515214 - Add profiler markers for setTimeout callbacks

Status: RESOLVED FIXED

(Core :: Gecko Profiler, enhancement, P3)

Description

[Markus Stange [:mstange]]

The order in which timeouts are run during page load, and whether they fire before or after the load event, seems to be rather central to page load performance. To make the analysis of these things easier, we should add markers for setTimeout callbacks. For bonus points, maybe we can include the "cause" callstack on these markers, i.e. the callstack at which setTimeout was called. We could limit the capturing of those callstacks to only happen while the profiler is active.

Comment 1

[Honza Bambas (:mayhemer)]

Connecting the two points of setTimeout/setInterval call and the callback invocation can be also interesting for Backtrack.

Comment 2

[Markus Stange [:mstange]]

More specifically:

• The marker's start and end time should cover the execution of the callback.
• The marker's cause should be captured when setTimeout was called; the cause's timestamp then tells us how much time was between the setTimeout call and the execution.
• There should be an extra field that says when the timer was supposed to run.
• and an extra field for the interval.

Comment 3

[Markus Stange [:mstange]]

Attachment: Bug 1515214 - Add CallbackObject::GetDescription and TimeoutHandler::GetDescription. r?bzbarsky

This allows us to create profiler markers whose description contains the name
of the function and its file / line number. This allows the profiler UI to
match up setTimeout callbacks for multiple instances of the same page load, in
order to create meaningful profile comparisons based on markers.

Unfortunately, we need to set up a JSContext before we can call
JS_GetFunctionDisplayId, JS_GetFunctionScript and JS_GetScriptBaseLineNumber.

It might be more efficient to obtain the name using the same call setup as is
used for the actual invocation of the CallbackObject, but there's no nice way
to slot this into the existing API, and CallbackObject::GetDescription is only
called when the profiler is running, so it doesn't need to be completely free
of overhead.

Comment 4

[Markus Stange [:mstange]]

Attachment: Bug 1515214 - Add markers with cause stacks and the name of the called function for setTimeout callback execution. r?jesup

These duplicate the existing setTimeout markers a bit.

Depends on D19192

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9aabc3ad2470
Add CallbackObject::GetDescription. r=bzbarsky
https://hg.mozilla.org/integration/autoland/rev/7c4973b0d0e8
Add markers with cause stacks and the name of the called function for setTimeout callback execution. r=jesup

Comment 6

[Cristian Brindusan [:cbrindusan]]

Backed out 2 changesets (Bug 1515214) for hazard build bustage at CallbackObject.cpp.

Backout: https://hg.mozilla.org/integration/autoland/rev/2d48960b28162a564b1f2896bdac851a62721b44

Push that started the failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=pending%2Crunning%2Ctestfailed%2Cbusted%2Cexception&selectedJob=232505773&revision=7c4973b0d0e80a4f6b9172454c8f709b60f9e431

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=232505773&repo=autoland&lineNumber=46252

Comment 7

[Markus Stange [:mstange]]

The failure is:

TEST-UNEXPECTED-FAIL | hazards | unrooted 'unwrappedCallback' of type 'JSObject*' live across GC call at dom/bindings/CallbackObject.cpp:143
TEST-UNEXPECTED-FAIL | hazards | 1 rooting hazards detected

and CallbackObject.cpp:143 is the line jsapi.Init();.

Boris, when you were in Toronto last time, you told me exactly what I had to do to fix this... unfortunately I didn't take notes and have forgotten everything again :(
Could you take another look and let me know what would be the right way to address this?

Comment 8

[Boris Zbarsky [:bzbarsky]]

I can't remember the exactl outcome of that conversation, though I think I was muttering that we really might not need a JSContext... :(

Basically, I think you have two options:

1. Use JS::Rooted<JSObject*> unwrappedCallback(RootingCx(), js::CheckedUnwrapStatic(wrappedCallback)); and keep all the rest of the code as-is.

2. Drop the AutoJSAPI completely. It's really only used in three places, apart from rooting: nsAutoJSString::init, JS_GetFunctionScript, and JS_GetScriptBaseLineNumber. This last does not use it at all and we should file a bug to remove that arg. We could grab a JSFlatString* from the thing JS_GetFunctionDisplayId returns (which I am pretty sure is always flat) and then use its chars/length directly with no cx in sight. The hard part would be JS_GetFunctionScript, which does need a cx to reify the script. But we really shouldn't need a script to get the filename and line number; LazyScript has those too. We should file a bug for better APIs on SpiderMonkey here.

I think we should do #1 for now and file the various bugs on JSAPI needed to do #2.

Comment 9

[Markus Stange [:mstange]]

Attachment: Bug 1515214 - Add TimeoutHandler::GetDescription which just calls through to CallbackObject::GetDescription for CallbackTimeoutHandlers. r?smaug

Depends on D19192

Comment 10

[Markus Stange [:mstange]]

Got a green hazard job: https://treeherder.mozilla.org/#/jobs?repo=try&revision=a188057eadc8b2cc820d0a0345df8be75698527d&selectedJob=255797557

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a6ad66ea6ddd
Add CallbackObject::GetDescription and TimeoutHandler::GetDescription. r=bzbarsky
https://hg.mozilla.org/integration/autoland/rev/835a18c6213d
Add TimeoutHandler::GetDescription which just calls through to CallbackObject::GetDescription for CallbackTimeoutHandlers. r=smaug
https://hg.mozilla.org/integration/autoland/rev/442fa46b63e9
Add markers with cause stacks and the name of the called function for setTimeout callback execution. r=jesup

Comment 12

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/a6ad66ea6ddd
https://hg.mozilla.org/mozilla-central/rev/835a18c6213d
https://hg.mozilla.org/mozilla-central/rev/442fa46b63e9