From 06aaaa8ad7d13e61306fd6d77a6e54375f617e46 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Tue, 19 Dec 2017 17:40:41 -0800 Subject: [PATCH] http2: perf_hooks integration Collect and report basic timing information about `Http2Session` and `Http2Stream` instances. Backport-PR-URL: https://github.com/nodejs/node/pull/18050 PR-URL: https://github.com/nodejs/node/pull/17906 Refs: https://github.com/nodejs/node/issues/17746 Reviewed-By: Matteo Collina --- doc/api/http2.md | 50 ++++++++++++ lib/perf_hooks.js | 5 +- src/node_http2.cc | 104 ++++++++++++++++++++++++- src/node_http2.h | 85 ++++++++++++++++++++ src/node_perf.cc | 6 +- src/node_perf.h | 6 +- src/node_perf_common.h | 3 +- test/parallel/test-http2-perf_hooks.js | 95 ++++++++++++++++++++++ 8 files changed, 343 insertions(+), 11 deletions(-) create mode 100644 test/parallel/test-http2-perf_hooks.js diff --git a/doc/api/http2.md b/doc/api/http2.md index d1c96ea0fd46a7..84552f052cab8e 100644 --- a/doc/api/http2.md +++ b/doc/api/http2.md @@ -2800,6 +2800,55 @@ given newly created [`Http2Stream`] on `Http2ServerRespose`. The callback will be called with an error with code `ERR_HTTP2_STREAM_CLOSED` if the stream is closed. +## Collecting HTTP/2 Performance Metrics + +The [Performance Observer][] API can be used to collect basic performance +metrics for each `Http2Session` and `Http2Stream` instance. + +```js +const { PerformanceObserver } = require('perf_hooks'); + +const obs = new PerformanceObserver((items) => { + const entry = items.getEntries()[0]; + console.log(entry.entryType); // prints 'http2' + if (entry.name === 'Http2Session') { + // entry contains statistics about the Http2Session + } else if (entry.name === 'Http2Stream') { + // entry contains statistics about the Http2Stream + } +}); +obs.observe({ entryTypes: ['http2'] }); +``` + +The `entryType` property of the `PerformanceEntry` will be equal to `'http2'`. + +The `name` property of the `PerformanceEntry` will be equal to either +`'Http2Stream'` or `'Http2Session'`. + +If `name` is equal to `Http2Stream`, the `PerformanceEntry` will contain the +following additional properties: + +* `timeToFirstByte` {number} The number of milliseconds elapsed between the + `PerformanceEntry` `startTime` and the reception of the first `DATA` frame. +* `timeToFirstHeader` {number} The number of milliseconds elapsed between the + `PerformanceEntry` `startTime` and the reception of the first header. + +If `name` is equal to `Http2Session`, the `PerformanceEntry` will contain the +following additional properties: + +* `pingRTT` {number} The number of milliseconds elapsed since the transmission + of a `PING` frame and the reception of its acknowledgement. Only present if + a `PING` frame has been sent on the `Http2Session`. +* `streamCount` {number} The number of `Http2Stream` instances processed by + the `Http2Session`. +* `streamAverageDuration` {number} The average duration (in milliseconds) for + all `Http2Stream` instances. +* `framesReceived` {number} The number of HTTP/2 frames received by the + `Http2Session`. +* `type` {string} Either `'server'` or `'client'` to identify the type of + `Http2Session`. + + [ALPN negotiation]: #http2_alpn_negotiation [Compatibility API]: #http2_compatibility_api [HTTP/1]: http.html @@ -2807,6 +2856,7 @@ if the stream is closed. [HTTPS]: https.html [Headers Object]: #http2_headers_object [Http2Session and Sockets]: #http2_http2session_and_sockets +[Performance Observer]: perf_hooks.html [Readable Stream]: stream.html#stream_class_stream_readable [Settings Object]: #http2_settings_object [Using options.selectPadding]: #http2_using_options_selectpadding diff --git a/lib/perf_hooks.js b/lib/perf_hooks.js index 4e7a0de7eb37be..7e1d085b525b44 100644 --- a/lib/perf_hooks.js +++ b/lib/perf_hooks.js @@ -18,6 +18,7 @@ const { NODE_PERFORMANCE_ENTRY_TYPE_MEASURE, NODE_PERFORMANCE_ENTRY_TYPE_GC, NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION, + NODE_PERFORMANCE_ENTRY_TYPE_HTTP2, NODE_PERFORMANCE_MILESTONE_NODE_START, NODE_PERFORMANCE_MILESTONE_V8_START, @@ -61,7 +62,8 @@ const observerableTypes = [ 'mark', 'measure', 'gc', - 'function' + 'function', + 'http2' ]; let errors; @@ -504,6 +506,7 @@ function mapTypes(i) { case 'measure': return NODE_PERFORMANCE_ENTRY_TYPE_MEASURE; case 'gc': return NODE_PERFORMANCE_ENTRY_TYPE_GC; case 'function': return NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION; + case 'http2': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP2; } } diff --git a/src/node_http2.cc b/src/node_http2.cc index 34c96b04e8c026..442fa64b6ca981 100644 --- a/src/node_http2.cc +++ b/src/node_http2.cc @@ -3,6 +3,7 @@ #include "node_buffer.h" #include "node_http2.h" #include "node_http2_state.h" +#include "node_perf.h" #include @@ -20,6 +21,7 @@ using v8::Uint32; using v8::Uint32Array; using v8::Undefined; +using node::performance::PerformanceEntry; namespace http2 { namespace { @@ -468,6 +470,7 @@ Http2Session::Http2Session(Environment* env, : AsyncWrap(env, wrap, AsyncWrap::PROVIDER_HTTP2SESSION), session_type_(type) { MakeWeak(this); + statistics_.start_time = uv_hrtime(); // Capture the configuration options for this session Http2Options opts(env); @@ -527,6 +530,86 @@ Http2Session::~Http2Session() { nghttp2_session_del(session_); } +inline bool HasHttp2Observer(Environment* env) { + uint32_t* observers = env->performance_state()->observers; + return observers[performance::NODE_PERFORMANCE_ENTRY_TYPE_HTTP2] != 0; +} + +inline void Http2Stream::EmitStatistics() { + if (!HasHttp2Observer(env())) + return; + Http2StreamPerformanceEntry* entry = + new Http2StreamPerformanceEntry(env(), statistics_); + env()->SetImmediate([](Environment* env, void* data) { + Local context = env->context(); + Http2StreamPerformanceEntry* entry = + static_cast(data); + if (HasHttp2Observer(env)) { + Local obj = entry->ToObject(); + v8::PropertyAttribute attr = + static_cast(v8::ReadOnly | v8::DontDelete); + obj->DefineOwnProperty( + context, + FIXED_ONE_BYTE_STRING(env->isolate(), "timeToFirstByte"), + Number::New(env->isolate(), + (entry->first_byte() - entry->startTimeNano()) / 1e6), + attr); + obj->DefineOwnProperty( + context, + FIXED_ONE_BYTE_STRING(env->isolate(), "timeToFirstHeader"), + Number::New(env->isolate(), + (entry->first_header() - entry->startTimeNano()) / 1e6), + attr); + entry->Notify(obj); + } + delete entry; + }, static_cast(entry)); +} + +inline void Http2Session::EmitStatistics() { + if (!HasHttp2Observer(env())) + return; + Http2SessionPerformanceEntry* entry = + new Http2SessionPerformanceEntry(env(), statistics_, TypeName()); + env()->SetImmediate([](Environment* env, void* data) { + Local context = env->context(); + Http2SessionPerformanceEntry* entry = + static_cast(data); + if (HasHttp2Observer(env)) { + Local obj = entry->ToObject(); + v8::PropertyAttribute attr = + static_cast(v8::ReadOnly | v8::DontDelete); + obj->DefineOwnProperty( + context, + FIXED_ONE_BYTE_STRING(env->isolate(), "type"), + String::NewFromUtf8(env->isolate(), + entry->typeName(), + v8::NewStringType::kInternalized) + .ToLocalChecked(), attr); + if (entry->ping_rtt() != 0) { + obj->DefineOwnProperty( + context, + FIXED_ONE_BYTE_STRING(env->isolate(), "pingRTT"), + Number::New(env->isolate(), entry->ping_rtt() / 1e6), attr); + } + obj->DefineOwnProperty( + context, + FIXED_ONE_BYTE_STRING(env->isolate(), "framesReceived"), + Integer::NewFromUnsigned(env->isolate(), entry->frame_count()), attr); + obj->DefineOwnProperty( + context, + FIXED_ONE_BYTE_STRING(env->isolate(), "streamCount"), + Integer::New(env->isolate(), entry->stream_count()), attr); + obj->DefineOwnProperty( + context, + FIXED_ONE_BYTE_STRING(env->isolate(), "streamAverageDuration"), + Number::New(env->isolate(), entry->stream_average_duration()), attr); + entry->Notify(obj); + } + delete entry; + }, static_cast(entry)); +} + // Closes the session and frees the associated resources void Http2Session::Close(uint32_t code, bool socket_closed) { DEBUG_HTTP2SESSION(this, "closing session"); @@ -560,6 +643,9 @@ void Http2Session::Close(uint32_t code, bool socket_closed) { static_cast(data)->Done(false); }, static_cast(ping)); } + + statistics_.end_time = uv_hrtime(); + EmitStatistics(); } // Locates an existing known stream by ID. nghttp2 has a similar method @@ -571,6 +657,7 @@ inline Http2Stream* Http2Session::FindStream(int32_t id) { inline void Http2Session::AddStream(Http2Stream* stream) { + CHECK_GE(++statistics_.stream_count, 0); streams_[stream->id()] = stream; } @@ -720,6 +807,7 @@ inline int Http2Session::OnFrameReceive(nghttp2_session* handle, const nghttp2_frame* frame, void* user_data) { Http2Session* session = static_cast(user_data); + session->statistics_.frame_count++; DEBUG_HTTP2SESSION2(session, "complete frame received: type: %d", frame->hd.type); switch (frame->hd.type) { @@ -1447,6 +1535,7 @@ Http2Stream::Http2Stream( id_(id), current_headers_category_(category) { MakeWeak(this); + statistics_.start_time = uv_hrtime(); // Limit the number of header pairs max_header_pairs_ = session->GetMaxHeaderPairs(); @@ -1530,6 +1619,8 @@ inline bool Http2Stream::HasDataChunks(bool ignore_eos) { // handles it's internal memory`. inline void Http2Stream::AddChunk(const uint8_t* data, size_t len) { CHECK(!this->IsDestroyed()); + if (this->statistics_.first_byte == 0) + this->statistics_.first_byte = uv_hrtime(); if (flags_ & NGHTTP2_STREAM_FLAG_EOS) return; char* buf = nullptr; @@ -1590,7 +1681,6 @@ inline void Http2Stream::Destroy() { // may still be some pending operations queued for this stream. env()->SetImmediate([](Environment* env, void* data) { Http2Stream* stream = static_cast(data); - // Free any remaining outgoing data chunks here. This should be done // here because it's possible for destroy to have been called while // we still have qeueued outbound writes. @@ -1603,6 +1693,12 @@ inline void Http2Stream::Destroy() { delete stream; }, this, this->object()); + + statistics_.end_time = uv_hrtime(); + session_->statistics_.stream_average_duration = + ((statistics_.end_time - statistics_.start_time) / + session_->statistics_.stream_count) / 1e6; + EmitStatistics(); } @@ -1815,6 +1911,8 @@ inline bool Http2Stream::AddHeader(nghttp2_rcbuf* name, nghttp2_rcbuf* value, uint8_t flags) { CHECK(!this->IsDestroyed()); + if (this->statistics_.first_header == 0) + this->statistics_.first_header = uv_hrtime(); size_t length = GetBufferLength(name) + GetBufferLength(value) + 32; if (current_headers_.size() == max_header_pairs_ || current_headers_length_ + length > max_header_length_) { @@ -2493,8 +2591,8 @@ void Http2Session::Http2Ping::Send(uint8_t* payload) { } void Http2Session::Http2Ping::Done(bool ack, const uint8_t* payload) { - uint64_t end = uv_hrtime(); - double duration = (end - startTime_) / 1e6; + session_->statistics_.ping_rtt = (uv_hrtime() - startTime_); + double duration = (session_->statistics_.ping_rtt - startTime_) / 1e6; Local buf = Undefined(env()->isolate()); if (payload != nullptr) { diff --git a/src/node_http2.h b/src/node_http2.h index 73d12c956f489c..0e2f489681f8d6 100644 --- a/src/node_http2.h +++ b/src/node_http2.h @@ -5,6 +5,7 @@ #include "nghttp2/nghttp2.h" #include "node_http2_state.h" +#include "node_perf.h" #include "stream_base-inl.h" #include "string_bytes.h" @@ -19,6 +20,8 @@ using v8::EscapableHandleScope; using v8::Isolate; using v8::MaybeLocal; +using performance::PerformanceEntry; + #ifdef NODE_DEBUG_HTTP2 // Adapted from nghttp2 own debug printer @@ -531,6 +534,8 @@ class Http2Stream : public AsyncWrap, Http2Session* session() { return session_; } + inline void EmitStatistics(); + inline bool HasDataChunks(bool ignore_eos = false); inline void AddChunk(const uint8_t* data, size_t len); @@ -690,6 +695,15 @@ class Http2Stream : public AsyncWrap, class Provider; + struct Statistics { + uint64_t start_time; + uint64_t end_time; + uint64_t first_header; // Time first header was received + uint64_t first_byte; // Time first data frame byte was received + }; + + Statistics statistics_ = {}; + private: Http2Session* session_; // The Parent HTTP/2 Session int32_t id_; // The Stream Identifier @@ -777,6 +791,8 @@ class Http2Session : public AsyncWrap { class Http2Ping; class Http2Settings; + inline void EmitStatistics(); + void Start(); void Stop(); void Close(uint32_t code = NGHTTP2_NO_ERROR, @@ -880,6 +896,17 @@ class Http2Session : public AsyncWrap { Http2Settings* PopSettings(); bool AddSettings(Http2Settings* settings); + struct Statistics { + uint64_t start_time; + uint64_t end_time; + uint64_t ping_rtt; + uint32_t frame_count; + int32_t stream_count; + double stream_average_duration; + }; + + Statistics statistics_ = {}; + private: // Frame Padding Strategies inline ssize_t OnMaxFrameSizePadding(size_t frameLength, @@ -1022,6 +1049,62 @@ class Http2Session : public AsyncWrap { friend class Http2Scope; }; +class Http2SessionPerformanceEntry : public PerformanceEntry { + public: + Http2SessionPerformanceEntry( + Environment* env, + const Http2Session::Statistics& stats, + const char* kind) : + PerformanceEntry(env, "Http2Session", "http2", + stats.start_time, + stats.end_time), + ping_rtt_(stats.ping_rtt), + frame_count_(stats.frame_count), + stream_count_(stats.stream_count), + stream_average_duration_(stats.stream_average_duration), + kind_(kind) { } + + uint64_t ping_rtt() const { return ping_rtt_; } + uint32_t frame_count() const { return frame_count_; } + int32_t stream_count() const { return stream_count_; } + double stream_average_duration() const { return stream_average_duration_; } + const char* typeName() const { return kind_; } + + void Notify(Local obj) { + PerformanceEntry::Notify(env(), kind(), obj); + } + + private: + uint64_t ping_rtt_; + uint32_t frame_count_; + int32_t stream_count_; + double stream_average_duration_; + const char* kind_; +}; + +class Http2StreamPerformanceEntry : public PerformanceEntry { + public: + Http2StreamPerformanceEntry( + Environment* env, + const Http2Stream::Statistics& stats) : + PerformanceEntry(env, "Http2Stream", "http2", + stats.start_time, + stats.end_time), + first_header_(stats.first_header), + first_byte_(stats.first_byte) { } + + uint64_t first_header() const { return first_header_; } + uint64_t first_byte() const { return first_byte_; } + + void Notify(Local obj) { + PerformanceEntry::Notify(env(), kind(), obj); + } + + private: + uint64_t first_header_; + uint64_t first_byte_; +}; + class Http2Session::Http2Ping : public AsyncWrap { public: explicit Http2Ping(Http2Session* session); @@ -1035,6 +1118,8 @@ class Http2Session::Http2Ping : public AsyncWrap { private: Http2Session* session_; uint64_t startTime_; + + friend class Http2Session; }; // The Http2Settings class is used to parse the settings passed in for diff --git a/src/node_perf.cc b/src/node_perf.cc index fcf7cd8b5af4e0..6a59d50fb64ff3 100644 --- a/src/node_perf.cc +++ b/src/node_perf.cc @@ -81,9 +81,9 @@ void PerformanceEntry::New(const FunctionCallbackInfo& args) { } // Pass the PerformanceEntry object to the PerformanceObservers -inline void PerformanceEntry::Notify(Environment* env, - PerformanceEntryType type, - Local object) { +void PerformanceEntry::Notify(Environment* env, + PerformanceEntryType type, + Local object) { Context::Scope scope(env->context()); uint32_t* observers = env->performance_state()->observers; if (observers != nullptr && diff --git a/src/node_perf.h b/src/node_perf.h index e5655f54fed07e..f1b182b4e3dcc7 100644 --- a/src/node_perf.h +++ b/src/node_perf.h @@ -47,9 +47,9 @@ NODE_EXTERN inline void MarkPerformanceMilestone( class PerformanceEntry { public: - static inline void Notify(Environment* env, - PerformanceEntryType type, - Local object); + static void Notify(Environment* env, + PerformanceEntryType type, + Local object); static void New(const FunctionCallbackInfo& args); diff --git a/src/node_perf_common.h b/src/node_perf_common.h index dc884cac97ce88..713f126d7f70d9 100644 --- a/src/node_perf_common.h +++ b/src/node_perf_common.h @@ -38,7 +38,8 @@ extern uint64_t performance_v8_start; V(MARK, "mark") \ V(MEASURE, "measure") \ V(GC, "gc") \ - V(FUNCTION, "function") + V(FUNCTION, "function") \ + V(HTTP2, "http2") enum PerformanceMilestone { #define V(name, _) NODE_PERFORMANCE_MILESTONE_##name, diff --git a/test/parallel/test-http2-perf_hooks.js b/test/parallel/test-http2-perf_hooks.js new file mode 100644 index 00000000000000..f2ef29cec25e06 --- /dev/null +++ b/test/parallel/test-http2-perf_hooks.js @@ -0,0 +1,95 @@ +'use strict'; + +const common = require('../common'); +if (!common.hasCrypto) + common.skip('missing crypto'); +const assert = require('assert'); +const h2 = require('http2'); + +const { PerformanceObserver } = require('perf_hooks'); + +const obs = new PerformanceObserver((items) => { + const entry = items.getEntries()[0]; + assert.strictEqual(entry.entryType, 'http2'); + assert.strictEqual(typeof entry.startTime, 'number'); + assert.strictEqual(typeof entry.duration, 'number'); + switch (entry.name) { + case 'Http2Session': + assert.strictEqual(typeof entry.pingRTT, 'number'); + assert.strictEqual(typeof entry.streamAverageDuration, 'number'); + assert.strictEqual(typeof entry.streamCount, 'number'); + assert.strictEqual(typeof entry.framesReceived, 'number'); + switch (entry.type) { + case 'server': + assert.strictEqual(entry.streamCount, 1); + assert.strictEqual(entry.framesReceived, 5); + break; + case 'client': + assert.strictEqual(entry.streamCount, 1); + assert.strictEqual(entry.framesReceived, 8); + break; + default: + assert.fail('invalid Http2Session type'); + } + break; + case 'Http2Stream': + assert.strictEqual(typeof entry.timeToFirstByte, 'number'); + assert.strictEqual(typeof entry.timeToFirstHeader, 'number'); + break; + default: + assert.fail('invalid entry name'); + } +}); +obs.observe({ entryTypes: ['http2'] }); + +const body = + '

this is some data

'; + +const server = h2.createServer(); + +// we use the lower-level API here +server.on('stream', common.mustCall(onStream)); + +function onStream(stream, headers, flags) { + assert.strictEqual(headers[':scheme'], 'http'); + assert.ok(headers[':authority']); + assert.strictEqual(headers[':method'], 'GET'); + assert.strictEqual(flags, 5); + stream.respond({ + 'content-type': 'text/html', + ':status': 200 + }); + stream.write(body.slice(0, 20)); + stream.end(body.slice(20)); +} + +server.on('session', common.mustCall((session) => { + session.ping(common.mustCall()); +})); + +server.listen(0); + +server.on('listening', common.mustCall(() => { + + const client = h2.connect(`http://localhost:${server.address().port}`); + + client.on('connect', common.mustCall(() => { + client.ping(common.mustCall()); + })); + + const req = client.request(); + + req.on('response', common.mustCall()); + + let data = ''; + req.setEncoding('utf8'); + req.on('data', (d) => data += d); + req.on('end', common.mustCall(() => { + assert.strictEqual(body, data); + })); + req.on('close', common.mustCall(() => { + client.close(); + server.close(); + })); + +}));