From cbe98724e725f2ed0fbd8df5e60ee0b8d8738ca5 Mon Sep 17 00:00:00 2001 From: theanarkh <2923878201@qq.com> Date: Sun, 8 May 2022 04:48:03 +0800 Subject: [PATCH] http: add perf_hooks detail 1. http: add perf_hooks detail for http request and client 2. net,dns: move hasObserver out of startPerf and stopPerf --- doc/api/perf_hooks.md | 16 +++++++ lib/_http_client.js | 31 +++++++++--- lib/_http_server.js | 31 +++++++++--- lib/dns.js | 69 ++++++++++++++++----------- lib/internal/dns/promises.js | 24 +++++++--- lib/internal/http.js | 22 --------- lib/internal/perf/observe.js | 33 +++++++------ lib/net.js | 7 ++- test/parallel/test-http-perf_hooks.js | 6 +++ 9 files changed, 151 insertions(+), 88 deletions(-) diff --git a/doc/api/perf_hooks.md b/doc/api/perf_hooks.md index 8c398a3aee71eb..062372d3578ad0 100644 --- a/doc/api/perf_hooks.md +++ b/doc/api/perf_hooks.md @@ -484,6 +484,22 @@ property will be an {Object} with two properties: * `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_ALL_EXTERNAL_MEMORY` * `perf_hooks.constants.NODE_PERFORMANCE_GC_FLAGS_SCHEDULE_IDLE` +### HTTP ('http') Details + +When `performanceEntry.type` is equal to `'http'`, the +`performanceEntry.detail` property will be an {Object} containing +additional information. + +If `performanceEntry.name` is equal to `HttpClient`, the `detail` +will contain the following properties: `req`, `res`. And the `req` property +will be an {Object} containing `method`, `url`, `headers`, the `res` property +will be an {Object} containing `statusCode`, `statusMessage`, `headers`. + +If `performanceEntry.name` is equal to `HttpRequest`, the `detail` +will contain the following properties: `req`, `res`. And the `req` property +will be an {Object} containing `method`, `url`, `headers`, the `res` property +will be an {Object} containing `statusCode`, `statusMessage`, `headers`. + ### HTTP/2 ('http2') Details When `performanceEntry.type` is equal to `'http2'`, the diff --git a/lib/_http_client.js b/lib/_http_client.js index a4f7a255a99671..d67bf392de261c 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, emitStatistics } = require('internal/http'); +const { kOutHeaders, kNeedDrain } = require('internal/http'); const { connResetException, codes } = require('internal/errors'); const { ERR_HTTP_HEADERS_SENT, @@ -77,6 +77,8 @@ const { const { hasObserver, + startPerf, + stopPerf, } = require('internal/perf/observe'); const kClientRequestStatistics = Symbol('ClientRequestStatistics'); @@ -344,10 +346,17 @@ 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', - }; + startPerf(this, kClientRequestStatistics, { + type: 'http', + name: 'HttpClient', + detail: { + req: { + method: this.method, + url: `${this.protocol}//${this.host}${this.path}`, + headers: typeof this.getHeaders === 'function' ? this.getHeaders() : {}, + }, + }, + }); } }; @@ -616,7 +625,17 @@ function parserOnIncomingClient(res, shouldKeepAlive) { } DTRACE_HTTP_CLIENT_RESPONSE(socket, req); - emitStatistics(req[kClientRequestStatistics]); + if (req[kClientRequestStatistics] && hasObserver('http')) { + stopPerf(req, kClientRequestStatistics, { + detail: { + res: { + statusCode: res.statusCode, + statusMessage: res.statusMessage, + headers: res.headers, + }, + }, + }); + } req.res = res; res.req = req; diff --git a/lib/_http_server.js b/lib/_http_server.js index c8dc22929bfabd..8b6607a542bc2d 100644 --- a/lib/_http_server.js +++ b/lib/_http_server.js @@ -51,7 +51,6 @@ const { OutgoingMessage } = require('_http_outgoing'); const { kOutHeaders, kNeedDrain, - emitStatistics } = require('internal/http'); const { defaultTriggerAsyncIdScope, @@ -93,6 +92,8 @@ const kServerResponse = Symbol('ServerResponse'); const kServerResponseStatistics = Symbol('ServerResponseStatistics'); const { + startPerf, + stopPerf, hasObserver, } = require('internal/perf/observe'); @@ -191,12 +192,18 @@ function ServerResponse(req) { req.headers.te); this.shouldKeepAlive = false; } - if (hasObserver('http')) { - this[kServerResponseStatistics] = { - startTime: process.hrtime(), - type: 'HttpRequest', - }; + startPerf(this, kServerResponseStatistics, { + type: 'http', + name: 'HttpRequest', + detail: { + req: { + method: req.method, + url: req.url, + headers: req.headers, + }, + }, + }); } } ObjectSetPrototypeOf(ServerResponse.prototype, OutgoingMessage.prototype); @@ -204,7 +211,17 @@ ObjectSetPrototypeOf(ServerResponse, OutgoingMessage); ServerResponse.prototype._finish = function _finish() { DTRACE_HTTP_SERVER_RESPONSE(this.socket); - emitStatistics(this[kServerResponseStatistics]); + if (this[kServerResponseStatistics] && hasObserver('http')) { + stopPerf(this, kServerResponseStatistics, { + detail: { + res: { + statusCode: this.statusCode, + statusMessage: this.statusMessage, + headers: typeof this.getHeaders === 'function' ? this.getHeaders() : {}, + }, + }, + }); + } OutgoingMessage.prototype._finish.call(this); }; diff --git a/lib/dns.js b/lib/dns.js index af5416c62478cc..5db39d16ec58bf 100644 --- a/lib/dns.js +++ b/lib/dns.js @@ -70,6 +70,7 @@ const kPerfHooksDnsLookupServiceContext = Symbol('kPerfHooksDnsLookupServiceCont const kPerfHooksDnsLookupResolveContext = Symbol('kPerfHooksDnsLookupResolveContext'); const { + hasObserver, startPerf, stopPerf, } = require('internal/perf/observe'); @@ -83,7 +84,9 @@ 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); + if (this[kPerfHooksDnsLookupContext] && hasObserver('dns')) { + stopPerf(this, kPerfHooksDnsLookupContext); + } } @@ -102,7 +105,9 @@ function onlookupall(err, addresses) { } this.callback(null, addresses); - stopPerf(this, kPerfHooksDnsLookupContext); + if (this[kPerfHooksDnsLookupContext] && hasObserver('dns')) { + stopPerf(this, kPerfHooksDnsLookupContext); + } } @@ -187,13 +192,15 @@ 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 }); + if (hasObserver('dns')) { + const detail = { + hostname, + family, + hints, + verbatim, + }; + startPerf(req, kPerfHooksDnsLookupContext, { type: 'dns', name: 'lookup', detail }); + } return req; } @@ -206,7 +213,9 @@ function onlookupservice(err, hostname, service) { return this.callback(dnsException(err, 'getnameinfo', this.hostname)); this.callback(null, hostname, service); - stopPerf(this, kPerfHooksDnsLookupServiceContext); + if (this[kPerfHooksDnsLookupServiceContext] && hasObserver('dns')) { + stopPerf(this, kPerfHooksDnsLookupServiceContext); + } } @@ -231,14 +240,16 @@ 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 - } - }); + if (hasObserver('dns')) { + startPerf(req, kPerfHooksDnsLookupServiceContext, { + type: 'dns', + name: 'lookupService', + detail: { + host: address, + port + } + }); + } return req; } @@ -255,7 +266,9 @@ function onresolve(err, result, ttls) { this.callback(dnsException(err, this.bindingName, this.hostname)); else { this.callback(null, result); - stopPerf(this, kPerfHooksDnsLookupResolveContext); + if (this[kPerfHooksDnsLookupResolveContext] && hasObserver('dns')) { + stopPerf(this, kPerfHooksDnsLookupResolveContext); + } } } @@ -278,14 +291,16 @@ 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 - } - }); + if (hasObserver('dns')) { + 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 9625e9e7b9b6ea..4cd439b94acd4e 100644 --- a/lib/internal/dns/promises.js +++ b/lib/internal/dns/promises.js @@ -48,6 +48,7 @@ const kPerfHooksDnsLookupResolveContext = Symbol('kPerfHooksDnsLookupResolveCont const { startPerf, stopPerf, + hasObserver, } = require('internal/perf/observe'); function onlookup(err, addresses) { @@ -58,7 +59,9 @@ function onlookup(err, addresses) { const family = this.family || isIP(addresses[0]); this.resolve({ address: addresses[0], family }); - stopPerf(this, kPerfHooksDnsLookupContext); + if (this[kPerfHooksDnsLookupContext] && hasObserver('dns')) { + stopPerf(this, kPerfHooksDnsLookupContext); + } } function onlookupall(err, addresses) { @@ -79,7 +82,9 @@ function onlookupall(err, addresses) { } this.resolve(addresses); - stopPerf(this, kPerfHooksDnsLookupContext); + if (this[kPerfHooksDnsLookupContext] && hasObserver('dns')) { + stopPerf(this, kPerfHooksDnsLookupContext); + } } function createLookupPromise(family, hostname, all, hints, verbatim) { @@ -110,7 +115,7 @@ function createLookupPromise(family, hostname, all, hints, verbatim) { if (err) { reject(dnsException(err, 'getaddrinfo', hostname)); - } else { + } else if (hasObserver('dns')) { const detail = { hostname, family, @@ -170,7 +175,9 @@ function onlookupservice(err, hostname, service) { } this.resolve({ hostname, service }); - stopPerf(this, kPerfHooksDnsLookupServiceContext); + if (this[kPerfHooksDnsLookupServiceContext] && hasObserver('dns')) { + stopPerf(this, kPerfHooksDnsLookupServiceContext); + } } function createLookupServicePromise(hostname, port) { @@ -187,7 +194,7 @@ function createLookupServicePromise(hostname, port) { if (err) reject(dnsException(err, 'getnameinfo', hostname)); - else + else if (hasObserver('dns')) { startPerf(req, kPerfHooksDnsLookupServiceContext, { type: 'dns', name: 'lookupService', @@ -196,6 +203,7 @@ function createLookupServicePromise(hostname, port) { port } }); + } }); } @@ -223,7 +231,9 @@ function onresolve(err, result, ttls) { result, (address, index) => ({ address, ttl: ttls[index] })); this.resolve(result); - stopPerf(this, kPerfHooksDnsLookupResolveContext); + if (this[kPerfHooksDnsLookupResolveContext] && hasObserver('dns')) { + stopPerf(this, kPerfHooksDnsLookupResolveContext); + } } function createResolverPromise(resolver, bindingName, hostname, ttl) { @@ -241,7 +251,7 @@ function createResolverPromise(resolver, bindingName, hostname, ttl) { if (err) reject(dnsException(err, bindingName, hostname)); - else { + else if (hasObserver('dns')) { startPerf(req, kPerfHooksDnsLookupResolveContext, { type: 'dns', name: bindingName, diff --git a/lib/internal/http.js b/lib/internal/http.js index 375118da49f59b..337d155340f7e6 100644 --- a/lib/internal/http.js +++ b/lib/internal/http.js @@ -9,13 +9,6 @@ const { const { setUnrefTimeout } = require('internal/timers'); -const { InternalPerformanceEntry } = require('internal/perf/performance_entry'); - -const { - enqueue, - hasObserver, -} = require('internal/perf/observe'); - let utcCache; function utcDate() { @@ -33,23 +26,8 @@ function resetCache() { utcCache = undefined; } -function emitStatistics(statistics) { - if (!hasObserver('http') || statistics == null) return; - const startTime = statistics.startTime; - const diff = process.hrtime(startTime); - const entry = new InternalPerformanceEntry( - statistics.type, - 'http', - startTime[0] * 1000 + startTime[1] / 1e6, - diff[0] * 1000 + diff[1] / 1e6, - undefined, - ); - enqueue(entry); -} - module.exports = { kOutHeaders: Symbol('kOutHeaders'), kNeedDrain: Symbol('kNeedDrain'), utcDate, - emitStatistics, }; diff --git a/lib/internal/perf/observe.js b/lib/internal/perf/observe.js index 18fc10eb789e01..daa53402b4989c 100644 --- a/lib/internal/perf/observe.js +++ b/lib/internal/perf/observe.js @@ -448,28 +448,27 @@ function hasObserver(type) { function startPerf(target, key, context = {}) { - if (hasObserver(context.type)) { - target[key] = { - ...context, - startTime: process.hrtime(), - }; - } + 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); + if (!ctx) { + return; } + 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 = { diff --git a/lib/net.js b/lib/net.js index 1c98cf4820178f..cad7d29189b155 100644 --- a/lib/net.js +++ b/lib/net.js @@ -132,6 +132,7 @@ const noop = () => {}; const kPerfHooksNetConnectContext = Symbol('kPerfHooksNetConnectContext'); const { + hasObserver, startPerf, stopPerf, } = require('internal/perf/observe'); @@ -958,7 +959,7 @@ function internalConnect( const ex = exceptionWithHostPort(err, 'connect', address, port, details); self.destroy(ex); - } else if (addressType === 6 || addressType === 4) { + } else if ((addressType === 6 || addressType === 4) && hasObserver('net')) { startPerf(self, kPerfHooksNetConnectContext, { type: 'net', name: 'connect', detail: { host: address, port } }); } } @@ -1185,7 +1186,9 @@ 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); + if (self[kPerfHooksNetConnectContext] && hasObserver('net')) { + stopPerf(self, kPerfHooksNetConnectContext); + } } else { self.connecting = false; let details; diff --git a/test/parallel/test-http-perf_hooks.js b/test/parallel/test-http-perf_hooks.js index 0708a1e8c06f5a..de6ed0295a1152 100644 --- a/test/parallel/test-http-perf_hooks.js +++ b/test/parallel/test-http-perf_hooks.js @@ -66,6 +66,12 @@ process.on('exit', () => { } else if (entry.name === 'HttpRequest') { numberOfHttpRequests++; } + assert.strictEqual(typeof entry.detail.req.method, 'string'); + assert.strictEqual(typeof entry.detail.req.url, 'string'); + assert.strictEqual(typeof entry.detail.req.headers, 'object'); + assert.strictEqual(typeof entry.detail.res.statusCode, 'number'); + assert.strictEqual(typeof entry.detail.res.statusMessage, 'string'); + assert.strictEqual(typeof entry.detail.res.headers, 'object'); }); assert.strictEqual(numberOfHttpClients, 2); assert.strictEqual(numberOfHttpRequests, 2);