benchmark: report latency percentiles in http benchmarks

benchmark/_http-benchmarkers.js

@@ -56,6 +56,17 @@ class AutocannonBenchmarker {
     }
     return result.requests.average;
   }
+
+  processLatency(output) {
+    // Autocannon records latencies in whole milliseconds.
+    const { latency } = JSON.parse(output);
+    return {
+      p50: latency.p50,
+      p90: latency.p90,
+      p99: latency.p99,
+      p99_9: latency.p99_9,
+    };
+  }
 }
 
 class WrkBenchmarker {
@@ -72,6 +83,7 @@ class WrkBenchmarker {
       options.duration;
     const scheme = options.scheme || 'http';
     const args = [
+      '--latency',
       '-d', duration,
       '-c', options.connections,
       '-t', Math.min(options.connections, require('os').availableParallelism() || 8),
@@ -93,6 +105,20 @@ class WrkBenchmarker {
     }
     return throughput;
   }
+
+  processLatency(output) {
+    // Lines of the "Latency Distribution" table printed with --latency,
+    // e.g. "     99%    1.05ms".
+    const lineRe = /^\s+(\d+(?:\.\d+)?)%\s+([0-9.]+)(us|ms|s)$/gm;
+    const unitToMs = { us: 1e-3, ms: 1, s: 1e3 };
+    const keys = { '50': 'p50', '90': 'p90', '99': 'p99', '99.9': 'p99_9' };
+    const latency = {};
+    for (const [, percentile, value, unit] of output.matchAll(lineRe)) {
+      const key = keys[String(Number(percentile))];
+      if (key) latency[key] = Number(value) * unitToMs[unit];
+    }
+    return Object.keys(latency).length > 0 ? latency : undefined;
+  }
 }
 
 /**
@@ -133,6 +159,10 @@ class TestDoubleBenchmarker {
     }
     return result.throughput;
   }
+
+  processLatency(output) {
+    return JSON.parse(output).latency;
+  }
 }
 
 /**
@@ -259,8 +289,9 @@ exports.run = function(options, callback) {
       return;
     }
 
+    const latency = benchmarker.processLatency?.(stdout);
     const elapsed = benchmark_end - benchmarker_start;
-    callback(null, code, options.benchmarker, result, elapsed);
+    callback(null, code, options.benchmarker, result, elapsed, latency);
   });
 
 };

benchmark/_test-double-benchmarker.js

@@ -11,24 +11,41 @@ if (myModule === 'https') {
 }
 
 const http = require(myModule);
+const { createHistogram } = require('perf_hooks');
 
 const duration = +process.env.duration;
 const url = process.env.test_url;
 
 const start = process.hrtime();
 let throughput = 0;
+const latencies = createHistogram();
+let requestStart;
+
+function latencyInMs() {
+  if (latencies.count === 0) {
+    return undefined;
+  }
+  const toMs = (ns) => ns / 1e6;
+  return {
+    p50: toMs(latencies.percentile(50)),
+    p90: toMs(latencies.percentile(90)),
+    p99: toMs(latencies.percentile(99)),
+    p99_9: toMs(latencies.percentile(99.9)),
+  };
+}
 
 function request(res, client) {
   res.resume();
   res.on('error', () => {});
   res.on('end', () => {
     throughput++;
+    latencies.record(process.hrtime.bigint() - requestStart);
     const [sec, nanosec] = process.hrtime(start);
     const ms = sec * 1000 + nanosec / 1e6;
     if (ms < duration * 1000) {
       run();
     } else {
-      console.log(JSON.stringify({ throughput }));
+      console.log(JSON.stringify({ throughput, latency: latencyInMs() }));
       if (client) {
         client.destroy();
         process.exit(0);
@@ -38,6 +55,7 @@ function request(res, client) {
 }
 
 function run() {
+  requestStart = process.hrtime.bigint();
   if (http.get) { // HTTP or HTTPS
     if (options) {
       http.get(url, options, request);

benchmark/common.js

@@ -183,7 +183,7 @@ class Benchmark {
                                  this.extra_options.benchmarker ||
                                  http_benchmarkers.default_http_benchmarker;
     http_benchmarkers.run(
-      http_options, (error, code, used_benchmarker, result, elapsed) => {
+      http_options, (error, code, used_benchmarker, result, elapsed, latency) => {
         if (cb) {
           cb(code);
         }
@@ -192,7 +192,7 @@ class Benchmark {
           process.exit(code || 1);
         }
         this.config.benchmarker = used_benchmarker;
-        this.report(result, elapsed);
+        this.report(result, elapsed, latency);
       },
     );
   }
@@ -319,14 +319,19 @@ class Benchmark {
     this.report(rate, elapsed);
   }
 
-  report(rate, elapsed) {
-    sendResult({
+  report(rate, elapsed, latency) {
+    const data = {
       name: this.name,
       conf: this.config,
       rate,
       time: nanoSecondsToString(elapsed),
       type: 'report',
-    });
+    };
+    // Latency percentiles in milliseconds, only reported by HTTP benchmarks.
+    if (latency !== undefined) {
+      data.latency = latency;
+    }
+    sendResult(data);
   }
 }
 
@@ -349,7 +354,17 @@ function formatResult(data) {
   let rate = data.rate.toString().split('.');
   rate[0] = rate[0].replace(/(\d)(?=(?:\d\d\d)+(?!\d))/g, '$1,');
   rate = (rate[1] ? rate.join('.') : rate[0]);
-  return `${data.name}${conf}: ${rate}\n`;
+  return `${data.name}${conf}: ${rate}${formatLatency(data.latency)}\n`;
+}
+
+function formatLatency(latency) {
+  if (latency === undefined) {
+    return '';
+  }
+  const percentiles = Object.entries(latency)
+    .map(([key, ms]) => `${key.slice(1).replace('_', '.')}%=${+ms.toFixed(3)}`)
+    .join(' ');
+  return ` (latency ms: ${percentiles})`;
 }
 
 function sendResult(data) {

benchmark/run.js

@@ -86,7 +86,13 @@ function runBenchmark(filename) {
         let rate = data.rate.toString().split('.');
         rate[0] = rate[0].replace(/(\d)(?=(?:\d\d\d)+(?!\d))/g, '$1,');
         rate = (rate[1] ? rate.join('.') : rate[0]);
-        console.log(`${data.name} ${conf}: ${rate}`);
+        let latency = '';
+        if (data.latency !== undefined) {
+          latency = ' (latency ms: ' + Object.entries(data.latency)
+            .map(([key, ms]) => `${key.slice(1).replace('_', '.')}%=${+ms.toFixed(3)}`)
+            .join(' ') + ')';
+        }
+        console.log(`${data.name} ${conf}: ${rate}${latency}`);
       }
     });
     child.once('close', (code) => {

doc/contributing/writing-and-running-benchmarks.md

@@ -55,6 +55,18 @@ node benchmark/run.js --set benchmarker=autocannon http
 node benchmark/http/simple.js benchmarker=autocannon
 ```
 
+Besides the throughput, HTTP benchmarks report the latency percentiles
+measured by the benchmarker, in milliseconds:
+
+```console
+http/simple.js c=500 benchmarker="autocannon": 16,217.34 (latency ms: 50%=28 90%=34 99%=257 99.9%=270)
+```
+
+The resolution depends on the benchmarker: `autocannon` records whole
+milliseconds, `wrk` reports microseconds and does not print the 99.9th
+percentile, and `h2load` reports no percentiles. The CSV output and the
+comparison tools only use the throughput.
+
 #### HTTPS benchmark requirements
 
 To run the `https` benchmarks, one of `autocannon` or `wrk` benchmarkers must