Skip to content

Commit

Permalink
net,dns: trace tcp connection and dns by perf_hooks
Browse files Browse the repository at this point in the history
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 <matteo.collina@gmail.com>
Reviewed-By: Paolo Insogna <paolo@cowtech.it>
Reviewed-By: Mohammed Keyvanzadeh <mohammadkeyvanzade94@gmail.com>
  • Loading branch information
theanarkh authored and juanarbol committed Apr 6, 2022
1 parent 902776e commit b71a810
Show file tree
Hide file tree
Showing 8 changed files with 272 additions and 3 deletions.
60 changes: 60 additions & 0 deletions doc/api/perf_hooks.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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/
Expand Down
40 changes: 39 additions & 1 deletion lib/dns.js
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@ const {
ObjectDefineProperties,
ObjectDefineProperty,
ReflectApply,
Symbol,
} = primordials;

const cares = internalBinding('cares_wrap');
Expand Down Expand Up @@ -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
Expand All @@ -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);
}


Expand All @@ -90,6 +101,7 @@ function onlookupall(err, addresses) {
}

this.callback(null, addresses);
stopPerf(this, kPerfHooksDnsLookupContext);
}


Expand Down Expand Up @@ -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;
}

Expand All @@ -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);
}


Expand All @@ -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;
}

Expand All @@ -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) {
Expand All @@ -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 });
Expand Down
41 changes: 41 additions & 0 deletions lib/internal/dns/promises.js
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@ const {
ObjectDefineProperty,
Promise,
ReflectApply,
Symbol,
} = primordials;

const {
Expand Down Expand Up @@ -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));
Expand All @@ -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) {
Expand All @@ -66,6 +77,7 @@ function onlookupall(err, addresses) {
}

this.resolve(addresses);
stopPerf(this, kPerfHooksDnsLookupContext);
}

function createLookupPromise(family, hostname, all, hints, verbatim) {
Expand Down Expand Up @@ -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 });
}
});
}
Expand Down Expand Up @@ -151,6 +171,7 @@ function onlookupservice(err, hostname, service) {
}

this.resolve({ hostname, service });
stopPerf(this, kPerfHooksDnsLookupServiceContext);
}

function createLookupServicePromise(hostname, port) {
Expand All @@ -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
}
});
});
}

Expand Down Expand Up @@ -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) {
Expand All @@ -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
}
});
}
});
}

Expand Down
34 changes: 34 additions & 0 deletions lib/internal/perf/observe.js
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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;
}
}

Expand Down Expand Up @@ -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,
};
10 changes: 9 additions & 1 deletion lib/net.js
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down Expand Up @@ -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 } });
}
}

Expand Down Expand Up @@ -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;
Expand Down
4 changes: 3 additions & 1 deletion src/node_perf_common.h
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
Loading

0 comments on commit b71a810

Please sign in to comment.