Skip to content

src: trace_events: support for metadata events #20757

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
ofrobots wants to merge 1 commit into from
Closed

src: trace_events: support for metadata events #20757

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions src/node.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4545,6 +4545,9 @@ inline int Start(Isolate* isolate, IsolateData* isolate_data,
Environment env(isolate_data, context, v8_platform.GetTracingAgent());
env.Start(argc, argv, exec_argc, exec_argv, v8_is_profiling);

TRACE_EVENT_METADATA1("__metadata", "thread_name", "name",
"JavaScriptMainThread");
Copy link
Member

@jasnell jasnell May 17, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Given that trace events can be enabled after this point, perhaps we should move this to ensure that it's always emitted when tracing is first turned on?

Copy link
Member

@jasnell jasnell May 17, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

fwiw... I plan on doing to same to emit some information about which node.js version is being traced

Copy link
Contributor Author

@ofrobots ofrobots May 17, 2018

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Given that trace events can be enabled after this point, perhaps we should move this to ensure that it's always emitted when tracing is first turned on?

I think the right way to go here would be to address the TODO I already added to the code regarding metadata events being kept in a separate buffer of their own and being emitted on each flush of the trace buffer. That would address the case you mention (tracing turned on later) and more (streaming). I think the emit of the event should should stay where it logically make sense. For example, when we create a thread, we should emit the event at that location rather than artificially moving the emit to a point to better align with the lifecycle of tracing.

I plan to implement this secondary buffer for metadata events in a follow-on. I think it will address the issue.

fwiw... I plan on doing to same to emit some information about which node.js version is being traced

👍


const char* path = argc > 1 ? argv[1] : nullptr;
StartInspector(&env, path, debug_options);

Expand Down
39 changes: 39 additions & 0 deletions src/tracing/trace_event.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,6 +118,15 @@ enum CategoryGroupEnabledFlags {
node::tracing::TraceEventHelper::GetTracingController() \
->UpdateTraceEventDuration

// Adds a metadata event to the trace log. The |AppendValueAsTraceFormat| method
// on the convertable value will be called at flush time.
// TRACE_EVENT_API_ADD_METADATA_EVENT(
// const unsigned char* category_group_enabled,
// const char* event_name,
// const char* arg_name,
// std::unique_ptr<ConvertableToTraceFormat> arg_value)
#define TRACE_EVENT_API_ADD_METADATA_EVENT node::tracing::AddMetadataEvent

// Defines atomic operations used internally by the tracing system.
#define TRACE_EVENT_API_ATOMIC_WORD intptr_t
#define TRACE_EVENT_API_ATOMIC_LOAD(var) (var)
Expand Down Expand Up @@ -259,6 +268,16 @@ enum CategoryGroupEnabledFlags {
} \
} while (0)

#define INTERNAL_TRACE_EVENT_METADATA_ADD(category_group, name, ...) \
do { \
INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category_group); \
if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED_FOR_RECORDING_MODE()) { \
TRACE_EVENT_API_ADD_METADATA_EVENT( \
INTERNAL_TRACE_EVENT_UID(category_group_enabled), name, \
##__VA_ARGS__); \
} \
} while(0)

// Enter and leave a context based on the current scope.
#define INTERNAL_TRACE_EVENT_SCOPED_CONTEXT(category_group, name, context) \
struct INTERNAL_TRACE_EVENT_UID(ScopedContext) { \
Expand Down Expand Up @@ -612,6 +631,26 @@ static V8_INLINE uint64_t AddTraceEventWithTimestamp(
arg_names, arg_types, arg_values, flags, timestamp);
}

template <class ARG1_TYPE>
static V8_INLINE uint64_t AddMetadataEvent(
const uint8_t* category_group_enabled, const char* name,
const char* arg1_name, ARG1_TYPE&& arg1_val) {
const int num_args = 1;
uint8_t arg_type;
uint64_t arg_value;
SetTraceValue(std::forward<ARG1_TYPE>(arg1_val), &arg_type, &arg_value);
// TODO(ofrobots): It would be good to add metadata events to a separate
// buffer so that they can be periodically reemitted. For now, we have a
// single buffer, so we just add them to the main buffer.
return TRACE_EVENT_API_ADD_TRACE_EVENT(
TRACE_EVENT_PHASE_METADATA,
category_group_enabled, name,
node::tracing::kGlobalScope, // scope
node::tracing::kNoId, // id
node::tracing::kNoId, // bind_id
num_args, &arg1_name, &arg_type, &arg_value, TRACE_EVENT_FLAG_NONE);
}

