Skip to content

Commit

Permalink
perf_hooks: add HttpRequest statistics monitoring nodejs#28445
Browse files Browse the repository at this point in the history
```js
const { PerformanceObserver, performance } = require('perf_hooks');
const http = require('http');

const obs = new PerformanceObserver((items) => {
  const entry = items.getEntries()[0];
  console.log(entry.name, entry.duration);
});
obs.observe({ entryTypes: ['http'] });

const server = http.Server(function(req, res) {
  server.close();
  res.writeHead(200);
  res.end('hello world\n');
});

server.listen(0, function() {
  const req = http.request({
    port: this.address().port,
    path: '/',
    method: 'POST'
  }).end();
});
```

PR-URL: nodejs#28486
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de>
  • Loading branch information
vmarchaud authored and addaleax committed Jul 11, 2019
1 parent ca0884a commit 0ebf01d
Show file tree
Hide file tree
Showing 7 changed files with 119 additions and 5 deletions.
2 changes: 1 addition & 1 deletion doc/api/perf_hooks.md
Original file line number Diff line number Diff line change
Expand Up @@ -183,7 +183,7 @@ added: v8.5.0
* {string}

The type of the performance entry. Currently it may be one of: `'node'`,
`'mark'`, `'measure'`, `'gc'`, `'function'`, or `'http2'`.
`'mark'`, `'measure'`, `'gc'`, `'function'`, `'http2'` or `'http'`.

### performanceEntry.kind
<!-- YAML
Expand Down
20 changes: 19 additions & 1 deletion lib/_http_server.js
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,12 @@ const {
prepareError,
} = require('_http_common');
const { OutgoingMessage } = require('_http_outgoing');
const { outHeadersKey, ondrain, nowDate } = require('internal/http');
const {
outHeadersKey,
ondrain,
nowDate,
emitStatistics
} = require('internal/http');
const {
defaultTriggerAsyncIdScope,
getOrSetAsyncId
Expand All @@ -56,8 +61,11 @@ const {
DTRACE_HTTP_SERVER_REQUEST,
DTRACE_HTTP_SERVER_RESPONSE
} = require('internal/dtrace');
const { observerCounts, constants } = internalBinding('performance');
const { NODE_PERFORMANCE_ENTRY_TYPE_HTTP } = constants;

const kServerResponse = Symbol('ServerResponse');
const kServerResponseStatistics = Symbol('ServerResponseStatistics');

const STATUS_CODES = {
100: 'Continue',
Expand Down Expand Up @@ -147,12 +155,22 @@ function ServerResponse(req) {
this.useChunkedEncodingByDefault = chunkExpression.test(req.headers.te);
this.shouldKeepAlive = false;
}

const httpObserverCount = observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_HTTP];
if (httpObserverCount > 0) {
this[kServerResponseStatistics] = {
startTime: process.hrtime()
};
}
}
Object.setPrototypeOf(ServerResponse.prototype, OutgoingMessage.prototype);
Object.setPrototypeOf(ServerResponse, OutgoingMessage);

ServerResponse.prototype._finish = function _finish() {
DTRACE_HTTP_SERVER_RESPONSE(this.connection);
if (this[kServerResponseStatistics] !== undefined) {
emitStatistics(this[kServerResponseStatistics]);
}
OutgoingMessage.prototype._finish.call(this);
};

Expand Down
20 changes: 19 additions & 1 deletion lib/internal/http.js
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
'use strict';

const { setUnrefTimeout } = require('internal/timers');
const { PerformanceEntry, notify } = internalBinding('performance');

var nowCache;
var utcCache;
Expand Down Expand Up @@ -31,9 +32,26 @@ function ondrain() {
if (this._httpMessage) this._httpMessage.emit('drain');
}

class HttpRequestTiming extends PerformanceEntry {
constructor(statistics) {
super();
this.name = 'HttpRequest';
this.entryType = 'http';
const startTime = statistics.startTime;
const diff = process.hrtime(startTime);
this.duration = diff[0] * 1000 + diff[1] / 1e6;
this.startTime = startTime[0] * 1000 + startTime[1] / 1e6;
}
}

function emitStatistics(statistics) {
notify('http', new HttpRequestTiming(statistics));
}

