Closed Bug 1515214 Opened 5 years ago Closed 4 years ago

Add profiler markers for setTimeout callbacks


(Core :: Gecko Profiler, enhancement, P3)




Tracking Status
firefox66 --- wontfix
firefox70 --- fixed


(Reporter: mstange, Assigned: mstange)



(3 files)

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.
Connecting the two points of setTimeout/setInterval call and the callback invocation can be also interesting for Backtrack.
Priority: -- → P3

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.
Assignee: nobody → mstange

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.

These duplicate the existing setTimeout markers a bit.

Depends on D19192

Pushed by
Add CallbackObject::GetDescription. r=bzbarsky
Add markers with cause stacks and the name of the called function for setTimeout callback execution. r=jesup

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?

Flags: needinfo?(mstange) → needinfo?(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.

Flags: needinfo?(bzbarsky)
Attachment #9042583 - Attachment description: Bug 1515214 - Add CallbackObject::GetDescription. r?bzbarsky → Bug 1515214 - Add CallbackObject::GetDescription and TimeoutHandler::GetDescription. r?bzbarsky
Pushed by
Add CallbackObject::GetDescription and TimeoutHandler::GetDescription. r=bzbarsky
Add TimeoutHandler::GetDescription which just calls through to CallbackObject::GetDescription for CallbackTimeoutHandlers. r=smaug
Add markers with cause stacks and the name of the called function for setTimeout callback execution. r=jesup
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla70
You need to log in before you can comment on or make changes to this bug.