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>

Author: theanarkh

doc/api/perf_hooks.md

@@ -1254,6 +1254,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');
+consthttp=require('http');
+
+constobs=newPerformanceObserver((items) => {
+items.getEntries().forEach((item) => {
+console.log(item);
+ });
+});
+
+obs.observe({ entryTypes: ['http'] });
+
+constPORT=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/

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');
+
+constkClientRequestStatistics=Symbol('ClientRequestStatistics');
+
 const{ addAbortSignal, finished }=require('stream');
 
 letdebug=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;
 

lib/_http_server.js

@@ -193,7 +193,8 @@ function ServerResponse(req) {
 
 if(hasObserver('http')){
 this[kServerResponseStatistics]={
-startTime: process.hrtime()
+startTime: process.hrtime(),
+type: 'HttpRequest',
 };
 }
 }

lib/internal/http.js

@@ -38,7 +38,7 @@ function emitStatistics(statistics) {
 conststartTime=statistics.startTime;
 constdiff=process.hrtime(startTime);
 constentry=newInternalPerformanceEntry(
-'HttpRequest',
+statistics.type,
 'http',
 startTime[0]*1000+startTime[1]/1e6,
 diff[0]*1000+diff[1]/1e6,

test/parallel/test-http-perf_hooks.js

@@ -5,13 +5,9 @@ const assert = require('assert');
 consthttp=require('http');
 
 const{ PerformanceObserver }=require('perf_hooks');
-
+constentries=[];
 constobs=newPerformanceObserver(common.mustCallAtLeast((items)=>{
-items.getEntries().forEach((entry)=>{
-assert.strictEqual(entry.entryType,'http');
-assert.strictEqual(typeofentry.startTime,'number');
-assert.strictEqual(typeofentry.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',()=>{
+letnumberOfHttpClients=0;
+letnumberOfHttpRequests=0;
+entries.forEach((entry)=>{
+assert.strictEqual(entry.entryType,'http');
+assert.strictEqual(typeofentry.startTime,'number');
+assert.strictEqual(typeofentry.duration,'number');
+if(entry.name==='HttpClient'){
+numberOfHttpClients++;
+}elseif(entry.name==='HttpRequest'){
+numberOfHttpRequests++;
+}
+});
+assert.strictEqual(numberOfHttpClients,2);
+assert.strictEqual(numberOfHttpRequests,2);
+});