Repository navigation
[trace_event] adding trace points to core #82
Description
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
Activity
[-][trace] adding trace points to core[/-][+][trace_event] adding trace points to core[/+]chinhuang007 commentedon Mar 9, 2018
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 commentedon Mar 9, 2018
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 thenode.async_hookscategory.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 commentedon Mar 12, 2018
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 commentedon Mar 12, 2018
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 commentedon Mar 13, 2018
@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 commentedon Mar 13, 2018
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 commentedon Mar 13, 2018
For synchronous resources, that's just a matter of instrumenting and benchmarking. If @chinhuang007 wants to get started on that, then ++ :)
chinhuang007 commentedon Mar 13, 2018
@jasnell I'd be glad to look into synchronous resources. Please suggest if you have certain resources in mind to track... Thanks.
jasnell commentedon Mar 13, 2018
Tracing sync fs operations is a great starting point.
AndreasMadsen commentedon Mar 13, 2018
v8category you can get information about whenv8is executing code, which is pretty close.node.async_hooks.v8category.jasnell commentedon Mar 13, 2018
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 commentedon Mar 13, 2018
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 commentedon Mar 15, 2018
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 commentedon Mar 15, 2018
I would just add the trace event macros to the sync code in node_file.cc.
5 remaining items
chinhuang007 commentedon Apr 13, 2018
@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 commentedon May 16, 2018
@jasnell Now fs sync trace is in. Any suggestions on other areas to add tracing in node core?
vmarchaud commentedon May 16, 2018
@chinhuang007 Is there a list of the current trace point currently implemented ?
jasnell commentedon May 16, 2018
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 commentedon May 16, 2018
@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 commentedon May 16, 2018
@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 commentedon May 16, 2018
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 commentedon Jun 21, 2018
@jasnell If you haven't done the DNS trace addition, I will update it and move it forward.
gireeshpunathil commentedon Oct 25, 2019
should this remain open? [ I am trying to chase dormant issues to closure ]
jasnell commentedon Oct 25, 2019
Yes this is not yet completed
github-actions commentedon Jul 19, 2020
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 commentedon Jul 21, 2020
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 commentedon Jul 22, 2020
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.