net,dns: trace tcp connection and dns by perf_hooks

use the perf_hooks to trace the time spent by net.connect, dns.lookup, dns.lookupService, dns.resolvexxx. PR-URL: #42390 Reviewed-By: Matteo Collina <[email protected]> Reviewed-By: Paolo Insogna <[email protected]> Reviewed-By: Mohammed Keyvanzadeh <[email protected]>
nodejs · Apr 6, 2022 · b71a810 · b71a810
1 parent 902776e
commit b71a810
Show file tree

Hide file tree

Showing 8 changed files with 272 additions and 3 deletions.
diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md
@@ -531,6 +531,30 @@ When `performanceEntry.type` is equal to `'function'`, the
 `performanceEntry.detail` property will be an {Array} listing
 the input arguments to the timed function.
 
+### Net ('net') Details
+
+When `performanceEntry.type` is equal to `'net'`, the
+`performanceEntry.detail` property will be an {Object} containing
+additional information.
+
+If `performanceEntry.name` is equal to `connect`, the `detail`
+will contain the following properties: `host`, `port`.
+
+### DNS ('dns') Details
+
+When `performanceEntry.type` is equal to `'dns'`, the
+`performanceEntry.detail` property will be an {Object} containing
+additional information.
+
+If `performanceEntry.name` is equal to `lookup`, the `detail`
+will contain the following properties: `hostname`, `family`, `hints`, `verbatim`.
+
+If `performanceEntry.name` is equal to `lookupService`, the `detail` will
+contain the following properties: `host`, `port`.
+
+If `performanceEntry.name` is equal to `queryxxx` or `getHostByAddr`, the `detail` will
+contain the following properties: `host`, `ttl`.
+
 ## Class: `PerformanceNodeTiming`
 
 <!-- YAML
