dtrace ustack helper broken with turbofan

[davidmarkclements]

• 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://gist.github.com/davidmarkclements/b4c7f1e4aba2b6a75340ff478f5585cb

Compare this with output on Node 8.2.1

https://gist.github.com/davidmarkclements/adee8d9a85193265d9c45be29f1b0ec8

And Node 6.11.2

https://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.

cc @mcollina @davepacheco @hashseed

[mcollina]

cc @bmeurer @fhinkel @nodejs/v8

[mcollina]

This might be related nodejs/llnode#121 cc @joyeecheung.

[jasnell]

ping @nodejs/diagnostics @nodejs/post-mortem

[davepacheco]

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]

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]

however.. also relevant: nodejs/node-v8#17

[benjamingr]

@nodejs/post-mortem

[misterdjules]

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]

Still looking into this, but a few things.

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

They are there. Here for example.

but I've actually just found that if you run the a profile for long enough the missing stacks seem to turn up

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]

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]

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]

@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]

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 --prof map 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]

@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.