trace_events: add file pattern cli option

AndreasMadsen · MylesBorins · commit 3d4cda3a7d68 · 2018-03-06T12:26:16.000-08:00
Allow the user to specify the filepath for the trace_events log file using a template string. Backport-PR-URL: #19144 PR-URL: #18480 Reviewed-By: Ali Ijaz Sheikh <ofrobots@google.com> Reviewed-By: Richard Lau <riclau@uk.ibm.com> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de>
diff --git a/doc/api/cli.md b/doc/api/cli.md
@@ -235,6 +235,14 @@ added: v7.7.0
 A comma separated list of categories that should be traced when trace event
 tracing is enabled using `--trace-events-enabled`.
 
+### `--trace-event-file-pattern`
+<!-- YAML
+added: REPLACEME
+-->
+
+Template string specifying the filepath for the trace event data, it
+supports `${rotation}` and `${pid}`.
+
 ### `--zero-fill-buffers`
 <!-- YAML
 added: v6.0.0
@@ -464,6 +472,7 @@ Node options that are allowed are:
 - `--trace-deprecation`
 - `--trace-events-categories`
 - `--trace-events-enabled`
+- `--trace-event-file-pattern`
 - `--trace-sync-io`
 - `--trace-warnings`
 - `--track-heap-objects`
