From f4d1802ea8489e54bb0dd8088becb31ca12a7d75 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Sat, 9 Mar 2019 17:34:15 +0000 Subject: [PATCH] perf_hooks: add reqwrap latency monitor Adds a histogram that tracks ReqWrap latency (defined as the length of time it takes from when the reqwrap is dispatched to when the callback is invoked) --- doc/api/perf_hooks.md | 244 ++++++++++------- doc/api/tracing.md | 10 +- lib/perf_hooks.js | 27 +- src/env-inl.h | 1 + src/env.cc | 20 ++ src/env.h | 12 + src/histogram-inl.h | 106 ++++++- src/histogram.h | 55 ++++ src/node_perf.cc | 259 +++++++++++------- src/node_perf.h | 72 +++-- src/req_wrap-inl.h | 6 + src/req_wrap.h | 1 + .../test-performance-eventloopdelay.js | 1 + .../test-performance-reqwraplatency.js | 107 ++++++++ 14 files changed, 709 insertions(+), 212 deletions(-) create mode 100644 test/sequential/test-performance-reqwraplatency.js diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index 687cdae3aa3244..13f23885701af3 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -4,10 +4,11 @@ > Stability: 1 - Experimental -The Performance Timing API provides an implementation of the -[W3C Performance Timeline][] specification. The purpose of the API -is to support collection of high resolution performance metrics. -This is the same Performance API as implemented in modern Web browsers. +The `perf_hooks` module provides an implementation of the Performance +Timing API based on the [W3C Performance Timeline][] specification, as +well as several other performance and timing diagnostic functions. The +purpose of the API is to support collection of high resolution performance +metrics. ```js const { PerformanceObserver, performance } = require('perf_hooks'); @@ -25,6 +26,113 @@ doSomeLongRunningProcess(() => { }); ``` +## Class: Histogram + +The `Histogram` class is returned by several `perf_hooks` APIs including +`perf_hooks.monitorEventLoopDelay()` and `perf_hooks.monitorRequestWrapLatency()`. + +### histogram.count + + +* {number} + +The total number of sample values recorded. + +### histogram.disable() + + +* Returns: {boolean} + +Disables the histogram tracking. Returns `true` if the tracking was +disabled, `false` if it was already disabled. + +### histogram.enable() + + +* Returns: {boolean} + +Enables the histogram tracking. Returns `true` if the tracking was +enabled, `false` if it was already enabled. + +### histogram.exceeds + + +* {number} + +The number of times the sample value exceeded the maximum. + +### histogram.max + + +* {number} + +The maximum recorded sample value. + +### histogram.mean + + +* {number} + +The mean of the recorded sample value. + +### histogram.min + + +* {number} + +The minimum recorded sample value. + +### histogram.percentile(percentile) + + +* `percentile` {number} A percentile value between 1 and 100. +* Returns: {number} + +Returns the value at the given percentile. + +### histogram.percentiles + + +* {Map} + +Returns a `Map` object detailing the accumulated percentile distribution. + +### histogram.reset() + + +Resets the collected histogram data. + +### histogram.stddev + + +* {number} + +The standard deviation of the recorded sample values. + ## Class: Performance -Tracks the event loop delay at a given sampling rate. +The maximum event loop delay that can be recorded is one hour. Values above +that limit are dropped. The number of dropped values is reported by the +`histogram.exceeds` property. -#### histogram.disable() +## perf_hooks.monitorRequestWrapLatency([options]) - -* Returns: {boolean} - -Disables the event loop delay sample timer. Returns `true` if the timer was -stopped, `false` if it was already stopped. - -#### histogram.enable() - -* Returns: {boolean} - -Enables the event loop delay sample timer. Returns `true` if the timer was -started, `false` if it was already started. - -#### histogram.exceeds - - -* {number} - -The number of times the event loop delay exceeded the maximum 1 hour event -loop delay threshold. - -#### histogram.max - - -* {number} - -The maximum recorded event loop delay. - -#### histogram.mean - - -* {number} - -The mean of the recorded event loop delays. - -#### histogram.min - - -* {number} - -The minimum recorded event loop delay. - -#### histogram.percentile(percentile) - - -* `percentile` {number} A percentile value between 1 and 100. -* Returns: {number} - -Returns the value at the given percentile. - -#### histogram.percentiles - - -* {Map} - -Returns a `Map` object detailing the accumulated percentile distribution. - -#### histogram.reset() - +* `options` {Object} + * `types` {string[]} A list of [async_hook types][] to include in the + histogram samples. If not specified, the histogram will record + values for all ReqWrap types. +* Returns: {Histogram} -Resets the collected histogram data. +Returns a `Histogram` object that reports the latency of libuv +request handles. A request handle is an async resource within +Node.js that tracks the state of an individual asynchronous +operation (e.g. a file read, a DNS lookup, etc). The latency +of a request is the length of time from when the request is +passed off to the event loop to when the corresponding callback +is invoked. -#### histogram.stddev - +The histogram effectively measures how long the event loop is +taking to perform and resolve individual asynchronous operations, +without differentiating between the types of operations +measured. -* {number} +```js +const { monitorRequestWrapLatency } = require('perf_hooks'); +const h = monitorRequestWrapLatency(); +h.enable(); +// Do something. +h.disable(); +console.log(h.min); +console.log(h.max); +console.log(h.mean); +console.log(h.stddev); +console.log(h.percentiles); +console.log(h.percentile(50)); +console.log(h.percentile(99)); +``` -The standard deviation of the recorded event loop delays. +The maximum latency that can be recorded is one hour. Values above +that limit are dropped. The number of dropped values is reported by the +`histogram.exceeds` property. ## Examples @@ -612,3 +669,4 @@ require('some-module'); [`timeOrigin`]: https://w3c.github.io/hr-time/#dom-performance-timeorigin [Async Hooks]: async_hooks.html [W3C Performance Timeline]: https://w3c.github.io/performance-timeline/ +[async_hook types]: async_hooks.html#async_hooks_type diff --git a/doc/api/tracing.md b/doc/api/tracing.md index e09455d6437b73..7c37dda6d5a5c9 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -23,18 +23,20 @@ The available categories are: * `node.environment` - Enables capture of Node.js Environment milestones. * `node.fs.sync` - Enables capture of trace data for file system sync methods. * `node.perf` - Enables capture of [Performance API] measurements. - * `node.perf.usertiming` - Enables capture of only Performance API User Timing - measures and marks. + * `node.perf.event_loop` - Enables capture of event loop delay information + when the `perf_hooks.monitorEventLoopDelay()` API is used. + * `node.perf.reqwrap` - Enables capture of ReqWrap Latency information when + the `perf_hooks.monitorRequestWrapLatency()` API is used. * `node.perf.timerify` - Enables capture of only Performance API timerify measurements. + * `node.perf.usertiming` - Enables capture of only Performance API User Timing + measures and marks. * `node.promises.rejections` - Enables capture of trace data tracking the number of unhandled Promise rejections and handled-after-rejections. * `node.vm.script` - Enables capture of trace data for the `vm` module's `runInNewContext()`, `runInContext()`, and `runInThisContext()` methods. * `v8` - The [V8] events are GC, compiling, and execution related. -By default the `node`, `node.async_hooks`, and `v8` categories are enabled. - ```txt node --trace-event-categories v8,node,node.async_hooks server.js ``` diff --git a/lib/perf_hooks.js b/lib/perf_hooks.js index b1d634bf3c632f..24631ab3d2cc20 100644 --- a/lib/perf_hooks.js +++ b/lib/perf_hooks.js @@ -1,7 +1,8 @@ 'use strict'; const { - ELDHistogram: _ELDHistogram, + ELDHistogram, + RWLHistogram, PerformanceEntry, mark: _mark, clearMark: _clearMark, @@ -548,7 +549,7 @@ function sortedInsert(list, entry) { list.splice(location, 0, entry); } -class ELDHistogram { +class Histogram { constructor(handle) { this[kHandle] = handle; this[kMap] = new Map(); @@ -558,6 +559,7 @@ class ELDHistogram { enable() { return this[kHandle].enable(); } disable() { return this[kHandle].disable(); } + get count() { return this[kHandle].count(); } get exceeds() { return this[kHandle].exceeds(); } get min() { return this[kHandle].min(); } get max() { return this[kHandle].max(); } @@ -588,7 +590,8 @@ class ELDHistogram { mean: this.mean, stddev: this.stddev, percentiles: this.percentiles, - exceeds: this.exceeds + exceeds: this.exceeds, + count: this.count }; } } @@ -608,13 +611,27 @@ function monitorEventLoopDelay(options = {}) { const errors = lazyErrors(); throw new errors.ERR_INVALID_OPT_VALUE.RangeError('resolution', resolution); } - return new ELDHistogram(new _ELDHistogram(resolution)); + return new Histogram(new ELDHistogram(resolution)); +} + +function monitorRequestWrapLatency(options = {}) { + if (typeof options !== 'object' || options === null) { + const errors = lazyErrors(); + throw new errors.ERR_INVALID_ARG_TYPE('options', 'Object', options); + } + const { types } = options; + if (types === null || (types && !Array.isArray(types))) { + const errors = lazyErrors(); + throw new errors.ERR_INVALID_ARG_TYPE('options.types', 'string[]', types); + } + return new Histogram(new RWLHistogram(types)); } module.exports = { performance, PerformanceObserver, - monitorEventLoopDelay + monitorEventLoopDelay, + monitorRequestWrapLatency, }; Object.defineProperty(module.exports, 'constants', { diff --git a/src/env-inl.h b/src/env-inl.h index 2a560f71d24bc1..266c2e8392fdde 100644 --- a/src/env-inl.h +++ b/src/env-inl.h @@ -33,6 +33,7 @@ #include "node_perf_common.h" #include "node_context_data.h" #include "node_worker.h" +#include "histogram-inl.h" #include #include diff --git a/src/env.cc b/src/env.cc index bd44480184bc4a..c4b5d0a043f3b8 100644 --- a/src/env.cc +++ b/src/env.cc @@ -942,6 +942,26 @@ char* Environment::Reallocate(char* data, size_t old_size, size_t size) { return new_data; } +void Environment::add_req_wrap_listener(ReqWrapHistogram* listener) { + req_wrap_listeners_.insert(listener); +} + +void Environment::remove_req_wrap_listener(ReqWrapHistogram* listener) { + req_wrap_listeners_.erase(listener); +} + +void Environment::record_req_wrap_latency(int type, uint64_t start_time) { + auto delta = uv_hrtime() - start_time; + for (auto listener : req_wrap_listeners_) { + listener->Record(type, delta); + } +} + +bool Environment::req_wrap_latency_enabled() { + return !req_wrap_listeners_.empty(); +} + + // Not really any better place than env.cc at this moment. void BaseObject::DeleteMe(void* data) { BaseObject* self = static_cast(data); diff --git a/src/env.h b/src/env.h index 5ab3e1baf33223..2adf7cd8281633 100644 --- a/src/env.h +++ b/src/env.h @@ -463,6 +463,11 @@ struct CompileFnEntry { CompileFnEntry(Environment* env, uint32_t id); }; +class ReqWrapHistogram { + public: + virtual void Record(int type, int64_t delta) = 0; +}; + // Listing the AsyncWrap provider types first enables us to cast directly // from a provider type to a debug category. #define DEBUG_CATEGORY_NAMES(V) \ @@ -814,6 +819,11 @@ class Environment { inline performance::performance_state* performance_state(); inline std::unordered_map* performance_marks(); + void add_req_wrap_listener(ReqWrapHistogram* listener); + void remove_req_wrap_listener(ReqWrapHistogram* listener); + void record_req_wrap_latency(int type, uint64_t start_time); + bool req_wrap_latency_enabled(); + void CollectUVExceptionInfo(v8::Local context, int errorno, const char* syscall = nullptr, @@ -1124,6 +1134,8 @@ class Environment { worker::Worker* worker_context_ = nullptr; + std::unordered_set req_wrap_listeners_; + static void RunTimers(uv_timer_t* handle); struct ExitCallback { diff --git a/src/histogram-inl.h b/src/histogram-inl.h index 3135041f7387a9..694aac926cd0aa 100644 --- a/src/histogram-inl.h +++ b/src/histogram-inl.h @@ -5,10 +5,80 @@ #include "histogram.h" #include "node_internals.h" +#include "env-inl.h" +#include "v8.h" namespace node { -inline Histogram::Histogram(int64_t lowest, int64_t highest, int figures) { +using v8::FunctionCallbackInfo; +using v8::Local; +using v8::Map; +using v8::Number; +using v8::Value; + +inline void Histogram::GetMin( + Histogram* histogram, + const FunctionCallbackInfo& args) { + double value = static_cast(histogram->Min()); + args.GetReturnValue().Set(value); +} + +inline void Histogram::GetMax( + Histogram* histogram, + const FunctionCallbackInfo& args) { + double value = static_cast(histogram->Max()); + args.GetReturnValue().Set(value); +} + +inline void Histogram::GetMean( + Histogram* histogram, + const FunctionCallbackInfo& args) { + args.GetReturnValue().Set(histogram->Mean()); +} + +inline void Histogram::GetExceeds( + Histogram* histogram, + const FunctionCallbackInfo& args) { + double value = static_cast(histogram->Exceeds()); + args.GetReturnValue().Set(value); +} + +inline void Histogram::GetCount( + Histogram* histogram, + const FunctionCallbackInfo& args) { + double value = static_cast(histogram->Count()); + args.GetReturnValue().Set(value); +} + +inline void Histogram::GetStddev( + Histogram* histogram, + const FunctionCallbackInfo& args) { + args.GetReturnValue().Set(histogram->Stddev()); +} + +inline void Histogram::GetPercentile( + Histogram* histogram, + const FunctionCallbackInfo& args) { + CHECK(args[0]->IsNumber()); + double percentile = args[0].As()->Value(); + args.GetReturnValue().Set(histogram->Percentile(percentile)); +} + +inline void Histogram::GetPercentiles( + Histogram* histogram, + const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + CHECK(args[0]->IsMap()); + Local map = args[0].As(); + histogram->Percentiles([&](double key, double value) { + map->Set(env->context(), + Number::New(env->isolate(), key), + Number::New(env->isolate(), value)).IsEmpty(); + }); +} + +inline Histogram::Histogram(int64_t lowest, int64_t highest, int figures) : + exceeds_(0), count_(0) { CHECK_EQ(0, hdr_init(lowest, highest, figures, &histogram_)); } @@ -18,10 +88,25 @@ inline Histogram::~Histogram() { inline void Histogram::Reset() { hdr_reset(histogram_); + exceeds_ = 0; + count_ = 0; } inline bool Histogram::Record(int64_t value) { - return hdr_record_value(histogram_, value); + bool ret = hdr_record_value(histogram_, value); + if (!ret && exceeds_ < 0xFFFFFFFF) + exceeds_++; + if (count_ < 0xFFFFFFFF) + count_++; + return ret; +} + +inline int64_t Histogram::Exceeds() { + return exceeds_; +} + +inline int64_t Histogram::Count() { + return count_; } inline int64_t Histogram::Min() { @@ -56,6 +141,23 @@ inline void Histogram::Percentiles(std::function fn) { } } +inline void Histogram::DumpToTracedValue(tracing::TracedValue* value) { + value->SetDouble("min", static_cast(Min())); + value->SetDouble("max", static_cast(Max())); + value->SetDouble("mean", static_cast(Mean())); + value->SetDouble("stddev", static_cast(Stddev())); + value->SetDouble("exceeds", static_cast(Exceeds())); + value->SetDouble("count", static_cast(Count())); + value->BeginArray("percentiles"); + Percentiles([&](double key, double val) { + value->BeginArray(); + value->AppendDouble(key); + value->AppendDouble(val); + value->EndArray(); + }); + value->EndArray(); +} + } // namespace node #endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS diff --git a/src/histogram.h b/src/histogram.h index eb94af5da2a997..2680a36790f5d4 100644 --- a/src/histogram.h +++ b/src/histogram.h @@ -3,7 +3,11 @@ #if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS +#include "env.h" #include "hdr_histogram.h" +#include "tracing/traced_value.h" +#include "v8.h" + #include #include @@ -16,21 +20,72 @@ class Histogram { inline bool Record(int64_t value); inline void Reset(); + inline int64_t Count(); inline int64_t Min(); inline int64_t Max(); inline double Mean(); inline double Stddev(); inline double Percentile(double percentile); inline void Percentiles(std::function fn); + inline int64_t Exceeds(); size_t GetMemorySize() const { return hdr_get_memory_size(histogram_); } + inline void DumpToTracedValue(tracing::TracedValue* value); + + static inline void GetCount( + Histogram* histogram, + const v8::FunctionCallbackInfo& args); + + static inline void GetMin( + Histogram* histogram, + const v8::FunctionCallbackInfo& args); + + static inline void GetMax( + Histogram* histogram, + const v8::FunctionCallbackInfo& args); + + static inline void GetMean( + Histogram* histogram, + const v8::FunctionCallbackInfo& args); + + static inline void GetExceeds( + Histogram* histogram, + const v8::FunctionCallbackInfo& args); + + static inline void GetStddev( + Histogram* histogram, + const v8::FunctionCallbackInfo& args); + + static inline void GetPercentile( + Histogram* histogram, + const v8::FunctionCallbackInfo& args); + + static inline void GetPercentiles( + Histogram* histogram, + const v8::FunctionCallbackInfo& args); + private: hdr_histogram* histogram_; + int64_t exceeds_; + int64_t count_; }; +#define HISTOGRAM_FNS(V) \ + V(exceeds, Exceeds) \ + V(count, Count) \ + V(min, Min) \ + V(max, Max) \ + V(mean, Mean) \ + V(stddev, Stddev) \ + V(percentile, Percentile) \ + V(percentiles, Percentiles) \ + V(enable, Enable) \ + V(disable, Disable) \ + V(reset, Reset) + } // namespace node #endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS diff --git a/src/node_perf.cc b/src/node_perf.cc index e16be29a872f80..56dac9f1cb0060 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -3,6 +3,7 @@ #include "node_perf.h" #include "node_buffer.h" #include "node_process.h" +#include "async_wrap-inl.h" #include @@ -25,7 +26,6 @@ using v8::HandleScope; using v8::Integer; using v8::Isolate; using v8::Local; -using v8::Map; using v8::MaybeLocal; using v8::Name; using v8::NewStringType; @@ -391,128 +391,125 @@ void Timerify(const FunctionCallbackInfo& args) { args.GetReturnValue().Set(wrap); } -// Event Loop Timing Histogram + namespace { -static void ELDHistogramMin(const FunctionCallbackInfo& args) { - ELDHistogram* histogram; +void HistogramMin(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); - double value = static_cast(histogram->Min()); - args.GetReturnValue().Set(value); + Histogram::GetMin(histogram, args); } -static void ELDHistogramMax(const FunctionCallbackInfo& args) { - ELDHistogram* histogram; +void HistogramMax(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); - double value = static_cast(histogram->Max()); - args.GetReturnValue().Set(value); + Histogram::GetMax(histogram, args); } -static void ELDHistogramMean(const FunctionCallbackInfo& args) { - ELDHistogram* histogram; +void HistogramMean(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); - args.GetReturnValue().Set(histogram->Mean()); + Histogram::GetMean(histogram, args); } -static void ELDHistogramExceeds(const FunctionCallbackInfo& args) { - ELDHistogram* histogram; +void HistogramCount(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); - double value = static_cast(histogram->Exceeds()); - args.GetReturnValue().Set(value); + Histogram::GetCount(histogram, args); } -static void ELDHistogramStddev(const FunctionCallbackInfo& args) { - ELDHistogram* histogram; +void HistogramExceeds(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); - args.GetReturnValue().Set(histogram->Stddev()); + Histogram::GetExceeds(histogram, args); } -static void ELDHistogramPercentile(const FunctionCallbackInfo& args) { - ELDHistogram* histogram; +void HistogramStddev(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); - CHECK(args[0]->IsNumber()); - double percentile = args[0].As()->Value(); - args.GetReturnValue().Set(histogram->Percentile(percentile)); + Histogram::GetStddev(histogram, args); } -static void ELDHistogramPercentiles(const FunctionCallbackInfo& args) { - Environment* env = Environment::GetCurrent(args); - ELDHistogram* histogram; +void HistogramPercentile(const FunctionCallbackInfo& args) { + HistogramBase* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + Histogram::GetPercentile(histogram, args); +} + +void HistogramPercentiles(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); - CHECK(args[0]->IsMap()); - Local map = args[0].As(); - histogram->Percentiles([&](double key, double value) { - map->Set(env->context(), - Number::New(env->isolate(), key), - Number::New(env->isolate(), value)).IsEmpty(); - }); + Histogram::GetPercentiles(histogram, args); } -static void ELDHistogramEnable(const FunctionCallbackInfo& args) { - ELDHistogram* histogram; +void HistogramEnable(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); args.GetReturnValue().Set(histogram->Enable()); } -static void ELDHistogramDisable(const FunctionCallbackInfo& args) { - ELDHistogram* histogram; +void HistogramDisable(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); args.GetReturnValue().Set(histogram->Disable()); } -static void ELDHistogramReset(const FunctionCallbackInfo& args) { - ELDHistogram* histogram; +void HistogramReset(const FunctionCallbackInfo& args) { + HistogramBase* histogram; ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); histogram->ResetState(); } -static void ELDHistogramNew(const FunctionCallbackInfo& args) { +void ELDHistogramNew(const FunctionCallbackInfo& args) { Environment* env = Environment::GetCurrent(args); CHECK(args.IsConstructCall()); int32_t resolution = args[0]->IntegerValue(env->context()).FromJust(); CHECK_GT(resolution, 0); new ELDHistogram(env, args.This(), resolution); } -} // namespace - -ELDHistogram::ELDHistogram( - Environment* env, - Local wrap, - int32_t resolution) : BaseObject(env, wrap), - Histogram(1, 3.6e12), - resolution_(resolution) { - MakeWeak(); - timer_ = new uv_timer_t(); - uv_timer_init(env->event_loop(), timer_); - timer_->data = this; -} - -void ELDHistogram::CloseTimer() { - if (timer_ == nullptr) - return; - - env()->CloseHandle(timer_, [](uv_timer_t* handle) { delete handle; }); - timer_ = nullptr; -} -ELDHistogram::~ELDHistogram() { - Disable(); - CloseTimer(); +void RWLHistogramNew(const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + CHECK(args.IsConstructCall()); + RWLHistogram* ret = new RWLHistogram(env, args.This()); + ret->SetTypes(args[0]); } void ELDHistogramDelayInterval(uv_timer_t* req) { ELDHistogram* histogram = reinterpret_cast(req->data); histogram->RecordDelta(); - TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), - "min", histogram->Min()); - TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), - "max", histogram->Max()); - TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), - "mean", histogram->Mean()); - TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), - "stddev", histogram->Stddev()); + if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( + TRACING_CATEGORY_NODE2(perf, event_loop)) != 0) { + auto value = tracing::TracedValue::Create(); + histogram->DumpToTracedValue(value.get()); + TRACE_EVENT_INSTANT1(TRACING_CATEGORY_NODE2(perf, event_loop), + "EventLoopDelay", + TRACE_EVENT_SCOPE_THREAD, + "histogram", + std::move(value)); + } } +} // namespace + +HistogramBase::HistogramBase( + Environment* env, + Local wrap, + int64_t lowest, + int64_t highest, + int figures) : + BaseObject(env, wrap), + Histogram(lowest, highest, figures) { + MakeWeak(); +} + +ELDHistogram::ELDHistogram( + Environment* env, + Local wrap, + int32_t resolution) : HistogramBase(env, wrap, 1, 3.6e12), + resolution_(resolution), + timer_(nullptr) {} + bool ELDHistogram::RecordDelta() { uint64_t time = uv_hrtime(); bool ret = true; @@ -521,10 +518,9 @@ bool ELDHistogram::RecordDelta() { if (delta > 0) { ret = Record(delta); TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), - "delay", delta); + "EventLoopDelay", + delta); if (!ret) { - if (exceeds_ < 0xFFFFFFFF) - exceeds_++; ProcessEmitWarning( env(), "Event loop delay exceeded 1 hour: %" PRId64 " nanoseconds", @@ -536,9 +532,22 @@ bool ELDHistogram::RecordDelta() { return ret; } +void ELDHistogram::Cleanup() { + if (timer_ == nullptr) + return; + env()->CloseHandle(timer_, [](uv_timer_t* handle) { delete handle; }); + timer_ = nullptr; +} + bool ELDHistogram::Enable() { - if (enabled_) return false; - enabled_ = true; + if (timer_ == nullptr) { + timer_ = new uv_timer_t(); + timer_->data = static_cast(this); + uv_timer_init(env()->event_loop(), timer_); + } else if (uv_is_active(reinterpret_cast(timer_))) { + // Timer is already running + return false; + } uv_timer_start(timer_, ELDHistogramDelayInterval, resolution_, @@ -548,12 +557,72 @@ bool ELDHistogram::Enable() { } bool ELDHistogram::Disable() { - if (!enabled_) return false; - enabled_ = false; - uv_timer_stop(timer_); + if (timer_ == nullptr) + return false; + Cleanup(); return true; } + +RWLHistogram::RWLHistogram( + Environment* env, + Local wrap) : HistogramBase(env, wrap, 1, 3.6e12), + providers_(0) {} + +bool RWLHistogram::Enable() { + if (!enabled_) { + enabled_ = true; + env()->add_req_wrap_listener(this); + return true; + } + return false; +} + +bool RWLHistogram::Disable() { + if (enabled_) { + enabled_ = false; + env()->remove_req_wrap_listener(this); + return true; + } + return false; +} + +void RWLHistogram::Record(int type, int64_t delta) { + if (!providers_[type]) + return; + Histogram::Record(delta); + if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( + TRACING_CATEGORY_NODE2(perf, reqwrap)) != 0) { + auto value = tracing::TracedValue::Create(); + DumpToTracedValue(value.get()); + TRACE_EVENT_INSTANT1(TRACING_CATEGORY_NODE2(perf, reqwrap), + "ReqWrapLatency", + TRACE_EVENT_SCOPE_THREAD, + "histogram", + std::move(value)); + } +} + +void RWLHistogram::SetTypes(Local names) { + if (names->IsArray()) { + Local array = names.As(); + uint32_t length = array->Length(); + for (uint32_t i = 0; i < length; ++i) { + Utf8Value name(env()->isolate(), + array->Get(env()->context(), i).ToLocalChecked()); +#define V(n) \ + if (strcmp(*name, #n) == 0) { \ + providers_.set(AsyncWrap::PROVIDER_ ## n); \ + } + NODE_ASYNC_PROVIDER_TYPES(V) +#undef V + } + } else if (names.IsEmpty() || names->IsUndefined()) { + for (uint32_t i = 0; i < AsyncWrap::PROVIDERS_LENGTH; i++) + providers_.set(i); + } +} + void Initialize(Local target, Local unused, Local context, @@ -628,18 +697,24 @@ void Initialize(Local target, env->NewFunctionTemplate(ELDHistogramNew); eldh->SetClassName(eldh_classname); eldh->InstanceTemplate()->SetInternalFieldCount(1); - env->SetProtoMethod(eldh, "exceeds", ELDHistogramExceeds); - env->SetProtoMethod(eldh, "min", ELDHistogramMin); - env->SetProtoMethod(eldh, "max", ELDHistogramMax); - env->SetProtoMethod(eldh, "mean", ELDHistogramMean); - env->SetProtoMethod(eldh, "stddev", ELDHistogramStddev); - env->SetProtoMethod(eldh, "percentile", ELDHistogramPercentile); - env->SetProtoMethod(eldh, "percentiles", ELDHistogramPercentiles); - env->SetProtoMethod(eldh, "enable", ELDHistogramEnable); - env->SetProtoMethod(eldh, "disable", ELDHistogramDisable); - env->SetProtoMethod(eldh, "reset", ELDHistogramReset); +#define SET_ELDH_FNS(name, fn) \ + env->SetProtoMethod(eldh, #name, Histogram##fn); + HISTOGRAM_FNS(SET_ELDH_FNS) +#undef SET_ELDH_FNS target->Set(context, eldh_classname, eldh->GetFunction(env->context()).ToLocalChecked()).FromJust(); + + Local rwlh_classname = FIXED_ONE_BYTE_STRING(isolate, "RWLHistogram"); + Local rwlh = + env->NewFunctionTemplate(RWLHistogramNew); + rwlh->SetClassName(rwlh_classname); + rwlh->InstanceTemplate()->SetInternalFieldCount(1); +#define SET_RWL_FNS(name, fn) \ + env->SetProtoMethod(rwlh, #name, Histogram##fn); + HISTOGRAM_FNS(SET_RWL_FNS) +#undef SET_RWL_FNS + target->Set(context, rwlh_classname, + rwlh->GetFunction(env->context()).ToLocalChecked()).FromJust(); } } // namespace performance diff --git a/src/node_perf.h b/src/node_perf.h index a8e43dc3476cc2..a61902011d3b22 100644 --- a/src/node_perf.h +++ b/src/node_perf.h @@ -8,10 +8,12 @@ #include "env.h" #include "base_object-inl.h" #include "histogram-inl.h" +#include "async_wrap.h" #include "v8.h" #include "uv.h" +#include #include namespace node { @@ -125,37 +127,75 @@ class GCPerformanceEntry : public PerformanceEntry { PerformanceGCKind gckind_; }; -class ELDHistogram : public BaseObject, public Histogram { +class HistogramBase : public BaseObject, + public Histogram { public: - ELDHistogram(Environment* env, - Local wrap, - int32_t resolution); + HistogramBase( + Environment* env, + Local wrap, + int64_t lowest, + int64_t highest, + int figures = 3); + virtual ~HistogramBase() { + Disable(); + } - ~ELDHistogram() override; + virtual void Cleanup() {} + virtual bool Enable() { + return false; + } - bool RecordDelta(); - bool Enable(); - bool Disable(); - void ResetState() { + virtual bool Disable() { + Cleanup(); + return false; + } + virtual void ResetState() { Reset(); - exceeds_ = 0; - prev_ = 0; } - int64_t Exceeds() { return exceeds_; } void MemoryInfo(MemoryTracker* tracker) const override { tracker->TrackFieldWithSize("histogram", GetMemorySize()); } +}; + +class RWLHistogram : public HistogramBase, + public ReqWrapHistogram { + public: + RWLHistogram(Environment* env, Local wrap); + + bool Enable() override; + bool Disable() override; + void Record(int type, int64_t delta) override; + void SetTypes(v8::Local names); + + SET_MEMORY_INFO_NAME(RWLHistogram) + SET_SELF_SIZE(RWLHistogram) + + private: + std::bitset providers_; + bool enabled_ = false; +}; + +class ELDHistogram : public HistogramBase { + public: + ELDHistogram(Environment* env, + Local wrap, + int32_t resolution); + + bool RecordDelta(); + void Cleanup() override; + bool Enable() override; + bool Disable() override; + void ResetState() override { + Reset(); + prev_ = 0; + } SET_MEMORY_INFO_NAME(ELDHistogram) SET_SELF_SIZE(ELDHistogram) private: - void CloseTimer(); - - bool enabled_ = false; int32_t resolution_ = 0; - int64_t exceeds_ = 0; uint64_t prev_ = 0; uv_timer_t* timer_; }; diff --git a/src/req_wrap-inl.h b/src/req_wrap-inl.h index 5fb965414838bb..f45ef21e3e1cc4 100644 --- a/src/req_wrap-inl.h +++ b/src/req_wrap-inl.h @@ -124,6 +124,10 @@ struct MakeLibuvRequestCallback { ReqWrap* req_wrap = ContainerOf(&ReqWrap::req_, req); req_wrap->env()->DecreaseWaitingRequestCounter(); F original_callback = reinterpret_cast(req_wrap->original_callback_); + if (req_wrap->env()->req_wrap_latency_enabled()) + req_wrap->env()->record_req_wrap_latency( + req_wrap->provider_type(), + req_wrap->start_timestamp_); original_callback(req, args...); } @@ -154,6 +158,8 @@ int ReqWrap::Dispatch(LibuvFunction fn, Args... args) { // | // Other (non-function) arguments are passed -----/ // through verbatim + if (env()->req_wrap_latency_enabled()) + start_timestamp_ = uv_hrtime(); int err = CallLibuvFunction::Call( fn, env()->event_loop(), diff --git a/src/req_wrap.h b/src/req_wrap.h index 890eb6cb61848c..ae0909b0aafd5b 100644 --- a/src/req_wrap.h +++ b/src/req_wrap.h @@ -66,6 +66,7 @@ class ReqWrap : public AsyncWrap, public ReqWrapBase { // req_. For more information please refer to // `doc/guides/node-postmortem-support.md` T req_; + uint64_t start_timestamp_; }; } // namespace node diff --git a/test/sequential/test-performance-eventloopdelay.js b/test/sequential/test-performance-eventloopdelay.js index 82f47b6fb29c47..d4802635c1901d 100644 --- a/test/sequential/test-performance-eventloopdelay.js +++ b/test/sequential/test-performance-eventloopdelay.js @@ -60,6 +60,7 @@ const { histogram.disable(); // The values are non-deterministic, so we just check that a value is // present, as opposed to a specific value. + assert(histogram.count > 0); assert(histogram.min > 0); assert(histogram.max > 0); assert(histogram.stddev > 0); diff --git a/test/sequential/test-performance-reqwraplatency.js b/test/sequential/test-performance-reqwraplatency.js new file mode 100644 index 00000000000000..31d6db5ffb95a5 --- /dev/null +++ b/test/sequential/test-performance-reqwraplatency.js @@ -0,0 +1,107 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const fs = require('fs'); +const { + monitorRequestWrapLatency +} = require('perf_hooks'); + +{ + const histogram = monitorRequestWrapLatency(); + assert(histogram); + assert(histogram.enable()); + assert(!histogram.enable()); + histogram.reset(); + assert(histogram.disable()); + assert(!histogram.disable()); +} + +{ + const histogram = monitorRequestWrapLatency(); + histogram.enable(); + let m = 5; + function spinAWhile() { + // do an async operation + fs.readFile(__filename, () => { /* We don't care about the results */ }); + common.busyLoop(1000); + if (--m > 0) { + setTimeout(spinAWhile, common.platformTimeout(500)); + } else { + histogram.disable(); + // The values are non-deterministic, so we just check that a value is + // present, as opposed to a specific value. + assert(histogram.count > 0); + assert(histogram.min > 0); + assert(histogram.max > 0); + assert(histogram.stddev > 0); + assert(histogram.mean > 0); + assert(histogram.percentiles.size > 0); + for (let n = 1; n < 100; n = n + 0.1) { + assert(histogram.percentile(n) >= 0); + } + histogram.reset(); + assert.strictEqual(histogram.min, 9223372036854776000); + assert.strictEqual(histogram.max, 0); + assert(Number.isNaN(histogram.stddev)); + assert(Number.isNaN(histogram.mean)); + assert.strictEqual(histogram.percentiles.size, 1); + + ['a', false, {}, []].forEach((i) => { + common.expectsError( + () => histogram.percentile(i), + { + type: TypeError, + code: 'ERR_INVALID_ARG_TYPE' + } + ); + }); + [-1, 0, 101].forEach((i) => { + common.expectsError( + () => histogram.percentile(i), + { + type: RangeError, + code: 'ERR_INVALID_ARG_VALUE' + } + ); + }); + } + } + spinAWhile(); +} + +{ + // Pick a AsyncWrap provider name that we won't use... + const histogram = monitorRequestWrapLatency({ + types: [ 'WRITEWRAP', 'not-a-real-value-wont-cause-an-error' ] + }); + histogram.enable(); + let m = 5; + function spinAWhile() { + // do an async operation + fs.readFile(__filename, () => { /* We don't care about the results */ }); + common.busyLoop(1000); + if (--m > 0) { + setTimeout(spinAWhile, common.platformTimeout(500)); + } else { + histogram.disable(); + assert.strictEqual(histogram.count, 0); + assert.strictEqual(histogram.min, 9223372036854776000); + assert.strictEqual(histogram.max, 0); + assert(Number.isNaN(histogram.stddev)); + assert(Number.isNaN(histogram.mean)); + assert.strictEqual(histogram.percentiles.size, 1); + } + } + spinAWhile(); +} + +[1, true, {}, 'test', null].forEach((i) => { + common.expectsError( + () => monitorRequestWrapLatency({ types: i }), + { + type: TypeError, + code: 'ERR_INVALID_ARG_TYPE' + } + ); +});