@@ -1284,6 +1308,42 @@ http.createServer((req, res) => {
 });
 ```
 
+### Measuring how long the `net.connect` (only for TCP) takes when the connection is successful
+
+```js
+'use strict';
+const { PerformanceObserver } = require('perf_hooks');
+const net = require('net');
+const obs = new PerformanceObserver((items) => {
+  items.getEntries().forEach((item) => {
+    console.log(item);
+  });
+});
+obs.observe({ entryTypes: ['net'] });
+const PORT = 8080;
+net.createServer((socket) => {
+  socket.destroy();
+}).listen(PORT, () => {
+  net.connect(PORT);
+});
+```
+
+### Measuring how long the DNS takes when the request is successful
+
+```js
+'use strict';
+const { PerformanceObserver } = require('perf_hooks');
+const dns = require('dns');
+const obs = new PerformanceObserver((items) => {
+  items.getEntries().forEach((item) => {
+    console.log(item);
+  });
+});
+obs.observe({ entryTypes: ['dns'] });
+dns.lookup('localhost', () => {});
+dns.promises.resolve('localhost');
+```
+
 [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/dns.js b/lib/dns.js
@@ -27,6 +27,7 @@ const {
   ObjectDefineProperties,
   ObjectDefineProperty,
   ReflectApply,
+  Symbol,
 } = primordials;
 
 const cares = internalBinding('cares_wrap');
@@ -63,6 +64,15 @@ const {
   QueryReqWrap,
 } = cares;
 
+const kPerfHooksDnsLookupContext = Symbol('kPerfHooksDnsLookupContext');
+const kPerfHooksDnsLookupServiceContext = Symbol('kPerfHooksDnsLookupServiceContext');
+const kPerfHooksDnsLookupResolveContext = Symbol('kPerfHooksDnsLookupResolveContext');
+
+const {
+  startPerf,
+  stopPerf,
+} = require('internal/perf/observe');
+
 const dnsException = errors.dnsException;
 
 let promises = null; // Lazy loaded
@@ -72,6 +82,7 @@ function onlookup(err, addresses) {
     return this.callback(dnsException(err, 'getaddrinfo', this.hostname));
   }
   this.callback(null, addresses[0], this.family || isIP(addresses[0]));
+  stopPerf(this, kPerfHooksDnsLookupContext);
 }
 
 
@@ -90,6 +101,7 @@ function onlookupall(err, addresses) {
   }
 
   this.callback(null, addresses);
+  stopPerf(this, kPerfHooksDnsLookupContext);
 }
 
 
@@ -176,6 +188,13 @@ function lookup(hostname, options, callback) {
     process.nextTick(callback, dnsException(err, 'getaddrinfo', hostname));
     return {};
   }
+  const detail = {
+    hostname,
+    family,
+    hints,
+    verbatim,
+  };
+  startPerf(req, kPerfHooksDnsLookupContext, { type: 'dns', name: 'lookup', detail });
   return req;
 }
 
@@ -188,6 +207,7 @@ function onlookupservice(err, hostname, service) {
     return this.callback(dnsException(err, 'getnameinfo', this.hostname));
 
   this.callback(null, hostname, service);
+  stopPerf(this, kPerfHooksDnsLookupServiceContext);
 }
 
 
@@ -212,6 +232,14 @@ function lookupService(address, port, callback) {
 
   const err = cares.getnameinfo(req, address, port);
   if (err) throw dnsException(err, 'getnameinfo', address);
+  startPerf(req, kPerfHooksDnsLookupServiceContext, {
+    type: 'dns',
+    name: 'lookupService',
+    detail: {
+      host: address,
+      port
+    }
+  });
   return req;
 }
 
@@ -226,8 +254,10 @@ function onresolve(err, result, ttls) {
 
   if (err)
     this.callback(dnsException(err, this.bindingName, this.hostname));
-  else
+  else {
     this.callback(null, result);
+    stopPerf(this, kPerfHooksDnsLookupResolveContext);
+  }
 }
 
 function resolver(bindingName) {
@@ -249,6 +279,14 @@ function resolver(bindingName) {
     req.ttl = !!(options && options.ttl);
     const err = this._handle[bindingName](req, toASCII(name));
     if (err) throw dnsException(err, bindingName, name);
+    startPerf(req, kPerfHooksDnsLookupResolveContext, {
+      type: 'dns',
+      name: bindingName,
+      detail: {
+        host: name,
+        ttl: req.ttl
+      }
+    });
     return req;
   }
   ObjectDefineProperty(query, 'name', { value: bindingName });

diff --git a/lib/internal/dns/promises.js b/lib/internal/dns/promises.js
@@ -5,6 +5,7 @@ const {
   ObjectDefineProperty,
   Promise,
   ReflectApply,
+  Symbol,
 } = primordials;
 
 const {
@@ -38,6 +39,15 @@ const {
   validateOneOf,
 } = require('internal/validators');
 
+const kPerfHooksDnsLookupContext = Symbol('kPerfHooksDnsLookupContext');
+const kPerfHooksDnsLookupServiceContext = Symbol('kPerfHooksDnsLookupServiceContext');
+const kPerfHooksDnsLookupResolveContext = Symbol('kPerfHooksDnsLookupResolveContext');
+
+const {
+  startPerf,
+  stopPerf,
+} = require('internal/perf/observe');
+
 function onlookup(err, addresses) {
   if (err) {
     this.reject(dnsException(err, 'getaddrinfo', this.hostname));
@@ -46,6 +56,7 @@ function onlookup(err, addresses) {
 
   const family = this.family || isIP(addresses[0]);
   this.resolve({ address: addresses[0], family });
+  stopPerf(this, kPerfHooksDnsLookupContext);
 }
 
 function onlookupall(err, addresses) {
@@ -66,6 +77,7 @@ function onlookupall(err, addresses) {
   }
 
   this.resolve(addresses);
+  stopPerf(this, kPerfHooksDnsLookupContext);
 }
 
 function createLookupPromise(family, hostname, all, hints, verbatim) {
@@ -96,6 +108,14 @@ function createLookupPromise(family, hostname, all, hints, verbatim) {
 
     if (err) {
       reject(dnsException(err, 'getaddrinfo', hostname));
+    } else {
+      const detail = {
+        hostname,
+        family,
+        hints,
+        verbatim,
+      };
+      startPerf(req, kPerfHooksDnsLookupContext, { type: 'dns', name: 'lookup', detail });
     }
   });
 }
@@ -151,6 +171,7 @@ function onlookupservice(err, hostname, service) {
   }
 
   this.resolve({ hostname, service });
+  stopPerf(this, kPerfHooksDnsLookupServiceContext);
 }
 
 function createLookupServicePromise(hostname, port) {
@@ -167,6 +188,15 @@ function createLookupServicePromise(hostname, port) {
 
     if (err)
       reject(dnsException(err, 'getnameinfo', hostname));
+    else
+      startPerf(req, kPerfHooksDnsLookupServiceContext, {
+        type: 'dns',
+        name: 'lookupService',
+        detail: {
+          host: hostname,
+          port
+        }
+      });
   });
 }
 
@@ -194,6 +224,7 @@ function onresolve(err, result, ttls) {
       result, (address, index) => ({ address, ttl: ttls[index] }));
 
   this.resolve(result);
+  stopPerf(this, kPerfHooksDnsLookupResolveContext);
 }
 
 function createResolverPromise(resolver, bindingName, hostname, ttl) {
@@ -211,6 +242,16 @@ function createResolverPromise(resolver, bindingName, hostname, ttl) {
 
     if (err)
       reject(dnsException(err, bindingName, hostname));
+    else {
+      startPerf(req, kPerfHooksDnsLookupResolveContext, {
+        type: 'dns',
+        name: bindingName,
+        detail: {
+          host: hostname,
+          ttl
+        }
+      });
+    }
   });
 }
 

diff --git a/lib/internal/perf/observe.js b/lib/internal/perf/observe.js
@@ -24,6 +24,8 @@ const {
     NODE_PERFORMANCE_ENTRY_TYPE_GC,
     NODE_PERFORMANCE_ENTRY_TYPE_HTTP2,
     NODE_PERFORMANCE_ENTRY_TYPE_HTTP,
+    NODE_PERFORMANCE_ENTRY_TYPE_NET,
+    NODE_PERFORMANCE_ENTRY_TYPE_DNS,
   },
   installGarbageCollectionTracking,
   observerCounts,
@@ -79,12 +81,14 @@ const kTypeMultiple = 1;
 let gcTrackingInstalled = false;
 
 const kSupportedEntryTypes = ObjectFreeze([
+  'dns',
   'function',
   'gc',
   'http',
   'http2',
   'mark',
   'measure',
+  'net',
 ]);
 
 // Performance timeline entry Buffers
@@ -118,6 +122,8 @@ function getObserverType(type) {
     case 'gc': return NODE_PERFORMANCE_ENTRY_TYPE_GC;
     case 'http2': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP2;
     case 'http': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP;
+    case 'net': return NODE_PERFORMANCE_ENTRY_TYPE_NET;
+    case 'dns': return NODE_PERFORMANCE_ENTRY_TYPE_DNS;
   }
 }
 
@@ -443,11 +449,39 @@ function hasObserver(type) {
   return observerCounts[observerType] > 0;
 }
 
+
+function startPerf(target, key, context = {}) {
+  if (hasObserver(context.type)) {
+    target[key] = {
+      ...context,
+      startTime: process.hrtime(),
+    };
+  }
+}
+
+function stopPerf(target, key, context = {}) {
+  const ctx = target[key];
+  if (ctx && hasObserver(ctx.type)) {
+    const startTime = ctx.startTime;
+    const diff = process.hrtime(startTime);
+    const entry = new InternalPerformanceEntry(
+      ctx.name,
+      ctx.type,
+      startTime[0] * 1000 + startTime[1] / 1e6,
+      diff[0] * 1000 + diff[1] / 1e6,
+      { ...ctx.detail, ...context.detail },
+    );
+    enqueue(entry);
+  }
+}
+
 module.exports = {
   PerformanceObserver,
   PerformanceObserverEntryList,
   enqueue,
   hasObserver,
   clearEntriesFromBuffer,
   filterBufferMapByNameAndType,
+  startPerf,
+  stopPerf,
 };
diff --git a/lib/net.js b/lib/net.js
@@ -130,6 +130,12 @@ const isWindows = process.platform === 'win32';
 
 const noop = () => {};
 
+const kPerfHooksNetConnectContext = Symbol('kPerfHooksNetConnectContext');
+const {
+  startPerf,
+  stopPerf,
+} = require('internal/perf/observe');
+
 function getFlags(ipv6Only) {
   return ipv6Only === true ? TCPConstants.UV_TCP_IPV6ONLY : 0;
 }
@@ -952,6 +958,8 @@ function internalConnect(
 
     const ex = exceptionWithHostPort(err, 'connect', address, port, details);
     self.destroy(ex);
+  } else if (addressType === 6 || addressType === 4) {
+    startPerf(self, kPerfHooksNetConnectContext, { type: 'net', name: 'connect', detail: { host: address, port } });
   }
 }
 
@@ -1177,7 +1185,7 @@ function afterConnect(status, handle, req, readable, writable) {
     // this doesn't actually consume any bytes, because len=0.
     if (readable && !self.isPaused())
       self.read(0);
-
+    stopPerf(self, kPerfHooksNetConnectContext);
   } else {
     self.connecting = false;
     let details;

diff --git a/src/node_perf_common.h b/src/node_perf_common.h
@@ -34,7 +34,9 @@ extern uint64_t performance_v8_start;
 #define NODE_PERFORMANCE_ENTRY_TYPES(V)                                       \
   V(GC, "gc")                                                                 \
   V(HTTP, "http")                                                             \
-  V(HTTP2, "http2")
+  V(HTTP2, "http2")                                                           \
+  V(NET, "net")                                                               \
+  V(DNS, "dns")
 
 enum PerformanceMilestone {
 #define V(name, _) NODE_PERFORMANCE_MILESTONE_##name,