From bcdd228f90b3e9e428b584814e7d52627616456a Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 7 Jan 2019 11:36:35 -0800 Subject: perf_hooks: implement histogram based api Add a sampling-based event loop delay monitor. ```js const { monitorEventLoopDelay } = require('perf_hooks'); const h = monitorEventLoopDelay(); h.enable(); h.disable(); console.log(h.percentiles); console.log(h.min); console.log(h.max); console.log(h.mean); console.log(h.stddev); console.log(h.percentile(50)); ``` PR-URL: https://github.com/nodejs/node/pull/25378 Reviewed-By: Matteo Collina Reviewed-By: Gireesh Punathil Reviewed-By: Stephen Belanger Reviewed-By: Richard Lau Reviewed-By: Anna Henningsen --- src/histogram-inl.h | 63 ++++++++++++++++++ src/histogram.h | 38 +++++++++++ src/node_perf.cc | 186 ++++++++++++++++++++++++++++++++++++++++++++++++++++ src/node_perf.h | 36 ++++++++++ 4 files changed, 323 insertions(+) create mode 100644 src/histogram-inl.h create mode 100644 src/histogram.h (limited to 'src') diff --git a/src/histogram-inl.h b/src/histogram-inl.h new file mode 100644 index 0000000000..3135041f73 --- /dev/null +++ b/src/histogram-inl.h @@ -0,0 +1,63 @@ +#ifndef SRC_HISTOGRAM_INL_H_ +#define SRC_HISTOGRAM_INL_H_ + +#if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS + +#include "histogram.h" +#include "node_internals.h" + +namespace node { + +inline Histogram::Histogram(int64_t lowest, int64_t highest, int figures) { + CHECK_EQ(0, hdr_init(lowest, highest, figures, &histogram_)); +} + +inline Histogram::~Histogram() { + hdr_close(histogram_); +} + +inline void Histogram::Reset() { + hdr_reset(histogram_); +} + +inline bool Histogram::Record(int64_t value) { + return hdr_record_value(histogram_, value); +} + +inline int64_t Histogram::Min() { + return hdr_min(histogram_); +} + +inline int64_t Histogram::Max() { + return hdr_max(histogram_); +} + +inline double Histogram::Mean() { + return hdr_mean(histogram_); +} + +inline double Histogram::Stddev() { + return hdr_stddev(histogram_); +} + +inline double Histogram::Percentile(double percentile) { + CHECK_GT(percentile, 0); + CHECK_LE(percentile, 100); + return hdr_value_at_percentile(histogram_, percentile); +} + +inline void Histogram::Percentiles(std::function fn) { + hdr_iter iter; + hdr_iter_percentile_init(&iter, histogram_, 1); + while (hdr_iter_next(&iter)) { + double key = iter.specifics.percentiles.percentile; + double value = iter.value; + fn(key, value); + } +} + +} // namespace node + +#endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS + +#endif // SRC_HISTOGRAM_INL_H_ diff --git a/src/histogram.h b/src/histogram.h new file mode 100644 index 0000000000..eb94af5da2 --- /dev/null +++ b/src/histogram.h @@ -0,0 +1,38 @@ +#ifndef SRC_HISTOGRAM_H_ +#define SRC_HISTOGRAM_H_ + +#if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS + +#include "hdr_histogram.h" +#include +#include + +namespace node { + +class Histogram { + public: + inline Histogram(int64_t lowest, int64_t highest, int figures = 3); + inline virtual ~Histogram(); + + inline bool Record(int64_t value); + inline void Reset(); + 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); + + size_t GetMemorySize() const { + return hdr_get_memory_size(histogram_); + } + + private: + hdr_histogram* histogram_; +}; + +} // namespace node + +#endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS + +#endif // SRC_HISTOGRAM_H_ diff --git a/src/node_perf.cc b/src/node_perf.cc index 33dd1d2051..b9c0183a83 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -1,5 +1,10 @@ +#include "aliased_buffer.h" #include "node_internals.h" #include "node_perf.h" +#include "node_buffer.h" +#include "node_process.h" + +#include #ifdef __POSIX__ #include // gettimeofday @@ -20,6 +25,7 @@ using v8::HandleScope; using v8::Integer; using v8::Isolate; using v8::Local; +using v8::Map; using v8::MaybeLocal; using v8::Name; using v8::NewStringType; @@ -387,6 +393,168 @@ void Timerify(const FunctionCallbackInfo& args) { args.GetReturnValue().Set(wrap); } +// Event Loop Timing Histogram +namespace { +static void ELDHistogramMin(const FunctionCallbackInfo& args) { + ELDHistogram* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + double value = static_cast(histogram->Min()); + args.GetReturnValue().Set(value); +} + +static void ELDHistogramMax(const FunctionCallbackInfo& args) { + ELDHistogram* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + double value = static_cast(histogram->Max()); + args.GetReturnValue().Set(value); +} + +static void ELDHistogramMean(const FunctionCallbackInfo& args) { + ELDHistogram* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + args.GetReturnValue().Set(histogram->Mean()); +} + +static void ELDHistogramExceeds(const FunctionCallbackInfo& args) { + ELDHistogram* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + double value = static_cast(histogram->Exceeds()); + args.GetReturnValue().Set(value); +} + +static void ELDHistogramStddev(const FunctionCallbackInfo& args) { + ELDHistogram* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + args.GetReturnValue().Set(histogram->Stddev()); +} + +static void ELDHistogramPercentile(const FunctionCallbackInfo& args) { + ELDHistogram* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + CHECK(args[0]->IsNumber()); + double percentile = args[0].As()->Value(); + args.GetReturnValue().Set(histogram->Percentile(percentile)); +} + +static void ELDHistogramPercentiles(const FunctionCallbackInfo& args) { + Environment* env = Environment::GetCurrent(args); + ELDHistogram* 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(); + }); +} + +static void ELDHistogramEnable(const FunctionCallbackInfo& args) { + ELDHistogram* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + args.GetReturnValue().Set(histogram->Enable()); +} + +static void ELDHistogramDisable(const FunctionCallbackInfo& args) { + ELDHistogram* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + args.GetReturnValue().Set(histogram->Disable()); +} + +static void ELDHistogramReset(const FunctionCallbackInfo& args) { + ELDHistogram* histogram; + ASSIGN_OR_RETURN_UNWRAP(&histogram, args.Holder()); + histogram->ResetState(); +} + +static 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 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()); +} + +bool ELDHistogram::RecordDelta() { + uint64_t time = uv_hrtime(); + bool ret = true; + if (prev_ > 0) { + int64_t delta = time - prev_; + if (delta > 0) { + ret = Record(delta); + TRACE_COUNTER1(TRACING_CATEGORY_NODE2(perf, event_loop), + "delay", delta); + if (!ret) { + if (exceeds_ < 0xFFFFFFFF) + exceeds_++; + ProcessEmitWarning( + env(), + "Event loop delay exceeded 1 hour: %" PRId64 " nanoseconds", + delta); + } + } + } + prev_ = time; + return ret; +} + +bool ELDHistogram::Enable() { + if (enabled_) return false; + enabled_ = true; + uv_timer_start(timer_, + ELDHistogramDelayInterval, + resolution_, + resolution_); + uv_unref(reinterpret_cast(timer_)); + return true; +} + +bool ELDHistogram::Disable() { + if (!enabled_) return false; + enabled_ = false; + uv_timer_stop(timer_); + return true; +} void Initialize(Local target, Local unused, @@ -456,6 +624,24 @@ void Initialize(Local target, env->constants_string(), constants, attr).ToChecked(); + + Local eldh_classname = FIXED_ONE_BYTE_STRING(isolate, "ELDHistogram"); + Local eldh = + 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); + target->Set(context, eldh_classname, + eldh->GetFunction(env->context()).ToLocalChecked()).FromJust(); } } // namespace performance diff --git a/src/node_perf.h b/src/node_perf.h index e3ef69c0fb..a8e43dc347 100644 --- a/src/node_perf.h +++ b/src/node_perf.h @@ -7,6 +7,7 @@ #include "node_perf_common.h" #include "env.h" #include "base_object-inl.h" +#include "histogram-inl.h" #include "v8.h" #include "uv.h" @@ -124,6 +125,41 @@ class GCPerformanceEntry : public PerformanceEntry { PerformanceGCKind gckind_; }; +class ELDHistogram : public BaseObject, public Histogram { + public: + ELDHistogram(Environment* env, + Local wrap, + int32_t resolution); + + ~ELDHistogram() override; + + bool RecordDelta(); + bool Enable(); + bool Disable(); + void ResetState() { + Reset(); + exceeds_ = 0; + prev_ = 0; + } + int64_t Exceeds() { return exceeds_; } + + void MemoryInfo(MemoryTracker* tracker) const override { + tracker->TrackFieldWithSize("histogram", GetMemorySize()); + } + + 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_; +}; + } // namespace performance } // namespace node -- cgit v1.2.3