Running benchmark/http/incoming_headers.js fails with error "autocannon produced strange output"

[trivikr]

• Version: master, v12.14.0, v10.18.0
• Platform: Ubuntu
• Subsystem: http

Describe the bug
Running benchmark/http/incoming_headers.js fails with error "autocannon produced strange output" for:

• master
• v12.14.0
• v10.18.0

To Reproduce
Follow instructions in running benchmarks to run benchmark/http/incoming_headers.js

Example:

$ node -v
v12.14.0

$ node benchmark/http/incoming_headers.js
Error: autocannon produced strange output: {"url":"http://127.0.0.1:12346/","requests":{"average":0,"mean":0,"stddev":0,"min":0,"max":0,"total":0,"p0_001":0,"p0_01":0,"p0_1":0,"p1":0,"p2_5":0,"p10":0,"p25":0,"p50":0,"p75":0,"p90":0,"p97_5":0,"p99":0,"p99_9":0,"p99_99":0,"p99_999":0,"sent":89280},"latency":{"average":0,"mean":0,"stddev":0,"min":0,"max":0,"p0_001":0,"p0_01":0,"p0_1":0,"p1":0,"p2_5":0,"p10":0,"p25":0,"p50":0,"p75":0,"p90":0,"p97_5":0,"p99":0,"p99_9":0,"p99_99":0,"p99_999":0},"throughput":{"average":0,"mean":0,"stddev":0,"min":0,"max":0,"total":0,"p0_001":0,"p0_01":0,"p0_1":0,"p1":0,"p2_5":0,"p10":0,"p25":0,"p50":0,"p75":0,"p90":0,"p97_5":0,"p99":0,"p99_9":0,"p99_99":0,"p99_999":0},"errors":0,"timeouts":0,"duration":5.03,"start":"2019-12-18T17:05:17.412Z","finish":"2019-12-18T17:05:22.440Z","connections":50,"pipelining":1,"non2xx":0,"1xx":0,"2xx":0,"3xx":0,"4xx":0,"5xx":0}

    at ChildProcess.<anonymous> (/home/trivikr/workspace/node/benchmark/_http-benchmarkers.js:235:16)
    at Object.onceWrapper (events.js:300:26)
    at ChildProcess.emit (events.js:210:5)
    at maybeClose (internal/child_process.js:1021:16)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:283:5)

$ nvm use 10
Now using node v10.18.0 (npm v6.13.4)

$ node benchmark/http/incoming_headers.js
Error: autocannon produced strange output: {"url":"http://127.0.0.1:12346/","requests":{"average":0,"mean":0,"stddev":0,"min":0,"max":0,"total":0,"p0_001":0,"p0_01":0,"p0_1":0,"p1":0,"p2_5":0,"p10":0,"p25":0,"p50":0,"p75":0,"p90":0,"p97_5":0,"p99":0,"p99_9":0,"p99_99":0,"p99_999":0,"sent":90101},"latency":{"average":0,"mean":0,"stddev":0,"min":0,"max":0,"p0_001":0,"p0_01":0,"p0_1":0,"p1":0,"p2_5":0,"p10":0,"p25":0,"p50":0,"p75":0,"p90":0,"p97_5":0,"p99":0,"p99_9":0,"p99_99":0,"p99_999":0},"throughput":{"average":0,"mean":0,"stddev":0,"min":0,"max":0,"total":0,"p0_001":0,"p0_01":0,"p0_1":0,"p1":0,"p2_5":0,"p10":0,"p25":0,"p50":0,"p75":0,"p90":0,"p97_5":0,"p99":0,"p99_9":0,"p99_99":0,"p99_999":0},"errors":0,"timeouts":0,"duration":5.11,"start":"2019-12-18T17:09:06.423Z","finish":"2019-12-18T17:09:11.532Z","connections":50,"pipelining":1,"non2xx":0,"1xx":0,"2xx":0,"3xx":0,"4xx":0,"5xx":0}

    at ChildProcess.child.once (/home/trivikr/workspace/node/benchmark/_http-benchmarkers.js:235:16)
    at Object.onceWrapper (events.js:286:20)
    at ChildProcess.emit (events.js:198:13)
    at maybeClose (internal/child_process.js:982:16)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:259:5)

Expected behavior
The benchmark/http/headers.js runs without any error

Additional context
I came across this issue as part of running benchmarks while moving to for...of loop in the initial commits of #30958

[trivikr]

cc @mcollina

[Trott]

@trivikr What do you get with autocannon -v?

[Trott]

@trivikr What do you get with autocannon -v?

