perf_hooks: add HttpRequest statistics monitoring #28445

doc/api/perf_hooks.md

@@ -183,7 +183,7 @@ added: v8.5.0
 * {string}
 
 The type of the performance entry. Currently it may be one of: `'node'`,
-`'mark'`, `'measure'`, `'gc'`, `'function'`, or `'http2'`.
+`'mark'`, `'measure'`, `'gc'`, `'function'`, `'http2'` or `'http'`.
 
 ### performanceEntry.kind
 <!-- YAML

lib/_http_server.js

@@ -38,7 +38,12 @@ const {
   _checkInvalidHeaderChar: checkInvalidHeaderChar
 } = require('_http_common');
 const { OutgoingMessage } = require('_http_outgoing');
-const { outHeadersKey, ondrain, nowDate } = require('internal/http');
+const {
+  outHeadersKey,
+  ondrain,
+  nowDate,
+  emitStatistics
+} = require('internal/http');
 const {
   defaultTriggerAsyncIdScope,
   getOrSetAsyncId
@@ -55,8 +60,11 @@ const {
   DTRACE_HTTP_SERVER_REQUEST,
   DTRACE_HTTP_SERVER_RESPONSE
 } = require('internal/dtrace');
+const { observerCounts, constants } = internalBinding('performance');
+const { NODE_PERFORMANCE_ENTRY_TYPE_HTTP } = constants;
 
 const kServerResponse = Symbol('ServerResponse');
+const kServerResponseStatistics = Symbol('ServerResponseStatistics');
 
 const STATUS_CODES = {
   100: 'Continue',
@@ -146,12 +154,22 @@ function ServerResponse(req) {
     this.useChunkedEncodingByDefault = chunkExpression.test(req.headers.te);
     this.shouldKeepAlive = false;
   }
+
+  const httpObserverCount = observerCounts[NODE_PERFORMANCE_ENTRY_TYPE_HTTP];
+  if (httpObserverCount > 0) {
+    this[kServerResponseStatistics] = {
+      startTime: process.hrtime()
+    };
+  }
 }
 Object.setPrototypeOf(ServerResponse.prototype, OutgoingMessage.prototype);
 Object.setPrototypeOf(ServerResponse, OutgoingMessage);
 
 ServerResponse.prototype._finish = function _finish() {
   DTRACE_HTTP_SERVER_RESPONSE(this.connection);
+  if (this[kServerResponseStatistics] !== undefined) {
+    emitStatistics(this[kServerResponseStatistics]);
+  }
   OutgoingMessage.prototype._finish.call(this);
 };
 

lib/internal/http.js

@@ -1,6 +1,7 @@
 'use strict';
 
 const { setUnrefTimeout } = require('internal/timers');
+const { PerformanceEntry, notify } = internalBinding('performance');
 
 var nowCache;
 var utcCache;
@@ -31,9 +32,26 @@ function ondrain() {
   if (this._httpMessage) this._httpMessage.emit('drain');
 }
 
+class HttpRequestTiming extends PerformanceEntry {
+  constructor(statistics) {
+    super();
+    this.name = 'HttpRequest';
+    this.entryType = 'http';
+    const startTime = statistics.startTime;
+    const diff = process.hrtime(startTime);
+    this.duration = diff[0] * 1000 + diff[1] / 1e6;
+    this.startTime = startTime[0] * 1000 + startTime[1] / 1e6;
+  }
+}
+
+function emitStatistics(statistics) {
+  notify('http', new HttpRequestTiming(statistics));
+}
+
 module.exports = {
   outHeadersKey: Symbol('outHeadersKey'),
   ondrain,
   nowDate,
-  utcDate
+  utcDate,
+  emitStatistics
 };

lib/perf_hooks.js

@@ -25,6 +25,7 @@ const {
   NODE_PERFORMANCE_ENTRY_TYPE_GC,
   NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION,
   NODE_PERFORMANCE_ENTRY_TYPE_HTTP2,
+  NODE_PERFORMANCE_ENTRY_TYPE_HTTP,
 
   NODE_PERFORMANCE_MILESTONE_NODE_START,
   NODE_PERFORMANCE_MILESTONE_V8_START,
@@ -70,7 +71,8 @@ const observerableTypes = [
   'measure',
   'gc',
   'function',
-  'http2'
+  'http2',
+  'http'
 ];
 
 const IDX_STREAM_STATS_ID = 0;
@@ -511,6 +513,7 @@ function mapTypes(i) {
     case 'gc': return NODE_PERFORMANCE_ENTRY_TYPE_GC;
     case 'function': return NODE_PERFORMANCE_ENTRY_TYPE_FUNCTION;
     case 'http2': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP2;
+    case 'http': return NODE_PERFORMANCE_ENTRY_TYPE_HTTP;
   }
 }
 

src/node_perf.cc

@@ -366,6 +366,21 @@ void Timerify(const FunctionCallbackInfo<Value>& args) {
   args.GetReturnValue().Set(wrap);
 }
 
+// Notify a custom PerformanceEntry to observers
+void Notify(const FunctionCallbackInfo<Value>& args) {
+  Environment* env = Environment::GetCurrent(args);
+  Utf8Value type(env->isolate(), args[0]);
+  Local<Value> entry = args[1];
+  PerformanceEntryType entry_type = ToPerformanceEntryTypeEnum(*type);
+  AliasedUint32Array& observers = env->performance_state()->observers;
+  if (entry_type != NODE_PERFORMANCE_ENTRY_TYPE_INVALID &&
+      observers[entry_type]) {
+    USE(env->performance_entry_callback()->
+      Call(env->context(), Undefined(env->isolate()), 1, &entry));
+  }
+}
+
+
 // Event Loop Timing Histogram
 namespace {
 static void ELDHistogramMin(const FunctionCallbackInfo<Value>& args) {
@@ -562,6 +577,7 @@ void Initialize(Local<Object> target,
   env->SetMethod(target, "timerify", Timerify);
   env->SetMethod(
       target, "setupGarbageCollectionTracking", SetupGarbageCollectionTracking);
+  env->SetMethod(target, "notify", Notify);
 
   Local<Object> constants = Object::New(isolate);
 

src/node_perf_common.h

@@ -35,7 +35,8 @@ extern uint64_t performance_v8_start;
   V(MEASURE, "measure")                                                       \
   V(GC, "gc")                                                                 \
   V(FUNCTION, "function")                                                     \
-  V(HTTP2, "http2")
+  V(HTTP2, "http2")                                                           \
+  V(HTTP, "http")
 
 enum PerformanceMilestone {
 #define V(name, _) NODE_PERFORMANCE_MILESTONE_##name,

test/parallel/test-http-perf_hooks.js

@@ -0,0 +1,58 @@
+'use strict';
+
+const common = require('../common');
+const assert = require('assert');
+const http = require('http');
+
+const { PerformanceObserver } = require('perf_hooks');
+
+const obs = new PerformanceObserver(common.mustCall((items) => {
+  const entry = items.getEntries()[0];
+  assert.strictEqual(entry.entryType, 'http');
+  assert.strictEqual(typeof entry.startTime, 'number');
+  assert.strictEqual(typeof entry.duration, 'number');
+}, 2));
+
+obs.observe({ entryTypes: ['http'] });
+
+const expected = 'Post Body For Test';
+const makeRequest = (options) => {
+  return new Promise((resolve, reject) => {
+    http.request(options, common.mustCall((res) => {
+      resolve();
+    })).on('error', reject).end(options.data);
+  });
+};
+
+const server = http.Server(common.mustCall((req, res) => {
+  let result = '';
+
+  req.setEncoding('utf8');
+  req.on('data', function(chunk) {
+    result += chunk;
+  });
+
+  req.on('end', common.mustCall(function() {
+    assert.strictEqual(result, expected);
+    res.writeHead(200);
+    res.end('hello world\n');
+  }));
+}, 2));
+
+server.listen(0, common.mustCall(async () => {
+  await Promise.all([
+    makeRequest({
+      port: server.address().port,
+      path: '/',
+      method: 'POST',
+      data: expected
+    }),
+    makeRequest({
+      port: server.address().port,
+      path: '/',
+      method: 'POST',
+      data: expected
+    })
+  ]);
+  server.close();
+}));