Skip to content

Commit

Permalink
http2: perf_hooks integration
Browse files Browse the repository at this point in the history 
Collect and report basic timing information about `Http2Session`
and `Http2Stream` instances.

Backport-PR-URL: #18050
Backport-PR-URL: #20456
PR-URL: #17906
Refs: #17746
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
  • Loading branch information
@jasnell @MylesBorins
jasnell authored and MylesBorins committed May 2, 2018
1 parent 72b42de commit dcc7f4d
Show file tree
Hide file tree
Showing 8 changed files with 344 additions and 13 deletions.
50 changes: 50 additions & 0 deletions doc/api/http2.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2819,13 +2819,63 @@ 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
[HTTP/2]: https://tools.ietf.org/html/rfc7540
[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
Expand Down
5 changes: 4 additions & 1 deletion lib/perf_hooks.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -61,7 +62,8 @@ const observerableTypes = [
'mark',
'measure',
'gc',
'function'
'function',
'http2'
];

let errors;
Expand Down Expand Up @@ -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;
}
}

Expand Down
104 changes: 101 additions & 3 deletions src/node_http2.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
#include "node_buffer.h"
#include "node_http2.h"
#include "node_http2_state.h"
#include "node_perf.h"

#include <algorithm>

Expand All @@ -20,6 +21,7 @@ using v8::Uint32;
using v8::Uint32Array;
using v8::Undefined;

using node::performance::PerformanceEntry;
namespace http2 {

namespace {
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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");
Expand Down Expand Up @@ -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
Expand All @@ -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;
}

Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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.
Expand All @@ -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();
}


Expand Down Expand Up @@ -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_) {
Expand Down Expand Up @@ -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<Value> buf = Undefined(env()->isolate());
if (payload != nullptr) {
Expand Down
Loading

0 comments on commit dcc7f4d

Please sign in to comment.