src: trace_events: support for metadata events

Add support for metadata events. At this point they are added to the
main buffer. Emit a metadata event for the main thread.

PR-URL: #20757
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

src/node.cc

@@ -4559,6 +4559,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");
+
   const char* path = argc > 1 ? argv[1] : nullptr;
   StartInspector(&env, path, debug_options);
 

src/tracing/trace_event.h

@@ -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)
@@ -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) {                         \
@@ -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:

test/parallel/test-trace-events-api.js

@@ -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 +

test/parallel/test-trace-events-binding.js

@@ -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);

test/parallel/test-trace-events-bootstrap.js

@@ -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));

test/parallel/test-trace-events-metadata.js

@@ -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'));
+  }));
+}));

test/parallel/test-trace-events-none.js

@@ -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)';
@@ -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'));
+  }));
 }));

test/parallel/test-trace-events-perf.js

@@ -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 +

test/parallel/test-trace-events-vm.js

@@ -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));