diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index 714876a16e330e..8c2a128861f590 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -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/ diff --git a/lib/_http_client.js b/lib/_http_client.js index a82a23b4bda3a4..0c1c60de278462 100644 --- a/lib/_http_client.js +++ b/lib/_http_client.js @@ -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, @@ -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) => { @@ -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() { @@ -604,6 +616,7 @@ function parserOnIncomingClient(res, shouldKeepAlive) { } DTRACE_HTTP_CLIENT_RESPONSE(socket, req); + emitStatistics(req[kClientRequestStatistics]); req.res = res; res.req = req; diff --git a/lib/_http_server.js b/lib/_http_server.js index 240cdc6ac59507..2e285f5fd74cb3 100644 --- a/lib/_http_server.js +++ b/lib/_http_server.js @@ -193,7 +193,8 @@ function ServerResponse(req) { if (hasObserver('http')) { this[kServerResponseStatistics] = { - startTime: process.hrtime() + startTime: process.hrtime(), + type: 'HttpRequest', }; } } diff --git a/lib/internal/http.js b/lib/internal/http.js index 56187a2b1cc315..375118da49f59b 100644 --- a/lib/internal/http.js +++ b/lib/internal/http.js @@ -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, diff --git a/test/parallel/test-http-perf_hooks.js b/test/parallel/test-http-perf_hooks.js index 826211472f222c..0708a1e8c06f5a 100644 --- a/test/parallel/test-http-perf_hooks.js +++ b/test/parallel/test-http-perf_hooks.js @@ -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' }); @@ -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); +});