Skip to content

Commit

Permalink
trace_events: add file pattern cli option
Browse files Browse the repository at this point in the history
Allow the user to specify the filepath for the trace_events log file
using a template string.

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>
  • Loading branch information
AndreasMadsen authored and apapirovski committed Mar 4, 2018
1 parent 523d44a commit 85212bb
Show file tree
Hide file tree
Showing 10 changed files with 98 additions and 10 deletions.
9 changes: 9 additions & 0 deletions doc/api/cli.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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`
Expand Down
9 changes: 9 additions & 0 deletions doc/api/tracing.md
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,15 @@ 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.
Expand Down
4 changes: 4 additions & 0 deletions doc/node.1
Original file line number Diff line number Diff line change
Expand Up @@ -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.

This comment has been minimized.

Copy link
@Alhadis

Alhadis Mar 19, 2018

Contributor

Random Roff tip-of-the-week: It's better to use \fP instead of \fR when undoing font changes, as the latter restores the font (formatting state) being used prior to the last font change.

Meaning of each letter:

  • \fP: Previous font
  • \fR: Roman (as opposed to Italic, Bold, and Bold Italic). You can also just think of it as standing for "Regular font" too. =)

This comment has been minimized.

Copy link
@Alhadis

Alhadis Mar 19, 2018

Contributor

Also, in mdoc, it's better to use .Ar ("Argument") to format references to parameters and the like. Using \f for arbitrary formatting isn't bad or even wrong, but it's a low-level Roff mechanism — and mdoc exists to help users abstract such things from content.

This should ideally have been:

Template string specifying the filepath for the trace event data, it
supports
.Ar ${rotation} No and Ar ${pid} .

Or even just:

Template string specifying the filepath for the trace event data, it
supports
.Ar ${rotation}
and
.Ar ${pid} .

The latter might be clearer for readers unfamiliar with mdoc syntax. Truth be told, the use of No to indicate "normal" text in a one-line chain of formatting tags is a commonly-criticised aspect of mdoc (I recall one author comparing it to Brainfuck 😀).

.
.It Fl -zero-fill-buffers
Automatically zero-fills all newly allocated Buffer and SlowBuffer instances.
.
Expand Down
17 changes: 16 additions & 1 deletion src/node.cc
Original file line number Diff line number Diff line change
Expand Up @@ -192,6 +192,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)
Expand Down Expand Up @@ -275,7 +277,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_);
Expand Down Expand Up @@ -3422,6 +3424,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"

This comment has been minimized.

Copy link
@addaleax

addaleax Aug 22, 2018

Member

@AndreasMadsen What does %2$u is the pid mean?

This comment has been minimized.

Copy link
@AndreasMadsen

AndreasMadsen Aug 23, 2018

Author Member

That is a leftover from an older version that used sprintf. I’m not sure why it is here. The last line looks like a merge bug.

" --track-heap-objects track heap object allocations for heap "
"snapshots\n"
" --prof-process process v8 profiler output generated\n"
Expand Down Expand Up @@ -3550,6 +3556,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",
Expand Down Expand Up @@ -3701,6 +3708,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) {
Expand Down
5 changes: 3 additions & 2 deletions src/tracing/agent.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
2 changes: 1 addition & 1 deletion src/tracing/agent.h
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@ class TracingController : public 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();

Expand Down
26 changes: 21 additions & 5 deletions src/tracing/node_trace_writer.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand Down
4 changes: 3 additions & 1 deletion src/tracing/node_trace_writer.h
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down
2 changes: 2 additions & 0 deletions test/parallel/test-cli-node-options.js
Original file line number Diff line number Diff line change
Expand Up @@ -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');
Expand Down
30 changes: 30 additions & 0 deletions test/parallel/test-trace-events-file-pattern.js
Original file line number Diff line number Diff line change
@@ -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);
}));
}));

0 comments on commit 85212bb

Please sign in to comment.