Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly
Appearance settings

Commit cf7e15c

Browse filesBrowse 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 <matteo.collina@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>
1 parent 4bdd05d commit cf7e15c
Copy full SHA for cf7e15c
Expand file treeCollapse file tree

18 files changed

+607
-73
lines changed
Open diff view settings
Collapse file

‎doc/api/tracing.md‎

Copy file name to clipboardExpand all lines: doc/api/tracing.md
+2-2Lines changed: 2 additions & 2 deletions
  • Display the source diff
  • Display the rich diff
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
Collapse file

‎lib/_http_common.js‎

Copy file name to clipboardExpand all lines: lib/_http_common.js
+1-2Lines changed: 1 addition & 2 deletions
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) {
Collapse file

‎lib/internal/bootstrap_node.js‎

Copy file name to clipboardExpand all lines: lib/internal/bootstrap_node.js
+1Lines changed: 1 addition & 0 deletions
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
Collapse file

‎lib/internal/trace_events_async_hooks.js‎

Copy file name to clipboard
+67Lines changed: 67 additions & 0 deletions
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+
};
Collapse file

‎node.gyp‎

Copy file name to clipboardExpand all lines: node.gyp
+2Lines changed: 2 additions & 0 deletions
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',
Collapse file

‎src/async-wrap.cc‎

Copy file name to clipboardExpand all lines: src/async-wrap.cc
+85-17Lines changed: 85 additions & 17 deletions
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
Collapse file

‎src/async-wrap.h‎

Copy file name to clipboardExpand all lines: src/async-wrap.h
+10-4Lines changed: 10 additions & 4 deletions
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

Collapse file

‎src/node.cc‎

Copy file name to clipboardExpand all lines: src/node.cc
+14-7Lines changed: 14 additions & 7 deletions
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() {
Collapse file

‎src/node_http_parser.cc‎

Copy file name to clipboardExpand all lines: src/node_http_parser.cc
+13Lines changed: 13 additions & 0 deletions
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 (0)
Morty Proxy This is a proxified and sanitized view of the page, visit original site.