Repository navigation
dtrace ustack helper broken with turbofan #15010
Description
- Version: 8.3.0, 8.4.0
- Platform: macOs
- Subsystem: tracing
Given a dtrace script:
#!/usr/sbin/dtrace -s
#pragma D option quiet
#pragma D option switchrate=1000hz
profile-1ms /pid == $target/ {
/* Sampling every 1ms therefore also recording timestamp at ms resolution */
printf("%s %d %d: %s:", execname, pid, timestamp / 1000000, probename);
ustack(10000);
printf("\n");
}
Profiling (ran with --perf-basic-prof):
const fs = require('fs')
setInterval(() => { x(()=>{
fs.writeFileSync('/dev/null', 'ok')
}) }, 10)
function x (cb) {
setTimeout(cb, 10, Math.round(Math.random()) ? null : Error(), {x: Math.random()})
}On Node 8.3.0 or Node 8.4.0 we get the output (gist, too big):
https://github.com/proxy/gist.github.com/davidmarkclements/b4c7f1e4aba2b6a75340ff478f5585cb
Compare this with output on Node 8.2.1
https://github.com/proxy/gist.github.com/davidmarkclements/adee8d9a85193265d9c45be29f1b0ec8
And Node 6.11.2
https://github.com/proxy/gist.github.com/davidmarkclements/775c1cb48995beafa48c7878ec6b03c7
There are no hex addresses in the dtrace output for 8.3.0/8.4.0 which means JS frames
aren't being captured by the ustack helper (https://github.com/nodejs/node/blob/master/src/v8ustack.d)
This is likely to affect a variety of ecosystem (and proprietary/internal) tooling.
For me it's affecting http://npm.im/0x. The option to use --prof and using the tick processor isn't quite viable because we lose libuv stacks.
Here's a related discussion about this problem at davidmarkclements/0x#76
I've observed a similar problem on Linux, and suspect that the perf output is also incompatible with Turbofan but we need to verify.
Activity
mcollina commentedon Aug 24, 2017
cc @bmeurer @fhinkel @nodejs/v8
mcollina commentedon Aug 24, 2017
This might be related nodejs/llnode#121 cc @joyeecheung.
jasnell commentedon Aug 24, 2017
ping @nodejs/diagnostics @nodejs/post-mortem
davepacheco commentedon Aug 24, 2017
I have not dug into this very deeply, but it seems that the recent V8 changes broke the behavior of most observability tools outside of V8 itself, including all of the postmortem debugging tools and the DTrace ustack helper. (These were always relying on V8 implementation details, unfortunately -- it's a limitation of this approach, but it was necessary because V8 didn't (and still doesn't) provide these facilities itself.)
davidmarkclements commentedon Aug 29, 2017
I'm sure there are some compatibility problems, but I've actually just found that if you run the a profile for long enough the missing stacks seem to turn up - the effect of initially missing stacks are shown clearly in my sample cases but for say, an Express server, the net effect of this seems negligible.. (cf davidmarkclements/0x#76 (comment))
davidmarkclements commentedon Aug 29, 2017
however.. also relevant: nodejs/node-v8#17
benjamingr commentedon Sep 1, 2017
@nodejs/post-mortem
misterdjules commentedon Sep 1, 2017
Unfortunately, this is a time when some people who can investigate (including myself) take some time off and are not always available, but @cjihrig and I have started to take a look at the recent breakage in post-mortem debugging tools and the next step is to take a look at this.
We should have an update on Thursday ~6:00pm Pacific Time.
cjihrig commentedon Sep 5, 2017
Still looking into this, but a few things.
They are there. Here for example.
It looks like they take a while to show up because the preceding stacks are spent in V8 compiling the code. Here for example. Were you capturing stack traces during that run but not the others?
What else is missing or broken (because I'm certainly not doubting that it is broken with such a big change)?
hashseed commentedon Sep 6, 2017
Most samples you see are due to snapshot being disabled. Bootstrapping V8 from scratch without snapshot takes long, and includes compiling all sorts of code objects. This has been fixed though. That explains samples with Isolate::Init and Genesis::Genesis on the stack.
That being said, the switch to Ignition and Turbofan does affect profiling. The former in particular. Previously, V8 always executed machine code, so you just need to attribute sampled PC to code object ranges. With Ignition, when you execute bytecode, you would just get samples of PC from bytecode handlers, which do not correspond to any code object belonging to a JavaScript function.
You can however try to manually walk the stack, like done in V8's internal sampling profiler.
mcollina commentedon Sep 13, 2017
I think we can close this for now. I verified it is working, even if I'm not 100% sure it is correct, as @hashseed said.
misterdjules commentedon Sep 13, 2017
@mcollina Does
jstack()actually give you the proper function names, line numbers and file names for JavaScript frames? I'd be surprised if that was the case.mcollina commentedon Sep 13, 2017
The mixed approach we are using for OSX in 0x is working for us now. It didn't work in some early builds, and it works decently enough to track down CPU-intensive functions (it does not work really well for non-cpu intensive tasks). We resolve those via
--profmap files. I haven't tested on Solaris.It feels like that something is broken, but I have no idea on how to help tracking that down. It might just be that the new pipeline is so different.
I used https://github.com/nearform/slow-rest-api for testing.
I'm 👍 to reopen if you think it should be.
misterdjules commentedon Sep 13, 2017
@mcollina
If 0x uses map files generated by V8, then I'm not sure if it actually uses the ustack helper at all. Unless I'm missing something, the ustack helper is not used to get the actual instruction and frame pointers, only to translate those into actual function names and locations, which seems to be done differently by 0x.
I'll open a separate issue if/when I get a chance to take a look at whether the ustack helper is actually broken (I suspect it is) and how to fix it.