diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index 58f3bb8259195f..cdcb9192f9545d 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -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: + + + +```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 59c4cac89e9d9d..42b4683d141ee0 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 b3cdc87249c593..00c810e51dfddc 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..f0cc69c767b497 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', () => { + 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); +});