Repository navigation
Investigate flaky parallel/test-fs-read-stream-concurrent-reads #22339
Description
Activity
Reopen:
- Version:
master - Platform: AIX
- Subsystem: fs
- test file - parallel/test-fs-read-stream-concurrent-reads
- ci job - aix/18926/nodes=aix61-ppc64
- ci worker - test-osuosl-aix61-ppc64_be-1
- output:
assert.js:351 throw err; ^ AssertionError [ERR_ASSERTION]: Retaining 524288 bytes in ABs for 1000 chunks of size 170 at ReadStream.fs.createReadStream.on.on.common.mustCall (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/parallel/test-fs-read-stream-concurrent-reads.js:37:9) at ReadStream.<anonymous> (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/common/index.js:346:15) at ReadStream.emit (events.js:187:15) at endReadableNT (_stream_readable.js:1098:12) at process.internalTickCallback (internal/process/next_tick.js:72:19) ```
- Version:
CI stress test: https://ci.nodejs.org/job/node-stress-single-test/2088/
RUN_TESTS:
-J --repeat 10 parallel/test-fs-read-stream-concurrent-reads
RUN_TIMES:100
RUN_LABEL:aix61-ppc64Stress test above confirms flakiness: 15 failures in 100 runs.
Stress test without parallelism: https://ci.nodejs.org/job/node-stress-single-test/2090/
RUN_TESTS:
-j 1 --repeat 10 parallel/test-fs-read-stream-concurrent-reads
RUN_TIMES:100
RUN_LABEL:aix61-ppc64easily recreated in AIX.
Looking at the test case especially the key assertion point:
and wondering what would be the significance of
3.I ran the test several iterations with varying iterations counts, buffer lengths with and without the fix (the test was testing) and have these observations:
- without the fix, the number of buffers (64K) are equal to the number of iterations, deterministically.
- with the fix, this is significantly reduced
- with the fix, the number of buffers is no more dependent on the number of iterations, instead the size of chunks, as well as the number of concurrent reads.
- however, the number of buffers is non-deterministic.
- the non-determinism is (probably) due to:
- the variations of read end callback of one sequence w.r.t data read callback of another sequence
- the variations of data read in one iteration (in 99% cases the whole file content is read in one shot, but due to various environmental circumstances this is split into 2 or 3 or 4 in rare cases)
So probably the number 3 should be relaxed by taking into these fluctuations into account.
/cc @addaleax
Reacted by Rich Trottand wondering what would be the significance of
3.It means that we allocate at most 3 times as much memory as we need. The fix in #25415, where we increase the number to 8, seems somewhat excessive? I think having that kind of memory overhead in Node.js would be considered a bug…
@addaleax - thanks. If you look at the failure message:
AssertionError [ERR_ASSERTION]: Retaining 524288 bytes in ABs for 1000 chunks of size 170showed that the actual consumption stepped out of the assumed value of 510000 (170 * 1000 * 3)
the reason I have identified (empirically) is because few file reads took more than one iterations.
as there is no guarantee on which reads can complete atomically (one shot) and which ones in two, I took the worst case of 2, for every reads, and hence arrived at the number 8.
If you think this is excessive, or being over-generous to the extend of loosing the meaning of this test, please suggest a better way, I am happy to modify.
I have confirmed that the current failures (in AIX and freebsd) do not reveal any issues with the original fix - as with and without the fix I see a drastic difference (in terms of few chunks vs. in terms of 1000 chunks) so it is just a matter of fine tuning the expectation, without causing flakes now and then.
@gireeshpunathil I think that is a part of the issue, yes – whether a read finishes in one piece does matter, you’re right about that.
I think the reason why this matters is that the test, in its current form, starts a new read for each chunk, not when a file stream ends – so it’s possible that the number of concurrent reads increases over time, depending on what the underlying fs operations do, which makes the test less reliable.
Also, the main issue for the high memory-to-content ratio that we are already seeing seems to be that we only use a handful of
ArrayBuffers – 5 or 6, when I run locally (4 initial + 1 or 2 because of the split chunks you are referring to) – of size 65536, which we cannot fill with the actual content (170 * 1000).So, what I would suggest is:
- Move the
startRead()call from.on('data')to.on('end'), so that we get a constant number of parallel reads, and therefore a constant number ofArrayBuffers. - Lightly increase the number of concurrent reads, so that the tests behaviour doesn’t change (e.g. to 6).
- Increase
Nso that we can actually fill theArrayBuffers fully. The formula would beN ~= (pool size) * (concurrent reads) / (file size), e.g.1500as a value that is slightly smaller than65536 * 4 / 170 ~= 1542.
- Move the
- added a commit that references this issue
on Jan 23, 2019 - added a commit that references this issue
on Apr 29, 2019 - added a commit that references this issue
on May 10, 2019 - added a commit that references this issue
on May 16, 2019
https://ci.nodejs.org/job/node-test-commit-aix/16983/nodes=aix61-ppc64/console