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: https://github.com/nodejs/node/pull/42390
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Paolo Insogna <paolo@cowtech.it>
Reviewed-By: Mohammed Keyvanzadeh <mohammadkeyvanzade94@gmail.com>

4 files changed, 123 insertions, 2 deletions

diff --git a/lib/dns.js b/lib/dns.js
index d795e8e0904..14937769d1d 100644
--- 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
index fcff215896a..314b121be5d 100644
--- 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
index ca9e68a9625..18fc10eb789 100644
--- 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,
@@ -75,12 +77,14 @@ const kTypeMultiple = 1;
 let gcTrackingInstalled = false;
 
 const kSupportedEntryTypes = ObjectFreeze([
+  'dns',
   'function',
   'gc',
   'http',
   'http2',
   'mark',
   'measure',
+  'net',
 ]);
 
 // Performance timeline entry Buffers
@@ -114,6 +118,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;
   }
 }
 
@@ -440,6 +446,32 @@ 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,
@@ -447,4 +479,6 @@ module.exports = {
   hasObserver,
   clearEntriesFromBuffer,
   filterBufferMapByNameAndType,
+  startPerf,
+  stopPerf,
 };
diff --git a/lib/net.js b/lib/net.js
index 53ecbd9a1f5..d05fa64e78a 100644
--- 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;