module.exports = {
outHeadersKey: Symbol('outHeadersKey'),
ondrain,
nowDate,
utcDate
utcDate,
emitStatistics
};
5 changes: 4 additions & 1 deletion lib/perf_hooks.js
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ const {
NODE_PERFORMANCE_ENTRY_TYPE_GC,
NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION,
NODE_PERFORMANCE_ENTRY_TYPE_HTTP2,
NODE_PERFORMANCE_ENTRY_TYPE_HTTP,

NODE_PERFORMANCE_MILESTONE_NODE_START,
NODE_PERFORMANCE_MILESTONE_V8_START,
Expand Down Expand Up @@ -70,7 +71,8 @@ const observerableTypes = [
'measure',
'gc',
'function',
'http2'
'http2',
'http'
];

const IDX_STREAM_STATS_ID = 0;
Expand Down Expand Up @@ -508,6 +510,7 @@ function mapTypes(i) {
case 'gc': return NODE_PERFORMANCE_ENTRY_TYPE_GC;
case 'function': return NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION;
case 'http2': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP2;
case 'http': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP;
}
}

Expand Down
16 changes: 16 additions & 0 deletions src/node_perf.cc
Original file line number Diff line number Diff line change
Expand Up @@ -366,6 +366,21 @@ void Timerify(const FunctionCallbackInfo<Value>& args) {
args.GetReturnValue().Set(wrap);
}

// Notify a custom PerformanceEntry to observers
void Notify(const FunctionCallbackInfo<Value>& args) {
Environment* env = Environment::GetCurrent(args);
Utf8Value type(env->isolate(), args[0]);
Local<Value> entry = args[1];
PerformanceEntryType entry_type = ToPerformanceEntryTypeEnum(*type);
AliasedUint32Array& observers = env->performance_state()->observers;
if (entry_type != NODE_PERFORMANCE_ENTRY_TYPE_INVALID &&
observers[entry_type]) {
USE(env->performance_entry_callback()->
Call(env->context(), Undefined(env->isolate()), 1, &entry));
}
}


// Event Loop Timing Histogram
namespace {
static void ELDHistogramMin(const FunctionCallbackInfo<Value>& args) {
Expand Down Expand Up @@ -562,6 +577,7 @@ void Initialize(Local<Object> target,
env->SetMethod(target, "timerify", Timerify);
env->SetMethod(
target, "setupGarbageCollectionTracking", SetupGarbageCollectionTracking);
env->SetMethod(target, "notify", Notify);

Local<Object> constants = Object::New(isolate);

Expand Down
3 changes: 2 additions & 1 deletion src/node_perf_common.h
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,8 @@ extern uint64_t performance_v8_start;
V(MEASURE, "measure") \
V(GC, "gc") \
V(FUNCTION, "function") \
V(HTTP2, "http2")
V(HTTP2, "http2") \
V(HTTP, "http")

enum PerformanceMilestone {
#define V(name, _) NODE_PERFORMANCE_MILESTONE_##name,
Expand Down
58 changes: 58 additions & 0 deletions test/parallel/test-http-perf_hooks.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,58 @@
'use strict';

const common = require('../common');
const assert = require('assert');
const http = require('http');

const { PerformanceObserver } = require('perf_hooks');

const obs = new PerformanceObserver(common.mustCall((items) => {
const entry = items.getEntries()[0];
assert.strictEqual(entry.entryType, 'http');
assert.strictEqual(typeof entry.startTime, 'number');
assert.strictEqual(typeof entry.duration, 'number');
}, 2));

obs.observe({ entryTypes: ['http'] });

const expected = 'Post Body For Test';
const makeRequest = (options) => {
return new Promise((resolve, reject) => {
http.request(options, common.mustCall((res) => {
resolve();
})).on('error', reject).end(options.data);
});
};

const server = http.Server(common.mustCall((req, res) => {
let result = '';

req.setEncoding('utf8');
req.on('data', function(chunk) {
result += chunk;
});

req.on('end', common.mustCall(function() {
assert.strictEqual(result, expected);
res.writeHead(200);
res.end('hello world\n');
}));
}, 2));

server.listen(0, common.mustCall(async () => {
await Promise.all([
makeRequest({
port: server.address().port,
path: '/',
method: 'POST',
data: expected
}),
makeRequest({
port: server.address().port,
path: '/',
method: 'POST',
data: expected
})
]);
server.close();
}));

0 comments on commit 0ebf01d

Please sign in to comment.