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

[mhdawson]

One more thing that @chinhuang007 might be able to do in parallel to adding tracing for synchronous resources is to start writing a document that captures some of the info here. How to enable tracing for the different parts were it already exists. Does that seem reasonable?

[chinhuang007]

For tracing sync fs operations, I am thinking to introduce a trace category 'node.fs', add a sync trace js utility with binding to c++ trace_events, and add code into fs.js for major xxSync functions. Of course I will also do benchmarking to see the performance impact. If any objections, please advise a better approach.

[jasnell]

I would just add the trace event macros to the sync code in node_file.cc.

[chinhuang007]

Okay, so I will just add code to node_file.cc, not exposing to the js side. I think we should still have a new trace category so the amount of trace log can be filtered therefore more manageable.

[chinhuang007]

The PR for adding trace points for fs sync operations has been approved, nodejs/node#19649 (review). The new trace category is node.fs.sync. Once enabled, the bytes processed for read and write will be tracked in addition to the essential trace data similarly seen for all other operations. Please review, help land it, and also suggest the next components or areas to add trace.

[chinhuang007]

I am thinking about enabling ad hoc user space tracing with a simple API. Developers can do it currently in their JavaScript by using trace_events with binding and start node with a custom category, ie --trace-event-categories my_own_category. I wonder if we should simply document it or provide an API to make it really easy to use, such as trace_userspace.emitBegin(...), trace_userspace.emitEnd(...), and trace_userspace.emitCounter(...) Comments are welcome.

[digitalinfinity]

@chinhuang007 this EPS from @jasongin could be a good starting point?

[ofrobots]

I think #153 would be a pre-requisite to exposing trace events to a user-space API. Until that happens, I am not sure if we should add expose an API to JS.

In the meanwhile, we have been using a workaround in modules like require-so-slow. As long as the time source is the same, trace events files are concatenate-able. It is possible to write a separate trace file from user-space code and later concatenate it with the trace file produced by code.

[chinhuang007]

@digitalinfinity Thanks for providing the reference. The EPS is indeed very close to what I was thinking, although my idea is to leverage existing code or even just document how user-space trace events can be recorded into the common trace output file, rather than add lots of new code. As @ofrobots suggested, I will wait for the development of #153 before further investigation on exposing additional API to JS. One thing to note, users can use binding and emit() to add custom trace data into node trace file today. I am just attempting to make it a bit more formal and convenient.

[chinhuang007]

@jasnell Now fs sync trace is in. Any suggestions on other areas to add tracing in node core?

[vmarchaud]

@chinhuang007 Is there a list of the current trace point currently implemented ?

[jasnell]

Until we get the js trace function into v8 there's not going to be a lot. I have a DNS trace events pr that needs to be updated and finished. If you'd like to take that one over, you're more than welcome! Just search for my open PRs and you should find it :)

[chinhuang007]

@vmarchaud The trace points implemented for async resources and callbacks are documented at https://nodejs.org/api/async_hooks.html#async_hooks_type and the trace points for sync resources are currently implemented for all file system (fs) operations, briefly mentioned here https://nodejs.org/api/tracing.html

[mhdawson]

@jasnell does that mean that we have tracepoints for all of the native side Node.js places they make sense (other than the not quite complete PRs)?

[jasnell]

No, it means that the most interesting parts of Node.js' behaviors that are going to be the most interesting to trace happen at both the JS and C++ layers. Until we have the JS function, it's going to be difficult to determine what will be the most useful traces.

[chinhuang007]

@jasnell If you haven't done the DNS trace addition, I will update it and move it forward.

[gireeshpunathil]

should this remain open? [ I am trying to chase dormant issues to closure ]

[jasnell]

Yes this is not yet completed

[github-actions]

This issue is stale because it has been open many days with no activity. It will be closed soon unless the stale label is removed or a comment is made.

[mmarchini]

I think this is still relevant, but we need a more comprehensive list of components we need to add tracing. Might be worth closing this issue, opening another one focused on listing components to start fresh (could be a deep dive), and then open another as a tracking issue.

[mhdawson]

I agree its still relevant and also agree we should close this issue in favor of a fresh start. See you already did this so closing, please let me know of you think it should still be open.