investigate flaky sequential/test-benchmark-http

[Trott]

• Version: v8.0.0-pre
• Platform: ubuntu1604-32
• Subsystem: test

https://ci.nodejs.org/job/node-test-commit-linux/9126/nodes=ubuntu1604-32/console

 duration_ms: 6.324
 severity: fail
 stack: |-
 
 http/bench-parser.js
 http/bench-parser.js n=1 len=1: 699.2112198229178
 
 http/check_invalid_header_char.js
 http/check_invalid_header_char.js n=1 key="": 1,391.0024398182795
 http/check_invalid_header_char.js n=1 key="1": 2,476.4367047542632
 http/check_invalid_header_char.js n=1 key="\t\t\t\t\t\t\t\t\t\tFoo bar baz": 3,290.751015196688
 http/check_invalid_header_char.js n=1 key="keep-alive": 2,944.10325558938
 http/check_invalid_header_char.js n=1 key="close": 3,087.3631140379316
 http/check_invalid_header_char.js n=1 key="gzip": 671.2657319515104
 http/check_invalid_header_char.js n=1 key="20091": 1,022.5733057238541
 http/check_invalid_header_char.js n=1 key="private": 2,383.250515377924
 http/check_invalid_header_char.js n=1 key="text/html; charset=utf-8": 3,135.199194880847
 http/check_invalid_header_char.js n=1 key="text/plain": 2,567.282044172655
 http/check_invalid_header_char.js n=1 key="Sat, 07 May 2016 16:54:48 GMT": 3,018.412315122246
 http/check_invalid_header_char.js n=1 key="SAMEORIGIN": 2,629.288698528387
 http/check_invalid_header_char.js n=1 key="en-US": 2,061.1969370613515
 http/check_invalid_header_char.js n=1 key="Here is a value that is really a folded header value\r\n this should be supported, but it is not currently": 1,317.3546990700793
 http/check_invalid_header_char.js n=1 key="中文呢": 2,332.818558038193
 http/check_invalid_header_char.js n=1 key="foo\nbar": 2,046.6639377814165
 http/check_invalid_header_char.js n=1 key="�": 3,564.9352964243703
 
 http/check_is_http_token.js
 http/check_is_http_token.js n=1 key="TCN": 3,193.9697850458333
 http/check_is_http_token.js n=1 key="ETag": 2,912.522390015873
 http/check_is_http_token.js n=1 key="date": 2,507.9376225754513
 http/check_is_http_token.js n=1 key="Vary": 3,599.569491488818
 http/check_is_http_token.js n=1 key="server": 2,737.798317349154
 http/check_is_http_token.js n=1 key="Server": 3,361.7287353848847
 http/check_is_http_token.js n=1 key="status": 3,139.0965052438605
 http/check_is_http_token.js n=1 key="version": 3,113.9261003057877
 http/check_is_http_token.js n=1 key="Expires": 2,320.2232982902274
 http/check_is_http_token.js n=1 key="alt-svc": 2,312.058541322266
 http/check_is_http_token.js n=1 key="location": 3,394.9056046496626
 http/check_is_http_token.js n=1 key="Connection": 3,323.4295133834507
 http/check_is_http_token.js n=1 key="Keep-Alive": 2,866.2657716274084
 http/check_is_http_token.js n=1 key="content-type": 1,048.6280275201939
 http/check_is_http_token.js n=1 key="Content-Type": 2,749.14845126722
 /home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-32/benchmark/run.js:62
 var rate = data.rate.toString().split('.');
 ^
 
 TypeError: Cannot read property 'toString' of null
 at ChildProcess.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-32/benchmark/run.js:62:27)
 at emitTwo (events.js:125:13)
 at ChildProcess.emit (events.js:213:7)
 at process.nextTick (internal/child_process.js:748:12)
 at _combinedTickCallback (internal/process/next_tick.js:73:7)
 at process._tickCallback (internal/process/next_tick.js:104:9)
 
 assert.js:86
 throw new assert.AssertionError({
 ^
 AssertionError: 1 === 0
 at ChildProcess.child.on (/home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-32/test/sequential/test-benchmark-http.js:32:10)
 at emitTwo (events.js:125:13)
 at ChildProcess.emit (events.js:213:7)
 at Process.ChildProcess._handle.onexit (internal/child_process.js:208:12)
 events.js:182
 throw er; // Unhandled 'error' event
 ^
 
 Error: channel closed
 at process.target.send (internal/child_process.js:544:16)
 at ChildProcess.sendResult (/home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-32/benchmark/common.js:221:13)
 at emitTwo (events.js:125:13)
 at ChildProcess.emit (events.js:213:7)
 at process.nextTick (internal/child_process.js:748:12)
 at _combinedTickCallback (internal/process/next_tick.js:73:7)
 at process._tickCallback (internal/process/next_tick.js:104:9)

/cc @joyeecheung

[joyeecheung]

Hmm..not sure how data.rate can be a null from a glance of run.js and common.js..I will investigate it

[refack]

ping @joyeecheung any progress? need help?

[joyeecheung]

@refack See #12934 ....

[joyeecheung]

To elaborate, probably on some hosts hrtime returns two 0s and results a in NaN as rate, then this turns into null during IPC message serialization. Now there would be an error when things like this happens so we probably need to wait for the next time it shows up in the CI.

The next step could be making the tests that result in a 0 elapsed time run a bit longer, I guess..? Or just skip the tests when hrtime is not precise enough

[Trott]

Or just skip the tests when hrtime is not precise enough

I think that's the way to go. But only after we've confirmed that this is really the source of the problem, or course...