http2: perf_hooks integration

Collect and report basic timing information about `Http2Session`
and `Http2Stream` instances.

PR-URL: https://github.com/nodejs/node/pull/17906
Refs: https://github.com/nodejs/node/issues/17746
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

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

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;
   }
 }
 

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 <algorithm>
 
@@ -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<Http2Session>(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> context = env->context();
+    Http2StreamPerformanceEntry* entry =
+      static_cast<Http2StreamPerformanceEntry*>(data);
+    if (HasHttp2Observer(env)) {
+      Local<Object> obj = entry->ToObject();
+      v8::PropertyAttribute attr =
+          static_cast<v8::PropertyAttribute>(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<void*>(entry));
+}
+
+inline void Http2Session::EmitStatistics() {
+  if (!HasHttp2Observer(env()))
+    return;
+  Http2SessionPerformanceEntry* entry =
+    new Http2SessionPerformanceEntry(env(), statistics_, TypeName());
+  env()->SetImmediate([](Environment* env, void* data) {
+    Local<Context> context = env->context();
+    Http2SessionPerformanceEntry* entry =
+      static_cast<Http2SessionPerformanceEntry*>(data);
+    if (HasHttp2Observer(env)) {
+      Local<Object> obj = entry->ToObject();
+      v8::PropertyAttribute attr =
+          static_cast<v8::PropertyAttribute>(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<void*>(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<Http2Session::Http2Ping*>(data)->Done(false);
     }, static_cast<void*>(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<Http2Session*>(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<Http2Stream>(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<Http2Stream*>(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();
+  session_->statistics_.ping_rtt = (uv_hrtime() - startTime_);
-  double duration = (end - startTime_) / 1e6;
+  double duration = (session_->statistics_.ping_rtt - startTime_) / 1e6;
 
   Local<Value> buf = Undefined(env()->isolate());
   if (payload != nullptr) {

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<Value> 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<Value> 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

src/node_perf.cc

@@ -81,9 +81,9 @@ void PerformanceEntry::New(const FunctionCallbackInfo<Value>& args) {
 }
 
 // Pass the PerformanceEntry object to the PerformanceObservers
-inline void PerformanceEntry::Notify(Environment* env,
+void PerformanceEntry::Notify(Environment* env,
-                                     PerformanceEntryType type,
+                              PerformanceEntryType type,
-                                     Local<Value> object) {
+                              Local<Value> object) {
   Context::Scope scope(env->context());
   uint32_t* observers = env->performance_state()->observers;
   if (observers != nullptr &&

src/node_perf.h

@@ -47,9 +47,9 @@ NODE_EXTERN inline void MarkPerformanceMilestone(
 
 class PerformanceEntry {
  public:
-  static inline void Notify(Environment* env,
+  static void Notify(Environment* env,
-                            PerformanceEntryType type,
+                     PerformanceEntryType type,
-                            Local<Value> object);
+                     Local<Value> object);
 
   static void New(const FunctionCallbackInfo<Value>& args);
 

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,

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 =
+  '<html><head></head><body><h1>this is some data</h2></body></html>';
+
+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();
+  }));
+
+}));