Skip to content

Commit

Permalink
http: trace http client by perf_hooks
Browse files Browse the repository at this point in the history
PR-URL: #42345
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Antoine du Hamel <duhamelantoine1995@gmail.com>
Reviewed-By: Ricky Zhou <0x19951125@gmail.com>
  • Loading branch information
theanarkh authored and danielleadams committed Apr 24, 2022
1 parent a458fbf commit 39fb114
Show file tree
Hide file tree
Showing 5 changed files with 66 additions and 9 deletions.
30 changes: 30 additions & 0 deletions doc/api/perf_hooks.md
Original file line number Diff line number Diff line change
Expand Up @@ -1246,6 +1246,36 @@ obs.observe({ entryTypes: ['function'], buffered: true });
require('some-module');
```

### Measuring how long one HTTP round-trip takes

The following example is used to trace the time spent by HTTP client
(`OutgoingMessage`) and HTTP request (`IncomingMessage`). For HTTP client,
it means the time interval between starting the request and receiving the
response, and for HTTP request, it means the time interval between receiving
the request and sending the response:

```js
'use strict';
const { PerformanceObserver } = require('perf_hooks');
const http = require('http');

const obs = new PerformanceObserver((items) => {
items.getEntries().forEach((item) => {
console.log(item);
});
});

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

const PORT = 8080;

http.createServer((req, res) => {
res.end('ok');
}).listen(PORT, () => {
http.get(`http://127.0.0.1:${PORT}`);
});
```

[Async Hooks]: async_hooks.md
[High Resolution Time]: https://www.w3.org/TR/hr-time-2
[Performance Timeline]: https://w3c.github.io/performance-timeline/
Expand Down
15 changes: 14 additions & 1 deletion lib/_http_client.js
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,7 @@ const Agent = require('_http_agent');
const { Buffer } = require('buffer');
const { defaultTriggerAsyncIdScope } = require('internal/async_hooks');
const { URL, urlToHttpOptions, searchParamsSymbol } = require('internal/url');
const { kOutHeaders, kNeedDrain } = require('internal/http');
const { kOutHeaders, kNeedDrain, emitStatistics } = require('internal/http');
const { connResetException, codes } = require('internal/errors');
const {
ERR_HTTP_HEADERS_SENT,
Expand All @@ -75,6 +75,12 @@ const {
DTRACE_HTTP_CLIENT_RESPONSE
} = require('internal/dtrace');

const {
hasObserver,
} = require('internal/perf/observe');

const kClientRequestStatistics = Symbol('ClientRequestStatistics');

const { addAbortSignal, finished } = require('stream');

let debug = require('internal/util/debuglog').debuglog('http', (fn) => {
Expand Down Expand Up @@ -337,6 +343,12 @@ ObjectSetPrototypeOf(ClientRequest, OutgoingMessage);
ClientRequest.prototype._finish = function _finish() {
DTRACE_HTTP_CLIENT_REQUEST(this, this.socket);
FunctionPrototypeCall(OutgoingMessage.prototype._finish, this);
if (hasObserver('http')) {
this[kClientRequestStatistics] = {
startTime: process.hrtime(),
type: 'HttpClient',
};
}
};

ClientRequest.prototype._implicitHeader = function _implicitHeader() {
Expand Down Expand Up @@ -604,6 +616,7 @@ function parserOnIncomingClient(res, shouldKeepAlive) {
}

DTRACE_HTTP_CLIENT_RESPONSE(socket, req);
emitStatistics(req[kClientRequestStatistics]);
req.res = res;
res.req = req;

Expand Down
3 changes: 2 additions & 1 deletion lib/_http_server.js
Original file line number Diff line number Diff line change
Expand Up @@ -193,7 +193,8 @@ function ServerResponse(req) {

if (hasObserver('http')) {
this[kServerResponseStatistics] = {
startTime: process.hrtime()
startTime: process.hrtime(),
type: 'HttpRequest',
};
}
}
Expand Down
2 changes: 1 addition & 1 deletion lib/internal/http.js
Original file line number Diff line number Diff line change
Expand Up @@ -38,7 +38,7 @@ function emitStatistics(statistics) {
const startTime = statistics.startTime;
const diff = process.hrtime(startTime);
const entry = new InternalPerformanceEntry(
'HttpRequest',
statistics.type,
'http',
startTime[0] * 1000 + startTime[1] / 1e6,
diff[0] * 1000 + diff[1] / 1e6,
Expand Down
25 changes: 19 additions & 6 deletions test/parallel/test-http-perf_hooks.js
Original file line number Diff line number Diff line change
Expand Up @@ -5,13 +5,9 @@ const assert = require('assert');
const http = require('http');

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

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

obs.observe({ type: 'http' });
Expand Down Expand Up @@ -57,3 +53,20 @@ server.listen(0, common.mustCall(async () => {
]);
server.close();
}));

process.on('exit', () => {
let numberOfHttpClients = 0;
let numberOfHttpRequests = 0;
entries.forEach((entry) => {
assert.strictEqual(entry.entryType, 'http');
assert.strictEqual(typeof entry.startTime, 'number');
assert.strictEqual(typeof entry.duration, 'number');
if (entry.name === 'HttpClient') {
numberOfHttpClients++;
} else if (entry.name === 'HttpRequest') {
numberOfHttpRequests++;
}
});
assert.strictEqual(numberOfHttpClients, 2);
assert.strictEqual(numberOfHttpRequests, 2);
});

0 comments on commit 39fb114

Please sign in to comment.