Stderr not flushed right away?

General Usage
1

stderr doesn’t seem to flush frequently enough. Is this by design?

Suppose we run this Julia script

#--- try.jl ---
for i = 1:100000
  println(stderr, i)
  sleep(0.5)
end

from the shell command line like so

$ julia try.jnl > log.txt 2>&1 &

Then, monitor the progress of the script by

$ tail -f log.txt

When I tested this on macOS and centOS, stderr is flushed very infrequently.

I’ve been told that stderr of Unix/Linux flushes right away because this is the channel intended for error messages.

To compare julia with sh, I’ve run this code

for n in $(seq 1 100000); do
  echo $n >&2
  sleep 0.5
done

like so

$ sh try.sh > log.txt 2>&1 &

and found that stderr is flushed right away.

2

in any case if you want a manual fix, add flush(stderr) after print

1 Like
3

Thanks! Of course!

(As you know, however, my question is about the design of the Julia implementation. Is this an intended behavior, some unavoidable consequence from the design of the julia interpreter, or a bug?)

4

That’s not due to Julia. If you run your code in a REPL it flushes stderr just fine. In fact more than fine, Julia’s stderr, if I understand correctly, isn’t buffered at all, unlike every other modern programming language in existence, so you don’t even need to flush it.

When you redirect output to a file, Julia hands the data over to the kernel, and the kernel then writes it to a file. When another process tries to read the same file, it is absolutely not expected to see changes after the most recent flush: it would cause bad system performance if the kernel actually tried to do that. This is the standard state of affairs for all file writes and reads, usually. It requires extra care and handling if you require something else.

See man fflush, man fwrite, man 'write(2)'

5

I’m afraid I don’t think your explanation is correct. Run the following C program:

#include<stdio.h>
#include<unistd.h> // for sleep()
int main() {
  for (int i = 1; i <= 100; ++i) {
    fprintf(stderr, "%d\n", i);
    sleep(1);
  }
}

like

$ ./a.out > log.txt 2>&1 &
$ tail -f log.txt

You will see each line immediately from the other process (which is the tail command).

The C program hands each line to the kernel and the kernel writes each line immediately. That’s the reason the other process sees the new lines immediately.

As you say, I expect writing each piece of data as the kernel receives it is inefficient. That’s the reason why stdout is buffered. (On the other hand, stderr is specified as “unbufferred” and probably is less efficient than stdout)

So, the conclusion is that Julia’s stderr is buffered somehow after each print function when the script is run like julia script.jl on the command line.

6

Okay, you’re right, I just saw this part:

   POSIX  requires  that  a  read(2)  that  can be proved to occur after a
   write() has returned will return the  new  data.   Note  that  not  all
   filesystems are POSIX conforming.

I used to think the kernel read/write rules were slightly weaker than that. But now from the point of view of Julia code:

I didn’t mean that it won’t see them ever, it depends on the situation. But the rules don’t require changes to be visible, and so it is “not expected”, and one mustn’t write code that expects it. It still happens, depending on what exactly is going on. That is, if you specifically need the data to appear on the other side (e.g., in logs), you either flush it or you make sure that it’s unbuffered.

I just assume @info and other such macros flush their outputs.

Your example highlights a particular behaviour of libc, that doesn’t quite mean that Julia will do the same thing.

So when I say it’s not buffered, this is what I mean. Try running the following program under strace:

strace julia -e 'foreach(println, 1:10)'

You will see that Julia prints everything one thing at a time:

...
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, [], 1024, 0)              = 0
write(13, "7", 17)                       = 1
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, [], 1024, 0)              = 0
write(13, "\n", 1
)                      = 1
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, [], 1024, 0)              = 0
write(13, "8", 18)                       = 1
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, [], 1024, 0)              = 0
write(13, "\n", 1
)                      = 1
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, [], 1024, 0)              = 0
write(13, "9", 19)                       = 1
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, [], 1024, 0)              = 0
write(13, "\n", 1
)                      = 1
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, [], 1024, 0)              = 0
write(13, "10", 210)                      = 2
epoll_wait(3, [], 1024, 0)              = 0
epoll_wait(3, [], 1024, 0)              = 0
write(13, "\n", 1
)                      = 1
...

and the newlines are printed with one syscall each! This is one reason why when printing lots of data it can be so much faster to print it to iobuf=IOBuffer() followed by write(stdout,take!(iobuf)). It is also one reason why @show can be slow with very large structures: every print is a syscall. You can see there’s no buffering here.

You do not see the same thing with

strace julia -e 'foreach(println, 1:100)' >out

where you get

...
write(14, "1\n2\n3\n4\n5\n6\n7\n8\n9\n10\n11\n12\n13\n14"..., 292) = 292

I don’t actually know what is buffering what precisely where in your original question. For example, it’s printing to file descriptor 13, even though stdout is normally fd 1, which means that something else is going on here. I assume it’s libuv that’s not buffering output to tty, but is buffering output to a file; it can definitely tell whether the script is being run with tty output vs a redirected >out output to a file. Whatever it is, it’s not the same as libc.

2 Likes
7

Thank you for your investigation. I see that the stderr isn’t sent to fd 2 (stderr) when the program is run as a command line argument to the julia command.

  1. Your definition of “not expected” doesn’t agree with the *common expectation" of Unix/Linux programmers.

  2. It would be helpful to provide an output stream that is unbufferred by default.

All you argue is that the current implementation does not violate the standard. You fail to argue that stderr should not automatically flush.

My position is that even though the standard doesn’t require it, stderr should automatically flush.

From the beginning of Unix, stderr has been the standard unbuffered output stream. It’s very natural that programmers with that background are upset and confused with Julia’s stderr. If Julia’s stderr doesn’t have that property, why is it called that in the first place?

It’s cumbersome that each time I write a print statement, I have to add flush(), to monitor the progress of my julia program.

As an alternative, is it possible to change the flushing mode for stdout or stderr? If it’s impossible, is it possible to specify the flushing mode when you open a file? Such as

log = open("my-log-file.txt", "c"; buffering=:line)
error_log = open("my-error-log.txt", "c"; bufferig=:none)
# . . .
println(error_log, "illegal value at . . .")