Node: console.log speed issue

[DmitryHetman]

• Version: 7.0.0
• Platform: GNU/Linux
• Subsystem: Gentoo nomultilib

console.log very slow compared to php echo.

here is comparison:
js program:

'use strict';
  let i=0;
  while (i++ < 999999)
    console.log('test');

php program:

<?php
  $i=0;
  while ($i++ < 999999)
    echo "test\n";
?>

dash/bash program:

i=0
while [ $i -lt 999999 ] ; do
  echo 'test'
  i=$(($i+1))
done

c program:

#include <stdio.h>
void main () {
  int i=0;
  while ( i++ < 999999 )
    printf("test\n");
}

Results:

xorg dwm st:

  php:  0m0.933s
  node: 0m3.713s
  bash: 0m7.384s
  dash: 0m4.078s
  c:    0m1.116s

wayland weston weston-terminal:

  php:  0m1.481s
  node: 0m4.242s
  bash: 0m8.582s
  dash: 0m3.664s
  c:    0m1.392s

wayland weston > xorg dwm st:

  php:  0m0.937s
  node: 0m3.883s
  bash: 0m7.383s
  dash: 0m3.296s
  c:    0m1.048s

xorg dwm > wayland weston weston-terminal:

  php:  0m0.827s
  node: 0m3.514s
  bash: 0m7.660s
  dash: 0m3.330s
  c:    0m0.796s

[addaleax]

console.log very slow compared to other interpreters.

It might help if you could be a bit more specific… compared to which interpreters? Do you have any code samples?

[Fishrock123]

@DmitryHetman If you are just printing strings could you try process.stdout.write(string + '\n')? Most overhead in console.log() comes from util.inspect() via util.format().

If you are printing objects... you could try printing JSON directly instead, that may be faster.

[DmitryHetman]

Thanks.
process.stdout.write('string') even slower than console.log.

[DronRathore]

process.stdout should ideally not be slow in comparison with console.log. Here are the results of both on 64bit machine.

• Version : 7.4.0
• Platform : OSX
• Subsystem: 10.12.2 64bit

bash stdout - 3 pass
# in-process logging using Date.now diff
Pass 1:
    Log took 4599
    Stdout took 3805
Pass 2:
    Log took 4954
    Stdout took 3884
Pass 3:
    Log took 4560
    Stdout took 4008

# test with just the for loop
console.log:
    Pass 1:
        real    0m5.397s
        user    0m3.671s
        sys 0m1.069s
    Pass 2:
        real    0m5.133s
        user    0m3.531s
        sys 0m1.019s
    Pass 3:
        real    0m5.263s
        user    0m3.608s
        sys 0m1.009s

process.stdout:
    Pass 1:
        real    0m4.861s
        user    0m3.282s
        sys 0m0.997s
    Pass 2:
        real    0m4.948s
        user    0m3.299s
        sys 0m1.012s
    Pass 3:
        real    0m4.802s
        user    0m3.248s
        sys 0m0.989s

# output to /dev/null
bash /dev/null - 3 pass
# in-process logging using Date.now diff
Pass 1:
    Log took 2616
    Stdout took 2434
Pass 2:
    Log took 2616
    Stdout took 2561
Pass 3:
    Log took 2677
    Stdout took 2185

# test with just the for loop
console.log:
    Pass 1:
        real    0m3.366s
        user    0m2.839s
        sys 0m0.505s
    Pass 2:
        real    0m2.979s
        user    0m2.533s
        sys 0m0.475s
    Pass 3:
        real    0m2.999s
        user    0m2.554s
        sys 0m0.465s

process.stdout:
    Pass 1:
        real    0m3.073s
        user    0m2.609s
        sys 0m0.460s
    Pass 2:
        real    0m2.896s
        user    0m2.499s
        sys 0m0.466s
    Pass 3:
        real    0m2.987s
        user    0m2.557s
        sys 0m0.480s

You are using 32bit build of node? I don't think arch would have anything to do with plain v8 interpretation of code for log and stdout, but, over to @Fishrock123

Having said that, Node works on async Streams so there should be cost for the same, php, bash and C are sync mod.

[Fishrock123]

process.stdout.write('string') even slower than console.log.

That's not actually possible? console.log uses process.stdout.write and does even more. @DmitryHetman Please share your benchmarks.

[joyeecheung]

The main cost comes from the abstraction of asynchronous stuff(streams and nextTick, .etc).

FWIW if we change console.log to process._rawDebug(which doesn't jump those hoops, though not excatly should be used outside core I think)

time node log.js 2&> 1 > /dev/null
0.58s user
0.64s system
91% cpu
1.335 total

Compared to console.log:

time node log.js > /dev/null
2.48s user
0.56s system
100% cpu
3.026 total

process.stdout.write:

time node log.js > /dev/null
2.41s user
0.57s system
101% cpu
2.927 total

(on v7.4.0, Darwin Kernel Version 15.6.0, x86_64)

[mcollina]

The problem you are facing is related to the fact that Node.js is an asynchronous platform.
console.log does not write strings synchronously to the output, but rather it queue them and deliver through the event loop. Because of this, calling console.log in this way would just queue a lot of data to be written, and it will write them when the process ends.

As @joyeecheung states, using a process._rawDebug removes the problem as it is synchronous.
In order to write at speed to stdout, you will need to handle the 'drain' event, as written in: https://nodejs.org/api/stream.html#stream_writable_write_chunk_encoding_callback.

'use strict';

var i=0;
var stream = process.stdout;

function write(data, cb) {
  if (!stream.write(data)) {
    stream.once('drain', cb);
  } else {
    process.nextTick(cb);
  }
}

function next() {
  if (i++ === 999999) {
    return
  }

  write('hello\n', next)
}

next()

Which results in:

real    0m1.864s
user    0m1.478s
sys     0m0.332s

compared to

real    0m2.661s
user    0m2.139s
sys     0m0.411s

More or less we are comparing two different things here. I think it can be closed.