diff --git a/benchmark/_http-benchmarkers.js b/benchmark/_http-benchmarkers.js index b9ef93c149f7..a189666d6d4d 100644 --- a/benchmark/_http-benchmarkers.js +++ b/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); }); }; diff --git a/benchmark/_test-double-benchmarker.js b/benchmark/_test-double-benchmarker.js index 2d05f9fd92be..ccaa555fb8c7 100644 --- a/benchmark/_test-double-benchmarker.js +++ b/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); diff --git a/benchmark/common.js b/benchmark/common.js index 734c664c80f5..12bcabf1c49f 100644 --- a/benchmark/common.js +++ b/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) { diff --git a/benchmark/run.js b/benchmark/run.js index 455ddc4f2dfc..dae412a72e4c 100644 --- a/benchmark/run.js +++ b/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) => { diff --git a/doc/contributing/writing-and-running-benchmarks.md b/doc/contributing/writing-and-running-benchmarks.md index bf397c123a24..8c7bff68c011 100644 --- a/doc/contributing/writing-and-running-benchmarks.md +++ b/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