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...