process.hrtime() unreliable? #13102
Description
- Version: v8.0.0-pre
- Platform: ubuntu1604-32
- Subsystem: process
From https://ci.nodejs.org/job/node-test-commit-linux/9926/nodes=ubuntu1604-32/consoleText:
not ok 1431 sequential/test-benchmark-http
---
duration_ms: 5.128
severity: fail
stack: |-
http/bench-parser.js
http/bench-parser.js n=1 len=1: 2,785.3291144881678
http/check_invalid_header_char.js
http/check_invalid_header_char.js n=1 key="": 2,725.8503290101344
http/check_invalid_header_char.js n=1 key="1": 3,342.2013074691513
http/check_invalid_header_char.js n=1 key="\t\t\t\t\t\t\t\t\t\tFoo bar baz": 2,301.1676124465553
http/check_invalid_header_char.js n=1 key="keep-alive": 1,714.8099561866056
http/check_invalid_header_char.js n=1 key="close": 1,836.9656266991933
http/check_invalid_header_char.js n=1 key="gzip": 2,570.79321824749
http/check_invalid_header_char.js n=1 key="20091": 2,455.1023163890354
http/check_invalid_header_char.js n=1 key="private": 3,152.505611459989
http/check_invalid_header_char.js n=1 key="text/html; charset=utf-8": 2,783.9023629763255
http/check_invalid_header_char.js n=1 key="text/plain": 1,932.2065992584191
http/check_invalid_header_char.js n=1 key="Sat, 07 May 2016 16:54:48 GMT": 2,396.380506882405
http/check_invalid_header_char.js n=1 key="SAMEORIGIN": 1,960.0387303653122
http/check_invalid_header_char.js n=1 key="en-US": 468.65297418893743
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": 2,780.4655611535595
http/check_invalid_header_char.js n=1 key="中文呢": 2,113.7403692704424
http/check_invalid_header_char.js n=1 key="foo\nbar": 2,560.6424139688165
http/check_invalid_header_char.js n=1 key="�": 2,448.3100539852367
http/check_is_http_token.js
http/check_is_http_token.js n=1 key="TCN": 2,627.61677785865
http/check_is_http_token.js n=1 key="ETag": 2,592.439926685799
http/check_is_http_token.js n=1 key="date": 3,146.6628067602906
http/check_is_http_token.js n=1 key="Vary": 2,676.5090827335725
http/check_is_http_token.js n=1 key="server": 1,933.1665654976161
http/check_is_http_token.js n=1 key="Server": 2,698.0431093328007
http/check_is_http_token.js n=1 key="status": 3,234.8536067000286
http/check_is_http_token.js n=1 key="version": 3,105.6575764069403
http/check_is_http_token.js n=1 key="Expires": 3,122.765271102867
http/check_is_http_token.js n=1 key="alt-svc": 2,156.3156328570753
http/check_is_http_token.js n=1 key="location": 1,954.7093835823962
/home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-32/benchmark/common.js:200
throw new Error('insufficient time precision for short benchmark');
^
Error: insufficient time precision for short benchmark
at Benchmark.end (/home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-32/benchmark/common.js:200:11)
at main (/home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-32/benchmark/http/check_is_http_token.js:51:9)
at Benchmark.process.nextTick (/home/iojs/build/workspace/node-test-commit-linux/nodes/ubuntu1604-32/benchmark/common.js:34:28)
at _combinedTickCallback (internal/process/next_tick.js:95:7)
at process._tickCallback (internal/process/next_tick.js:161:9)
at Function.Module.runMain (module.js:607:11)
at startup (bootstrap_node.js:144:16)
at bootstrap_node.js:561:3
assert.js:92
throw new AssertionError({
^
AssertionError [ERR_ASSERTION]: 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:197:12)
...Relevant code
Quick and easy
test/benchmark/check_is_http_token.js: Pretty straightforward, but worth checking for anything funky.lib/_http_common.js: The_checkIsHttpToken()function is also straightforward, but worth looking at just in case...
Slightly more involved
benchmark/common.js:Benchmark.prototype.start()andBenchmark.prototype.end()are pretty straightforward and seem unlikely sources of the problem. Thethrowin the stack trace above is on line 200 (currently). This is the "what in the world is going on?!?!?!" part.process.hrtime()is called in one function and saved tothis._time. Then at a later time,process.hrtime(this._time)is called and the result is[0, 0]. ???? (I don't see anything funky going on withthisbut maybe there's a subtlety I'm missing?)
Deeper dive
lib/internal/process.js:setup_hrtime()src/node.cc:Hrtime()deps/uv/src/unix/linux-core.c:uv__hrtime()
Anything at all going on in the above that could somehow result in this odd behavior?
Possible causes
I'm having trouble coming up with an explanation that seems likely, but it's gotta be something, so...
- Somehow, this fairly fast machine running Ubuntu 16.04 nonetheless lacks nanosecond precision.
- Some subtle bug in the benchmark
common.jsthat causesthis._timeto be set incorrectly. - Small but infrequently triggered bug in the bit-shifting arithmetic in the
Deeper diveitems listed above? - Bug in Linux
- Expected behavior in Linux unexpected in our benchmark/core code. (Maybe calling
clock_gettime()too many times in fast succession might return the same time even though it's supposed to have nanosecond precision in this situation?) - Bug/expected behavior specific to some container/virtual machine magic Digital Ocean is using?
Any other ideas?
/cc @nodejs/benchmarking @mscdex @joyeecheung @jasnell @nodejs/build @addaleax @saghul
Refs: #12934