// Used by TRACE_EVENTx macros. Do not use directly.
class ScopedTracer {
public:
Expand Down
3 changes: 2 additions & 1 deletion test/parallel/test-trace-events-api.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -130,7 +130,8 @@ if (isChild) {

assert(common.fileExists(file));
fs.readFile(file, common.mustCall((err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
const traces = JSON.parse(data.toString()).traceEvents
.filter((trace) => trace.cat !== '__metadata');
assert.strictEqual(traces.length,
expectedMarks.length +
expectedBegins.length +
Expand Down
3 changes: 2 additions & 1 deletion test/parallel/test-trace-events-binding.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,8 @@ const proc = cp.spawn(process.execPath,
proc.once('exit', common.mustCall(() => {
assert(common.fileExists(FILE_NAME));
fs.readFile(FILE_NAME, common.mustCall((err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
const traces = JSON.parse(data.toString()).traceEvents
.filter((trace) => trace.cat !== '__metadata');
assert.strictEqual(traces.length, 3);

assert.strictEqual(traces[0].pid, proc.pid);
Expand Down
3 changes: 2 additions & 1 deletion test/parallel/test-trace-events-bootstrap.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,8 @@ if (process.argv[2] === 'child') {

assert(common.fileExists(file));
fs.readFile(file, common.mustCall((err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
const traces = JSON.parse(data.toString()).traceEvents
.filter((trace) => trace.cat !== '__metadata');
traces.forEach((trace) => {
assert.strictEqual(trace.pid, proc.pid);
assert(names.includes(trace.name));
Expand Down
26 changes: 26 additions & 0 deletions test/parallel/test-trace-events-metadata.js
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
'use strict';
const common = require('../common');
const assert = require('assert');
const cp = require('child_process');
const fs = require('fs');

const CODE =
'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
const FILE_NAME = 'node_trace.1.log';

const tmpdir = require('../common/tmpdir');
tmpdir.refresh();
process.chdir(tmpdir.path);

const proc = cp.spawn(process.execPath,
[ '--trace-events-enabled', '-e', CODE ]);
proc.once('exit', common.mustCall(() => {
assert(common.fileExists(FILE_NAME));
fs.readFile(FILE_NAME, common.mustCall((err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
assert(traces.length > 0);
assert(traces.some((trace) =>
trace.cat === '__metadata' && trace.name === 'thread_name' &&
trace.args.name === 'JavaScriptMainThread'));
}));
}));
8 changes: 7 additions & 1 deletion test/parallel/test-trace-events-none.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
const common = require('../common');
const assert = require('assert');
const cp = require('child_process');
const fs = require('fs');

const CODE =
'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
Expand All @@ -17,5 +18,10 @@ const proc_no_categories = cp.spawn(
);

proc_no_categories.once('exit', common.mustCall(() => {
assert(!common.fileExists(FILE_NAME));
assert(common.fileExists(FILE_NAME));
// Only __metadata categories should have been emitted.
fs.readFile(FILE_NAME, common.mustCall((err, data) => {
assert.ok(JSON.parse(data.toString()).traceEvents.every(
(trace) => trace.cat === '__metadata'));
}));
}));
3 changes: 2 additions & 1 deletion test/parallel/test-trace-events-perf.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -49,7 +49,8 @@ if (process.argv[2] === 'child') {

assert(common.fileExists(file));
fs.readFile(file, common.mustCall((err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
const traces = JSON.parse(data.toString()).traceEvents
.filter((trace) => trace.cat !== '__metadata');
assert.strictEqual(traces.length,
expectedMarks.length +
expectedBegins.length +
Expand Down
3 changes: 2 additions & 1 deletion test/parallel/test-trace-events-vm.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,8 @@ if (process.argv[2] === 'child') {

assert(common.fileExists(file));
fs.readFile(file, common.mustCall((err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
const traces = JSON.parse(data.toString()).traceEvents
.filter((trace) => trace.cat !== '__metadata');
traces.forEach((trace) => {
assert.strictEqual(trace.pid, proc.pid);
assert(names.includes(trace.name));
Expand Down