Investigate flaky parallel/test-fs-read-stream-concurrent-reads

[Trott]

• Version: 11.0.0-pre (master)
• Platform: aix61-ppc64
• Subsystem: test fs

https://ci.nodejs.org/job/node-test-commit-aix/16983/nodes=aix61-ppc64/console

03:23:13 not ok 649 parallel/test-fs-read-stream-concurrent-reads
03:23:13   ---
03:23:13   duration_ms: 0.861
03:23:13   severity: fail
03:23:13   exitcode: 1
03:23:13   stack: |-
03:23:13     assert.js:338
03:23:13         throw err;
03:23:13         ^
03:23:13     
03:23:13     AssertionError [ERR_ASSERTION]: Retaining 524288 bytes in ABs for 1000 chunks of size 170
03:23:13         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)
03:23:13         at ReadStream.<anonymous> (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/common/index.js:460:15)
03:23:13         at ReadStream.emit (events.js:187:15)
03:23:13         at endReadableNT (_stream_readable.js:1085:12)
03:23:13         at process._tickCallback (internal/process/next_tick.js:63:19)
03:23:13   ...

[refack]

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)  ```

[Trott]

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

[Trott]

Stress 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-ppc64

[gireeshpunathil]

easily recreated in AIX.

Looking at the test case especially the key assertion point:

node/test/parallel/test-fs-read-stream-concurrent-reads.js

Line 37 in 6c01621

assert(retainedMemory / (N * content.length) <= 3,

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

[addaleax]

and 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…

[gireeshpunathil]

@addaleax - thanks. If you look at the failure message:

AssertionError [ERR_ASSERTION]: Retaining 524288 bytes in ABs for 1000 chunks of size 170

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

[addaleax]

@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 of ArrayBuffers.
• Lightly increase the number of concurrent reads, so that the tests behaviour doesn’t change (e.g. to 6).
• Increase N so that we can actually fill the ArrayBuffers fully. The formula would be N ~= (pool size) * (concurrent reads) / (file size), e.g. 1500 as a value that is slightly smaller than 65536 * 4 / 170 ~= 1542.