diff --git a/doc/api/tracing.md b/doc/api/tracing.md
@@ -19,3 +19,16 @@ node --trace-events-enabled --trace-event-categories v8,node,node.async_hooks se
 Running Node.js with tracing enabled will produce log files that can be opened
 in the [`chrome://tracing`](https://www.chromium.org/developers/how-tos/trace-event-profiling-tool)
 tab of Chrome.
+
+The logging file is by default called `node_trace.${rotation}.log`, where
+`${rotation}` is an incrementing log-rotation id. The filepath pattern can
+be specified with `--trace-event-file-pattern` that accepts a template
+string that supports `${rotation}` and `${pid}`. For example:
+
+```txt
+node --trace-events-enabled --trace-event-file-pattern '${pid}-${rotation}.log' server.js
+```
+
+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.
diff --git a/doc/node.1 b/doc/node.1
@@ -156,6 +156,10 @@ Enable the collection of trace event tracing information.
 A comma-separated list of categories that should be traced when trace event tracing is enabled using
 .Fl -trace-events-enabled .
 .
+.It Fl -trace-event-file-pattern Ar pattern
+Template string specifying the filepath for the trace event data, it
+supports \fB${rotation}\fR and \fB${pid}\fR.
+.
 .It Fl -zero-fill-buffers
 Automatically zero-fills all newly allocated Buffer and SlowBuffer instances.
 .
diff --git a/src/node.cc b/src/node.cc
@@ -197,6 +197,8 @@ static node_module* modlist_linked;
 static node_module* modlist_addon;
 static bool trace_enabled = false;
 static std::string trace_enabled_categories;  // NOLINT(runtime/string)
+static std::string trace_file_pattern =  // NOLINT(runtime/string)
+  "node_trace.${rotation}.log";
 static bool abort_on_uncaught_exception = false;
 
 // Bit flag used to track security reverts (see node_revert.h)
@@ -280,7 +282,7 @@ static struct {
 #if NODE_USE_V8_PLATFORM
   void Initialize(int thread_pool_size) {
     if (trace_enabled) {
-      tracing_agent_.reset(new tracing::Agent());
+      tracing_agent_.reset(new tracing::Agent(trace_file_pattern));
       platform_ = new NodePlatform(thread_pool_size,
         tracing_agent_->GetTracingController());
       V8::InitializePlatform(platform_);
@@ -3722,6 +3724,10 @@ static void PrintHelp() {
          "  --trace-events-enabled     track trace events\n"
          "  --trace-event-categories   comma separated list of trace event\n"
          "                             categories to record\n"
+         "  --trace-event-file-pattern Template string specifying the\n"
+         "                             filepath for the trace-events data, it\n"
+         "                             supports ${rotation} and ${pid}\n"
+         "                             log-rotation id. %%2$u is the pid.\n"
          "  --track-heap-objects       track heap object allocations for heap "
          "snapshots\n"
          "  --prof-process             process v8 profiler output generated\n"
@@ -3850,6 +3856,7 @@ static void CheckIfAllowedInEnv(const char* exe, bool is_env,
     "--no-force-async-hooks-checks",
     "--trace-events-enabled",
     "--trace-event-categories",
+    "--trace-event-file-pattern",
     "--track-heap-objects",
     "--zero-fill-buffers",
     "--v8-pool-size",
@@ -4001,6 +4008,14 @@ static void ParseArgs(int* argc,
       }
       args_consumed += 1;
       trace_enabled_categories = categories;
+    } else if (strcmp(arg, "--trace-event-file-pattern") == 0) {
+      const char* file_pattern = argv[index + 1];
+      if (file_pattern == nullptr) {
+        fprintf(stderr, "%s: %s requires an argument\n", argv[0], arg);
+        exit(9);
+      }
+      args_consumed += 1;
+      trace_file_pattern = file_pattern;
     } else if (strcmp(arg, "--track-heap-objects") == 0) {
       track_heap_objects = true;
     } else if (strcmp(arg, "--throw-deprecation") == 0) {
diff --git a/src/tracing/agent.cc b/src/tracing/agent.cc
@@ -13,11 +13,12 @@ namespace tracing {
 using v8::platform::tracing::TraceConfig;
 using std::string;
 
-Agent::Agent() {
+Agent::Agent(const std::string& log_file_pattern) {
   int err = uv_loop_init(&tracing_loop_);
   CHECK_EQ(err, 0);
 
-  NodeTraceWriter* trace_writer = new NodeTraceWriter(&tracing_loop_);
+  NodeTraceWriter* trace_writer = new NodeTraceWriter(
+      log_file_pattern, &tracing_loop_);
   TraceBuffer* trace_buffer = new NodeTraceBuffer(
       NodeTraceBuffer::kBufferChunks, trace_writer, &tracing_loop_);
   tracing_controller_ = new TracingController();
diff --git a/src/tracing/agent.h b/src/tracing/agent.h
@@ -12,7 +12,7 @@ using v8::platform::tracing::TracingController;
 
 class Agent {
  public:
-  Agent();
+  explicit Agent(const std::string& log_file_pattern);
   void Start(const std::string& enabled_categories);
   void Stop();
 
diff --git a/src/tracing/node_trace_writer.cc b/src/tracing/node_trace_writer.cc
@@ -8,8 +8,9 @@
 namespace node {
 namespace tracing {
 
-NodeTraceWriter::NodeTraceWriter(uv_loop_t* tracing_loop)
-    : tracing_loop_(tracing_loop) {
+NodeTraceWriter::NodeTraceWriter(const std::string& log_file_pattern,
+                                 uv_loop_t* tracing_loop)
+    : tracing_loop_(tracing_loop), log_file_pattern_(log_file_pattern) {
   flush_signal_.data = this;
   int err = uv_async_init(tracing_loop_, &flush_signal_, FlushSignalCb);
   CHECK_EQ(err, 0);
@@ -54,12 +55,27 @@ NodeTraceWriter::~NodeTraceWriter() {
   }
 }
 
+void replace_substring(std::string* target,
+                       const std::string& search,
+                       const std::string& insert) {
+  size_t pos = target->find(search);
+  for (; pos != std::string::npos; pos = target->find(search, pos)) {
+    target->replace(pos, search.size(), insert);
+    pos += insert.size();
+  }
+}
+
 void NodeTraceWriter::OpenNewFileForStreaming() {
   ++file_num_;
   uv_fs_t req;
-  std::ostringstream log_file;
-  log_file << "node_trace." << file_num_ << ".log";
-  fd_ = uv_fs_open(tracing_loop_, &req, log_file.str().c_str(),
+
+  // Evaluate a JS-style template string, it accepts the values ${pid} and
+  // ${rotation}
+  std::string filepath(log_file_pattern_);
+  replace_substring(&filepath, "${pid}", std::to_string(uv_os_getpid()));
+  replace_substring(&filepath, "${rotation}", std::to_string(file_num_));
+
+  fd_ = uv_fs_open(tracing_loop_, &req, filepath.c_str(),
       O_CREAT | O_WRONLY | O_TRUNC, 0644, nullptr);
   CHECK_NE(fd_, -1);
   uv_fs_req_cleanup(&req);
diff --git a/src/tracing/node_trace_writer.h b/src/tracing/node_trace_writer.h
@@ -16,7 +16,8 @@ using v8::platform::tracing::TraceWriter;
 
 class NodeTraceWriter : public TraceWriter {
  public:
-  explicit NodeTraceWriter(uv_loop_t* tracing_loop);
+  explicit NodeTraceWriter(const std::string& log_file_pattern,
+                           uv_loop_t* tracing_loop);
   ~NodeTraceWriter();
 
   void AppendTraceEvent(TraceObject* trace_event) override;
@@ -62,6 +63,7 @@ class NodeTraceWriter : public TraceWriter {
   int highest_request_id_completed_ = 0;
   int total_traces_ = 0;
   int file_num_ = 0;
+  const std::string& log_file_pattern_;
   std::ostringstream stream_;
   TraceWriter* json_trace_writer_ = nullptr;
   bool exited_ = false;
diff --git a/test/parallel/test-cli-node-options.js b/test/parallel/test-cli-node-options.js
@@ -25,6 +25,8 @@ expect('--throw-deprecation', 'B\n');
 expect('--zero-fill-buffers', 'B\n');
 expect('--v8-pool-size=10', 'B\n');
 expect('--trace-event-categories node', 'B\n');
+// eslint-disable-next-line no-template-curly-in-string
+expect('--trace-event-file-pattern {pid}-${rotation}.trace_events', 'B\n');
 
 if (!common.isWindows) {
   expect('--perf-basic-prof', 'B\n');
diff --git a/test/parallel/test-trace-events-file-pattern.js b/test/parallel/test-trace-events-file-pattern.js
@@ -0,0 +1,30 @@
+'use strict';
+const common = require('../common');
+const tmpdir = require('../common/tmpdir');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+
+tmpdir.refresh();
+process.chdir(tmpdir.path);
+
+const CODE =
+  'setTimeout(() => { for (var i = 0; i < 100000; i++) { "test" + i } }, 1)';
+
+const proc = cp.spawn(process.execPath, [
+  '--trace-events-enabled',
+  '--trace-event-file-pattern',
+  // eslint-disable-next-line no-template-curly-in-string
+  '${pid}-${rotation}-${pid}-${rotation}.tracing.log',
+  '-e', CODE
+]);
+
+proc.once('exit', common.mustCall(() => {
+  const expectedFilename = `${proc.pid}-1-${proc.pid}-1.tracing.log`;
+
+  assert(common.fileExists(expectedFilename));
+  fs.readFile(expectedFilename, common.mustCall((err, data) => {
+    const traces = JSON.parse(data.toString()).traceEvents;
+    assert(traces.length > 0);
+  }));
+}));

Original file line number	Diff line number	Diff line change
`@@ -156,6 +156,10 @@ Enable the collection of trace event tracing information.`
`156`	`156`	`A comma-separated list of categories that should be traced when trace event tracing is enabled using`
`157`	`157`	`.Fl -trace-events-enabled .`
`158`	`158`	`.`
	`159`	`+.It Fl -trace-event-file-pattern Ar pattern`
	`160`	`+Template string specifying the filepath for the trace event data, it`
	`161`	`+supports \fB${rotation}\fR and \fB${pid}\fR.`
	`162`	`+.`
`159`	`163`	`.It Fl -zero-fill-buffers`
`160`	`164`	`Automatically zero-fills all newly allocated Buffer and SlowBuffer instances.`
`161`	`165`	`.`