TypeError: Expected a number, got number

[bzoz]

When benchmarking this node.js script with:
autocannon -d 1 localhost:1234

Result:

Running 1s test @ http://localhost:1234
10 connections

/usr/local/lib/node_modules/autocannon/node_modules/pretty-bytes/index.js:6
        throw new TypeError('Expected a number, got ' + typeof num);
        ^

TypeError: Expected a number, got number
    at module.exports (/usr/local/lib/node_modules/autocannon/node_modules/pretty-bytes/index.js:6:9)
    at asBytes (/usr/local/lib/node_modules/autocannon/lib/progressTracker.js:170:20)
    at EventEmitter.instance.on (/usr/local/lib/node_modules/autocannon/lib/progressTracker.js:59:38)
    at emitOne (events.js:101:20)
    at EventEmitter.emit (events.js:188:7)
    at Timeout.setInterval (/usr/local/lib/node_modules/autocannon/lib/run.js:181:15)
    at Timeout.wrapper (timers.js:425:11)
    at tryOnTimeout (timers.js:232:11)
    at Timer.listOnTimeout (timers.js:202:5)

This does not happen, when -j is used, which produces:

{"url":"http://localhost:1234","requests":{"average":1680,"mean":1680,"stddev":0,"min":1680,"max":1680,"total":1680,"sent":1690},"latency":{"average":5.54,"mean":5.54,"stddev":2.36,"min":3,"max":19,"p50":4,"p75":7,"p90":9,"p99":14,"p999":17,"p9999":19,"p99999":19},"throughput":{"average":null,"mean":null,"stddev":null,"min":-1,"max":0,"total":1761814320},"errors":0,"timeouts":0,"duration":1,"start":"2016-08-08T10:58:21.518Z","finish":"2016-08-08T10:58:22.540Z","connections":10,"pipelining":1,"non2xx":0,"1xx":0,"2xx":1680,"3xx":0,"4xx":0,"5xx":0}

[GlenTiki]

Unfortunately I'm having some trouble reproducing this, can you confirm this is happening with current master?

[mcollina]

Maybe this is related: #83

[bzoz]

@thekemkid Tried with master, same results.

@mcollina Changing -d does not make any difference, so they seem unrelated.

From what I observed, this error only occurs with high values for len. If I change it from 1m to 1k autocannon works as expected. Also note, that in the json output all values for "throughput" are null.

[mcollina]

@bzoz can you please upload a little test server that exhibits this? And also the actual options you are using for autocannon.

[bzoz]

Here https://gist.github.com/bzoz/4bedbd51c3160875144c1dd108673eaa.

This is cropped version of https://github.com/nodejs/node/blob/master/benchmark/http/end-vs-write-end.js. With buf as type, 1024 as kb and write as method.

[mcollina]

I can't reproduce with v0.13.3. Which version are you on?

I can get:

$ ./autocannon.js -d 1 localhost:1234
Running 1s test @ http://localhost:1234
10 connections

Stat         Avg Stdev Max
Latency (ms) NaN NaN   0
Req/Sec      0   0     0
Bytes/Sec    0 B 0 B   0 B

0 requests in 1s, 0 B read

Meaning that 0 requests completed (with a buffer of 1024*1024*1024).

[bzoz]

I'm trying it with one in the master branch. It happens when autocannon tires to pretty-print result.throughput which contains NaN values. The json output I get:

{"url":"http://localhost:1234","requests":{"average":1605,"mean":1605,"stddev":0,"min":1605,"max":1605,"total":1605,"sent":1615},"latency":{"average":5.81,"mean":5.81,"stddev":2.94,"min":2,"max":34,"p50":4,"p75":7,"p90":9,"p99":16,"p999":23,"p9999":34,"p99999":34},"throughput":{"average":null,"mean":null,"stddev":null,"min":-1,"max":0,"total":1683161895},"errors":0,"timeouts":0,"duration":1,"start":"2016-08-16T12:44:33.606Z","finish":"2016-08-16T12:44:34.625Z","connections":10,"pipelining":1,"non2xx":0,"1xx":0,"2xx":1605,"3xx":0,"4xx":0,"5xx":0}

It seems it is somewhat flaky, as I am able to run autocannon successfully from time to time.

[bzoz]

Another thing I found: if I slow down my VM, problem goes away. Could there be overflow somewhere in throughput calculations?

[bzoz]

I played some more, and I think I nailed it: this happens when rate gets above 1 GB/s.

[mcollina]

@bzoz I can't get it to trigger the error :(.

I played some more, and I think I nailed it: this happens when rate gets above 1 GB/s.

I'm very impressed autocannon can go that fast 💨 💃 .

throughput":{"average":null,"mean":null,"stddev":null,"min":-1,"max":0,"total":1683161895}

This is probably wrong, and maybe it's related to a duration of 1s. Can you try something longer, maybe 5-10s? Can you still reproduce?

Worst-case: we just wrap it in a check if it is NaN or null: https://github.com/mcollina/autocannon/blob/master/lib/progressTracker.js#L95.

[bzoz]

I've added if (numberIsNan(num)) return 'NaN'; to pretty-bytes. Now I get this:

Running 10s test @ http://localhost:1234
10 connections

Stat         Avg    Stdev  Max  
Latency (ms) 4.66   2      26   
Req/Sec      1987.8 158.83 2131 
Bytes/Sec    NaN    NaN    0 B  

20k requests in 10s, 20.84 GB read

[bzoz]

https://github.com/mcollina/autocannon/blob/master/lib/run.js#L37 causes this. If I add one more zero there it works. If you remove one or two you should start getting the same errors that I had.

[mcollina]

LOL, I thought 1000000000 was a bigger enough number. Would you like to send a PR on that? Adding zeros is perfect.

[bzoz]

I'll make the PR. I think two more will be enough :)