fs.writeFile callback get slower with the call times grows

[lolobug]

Since No reply in https://github.com/nodejs/help for 12 day.

• Node.js Version:v10.3.0
• OS:mac
• Scope (install, code, runtime, meta, other?):runtime
• Module (and version) (if relevant):fs

Simple benchmark as following below.

const fs = require('fs');

const testCount = 50;

const cols = 4196;
var strArrs = [];
for (var i = 0; i < testCount; i++) {
  strArrs.push(randomRow(cols));
}

var begin = Date.now(); 
var suc=0; 
for (var i = 0; i < testCount; i++) {
    wr(i, strArrs[i]);
}

function wr(index, str) {
  fs.writeFile('./test' + '_'+ index + '.txt', str, err=>{
    if (err)return;
    console.log(index + ' cost:' + (Date.now() - begin));
    if (++suc ==testCount) {
      console.log('all cost:' + (Date.now() - begin));
    }
  });
}

function randomChar() {
  return String.fromCharCode(Math.floor(Math.random() * (122 - 65) + 65));
}

function randomString(length) {
  let string = '';
  for (let i = 0; i < length; i++) {
    string += randomChar();
  }
  return string;
}

function randomRow(cols) {
  const cells = [];
  for (let i = 0; i < cols; i++) {
    cells.push(randomString(200));
  }
  return cells.join(',') + '\n';
}

when testCount=50, the output:

0 cost:177 \\first callback
4 cost:180
.....
49 cost:182
48 cost:182
all cost:182

when testCount=4, the output:

0 cost:16 \\first callback
3 cost:18
1 cost:19
2 cost:19
all cost:19

Why the first callback get much slower when the call times grow to 50.
I think all the fs.writeFile invocations will be queued in the thread pool. And in the uv_run, the epoll step
will callback when the first fs.writeFile done. But the cost of the first fs.writeFile should not be relevant to the call times ？

Using fs.readFile 、 fs.createWriteStream 、fs.createReadStream has the same issue.

[bnoordhuis]

I don't think there's an actual bug here but I can see why it's surprising behavior. I'll explain.

Start node with node --trace_gc --trace_gc_verbose script.js and note how much garbage it collects. Your script creates really long cons strings (tree of string fragments) that need to be flattened before they can be written to disk. That takes up time and memory, and more memory means more work for the garbage collector.

If you insert for (var i = 0; i < testCount; i++) Number(strArrs[i]) before var begin = Date.now() you force the strings to flatten upfront and you'll notice how the throughput times go down by about 50%.

Alternatively, if you replace the call to randomRows() with 'x'.repeat(824 * 1024) (I think I got the size right) you'll notice the same drop in throughput times.

To summarize: the fs throughput times are really a red herring, the real cost center was elsewhere.