Skip to content

Commit

Permalink
vm,trace_events: add node.vm.script trace events category
Browse files Browse the repository at this point in the history
Add basic trace events for node_contextify. These generally
align very well with V8.ScriptCompile and V8.ScriptExecute
trace events and provide good additional context. For instance,
using the node.vm.script trace category at startup allows us to
see exactly how long compilation and init of each of our core
modules adds to the startup time.

PR-URL: #20728
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
  • Loading branch information
jasnell authored and MylesBorins committed May 22, 2018
1 parent 8f489a2 commit 740bf78
Show file tree
Hide file tree
Showing 3 changed files with 80 additions and 0 deletions.
2 changes: 2 additions & 0 deletions doc/api/tracing.md
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,8 @@ The available categories are:
* `node.perf.timerify` - Enables capture of only Performance API timerify
measurements.
* `node.fs.sync` - Enables capture of trace data for file system sync methods.
* `node.vm.script` - Enables capture of trace data for the `vm` module's
`runInNewContext()`, `runInContext()`, and `runInThisContext()` methods.
* `v8` - The [V8] events are GC, compiling, and execution related.

By default the `node`, `node.async_hooks`, and `v8` categories are enabled.
Expand Down
36 changes: 36 additions & 0 deletions src/node_contextify.cc
Original file line number Diff line number Diff line change
Expand Up @@ -665,6 +665,16 @@ class ContextifyScript : public BaseObject {
ContextifyScript* contextify_script =
new ContextifyScript(env, args.This());

if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
TRACING_CATEGORY_NODE2(vm, script)) != 0) {
Utf8Value fn(isolate, filename);
TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(
TRACING_CATEGORY_NODE2(vm, script),
"ContextifyScript::New",
contextify_script,
"filename", TRACE_STR_COPY(*fn));
}

ScriptCompiler::CachedData* cached_data = nullptr;
if (!cached_data_buf.IsEmpty()) {
ArrayBuffer::Contents contents = cached_data_buf->Buffer()->GetContents();
Expand Down Expand Up @@ -694,6 +704,10 @@ class ContextifyScript : public BaseObject {
DecorateErrorStack(env, try_catch);
no_abort_scope.Close();
try_catch.ReThrow();
TRACE_EVENT_NESTABLE_ASYNC_END0(
TRACING_CATEGORY_NODE2(vm, script),
"ContextifyScript::New",
contextify_script);
return;
}
contextify_script->script_.Reset(isolate, v8_script.ToLocalChecked());
Expand All @@ -717,6 +731,10 @@ class ContextifyScript : public BaseObject {
env->cached_data_produced_string(),
Boolean::New(isolate, cached_data_produced));
}
TRACE_EVENT_NESTABLE_ASYNC_END0(
TRACING_CATEGORY_NODE2(vm, script),
"ContextifyScript::New",
contextify_script);
}


Expand All @@ -729,6 +747,12 @@ class ContextifyScript : public BaseObject {
static void RunInThisContext(const FunctionCallbackInfo<Value>& args) {
Environment* env = Environment::GetCurrent(args);

ContextifyScript* wrapped_script;
ASSIGN_OR_RETURN_UNWRAP(&wrapped_script, args.Holder());

TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(
TRACING_CATEGORY_NODE2(vm, script), "RunInThisContext", wrapped_script);

CHECK_EQ(args.Length(), 3);

CHECK(args[0]->IsNumber());
Expand All @@ -742,11 +766,17 @@ class ContextifyScript : public BaseObject {

// Do the eval within this context
EvalMachine(env, timeout, display_errors, break_on_sigint, args);

TRACE_EVENT_NESTABLE_ASYNC_END0(
TRACING_CATEGORY_NODE2(vm, script), "RunInThisContext", wrapped_script);
}

static void RunInContext(const FunctionCallbackInfo<Value>& args) {
Environment* env = Environment::GetCurrent(args);

ContextifyScript* wrapped_script;
ASSIGN_OR_RETURN_UNWRAP(&wrapped_script, args.Holder());

CHECK_EQ(args.Length(), 4);

CHECK(args[0]->IsObject());
Expand All @@ -759,6 +789,9 @@ class ContextifyScript : public BaseObject {
if (contextify_context->context().IsEmpty())
return;

TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(
TRACING_CATEGORY_NODE2(vm, script), "RunInContext", wrapped_script);

CHECK(args[1]->IsNumber());
int64_t timeout = args[1]->IntegerValue(env->context()).FromJust();

Expand All @@ -775,6 +808,9 @@ class ContextifyScript : public BaseObject {
display_errors,
break_on_sigint,
args);

TRACE_EVENT_NESTABLE_ASYNC_END0(
TRACING_CATEGORY_NODE2(vm, script), "RunInContext", wrapped_script);
}

static void DecorateErrorStack(Environment* env, const TryCatch& try_catch) {
Expand Down
42 changes: 42 additions & 0 deletions test/parallel/test-trace-events-vm.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,42 @@
'use strict';
const common = require('../common');
const assert = require('assert');
const cp = require('child_process');
const path = require('path');
const fs = require('fs');
const tmpdir = require('../common/tmpdir');

const names = [
'ContextifyScript::New',
'RunInThisContext',
'RunInContext'
];

if (process.argv[2] === 'child') {
const vm = require('vm');
vm.runInNewContext('1 + 1');
} else {
tmpdir.refresh();
process.chdir(tmpdir.path);

const proc = cp.fork(__filename,
[ 'child' ], {
execArgv: [
'--trace-event-categories',
'node.vm.script'
]
});

proc.once('exit', common.mustCall(() => {
const file = path.join(tmpdir.path, 'node_trace.1.log');

assert(common.fileExists(file));
fs.readFile(file, common.mustCall((err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
traces.forEach((trace) => {
assert.strictEqual(trace.pid, proc.pid);
assert(names.includes(trace.name));
});
}));
}));
}

0 comments on commit 740bf78

Please sign in to comment.