Open gregtatum opened 6 years ago
On the JS side of things, the Gecko profiler provides us with only the line information for the function itself, not for where we were in the function.
For instance with this html file:
<!DOCTYPE html>
<html>
<head>
<meta charset="utf-8">
<title>Slow single function</title>
</head>
<body>
This file demonstrates a slow function that is slow on different lines.
<script>
function doWork () {
let i = 0
const step = 50000;
console.time('doWork')
for (; i < 1 * step; i += Math.random()) {}
for (; i < 2 * step; i += Math.random()) {}
for (; i < 3 * step; i += Math.random()) {}
for (; i < 4 * step; i += Math.random()) {}
console.timeEnd('doWork')
console.log('Done doing work', i)
}
doWork();
</script>
</body>
</html>
For each frame entry in the thread, the Gecko profiler has a string location
field. This location points to the following string: "doWork (file:///Users/gregorytatum/Desktop/html/slow-single-function.html:11)"
The :11
is the line function doWork () {
in the above example. In an ideal world we could have the line and column information, especially as sources are often minified.
From there if we could fetch the sources, then we could potentially then place blame on where exactly time was spent within a JS function. This information could then be surfaced in a sidebar panel, OR a sources view.
C++ code already has locations that come in as raw memory addresses. We could map those to individual assembly instructions. Ideally it would be nice to map these back to the original C++ source code as well. @mstange is this possible?
With enough symbol information, for sure! You would go directly from address to file+line, not from assembly instruction to file+line.
The .sym files already contain this information. The new symbolication API will not expose it, though. And we also don't have the information if we use nm to dump symbols for system libraries or local builds on Mac + Linux. These are all solvable problems.
Oh, and I could also see JIT invalidations being an issue on a single hot function.
On the JS side of things, the Gecko profiler provides us with only the line information for the function itself, not for where we were in the function.
I took a look at your profile https://perfht.ml/2qs05TQ and it looks like we actually do have information about which line of a JS function was executing if that JS function was running in the interpreter. More specifically: For frames whose implementation
is null
and whose func
has isJS == true
, frame.line
will be the line that was executing at that time. For example, in profile.threads[2]
, frame 1014 and frame 1017 both point to the same func 954 (createThunkMiddleware/</</<
) which has a null
implementation
, meaning that these frames ran in the interpreter. The func has lineNumber
67357, frame 1014 has line
67359 and frame 1017 has line
67362. On the other hand, func 1359 (getMarkerTiming
) is used by multiple frames who all seem to have identical information on them: frame 1491, 1497 and 1501 all haveimplementation: "baseline"
and line: null
.
It seems like we should be able to obtain per-line execution information even for JIT frames.
I've filed https://bugzilla.mozilla.org/show_bug.cgi?id=1441689 about getting line information for all JS frames.
In an ideal world we could have the line and column information, especially as sources are often minified.
I've attached patches that do this to bug 785922.
Here is an example perf problem that involves a single hot function. I had to fix it by instrument the function itself with timing information.
This is a JS only example, it would be nice to have a C++ example.
From PR #695 Before: https://perfht.ml/2qs05TQ After: https://perfht.ml/2qrczLn
┆Issue is synchronized with this Jira Task