Actually, never mind. I'm able to reproduce with latest autocannon (4.4.1). Have to set PATH to ignore wrk (or uninstall wrk or something else to get wrk to be ignored) I think because the benchmarker will favor wrk.

So, @trivikr, if you want, a quick workaround might be to install wrk.

[trivikr]

What do you get with autocannon -v?

I don't have my laptop with me right now, but it's the latest one. As per npm, it should be v4.4.1

I installed it while testing headers benchmarks #31022 (comment)

[Trott]

I think I see the bug in our code, or at least part of the bug. autocannon is returning 0 for a value where it is checked for being truthy. It probably should accept 0. Will mess around a bit more.

[Trott]

Looks like autocannon is always returning 0 for the average which seems like a bug in autocannon? Or maybe a bug in the benchmark somehow? I've modified the _http-benchmarkers.js to allow 0 as a value. I've tried autocannon 4.4.1, 4.0.0, 3.x, 2.x, and 1.x, and they all return 0 for the average for this test.

http/incoming_headers.js n=0 c=50 benchmarker="autocannon": 0
http/incoming_headers.js n=5 c=50 benchmarker="autocannon": 0
http/incoming_headers.js n=20 c=50 benchmarker="autocannon": 0
http/incoming_headers.js n=0 c=500 benchmarker="autocannon": 0
http/incoming_headers.js n=5 c=500 benchmarker="autocannon": 0
http/incoming_headers.js n=20 c=500 benchmarker="autocannon": 0

wrk on the other hand, returns non-zero values:

http/incoming_headers.js n=0 c=50 benchmarker="wrk": 7,224.63
http/incoming_headers.js n=5 c=50 benchmarker="wrk": 6,806.98
http/incoming_headers.js n=20 c=50 benchmarker="wrk": 6,542.53
http/incoming_headers.js n=0 c=500 benchmarker="wrk": 5,246.36
http/incoming_headers.js n=5 c=500 benchmarker="wrk": 4,281.04
http/incoming_headers.js n=20 c=500 benchmarker="wrk": 5,346.91

[Trott]

Also kind of strange, but if I uninstall autocannon and the code can't find wrk, it still reports that it's using autocannon......

$ which autocannon
$ ./node benchmark/http/incoming_headers.js 
 
Error: autocannon produced strange output: {"url":"http://127.0.0.1:12346/","requests":{"average":0,"mean":0,"stddev":0,"min":0,"max":0,"total":0,"p0_001":0,"p0_01":0,"p0_1":0,"p1":0,"p2_5":0,"p10":0,"p25":0,"p50":0,"p75":0,"p90":0,"p97_5":0,"p99":0,"p99_9":0,"p99_99":0,"p99_999":0,"sent":1015},"latency":{"average":0,"mean":0,"stddev":0,"min":0,"max":0,"p0_001":0,"p0_01":0,"p0_1":0,"p1":0,"p2_5":0,"p10":0,"p25":0,"p50":0,"p75":0,"p90":0,"p97_5":0,"p99":0,"p99_9":0,"p99_99":0,"p99_999":0},"throughput":{"average":0,"mean":0,"stddev":0,"min":0,"max":0,"total":0,"p0_001":0,"p0_01":0,"p0_1":0,"p1":0,"p2_5":0,"p10":0,"p25":0,"p50":0,"p75":0,"p90":0,"p97_5":0,"p99":0,"p99_9":0,"p99_99":0,"p99_999":0},"errors":0,"timeouts":0,"duration":5.2,"start":"2019-12-18T18:38:37.115Z","finish":"2019-12-18T18:38:42.318Z","connections":50,"pipelining":1,"non2xx":0,"1xx":0,"2xx":0,"3xx":0,"4xx":0,"5xx":0}
$

Also, note all the zeroes in the JSON results.

[Trott]

Also kind of strange, but if I uninstall autocannon and the code can't find wrk, it still reports that it's using autocannon......

Whoops, that was my mistake. Set my PATH incorrectly so was picking up a stray autocannon.

[Trott]

Using test-http-double benchmarker gives meaningful results too. So autocannon is the only one not working for this benchmark, I think.

http/incoming_headers.js n=0 c=50 benchmarker="test-double-http": 2,934
http/incoming_headers.js n=5 c=50 benchmarker="test-double-http": 1,420
http/incoming_headers.js n=20 c=50 benchmarker="test-double-http": 1,018
http/incoming_headers.js n=0 c=500 benchmarker="test-double-http": 953
http/incoming_headers.js n=5 c=500 benchmarker="test-double-http": 856
http/incoming_headers.js n=20 c=500 benchmarker="test-double-http": 820