Skip to content

Commit cf7e15c

Browse files
AndreasMadsenMylesBorins
AndreasMadsen
authored and
MylesBorins
committed
async_hooks: add trace events to async_hooks
This will allow trace event to record timing information for all asynchronous operations that are observed by async_hooks. PR-URL: #15538 Reviewed-By: Matteo Collina <[email protected]> Reviewed-By: James M Snell <[email protected]> Reviewed-By: Anna Henningsen <[email protected]>
1 parent 4bdd05d commit cf7e15c

18 files changed

+607
-73
lines changed

‎doc/api/tracing.md

+2-2
Original file line numberDiff line numberDiff line change
@@ -8,10 +8,10 @@ Node.js application.
88

99
The set of categories for which traces are recorded can be specified using the
1010
`--trace-event-categories` flag followed by a list of comma separated category names.
11-
By default the `node` and `v8` categories are enabled.
11+
By default the `node`, `node.async_hooks`, and `v8` categories are enabled.
1212

1313
```txt
14-
node --trace-events-enabled --trace-event-categories v8,node server.js
14+
node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js
1515
```
1616

1717
Running Node.js with tracing enabled will produce log files that can be opened

‎lib/_http_common.js

+1-2
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,6 @@ const { methods, HTTPParser } = binding;
2727
const FreeList = require('internal/freelist');
2828
const { ondrain } = require('internal/http');
2929
const incoming = require('_http_incoming');
30-
const { emitDestroy } = require('async_hooks');
3130
const {
3231
IncomingMessage,
3332
readStart,
@@ -218,7 +217,7 @@ function freeParser(parser, req, socket) {
218217
} else {
219218
// Since the Parser destructor isn't going to run the destroy() callbacks
220219
// it needs to be triggered manually.
221-
emitDestroy(parser.getAsyncId());
220+
parser.free();
222221
}
223222
}
224223
if (req) {

‎lib/internal/bootstrap_node.js

+1
Original file line numberDiff line numberDiff line change
@@ -59,6 +59,7 @@
5959
if (global.__coverage__)
6060
NativeModule.require('internal/process/write-coverage').setup();
6161

62+
NativeModule.require('internal/trace_events_async_hooks').setup();
6263
NativeModule.require('internal/inspector_async_hook').setup();
6364

6465
// Do not initialize channel in debugger agent, it deletes env variable

‎lib/internal/trace_events_async_hooks.js

+67
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,67 @@
1+
'use strict';
2+
3+
const trace_events = process.binding('trace_events');
4+
const async_wrap = process.binding('async_wrap');
5+
const async_hooks = require('async_hooks');
6+
7+
// Use small letters such that chrome://traceing groups by the name.
8+
// The behaviour is not only useful but the same as the events emitted using
9+
// the specific C++ macros.
10+
const BEFORE_EVENT = 'b'.charCodeAt(0);
11+
const END_EVENT = 'e'.charCodeAt(0);
12+
13+
// In trace_events it is not only the id but also the name that needs to be
14+
// repeated. Since async_hooks doesn't expose the provider type in the
15+
// non-init events, use a map to manually map the asyncId to the type name.
16+
const typeMemory = new Map();
17+
18+
// It is faster to emit trace_events directly from C++. Thus, this happens in
19+
// async_wrap.cc. However, events emitted from the JavaScript API or the
20+
// Embedder C++ API can't be emitted from async_wrap.cc. Thus they are
21+
// emitted using the JavaScript API. To prevent emitting the same event
22+
// twice the async_wrap.Providers list is used to filter the events.
23+
const nativeProviders = new Set(Object.keys(async_wrap.Providers));
24+
25+
const hook = async_hooks.createHook({
26+
init(asyncId, type, triggerAsyncId, resource) {
27+
if (nativeProviders.has(type)) return;
28+
29+
typeMemory.set(asyncId, type);
30+
trace_events.emit(BEFORE_EVENT, 'node.async_hooks',
31+
type, asyncId, 'triggerAsyncId', triggerAsyncId);
32+
},
33+
34+
before(asyncId) {
35+
const type = typeMemory.get(asyncId);
36+
if (type === undefined) return;
37+
38+
trace_events.emit(BEFORE_EVENT, 'node.async_hooks',
39+
type + '_CALLBACK', asyncId);
40+
},
41+
42+
after(asyncId) {
43+
const type = typeMemory.get(asyncId);
44+
if (type === undefined) return;
45+
46+
trace_events.emit(END_EVENT, 'node.async_hooks',
47+
type + '_CALLBACK', asyncId);
48+
},
49+
50+
destroy(asyncId) {
51+
const type = typeMemory.get(asyncId);
52+
if (type === undefined) return;
53+
54+
trace_events.emit(END_EVENT, 'node.async_hooks',
55+
type, asyncId);
56+
57+
// cleanup asyncId to type map
58+
typeMemory.delete(asyncId);
59+
}
60+
});
61+
62+
63+
exports.setup = function() {
64+
if (trace_events.categoryGroupEnabled('node.async_hooks')) {
65+
hook.enable();
66+
}
67+
};

‎node.gyp

+2
Original file line numberDiff line numberDiff line change
@@ -121,6 +121,7 @@
121121
'lib/internal/socket_list.js',
122122
'lib/internal/test/unicode.js',
123123
'lib/internal/tls.js',
124+
'lib/internal/trace_events_async_hooks.js',
124125
'lib/internal/url.js',
125126
'lib/internal/util.js',
126127
'lib/internal/util/comparisons.js',
@@ -213,6 +214,7 @@
213214
'src/node_platform.cc',
214215
'src/node_perf.cc',
215216
'src/node_serdes.cc',
217+
'src/node_trace_events.cc',
216218
'src/node_url.cc',
217219
'src/node_util.cc',
218220
'src/node_v8.cc',

‎src/async-wrap.cc

+85-17
Original file line numberDiff line numberDiff line change
@@ -167,18 +167,6 @@ static void DestroyAsyncIdsCallback(uv_timer_t* handle) {
167167
}
168168

169169

170-
static void PushBackDestroyAsyncId(Environment* env, double id) {
171-
if (env->async_hooks()->fields()[AsyncHooks::kDestroy] == 0)
172-
return;
173-
174-
if (env->destroy_async_id_list()->empty())
175-
uv_timer_start(env->destroy_async_ids_timer_handle(),
176-
DestroyAsyncIdsCallback, 0, 0);
177-
178-
env->destroy_async_id_list()->push_back(id);
179-
}
180-
181-
182170
void AsyncWrap::EmitPromiseResolve(Environment* env, double async_id) {
183171
AsyncHooks* async_hooks = env->async_hooks();
184172

@@ -198,6 +186,21 @@ void AsyncWrap::EmitPromiseResolve(Environment* env, double async_id) {
198186
}
199187

200188

189+
void AsyncWrap::EmitTraceEventBefore() {
190+
switch (provider_type()) {
191+
#define V(PROVIDER) \
192+
case PROVIDER_ ## PROVIDER: \
193+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("node.async_hooks", \
194+
#PROVIDER "_CALLBACK", static_cast<int64_t>(get_async_id())); \
195+
break;
196+
NODE_ASYNC_PROVIDER_TYPES(V)
197+
#undef V
198+
default:
199+
UNREACHABLE();
200+
}
201+
}
202+
203+
201204
void AsyncWrap::EmitBefore(Environment* env, double async_id) {
202205
AsyncHooks* async_hooks = env->async_hooks();
203206

@@ -217,6 +220,21 @@ void AsyncWrap::EmitBefore(Environment* env, double async_id) {
217220
}
218221

219222

223+
void AsyncWrap::EmitTraceEventAfter() {
224+
switch (provider_type()) {
225+
#define V(PROVIDER) \
226+
case PROVIDER_ ## PROVIDER: \
227+
TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks", \
228+
#PROVIDER "_CALLBACK", static_cast<int64_t>(get_async_id())); \
229+
break;
230+
NODE_ASYNC_PROVIDER_TYPES(V)
231+
#undef V
232+
default:
233+
UNREACHABLE();
234+
}
235+
}
236+
237+
220238
void AsyncWrap::EmitAfter(Environment* env, double async_id) {
221239
AsyncHooks* async_hooks = env->async_hooks();
222240

@@ -327,8 +345,10 @@ static void PromiseHook(PromiseHookType type, Local<Promise> promise,
327345
if (type == PromiseHookType::kBefore) {
328346
env->async_hooks()->push_async_ids(
329347
wrap->get_async_id(), wrap->get_trigger_async_id());
348+
wrap->EmitTraceEventBefore();
330349
AsyncWrap::EmitBefore(wrap->env(), wrap->get_async_id());
331350
} else if (type == PromiseHookType::kAfter) {
351+
wrap->EmitTraceEventAfter();
332352
AsyncWrap::EmitAfter(wrap->env(), wrap->get_async_id());
333353
if (env->execution_async_id() == wrap->get_async_id()) {
334354
// This condition might not be true if async_hooks was enabled during
@@ -455,7 +475,8 @@ void AsyncWrap::AsyncReset(const FunctionCallbackInfo<Value>& args) {
455475

456476
void AsyncWrap::QueueDestroyAsyncId(const FunctionCallbackInfo<Value>& args) {
457477
CHECK(args[0]->IsNumber());
458-
PushBackDestroyAsyncId(Environment::GetCurrent(args), args[0]->NumberValue());
478+
AsyncWrap::EmitDestroy(
479+
Environment::GetCurrent(args), args[0]->NumberValue());
459480
}
460481

461482
void AsyncWrap::AddWrapMethods(Environment* env,
@@ -604,7 +625,34 @@ AsyncWrap::AsyncWrap(Environment* env,
604625

605626

606627
AsyncWrap::~AsyncWrap() {
607-
PushBackDestroyAsyncId(env(), get_async_id());
628+
EmitTraceEventDestroy();
629+
EmitDestroy(env(), get_async_id());
630+
}
631+
632+
void AsyncWrap::EmitTraceEventDestroy() {
633+
switch (provider_type()) {
634+
#define V(PROVIDER) \
635+
case PROVIDER_ ## PROVIDER: \
636+
TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks", \
637+
#PROVIDER, static_cast<int64_t>(get_async_id())); \
638+
break;
639+
NODE_ASYNC_PROVIDER_TYPES(V)
640+
#undef V
641+
default:
642+
UNREACHABLE();
643+
}
644+
}
645+
646+
void AsyncWrap::EmitDestroy(Environment* env, double async_id) {
647+
if (env->async_hooks()->fields()[AsyncHooks::kDestroy] == 0)
648+
return;
649+
650+
if (env->destroy_async_id_list()->empty()) {
651+
uv_timer_start(env->destroy_async_ids_timer_handle(),
652+
DestroyAsyncIdsCallback, 0, 0);
653+
}
654+
655+
env->destroy_async_id_list()->push_back(async_id);
608656
}
609657

610658

@@ -616,6 +664,19 @@ void AsyncWrap::AsyncReset(double execution_async_id, bool silent) {
616664
execution_async_id == -1 ? env()->new_async_id() : execution_async_id;
617665
trigger_async_id_ = env()->get_init_trigger_async_id();
618666

667+
switch (provider_type()) {
668+
#define V(PROVIDER) \
669+
case PROVIDER_ ## PROVIDER: \
670+
TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("node.async_hooks", \
671+
#PROVIDER, static_cast<int64_t>(get_async_id()), \
672+
"triggerAsyncId", static_cast<int64_t>(get_trigger_async_id())); \
673+
break;
674+
NODE_ASYNC_PROVIDER_TYPES(V)
675+
#undef V
676+
default:
677+
UNREACHABLE();
678+
}
679+
619680
if (silent) return;
620681

621682
EmitAsyncInit(env(), object(),
@@ -662,8 +723,15 @@ void AsyncWrap::EmitAsyncInit(Environment* env,
662723
MaybeLocal<Value> AsyncWrap::MakeCallback(const Local<Function> cb,
663724
int argc,
664725
Local<Value>* argv) {
726+
EmitTraceEventBefore();
727+
665728
async_context context { get_async_id(), get_trigger_async_id() };
666-
return InternalMakeCallback(env(), object(), cb, argc, argv, context);
729+
MaybeLocal<Value> ret = InternalMakeCallback(
730+
env(), object(), cb, argc, argv, context);
731+
732+
EmitTraceEventAfter();
733+
734+
return ret;
667735
}
668736

669737

@@ -713,8 +781,8 @@ async_context EmitAsyncInit(Isolate* isolate,
713781
}
714782

715783
void EmitAsyncDestroy(Isolate* isolate, async_context asyncContext) {
716-
PushBackDestroyAsyncId(Environment::GetCurrent(isolate),
717-
asyncContext.async_id);
784+
AsyncWrap::EmitDestroy(
785+
Environment::GetCurrent(isolate), asyncContext.async_id);
718786
}
719787

720788
} // namespace node

‎src/async-wrap.h

+10-4
Original file line numberDiff line numberDiff line change
@@ -129,12 +129,18 @@ class AsyncWrap : public BaseObject {
129129
static void EmitAsyncInit(Environment* env,
130130
v8::Local<v8::Object> object,
131131
v8::Local<v8::String> type,
132-
double id,
132+
double async_id,
133133
double trigger_async_id);
134134

135-
static void EmitBefore(Environment* env, double id);
136-
static void EmitAfter(Environment* env, double id);
137-
static void EmitPromiseResolve(Environment* env, double id);
135+
static void EmitDestroy(Environment* env, double async_id);
136+
static void EmitBefore(Environment* env, double async_id);
137+
static void EmitAfter(Environment* env, double async_id);
138+
static void EmitPromiseResolve(Environment* env, double async_id);
139+
140+
void EmitTraceEventBefore();
141+
void EmitTraceEventAfter();
142+
void EmitTraceEventDestroy();
143+
138144

139145
inline ProviderType provider_type() const;
140146

‎src/node.cc

+14-7
Original file line numberDiff line numberDiff line change
@@ -263,13 +263,20 @@ node::DebugOptions debug_options;
263263
static struct {
264264
#if NODE_USE_V8_PLATFORM
265265
void Initialize(int thread_pool_size) {
266-
tracing_agent_.reset(
267-
trace_enabled ? new tracing::Agent() : nullptr);
268-
platform_ = new NodePlatform(thread_pool_size,
269-
trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
270-
V8::InitializePlatform(platform_);
271-
tracing::TraceEventHelper::SetTracingController(
272-
trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
266+
if (trace_enabled) {
267+
tracing_agent_.reset(new tracing::Agent());
268+
platform_ = new NodePlatform(thread_pool_size,
269+
tracing_agent_->GetTracingController());
270+
V8::InitializePlatform(platform_);
271+
tracing::TraceEventHelper::SetTracingController(
272+
tracing_agent_->GetTracingController());
273+
} else {
274+
tracing_agent_.reset(nullptr);
275+
platform_ = new NodePlatform(thread_pool_size, nullptr);
276+
V8::InitializePlatform(platform_);
277+
tracing::TraceEventHelper::SetTracingController(
278+
new v8::TracingController());
279+
}
273280
}
274281

275282
void Dispose() {

‎src/node_http_parser.cc

+13
Original file line numberDiff line numberDiff line change
@@ -397,6 +397,18 @@ class Parser : public AsyncWrap {
397397
}
398398

399399

400+
static void Free(const FunctionCallbackInfo<Value>& args) {
401+
Environment* env = Environment::GetCurrent(args);
402+
Parser* parser;
403+
ASSIGN_OR_RETURN_UNWRAP(&parser, args.Holder());
404+
405+
// Since the Parser destructor isn't going to run the destroy() callbacks
406+
// it needs to be triggered manually.
407+
parser->EmitTraceEventDestroy();
408+
parser->EmitDestroy(env, parser->get_async_id());
409+
}
410+
411+
400412
void Save() {
401413
url_.Save();
402414
status_message_.Save();
@@ -792,6 +804,7 @@ void InitHttpParser(Local<Object> target,
792804

793805
AsyncWrap::AddWrapMethods(env, t);
794806
env->SetProtoMethod(t, "close", Parser::Close);
807+
env->SetProtoMethod(t, "free", Parser::Free);
795808
env->SetProtoMethod(t, "execute", Parser::Execute);
796809
env->SetProtoMethod(t, "finish", Parser::Finish);
797810
env->SetProtoMethod(t, "reinitialize", Parser::Reinitialize);

0 commit comments

Comments
 (0)