Writing to stdout stream is always blocking in linux/unix, even when it refers to pipes.

2,346 views
Skip to first unread message

Pedro Ballesteros

unread,
Feb 12, 2014, 10:47:41 AM2/12/14
to nod...@googlegroups.com
Hi,

We have found that the writing to "process.stdout" in linux systems is always using blocking IO. So a call to "process.stdout.write" always blocks the thread execution until the data is flushed to the operating system. You get the same behavior even when process.stdout refer a pipe.

This is not consistent with the documentation of the API: http://nodejs.org/api/process.html#process_process_stdout.
"process.stderr and process.stdout are unlike other streams in Node in that writes to them are usually blocking. They are blocking in the case that they refer to regular files or TTY file descriptors. In the case they refer to pipes, they are non-blocking like other streams".

We have found that when stdout refer to a pipe:
  • libuv is using "blocking IO" in linux/unix.
  • libuv is using "non-blocking IO" in windows.

So I think that any of these actions would be recommended:
  • Change the API documentation: "in case stdout refer to pipes, the stream is non-blocking in windows, but blocking in linx/unix".
  • Change the libuv unix/linux implementation to use non-blocking writings.
  • Change the libuv windows implementation to use blocking writings.
You can see in the libuv code that the linux/unix implementation is not using non-blocking IO.

The creation of the stdout stream in the startup node.js source file is actually creating a net.Socket stream when stdout is a "PIPE". 

But when a net.Socket is created with a file descriptor ({fd: 1} with stdout), node is creating a native "Pipe" object of the "pipe_wap" module.

And finally opening that pipe with the file descriptor of stdout:

this._handle.open(options.fd);

That finally is opening that pipe with the file descriptor of stdout: Pipe.open(1)

Pipe.open is implemented using uv_pipe_open of libuv:

uv_pipe_open(&wrap->handle_, args[0]->Int32Value())

You can see that uv_pipe_open implementation in unix/linux doesn't set the non_blocking flag in the fd. The code is not calling uv__nonblock(fd, 1). So writings using that pipe will be blocking:

But windows implementation it's always using non_blocking IO:

Or using FILE_FLAG_OVERLAPPED IO or using thread polling with QueueUserWorkItem.

It is easy to check that writing to stdout is blocking even when it refers to a pipe, running a simple js script to write to stdout as fast as you can (for example writing in a setInmediate callback).

If you run the script like this:
node stdout-writing-test.js 2>error.log 1|more

You can see that when the "more" command blocks the console, the process is stopped, consuming few CPU. If you write to stderr the size of the stream buffer:
console.error(process.stdout._writableState.buffer.length) 
You will see that "tail -f error.log" is stopped until you resume the "more" command.

You can debug the application with node-inspector to check that the execution get blocked in "proccess.stdout.write" line until you resume the "more" command.

If you run your script with tee:
node stdout-writing-test.js 2>error.log 1|tee data.log > /dev/null
You will see that the stream buffer is never used, it is always zero length.

You can run the same tests in Windows to check that the buffer grows without control, because the process.stdout.write is never blocked and the data is queued to the buffer array.


Best Regards,
        Pedro Ballesteros
Message has been deleted

Pedro Ballesteros

unread,
Feb 21, 2014, 6:20:25 AM2/21/14
to nod...@googlegroups.com
The documentation has been updated (v0.10.26) to tell the non-blocking behaviour in windows and blocking in linux. It is important because this can affect your application when your logging system is based on stdout or console.log.

http://nodejs.org/dist/v0.10.26/docs/api/process.html#process_process_stdout

Reply all
Reply to author
Forward
0 new messages