Skip to content

Commit

Permalink
http: trace http client by perf_hooks
Browse files Browse the repository at this point in the history
  • Loading branch information
theanarkh committed Mar 16, 2022
1 parent 4586ac4 commit e8f8028
Show file tree
Hide file tree
Showing 5 changed files with 69 additions and 9 deletions.
33 changes: 33 additions & 0 deletions doc/api/perf_hooks.md
Expand Up @@ -1276,6 +1276,39 @@ obs.observe({ entryTypes: ['function'], buffered: true });
require('some-module');
```

### Trace http by perf\_hooks

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:

<!-- eslint-disable no-global-assign -->

```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
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
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
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
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', () => {
const httpClients = [];
const httpRequests = [];
entries.forEach((entry) => {
assert.strictEqual(entry.entryType, 'http');
assert.strictEqual(typeof entry.startTime, 'number');
assert.strictEqual(typeof entry.duration, 'number');
if (entry.name === 'HttpClient') {
httpClients.push(entry);
} else if (entry.name === 'HttpRequest') {
httpRequests.push(entry);
}
});
assert.strictEqual(httpClients.length, 2);
assert.strictEqual(httpRequests.length, 2);
});

0 comments on commit e8f8028

Please sign in to comment.