From node.js, which is faster, shell grep or fs.readFile?

To answer this question, I wrote this little program.

#!/usr/local/bin/node
'use strict';

const fs = require('fs');
const log = '/var/log/maillog';
const fsOpts = { flag: 'r', encoding: 'utf8' };
const wantsRe = new RegExp(process.argv[2]);

function handleResults (err, data) {
    console.log(data);
}

function grepWithFs (file, done) {
    fs.readFile(log, fsOpts, function (err, data) {
        if (err) throw (err);
        let res = '';
        data.toString().split(/\n/).forEach(function (line) {
            if (wantsRe && !wantsRe.test(line)) return;
            res += line + '\n';
        });
        done(null, res);
    });
};

function grepWithShell (file, done) {
    const spawn = require('child_process').spawn;
    let res = '';

    const child = spawn('grep', [ '-e', process.argv[2], file ]);
    child.stdout.on('data', function (buffer) { res += buffer.toString(); });
    child.stdout.on('end', function() { done(null, res); });
};

for (let i=0; i < 10; i++) {
    // grepWithFs(log, handleResults);
    grepWithShell(log, handleResults);
}

Then I alternately ran both functions inside a loop 10x and measured the time it took them to grep the result from a log file that's representative of my use case:

$ ls -alh /var/log/maillog
-rw-r--r--  1 root  wheel    37M Feb  8 16:44 /var/log/maillog

The file system is a pair of mirrored SSDs which are generally quick enough that they aren't the bottleneck. Here are the results:

grepWithShell

$ time node logreader.js 3E-4C03-86DD-FB6EF

real    0m0.238s
user    0m0.181s
sys     0m1.550s

grepWithFs

$ time node logreader.js 3E-4C03-86DD-FB6EF

real    0m6.599s
user    0m5.710s
sys     0m1.751s

The different is huge. Using a shell grep process is dramatically faster. As Andras points out, node's I/O can be tricky, and I didn't try any other fs.read* methods. If there's a better way, please do point it out (preferably with similar test scenario and results).

Here's my nodejs implementation, results are pretty much as expected: small files run faster than a forked grep (files up to 2-3k short lines), large files run slower. The larger the file, the bigger the difference. (And perhaps the more complex the regex, the smaller the difference -- see below.)

I used my own qfgets package for fast line-at-a-time file i/o; there may be better ones out there, I don't know.

I saw an unexpected anomaly that I did not investigate: the below timings are for the constant string regexp /foobar/. When I changed it to /[f][o][o][b][a][r]/ to actually exercise the regex engine, grep slowed down 3x, while node sped up! The 3x slowdown of grep is reproducible on the command line.

filename = "/var/log/apache2/access.log";     // 2,540,034 lines, 187MB
//filename = "/var/log/messages";             // 25,703 lines, 2.5MB
//filename = "out";                           // 2000 lines, 188K (head -2000 access.log)
//filename = "/etc/motd";                     // 7 lines, 286B
regexp = /foobar/;

child_process = require('child_process');
qfgets = require('qfgets');

function grepWithFs( filename, regexp, done ) {
    fp = new qfgets(filename, "r");
    function loop() {
        for (i=0; i<40; i++) {
            line = fp.fgets();
            if (line && line.match(regexp)) process.stdout.write(line);
        }
        if (!fp.feof()) setImmediate(loop);
        else done();
    }
    loop();
}

function grepWithFork( filename, regexp, done ) {
    cmd = "egrep '" + regexp.toString().slice(1, -1) + "' " + filename;
    child_process.exec(cmd, {maxBuffer: 200000000}, function(err, stdout, stderr) {
        process.stdout.write(stdout);
        done(err);
    });
}

The test:

function fptime() { t = process.hrtime(); return t[0] + t[1]*1e-9 }

t1 = fptime();
if (0) {
    grepWithFs(filename, regexp, function(){
        console.log("fs done", fptime() - t1);
    });
}
else {
    grepWithFork(filename, regexp, function(err){
        console.log("fork done", fptime() - t1);
    });
}

Results:

/**
results (all file contents memory resident, no disk i/o):
times in seconds, best run out of 5

/foobar/
             fork   fs
motd        .00876  .00358  0.41 x  7 lines
out         .00922  .00772  0.84 x  2000 lines
messages    .0101   .0335   3.32 x  25.7 k lines
access.log  .1367   1.032   7.55 x  2.54 m lines

/[f][o][o][b][a][r]/
access.log  .4244   .8348   1.97 x  2.54 m lines

**/

(The above code was all one file, I split it up to avoid the scrollbar)

Edit: to highlight the key results:

185MB, 2.54 million lines, search RegExp /[f][o][o][b][a][r]/:

grepWithFs

elapsed: .83 sec

grepWithFork

elapsed: .42 sec