summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--doc/api/perf_hooks.md4
-rw-r--r--doc/api/tracing.md18
-rw-r--r--src/node_perf.cc20
-rw-r--r--src/node_perf.h1
-rw-r--r--src/tracing/trace_event.h17
-rw-r--r--test/parallel/test-trace-events-perf.js82
6 files changed, 131 insertions, 11 deletions
diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md
index 5bef91eafb..4e31a24785 100644
--- a/doc/api/perf_hooks.md
+++ b/doc/api/perf_hooks.md
@@ -268,8 +268,8 @@ added: v8.5.0
* {string}
-The type of the performance entry. Current it may be one of: `'node'`, `'mark'`,
-`'measure'`, `'gc'`, or `'function'`.
+The type of the performance entry. Currently it may be one of: `'node'`,
+`'mark'`, `'measure'`, `'gc'`, or `'function'`.
### performanceEntry.kind
<!-- YAML
diff --git a/doc/api/tracing.md b/doc/api/tracing.md
index 67b3394d55..3a534177a3 100644
--- a/doc/api/tracing.md
+++ b/doc/api/tracing.md
@@ -10,8 +10,20 @@ starting a 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`, `node.async_hooks`, and `v8` categories are
-enabled.
+names.
+
+The available categories are:
+
+* `node`
+* `node.async_hooks` - Enables capture of detailed async_hooks trace data.
+* `node.perf` - Enables capture of [Performance API] measurements.
+ * `node.perf.usertiming` - Enables capture of only Performance API User Timing
+ measures and marks.
+ * `node.perf.timerify` - Enables capture of only Performance API timerify
+ measurements.
+* `v8`
+
+By default the `node`, `node.async_hooks`, and `v8` categories are enabled.
```txt
node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks server.js
@@ -24,3 +36,5 @@ tab of Chrome.
Starting with Node 10.0.0, the tracing system uses the same time source as the
one used by `process.hrtime()` however the trace-event timestamps are expressed
in microseconds, unlike `process.hrtime()` which returns nanoseconds.
+
+[Performance API]: perf_hooks.html
diff --git a/src/node_perf.cc b/src/node_perf.cc
index a4297c21f0..db4eff5353 100644
--- a/src/node_perf.cc
+++ b/src/node_perf.cc
@@ -105,8 +105,8 @@ void Mark(const FunctionCallbackInfo<Value>& args) {
auto marks = env->performance_marks();
(*marks)[*name] = now;
- // TODO(jasnell): Once Tracing API is fully implemented, this should
- // record a trace event also.
+ TRACE_EVENT_COPY_MARK_WITH_TIMESTAMP(
+ "node.perf,node.perf.usertiming", *name, now / 1000);
PerformanceEntry entry(env, *name, "mark", now, now);
Local<Object> obj = entry.ToObject();
@@ -153,8 +153,10 @@ void Measure(const FunctionCallbackInfo<Value>& args) {
if (endTimestamp < startTimestamp)
endTimestamp = startTimestamp;
- // TODO(jasnell): Once Tracing API is fully implemented, this should
- // record a trace event also.
+ TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
+ "node.perf,node.perf.usertiming", *name, *name, startTimestamp / 1000);
+ TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
+ "node.perf,node.perf.usertiming", *name, *name, endTimestamp / 1000);
PerformanceEntry entry(env, *name, "measure", startTimestamp, endTimestamp);
Local<Object> obj = entry.ToObject();
@@ -269,10 +271,15 @@ void TimerFunctionCall(const FunctionCallbackInfo<Value>& args) {
v8::TryCatch try_catch(isolate);
if (args.IsConstructCall()) {
start = PERFORMANCE_NOW();
+ TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
+ "node.perf,node.perf.timerify", *name, *name, start / 1000);
v8::MaybeLocal<Object> ret = fn->NewInstance(context,
call_args.size(),
call_args.data());
end = PERFORMANCE_NOW();
+ TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
+ "node.perf,node.perf.timerify", *name, *name, end / 1000);
+
if (ret.IsEmpty()) {
try_catch.ReThrow();
return;
@@ -280,11 +287,16 @@ void TimerFunctionCall(const FunctionCallbackInfo<Value>& args) {
args.GetReturnValue().Set(ret.ToLocalChecked());
} else {
start = PERFORMANCE_NOW();
+ TRACE_EVENT_COPY_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
+ "node.perf,node.perf.timerify", *name, *name, start / 1000);
v8::MaybeLocal<Value> ret = fn->Call(context,
args.This(),
call_args.size(),
call_args.data());
end = PERFORMANCE_NOW();
+ TRACE_EVENT_COPY_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
+ "node.perf,node.perf.timerify", *name, *name, end / 1000);
+
if (ret.IsEmpty()) {
try_catch.ReThrow();
return;
diff --git a/src/node_perf.h b/src/node_perf.h
index f1b182b4e3..82e3f46eb8 100644
--- a/src/node_perf.h
+++ b/src/node_perf.h
@@ -4,6 +4,7 @@
#if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
#include "node.h"
+#include "node_internals.h"
#include "node_perf_common.h"
#include "env.h"
#include "base_object-inl.h"
diff --git a/src/tracing/trace_event.h b/src/tracing/trace_event.h
index 4aac9e5543..3fbe1b0a1f 100644
--- a/src/tracing/trace_event.h
+++ b/src/tracing/trace_event.h
@@ -244,9 +244,20 @@ enum CategoryGroupEnabledFlags {
// Adds a trace event with a given id, thread_id, and timestamp. Not
// Implemented.
-#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
- phase, category_group, name, id, thread_id, timestamp, flags, ...) \
- UNIMPLEMENTED()
+#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP( \
+ phase, category_group, name, id, thread_id, timestamp, flags, ...) \
+ do { \
+ INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category_group); \
+ if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED_FOR_RECORDING_MODE()) { \
+ unsigned int trace_event_flags = flags | TRACE_EVENT_FLAG_HAS_ID; \
+ node::tracing::TraceID trace_event_trace_id(id, \
+ &trace_event_flags); \
+ node::tracing::AddTraceEventWithTimestamp( \
+ phase, INTERNAL_TRACE_EVENT_UID(category_group_enabled), name, \
+ trace_event_trace_id.scope(), trace_event_trace_id.raw_id(), \
+ node::tracing::kNoId, trace_event_flags, timestamp, ##__VA_ARGS__);\
+ } \
+ } while (0)
// Enter and leave a context based on the current scope.
#define INTERNAL_TRACE_EVENT_SCOPED_CONTEXT(category_group, name, context) \
diff --git a/test/parallel/test-trace-events-perf.js b/test/parallel/test-trace-events-perf.js
new file mode 100644
index 0000000000..e73579f87e
--- /dev/null
+++ b/test/parallel/test-trace-events-perf.js
@@ -0,0 +1,82 @@
+'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');
+
+if (process.argv[2] === 'child') {
+ const { performance } = require('perf_hooks');
+
+ // Will emit mark and measure trace events
+ performance.mark('A');
+ setTimeout(() => {
+ performance.mark('B');
+ performance.measure('A to B', 'A', 'B');
+ }, 1);
+
+ // Intentional non-op, part of the test
+ function f() {}
+ const ff = performance.timerify(f);
+ ff(); // Will emit a timerify trace event
+} else {
+ tmpdir.refresh();
+ process.chdir(tmpdir.path);
+
+ const expectedMarks = ['A', 'B'];
+ const expectedBegins = [
+ { cat: 'node.perf,node.perf.timerify', name: 'f' },
+ { cat: 'node.perf,node.perf.usertiming', name: 'A to B' }
+ ];
+ const expectedEnds = [
+ { cat: 'node.perf,node.perf.timerify', name: 'f' },
+ { cat: 'node.perf,node.perf.usertiming', name: 'A to B' }
+ ];
+
+ const proc = cp.fork(__filename,
+ [
+ 'child'
+ ], {
+ execArgv: [
+ '--trace-events-enabled',
+ '--trace-event-categories',
+ 'node.perf'
+ ]
+ });
+
+ 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;
+ assert.strictEqual(traces.length,
+ expectedMarks.length +
+ expectedBegins.length +
+ expectedEnds.length);
+
+ traces.forEach((trace) => {
+ assert.strictEqual(trace.pid, proc.pid);
+ switch (trace.ph) {
+ case 'R':
+ assert.strictEqual(trace.cat, 'node.perf,node.perf.usertiming');
+ assert.strictEqual(trace.name, expectedMarks.shift());
+ break;
+ case 'b':
+ const expectedBegin = expectedBegins.shift();
+ assert.strictEqual(trace.cat, expectedBegin.cat);
+ assert.strictEqual(trace.name, expectedBegin.name);
+ break;
+ case 'e':
+ const expectedEnd = expectedEnds.shift();
+ assert.strictEqual(trace.cat, expectedEnd.cat);
+ assert.strictEqual(trace.name, expectedEnd.name);
+ break;
+ default:
+ assert.fail('Unexpected trace event phase');
+ }
+ });
+ }));
+ }));
+}
generated by cgit v1.2.3 (git 2.39.1) at 2024-05-12 16:36:54 +0000