Skip to content

Commit 331b175

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. Backport-PR-URL: #18179 PR-URL: #15538 Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>
1 parent ace2c2f commit 331b175

18 files changed

+607
-73
lines changed

‎doc/api/tracing.md

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

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

1515
```txt
16-
node --trace-events-enabled --trace-event-categories v8,node server.js
16+
node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js
1717
```
1818

1919
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
@@ -26,7 +26,6 @@ const { methods, HTTPParser } = process.binding('http_parser');
2626
const FreeList = require('internal/freelist');
2727
const { ondrain } = require('internal/http');
2828
const incoming = require('_http_incoming');
29-
const { emitDestroy } = require('async_hooks');
3029
const {
3130
IncomingMessage,
3231
readStart,
@@ -217,7 +216,7 @@ function freeParser(parser, req, socket) {
217216
} else {
218217
// Since the Parser destructor isn't going to run the destroy() callbacks
219218
// it needs to be triggered manually.
220-
emitDestroy(parser.getAsyncId());
219+
parser.free();
221220
}
222221
}
223222
if (req) {

‎lib/internal/bootstrap_node.js

+1
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,7 @@
5555
if (global.__coverage__)
5656
NativeModule.require('internal/process/write-coverage').setup();
5757

58+
NativeModule.require('internal/trace_events_async_hooks').setup();
5859
NativeModule.require('internal/inspector_async_hook').setup();
5960

6061
// 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
@@ -113,6 +113,7 @@
113113
'lib/internal/repl.js',
114114
'lib/internal/socket_list.js',
115115
'lib/internal/test/unicode.js',
116+
'lib/internal/trace_events_async_hooks.js',
116117
'lib/internal/url.js',
117118
'lib/internal/util.js',
118119
'lib/internal/util/types.js',
@@ -202,6 +203,7 @@
202203
'src/node_platform.cc',
203204
'src/node_perf.cc',
204205
'src/node_serdes.cc',
206+
'src/node_trace_events.cc',
205207
'src/node_url.cc',
206208
'src/node_util.cc',
207209
'src/node_v8.cc',

‎src/async-wrap.cc

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

170170

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

@@ -199,6 +187,21 @@ void AsyncWrap::EmitPromiseResolve(Environment* env, double async_id) {
199187
}
200188

201189

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

@@ -218,6 +221,21 @@ void AsyncWrap::EmitBefore(Environment* env, double async_id) {
218221
}
219222

220223

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

@@ -328,8 +346,10 @@ static void PromiseHook(PromiseHookType type, Local<Promise> promise,
328346
if (type == PromiseHookType::kBefore) {
329347
env->async_hooks()->push_async_ids(
330348
wrap->get_async_id(), wrap->get_trigger_async_id());
349+
wrap->EmitTraceEventBefore();
331350
AsyncWrap::EmitBefore(wrap->env(), wrap->get_async_id());
332351
} else if (type == PromiseHookType::kAfter) {
352+
wrap->EmitTraceEventAfter();
333353
AsyncWrap::EmitAfter(wrap->env(), wrap->get_async_id());
334354
if (env->execution_async_id() == wrap->get_async_id()) {
335355
// This condition might not be true if async_hooks was enabled during
@@ -456,7 +476,8 @@ void AsyncWrap::AsyncReset(const FunctionCallbackInfo<Value>& args) {
456476

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

462483
void AsyncWrap::AddWrapMethods(Environment* env,
@@ -605,7 +626,34 @@ AsyncWrap::AsyncWrap(Environment* env,
605626

606627

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

611659

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

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

622683
AsyncWrap::EmitAsyncInit(
@@ -664,8 +725,15 @@ void AsyncWrap::EmitAsyncInit(Environment* env,
664725
MaybeLocal<Value> AsyncWrap::MakeCallback(const Local<Function> cb,
665726
int argc,
666727
Local<Value>* argv) {
728+
EmitTraceEventBefore();
729+
667730
async_context context { get_async_id(), get_trigger_async_id() };
668-
return InternalMakeCallback(env(), object(), cb, argc, argv, context);
731+
MaybeLocal<Value> ret = InternalMakeCallback(
732+
env(), object(), cb, argc, argv, context);
733+
734+
EmitTraceEventAfter();
735+
736+
return ret;
669737
}
670738

671739

@@ -723,8 +791,8 @@ async_context EmitAsyncInit(Isolate* isolate,
723791
}
724792

725793
void EmitAsyncDestroy(Isolate* isolate, async_context asyncContext) {
726-
PushBackDestroyAsyncId(Environment::GetCurrent(isolate),
727-
asyncContext.async_id);
794+
AsyncWrap::EmitDestroy(
795+
Environment::GetCurrent(isolate), asyncContext.async_id);
728796
}
729797

730798
} // namespace node

‎src/async-wrap.h

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

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

140146
inline ProviderType provider_type() const;
141147

‎src/node.cc

+14-7
Original file line numberDiff line numberDiff line change
@@ -272,13 +272,20 @@ node::DebugOptions debug_options;
272272
static struct {
273273
#if NODE_USE_V8_PLATFORM
274274
void Initialize(int thread_pool_size, uv_loop_t* loop) {
275-
tracing_agent_.reset(
276-
trace_enabled ? new tracing::Agent() : nullptr);
277-
platform_ = new NodePlatform(thread_pool_size, loop,
278-
trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
279-
V8::InitializePlatform(platform_);
280-
tracing::TraceEventHelper::SetTracingController(
281-
trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
275+
if (trace_enabled) {
276+
tracing_agent_.reset(new tracing::Agent());
277+
platform_ = new NodePlatform(thread_pool_size, loop,
278+
tracing_agent_->GetTracingController());
279+
V8::InitializePlatform(platform_);
280+
tracing::TraceEventHelper::SetTracingController(
281+
tracing_agent_->GetTracingController());
282+
} else {
283+
tracing_agent_.reset(nullptr);
284+
platform_ = new NodePlatform(thread_pool_size, loop, nullptr);
285+
V8::InitializePlatform(platform_);
286+
tracing::TraceEventHelper::SetTracingController(
287+
new v8::TracingController());
288+
}
282289
}
283290

284291
void Dispose() {

‎src/node_http_parser.cc

+13
Original file line numberDiff line numberDiff line change
@@ -399,6 +399,18 @@ class Parser : public AsyncWrap {
399399
}
400400

401401

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

795807
AsyncWrap::AddWrapMethods(env, t);
796808
env->SetProtoMethod(t, "close", Parser::Close);
809+
env->SetProtoMethod(t, "free", Parser::Free);
797810
env->SetProtoMethod(t, "execute", Parser::Execute);
798811
env->SetProtoMethod(t, "finish", Parser::Finish);
799812
env->SetProtoMethod(t, "reinitialize", Parser::Reinitialize);

0 commit comments

Comments
 (0)