From 96cb4fb795808aa2774e842974aeb411c5d3dd94 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Tue, 6 Mar 2018 10:42:37 -0800 Subject: [PATCH] perf_hooks,trace_events: emit perf milestone trace events Emit the perf_hooks node timing milestones as trace events. PR-URL: https://github.com/nodejs/node/pull/19175 Reviewed-By: Anna Henningsen --- doc/api/tracing.md | 1 + src/env.cc | 17 +++---- src/node.cc | 6 ++- src/node_perf.cc | 16 ++++-- src/node_perf.h | 18 ++++--- src/node_perf_common.h | 9 ++-- test/parallel/test-trace-events-bootstrap.js | 53 ++++++++++++++++++++ 7 files changed, 92 insertions(+), 28 deletions(-) create mode 100644 test/parallel/test-trace-events-bootstrap.js diff --git a/doc/api/tracing.md b/doc/api/tracing.md index ef58eb72bac..b53197b8109 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -16,6 +16,7 @@ The available categories are: * `node` * `node.async_hooks` - Enables capture of detailed async_hooks trace data. +* `node.bootstrap` - Enables capture of Node.js bootstrap milestones. * `node.perf` - Enables capture of [Performance API] measurements. * `node.perf.usertiming` - Enables capture of only Performance API User Timing measures and marks. diff --git a/src/env.cc b/src/env.cc index 3d1e5d3ac1e..c876103972f 100644 --- a/src/env.cc +++ b/src/env.cc @@ -115,15 +115,14 @@ Environment::Environment(IsolateData* isolate_data, destroy_async_id_list_.reserve(512); performance_state_.reset(new performance::performance_state(isolate())); - performance_state_->milestones[ - performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT] = - PERFORMANCE_NOW(); - performance_state_->milestones[ - performance::NODE_PERFORMANCE_MILESTONE_NODE_START] = - performance::performance_node_start; - performance_state_->milestones[ - performance::NODE_PERFORMANCE_MILESTONE_V8_START] = - performance::performance_v8_start; + performance_state_->Mark( + performance::NODE_PERFORMANCE_MILESTONE_ENVIRONMENT); + performance_state_->Mark( + performance::NODE_PERFORMANCE_MILESTONE_NODE_START, + performance::performance_node_start); + performance_state_->Mark( + performance::NODE_PERFORMANCE_MILESTONE_V8_START, + performance::performance_v8_start); // By default, always abort when --abort-on-uncaught-exception was passed. should_abort_on_uncaught_toggle_[0] = 1; diff --git a/src/node.cc b/src/node.cc index 4833ef0fd15..e7dd6669347 100644 --- a/src/node.cc +++ b/src/node.cc @@ -4474,7 +4474,8 @@ inline int Start(Isolate* isolate, IsolateData* isolate_data, { SealHandleScope seal(isolate); bool more; - PERFORMANCE_MARK(&env, LOOP_START); + env.performance_state()->Mark( + node::performance::NODE_PERFORMANCE_MILESTONE_LOOP_START); do { uv_run(env.event_loop(), UV_RUN_DEFAULT); @@ -4490,7 +4491,8 @@ inline int Start(Isolate* isolate, IsolateData* isolate_data, // event, or after running some callbacks. more = uv_loop_alive(env.event_loop()); } while (more == true); - PERFORMANCE_MARK(&env, LOOP_EXIT); + env.performance_state()->Mark( + node::performance::NODE_PERFORMANCE_MILESTONE_LOOP_EXIT); } env.set_trace_sync_io(false); diff --git a/src/node_perf.cc b/src/node_perf.cc index 8260d78c329..8b476890e19 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -40,6 +40,15 @@ uint64_t performance_v8_start; uint64_t performance_last_gc_start_mark_ = 0; v8::GCType performance_last_gc_type_ = v8::GCType::kGCTypeAll; +void performance_state::Mark(enum PerformanceMilestone milestone, + uint64_t ts) { + this->milestones[milestone] = ts; + TRACE_EVENT_INSTANT_WITH_TIMESTAMP0( + TRACING_CATEGORY_NODE1(bootstrap), + GetPerformanceMilestoneName(milestone), + TRACE_EVENT_SCOPE_THREAD, ts); +} + double GetCurrentTimeInMicroseconds() { #ifdef _WIN32 // The difference between the Unix Epoch and the Windows Epoch in 100-ns ticks. @@ -200,14 +209,11 @@ void Measure(const FunctionCallbackInfo& args) { void MarkMilestone(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); Local context = env->context(); - AliasedBuffer& milestones = - env->performance_state()->milestones; PerformanceMilestone milestone = static_cast( args[0]->Int32Value(context).ToChecked()); - if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) { - milestones[milestone] = PERFORMANCE_NOW(); - } + if (milestone != NODE_PERFORMANCE_MILESTONE_INVALID) + env->performance_state()->Mark(milestone); } diff --git a/src/node_perf.h b/src/node_perf.h index 0db99acd03e..703ef81ce48 100644 --- a/src/node_perf.h +++ b/src/node_perf.h @@ -27,6 +27,18 @@ extern const uint64_t timeOrigin; double GetCurrentTimeInMicroseconds(); +static inline const char* GetPerformanceMilestoneName( + enum PerformanceMilestone milestone) { + switch (milestone) { +#define V(name, label) case NODE_PERFORMANCE_MILESTONE_##name: return label; + NODE_PERFORMANCE_MILESTONES(V) +#undef V + default: + UNREACHABLE(); + return 0; + } +} + static inline PerformanceMilestone ToPerformanceMilestoneEnum(const char* str) { #define V(name, label) \ if (strcmp(str, label) == 0) return NODE_PERFORMANCE_MILESTONE_##name; @@ -44,12 +56,6 @@ static inline PerformanceEntryType ToPerformanceEntryTypeEnum( return NODE_PERFORMANCE_ENTRY_TYPE_INVALID; } -NODE_EXTERN inline void MarkPerformanceMilestone( - Environment* env, - PerformanceMilestone milestone) { - env->performance_state()->milestones[milestone] = PERFORMANCE_NOW(); -} - class PerformanceEntry { public: static void Notify(Environment* env, diff --git a/src/node_perf_common.h b/src/node_perf_common.h index 7ff57359ba5..9754e1e66f3 100644 --- a/src/node_perf_common.h +++ b/src/node_perf_common.h @@ -56,12 +56,6 @@ enum PerformanceEntryType { NODE_PERFORMANCE_ENTRY_TYPE_INVALID }; -#define PERFORMANCE_MARK(env, n) \ - do { \ - node::performance::MarkPerformanceMilestone(env, \ - node::performance::NODE_PERFORMANCE_MILESTONE_##n); \ - } while (0); - class performance_state { public: explicit performance_state(v8::Isolate* isolate) : @@ -86,6 +80,9 @@ class performance_state { AliasedBuffer milestones; AliasedBuffer observers; + void Mark(enum PerformanceMilestone milestone, + uint64_t ts = PERFORMANCE_NOW()); + private: struct performance_state_internal { // doubles first so that they are always sizeof(double)-aligned diff --git a/test/parallel/test-trace-events-bootstrap.js b/test/parallel/test-trace-events-bootstrap.js new file mode 100644 index 00000000000..6693291664e --- /dev/null +++ b/test/parallel/test-trace-events-bootstrap.js @@ -0,0 +1,53 @@ +'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'); + +const names = [ + 'environment', + 'nodeStart', + 'v8Start', + 'loopStart', + 'loopExit', + 'bootstrapComplete', + 'thirdPartyMainStart', + 'thirdPartyMainEnd', + 'clusterSetupStart', + 'clusterSetupEnd', + 'moduleLoadStart', + 'moduleLoadEnd', + 'preloadModulesLoadStart', + 'preloadModulesLoadEnd' +]; + +if (process.argv[2] === 'child') { + 1 + 1; +} else { + tmpdir.refresh(); + process.chdir(tmpdir.path); + + const proc = cp.fork(__filename, + [ 'child' ], { + execArgv: [ + '--trace-events-enabled', + '--trace-event-categories', + 'node.bootstrap' + ] + }); + + 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; + traces.forEach((trace) => { + assert.strictEqual(trace.pid, proc.pid); + assert(names.includes(trace.name)); + }); + })); + })); +}