http: trace http client by perf_hooks

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>
nodejs · Mar 18, 2022 · 3f3fa6d · 3f3fa6d
1 parent 44131ad
commit 3f3fa6d
Show file tree

Hide file tree

Showing 5 changed files with 66 additions and 9 deletions.
diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md
@@ -1276,6 +1276,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
@@ -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
@@ -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
@@ -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
@@ -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);
+});