[trace_event] adding trace points to core

[joshgav]

To make Trace Controller more useful in Node we want to add appropriate macros from trace_event.h to Node's built in modules and other locations. This will provide more insight and troubleshooting info to all app developers without requiring more work by them.

This thread is to track what areas to instrument in core and discuss progress or issues. Please modify the list of areas by editing this top-level post and comment on ongoing work in this thread.

Areas to add trace points in core:

• async-wrap
• env, node

[chinhuang007]

A few areas we could add trace points, event loop time, MakeCallBack(), synchronous resources in Node, GC callback, and user's javascript synchronous trace enablement/API. I will start from tracing event loop time. Comments are welcome.

[jasnell]

The event loop timing details are being worked on and will require an update to libuv2 in order to do properly. That is in progress.

MakeCallback() should be emitting trace events when using the node.async_hooks category.

Synchronous resources definitely still need to be tracked. I'll look at that shortly.

GC callback should be there currently but if not I'll take a look at that also.

[chinhuang007]

Are you saying some changes will be made in libuv to properly support event loop time tracing and you are working on it? One possibility with the current code is to add tracing around the uv_run in node.cc and change to UV_RUN_ONCE. That will actually provide the loop time, including an additional uv__run_timers at the end of the loop. Is this the problem you are trying to fix and make it a true loop time for UV_RUN_DEFAULT?

[jasnell]

I've an open pull request to land detailed timing metrics in libuv that provides not only loop timing but timing for each phase within the loop. It also provides threadpool stats using a modified version of code originally written by @sam_github.

[mhdawson]

@jasnell when you say you will "look at that shortly", @chinhuang007 was volunteering to help add trace points in those areas so it would be good to figure out how to get you two working together.

[jasnell]

libuv/libuv#1764

The changes necessarily are ABI breaking so require libuv2 which will come very soon, I hope. Following that, I already have code locally that emits trace events in core based on these changes.

[jasnell]

For synchronous resources, that's just a matter of instrumenting and benchmarking. If @chinhuang007 wants to get started on that, then ++ :)

[chinhuang007]

@jasnell I'd be glad to look into synchronous resources. Please suggest if you have certain resources in mind to track... Thanks.

[jasnell]

Tracing sync fs operations is a great starting point.

[AndreasMadsen]

A few areas we could add trace points, event loop time, MakeCallback(), synchronous resources in Node, GC callback, and user's javascript synchronous trace enablement/API. I will start from tracing event loop time. Comments are welcome.

• event loop time: with the v8 category you can get information about when v8 is executing code, which is pretty close.
• MakeCallback(): This is exposed through node.async_hooks.
• GC callback: All GC callbacks are available through the v8 category.

[jasnell]

event loop time: with the v8 category you can get information about when v8 is executing code, which is pretty close.

Yep, they are quite close. As I've been playing with it, Overlaying what v8 and node.async_hooks already provide with the spans for each event loop phase provide darn near everything you need in most cases. The latter mostly to just provide context for identifying what js code v8 is executing.

Thank you for the confirmation on GC. I was fairly certain but I've never dug into everything v8 outputs.