Skip to content

Commit

Permalink
async_hooks: add trace events to async_hooks
Browse files Browse the repository at this point in the history
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>
  • Loading branch information
AndreasMadsen authored and MylesBorins committed Dec 11, 2017
1 parent 4bdd05d commit cf7e15c
Show file tree
Hide file tree
Showing 18 changed files with 607 additions and 73 deletions.
4 changes: 2 additions & 2 deletions doc/api/tracing.md
Original file line number Diff line number Diff line change
Expand Up @@ -8,10 +8,10 @@ Node.js application.

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

```txt
node --trace-events-enabled --trace-event-categories v8,node server.js
node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js
```

Running Node.js with tracing enabled will produce log files that can be opened
Expand Down
3 changes: 1 addition & 2 deletions lib/_http_common.js
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,6 @@ const { methods, HTTPParser } = binding;
const FreeList = require('internal/freelist');
const { ondrain } = require('internal/http');
const incoming = require('_http_incoming');
const { emitDestroy } = require('async_hooks');
const {
IncomingMessage,
readStart,
Expand Down Expand Up @@ -218,7 +217,7 @@ function freeParser(parser, req, socket) {
} else {
// Since the Parser destructor isn't going to run the destroy() callbacks
// it needs to be triggered manually.
emitDestroy(parser.getAsyncId());
parser.free();
}
}
if (req) {
Expand Down
1 change: 1 addition & 0 deletions lib/internal/bootstrap_node.js
Original file line number Diff line number Diff line change
Expand Up @@ -59,6 +59,7 @@
if (global.__coverage__)
NativeModule.require('internal/process/write-coverage').setup();

NativeModule.require('internal/trace_events_async_hooks').setup();
NativeModule.require('internal/inspector_async_hook').setup();

// Do not initialize channel in debugger agent, it deletes env variable
Expand Down
67 changes: 67 additions & 0 deletions lib/internal/trace_events_async_hooks.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,67 @@
'use strict';

const trace_events = process.binding('trace_events');
const async_wrap = process.binding('async_wrap');
const async_hooks = require('async_hooks');

// Use small letters such that chrome://traceing groups by the name.
// The behaviour is not only useful but the same as the events emitted using
// the specific C++ macros.
const BEFORE_EVENT = 'b'.charCodeAt(0);
const END_EVENT = 'e'.charCodeAt(0);

// In trace_events it is not only the id but also the name that needs to be
// repeated. Since async_hooks doesn't expose the provider type in the
// non-init events, use a map to manually map the asyncId to the type name.
const typeMemory = new Map();

// It is faster to emit trace_events directly from C++. Thus, this happens in
// async_wrap.cc. However, events emitted from the JavaScript API or the
// Embedder C++ API can't be emitted from async_wrap.cc. Thus they are
// emitted using the JavaScript API. To prevent emitting the same event
// twice the async_wrap.Providers list is used to filter the events.
const nativeProviders = new Set(Object.keys(async_wrap.Providers));

const hook = async_hooks.createHook({
init(asyncId, type, triggerAsyncId, resource) {
if (nativeProviders.has(type)) return;

typeMemory.set(asyncId, type);
trace_events.emit(BEFORE_EVENT, 'node.async_hooks',
type, asyncId, 'triggerAsyncId', triggerAsyncId);
},

before(asyncId) {
const type = typeMemory.get(asyncId);
if (type === undefined) return;

trace_events.emit(BEFORE_EVENT, 'node.async_hooks',
type + '_CALLBACK', asyncId);
},

after(asyncId) {
const type = typeMemory.get(asyncId);
if (type === undefined) return;

trace_events.emit(END_EVENT, 'node.async_hooks',
type + '_CALLBACK', asyncId);
},

destroy(asyncId) {
const type = typeMemory.get(asyncId);
if (type === undefined) return;

trace_events.emit(END_EVENT, 'node.async_hooks',
type, asyncId);

// cleanup asyncId to type map
typeMemory.delete(asyncId);
}
});


exports.setup = function() {
if (trace_events.categoryGroupEnabled('node.async_hooks')) {
hook.enable();
}
};
2 changes: 2 additions & 0 deletions node.gyp
Original file line number Diff line number Diff line change
Expand Up @@ -121,6 +121,7 @@
'lib/internal/socket_list.js',
'lib/internal/test/unicode.js',
'lib/internal/tls.js',
'lib/internal/trace_events_async_hooks.js',
'lib/internal/url.js',
'lib/internal/util.js',
'lib/internal/util/comparisons.js',
Expand Down Expand Up @@ -213,6 +214,7 @@
'src/node_platform.cc',
'src/node_perf.cc',
'src/node_serdes.cc',
'src/node_trace_events.cc',
'src/node_url.cc',
'src/node_util.cc',
'src/node_v8.cc',
Expand Down
102 changes: 85 additions & 17 deletions src/async-wrap.cc
Original file line number Diff line number Diff line change
Expand Up @@ -167,18 +167,6 @@ static void DestroyAsyncIdsCallback(uv_timer_t* handle) {
}


static void PushBackDestroyAsyncId(Environment* env, double id) {
if (env->async_hooks()->fields()[AsyncHooks::kDestroy] == 0)
return;

if (env->destroy_async_id_list()->empty())
uv_timer_start(env->destroy_async_ids_timer_handle(),
DestroyAsyncIdsCallback, 0, 0);

env->destroy_async_id_list()->push_back(id);
}


void AsyncWrap::EmitPromiseResolve(Environment* env, double async_id) {
AsyncHooks* async_hooks = env->async_hooks();

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


void AsyncWrap::EmitTraceEventBefore() {
switch (provider_type()) {
#define V(PROVIDER) \
case PROVIDER_ ## PROVIDER: \
TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("node.async_hooks", \
#PROVIDER "_CALLBACK", static_cast<int64_t>(get_async_id())); \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
default:
UNREACHABLE();
}
}


void AsyncWrap::EmitBefore(Environment* env, double async_id) {
AsyncHooks* async_hooks = env->async_hooks();

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


void AsyncWrap::EmitTraceEventAfter() {
switch (provider_type()) {
#define V(PROVIDER) \
case PROVIDER_ ## PROVIDER: \
TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks", \
#PROVIDER "_CALLBACK", static_cast<int64_t>(get_async_id())); \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
default:
UNREACHABLE();
}
}


void AsyncWrap::EmitAfter(Environment* env, double async_id) {
AsyncHooks* async_hooks = env->async_hooks();

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

void AsyncWrap::QueueDestroyAsyncId(const FunctionCallbackInfo<Value>& args) {
CHECK(args[0]->IsNumber());
PushBackDestroyAsyncId(Environment::GetCurrent(args), args[0]->NumberValue());
AsyncWrap::EmitDestroy(
Environment::GetCurrent(args), args[0]->NumberValue());
}

void AsyncWrap::AddWrapMethods(Environment* env,
Expand Down Expand Up @@ -604,7 +625,34 @@ AsyncWrap::AsyncWrap(Environment* env,


AsyncWrap::~AsyncWrap() {
PushBackDestroyAsyncId(env(), get_async_id());
EmitTraceEventDestroy();
EmitDestroy(env(), get_async_id());
}

void AsyncWrap::EmitTraceEventDestroy() {
switch (provider_type()) {
#define V(PROVIDER) \
case PROVIDER_ ## PROVIDER: \
TRACE_EVENT_NESTABLE_ASYNC_END0("node.async_hooks", \
#PROVIDER, static_cast<int64_t>(get_async_id())); \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
default:
UNREACHABLE();
}
}

void AsyncWrap::EmitDestroy(Environment* env, double async_id) {
if (env->async_hooks()->fields()[AsyncHooks::kDestroy] == 0)
return;

if (env->destroy_async_id_list()->empty()) {
uv_timer_start(env->destroy_async_ids_timer_handle(),
DestroyAsyncIdsCallback, 0, 0);
}

env->destroy_async_id_list()->push_back(async_id);
}


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

switch (provider_type()) {
#define V(PROVIDER) \
case PROVIDER_ ## PROVIDER: \
TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("node.async_hooks", \
#PROVIDER, static_cast<int64_t>(get_async_id()), \
"triggerAsyncId", static_cast<int64_t>(get_trigger_async_id())); \
break;
NODE_ASYNC_PROVIDER_TYPES(V)
#undef V
default:
UNREACHABLE();
}

if (silent) return;

EmitAsyncInit(env(), object(),
Expand Down Expand Up @@ -662,8 +723,15 @@ void AsyncWrap::EmitAsyncInit(Environment* env,
MaybeLocal<Value> AsyncWrap::MakeCallback(const Local<Function> cb,
int argc,
Local<Value>* argv) {
EmitTraceEventBefore();

async_context context { get_async_id(), get_trigger_async_id() };
return InternalMakeCallback(env(), object(), cb, argc, argv, context);
MaybeLocal<Value> ret = InternalMakeCallback(
env(), object(), cb, argc, argv, context);

EmitTraceEventAfter();

return ret;
}


Expand Down Expand Up @@ -713,8 +781,8 @@ async_context EmitAsyncInit(Isolate* isolate,
}

void EmitAsyncDestroy(Isolate* isolate, async_context asyncContext) {
PushBackDestroyAsyncId(Environment::GetCurrent(isolate),
asyncContext.async_id);
AsyncWrap::EmitDestroy(
Environment::GetCurrent(isolate), asyncContext.async_id);
}

} // namespace node
Expand Down
14 changes: 10 additions & 4 deletions src/async-wrap.h
Original file line number Diff line number Diff line change
Expand Up @@ -129,12 +129,18 @@ class AsyncWrap : public BaseObject {
static void EmitAsyncInit(Environment* env,
v8::Local<v8::Object> object,
v8::Local<v8::String> type,
double id,
double async_id,
double trigger_async_id);

static void EmitBefore(Environment* env, double id);
static void EmitAfter(Environment* env, double id);
static void EmitPromiseResolve(Environment* env, double id);
static void EmitDestroy(Environment* env, double async_id);
static void EmitBefore(Environment* env, double async_id);
static void EmitAfter(Environment* env, double async_id);
static void EmitPromiseResolve(Environment* env, double async_id);

void EmitTraceEventBefore();
void EmitTraceEventAfter();
void EmitTraceEventDestroy();


inline ProviderType provider_type() const;

Expand Down
21 changes: 14 additions & 7 deletions src/node.cc
Original file line number Diff line number Diff line change
Expand Up @@ -263,13 +263,20 @@ node::DebugOptions debug_options;
static struct {
#if NODE_USE_V8_PLATFORM
void Initialize(int thread_pool_size) {
tracing_agent_.reset(
trace_enabled ? new tracing::Agent() : nullptr);
platform_ = new NodePlatform(thread_pool_size,
trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
V8::InitializePlatform(platform_);
tracing::TraceEventHelper::SetTracingController(
trace_enabled ? tracing_agent_->GetTracingController() : nullptr);
if (trace_enabled) {
tracing_agent_.reset(new tracing::Agent());
platform_ = new NodePlatform(thread_pool_size,
tracing_agent_->GetTracingController());
V8::InitializePlatform(platform_);
tracing::TraceEventHelper::SetTracingController(
tracing_agent_->GetTracingController());
} else {
tracing_agent_.reset(nullptr);
platform_ = new NodePlatform(thread_pool_size, nullptr);
V8::InitializePlatform(platform_);
tracing::TraceEventHelper::SetTracingController(
new v8::TracingController());
}
}

void Dispose() {
Expand Down
13 changes: 13 additions & 0 deletions src/node_http_parser.cc
Original file line number Diff line number Diff line change
Expand Up @@ -397,6 +397,18 @@ class Parser : public AsyncWrap {
}


static void Free(const FunctionCallbackInfo<Value>& args) {
Environment* env = Environment::GetCurrent(args);
Parser* parser;
ASSIGN_OR_RETURN_UNWRAP(&parser, args.Holder());

// Since the Parser destructor isn't going to run the destroy() callbacks
// it needs to be triggered manually.
parser->EmitTraceEventDestroy();
parser->EmitDestroy(env, parser->get_async_id());
}


void Save() {
url_.Save();
status_message_.Save();
Expand Down Expand Up @@ -792,6 +804,7 @@ void InitHttpParser(Local<Object> target,

AsyncWrap::AddWrapMethods(env, t);
env->SetProtoMethod(t, "close", Parser::Close);
env->SetProtoMethod(t, "free", Parser::Free);
env->SetProtoMethod(t, "execute", Parser::Execute);
env->SetProtoMethod(t, "finish", Parser::Finish);
env->SetProtoMethod(t, "reinitialize", Parser::Reinitialize);
Expand Down
Loading

0 comments on commit cf7e15c

Please sign in to comment.