VM intrinsic trace event...

[jasnell]

To parallel the trace event support at the native layer, it would be helpful to have an intrinsic trace event facility accessible on the JS layer that we can use to efficiently instrument core js code. This does not need to be as expressive as the current set of macros (the ability to mark instants and span start/end should be sufficient).

The motivation for a vm intrinsic is the ability for the vm to optimize these as much as possible. We could implement these via a process binding but doing so certainly adds a runtime cost that an intrinsic should be able to avoid.

In most cases in core, the existing async_hooks/trace_events coverage actually covers the most interesting cases. It does not cover things like EventEmitter, however. Emitting an event, for instance, should cause a trace event to be emitted if trace events are enabled and should be a non-op with no runtime cost if not (e.g. have the compiler optimize the trace call out if v8 is not tracing).

ee.prototype.emit(event, ...args) {
  %trace_event_begin('node', 'eventemitter.emit', event, ...)
  // synchronously emit events
  %trace_event_end('node', 'eventemitter.emit', event, ...)
}

[ofrobots]

/cc @bmeurer and @hashseed. We have chatted about this recently.

[hashseed]

Easiest approach I could think of is to dump trace events into a buffer first and every time the buffer is full, switch to C++ to commit these events. Or do the committing off-thread.

Looking at the implementation of trace events I think inlining into jit code is very difficult and also hard to maintain.

[jasnell]

We could buffer in each js stack and as we exit, after we handle the nextTicks we can commit the buffer... that should limit the amount of buffering and would ensure only one boundary cross per stack.

[hashseed]

Problem with buffering is that you lose information if you crash before committing.

[jasnell]

yep... which is why I'd prefer to avoid it or at least minimize what we're buffering.

[ofrobots]

We don't necessarily have to stick with the trace events macros' implementation of the trace buffer writing. If there is a different way this could be implemented by the v8 supported intrinsic, we could adjust how the macros work.

[ofrobots]

To capture what was discussed in person.. what is essential is that the compare and branch is fast. The actual writing to the buffer doesn't need to be inlined necessarily.

[hashseed]

Currently the idea I have in mind is:

• V8 exposes a JavaScript function that logs trace events
• This function should perform tracing as fast as possible (inlining, lightweight C++ call, etc)
• Node.js can call this function for tracing.
• Override this function by empty function if tracing is disabled. V8 to make sure empty functions always get inlined.

[hashseed]

@bmeurer wdyt?

[jasnell]

Definitely sounds reasonable on this end. The one question that remains is how Node.js would access that function but I assume that's a minor detail so long as the vms are still able to inline them.

@mike-kaufman ... any thoughts on whether that would work for chakra?

[ofrobots]

I can see a few scenarios:

• Scenario that all trace-events are disabled. VM should be able to completely eliminate the trace-event overhead.
• I would expect that production workloads would have trace-events always enabled for a limited subset of categories. This means that we need the compare-and-branch that guards the (infrequently executed) add-to-trace-buffer operation needs to be as fast as possible.

Simply replacing the function by an empty function wouldn't serve the production use-case well. I guess the broader point I will make is that the concept that diagnostics == debugging is not true. For server side applications diagnostics == production.

[mike-kaufman]

/cc @digitalinfinity, @MSLaguana - any thoughts on how this would work on node-chakra-core?

[mike-kaufman]

To capture what was discussed in person.. what is essential is that the compare and branch is fast.

What is the thinking about arguments passed to trace function here? If intent is this is fast and simple implementation on back-end, API would be something like this:

const category = ...
%if_trace_enabled(category) {
  %trace(category, someExpensiveFuncWithSideEffects());
}

Without %if_trace_enabled construct, you'd have to eval args to the trace functions, and this could be expensive (or you'd have to do some special-casing magic in the jit/interpreter that introduces consequence of code not executing as expected.

[jasnell]

So just out of curiosity I decided to try instrumenting the synchronous code in EventEmitter to output trace events using the same internal binding used by js AsyncResources. Emitting a begin and end marking the entry and exit of emit, along with begin and end events marking each handler yields some extremely interesting information about sync code flow but results in an average 85% perf loss in the events benchmarks without actually emitting any events -- due largely to just the category enabled checks. I'm going to play around with it a bit more but the perf results are an interesting data point here