System.out.println and System.err.println out of order System.out.println and System.err.println out of order java java

System.out.println and System.err.println out of order


They are different streams and are flushed at different times.

If you put

System.out.flush();System.err.flush();

inside your loop, it will work as expected.

To clarify, output streams are cached so all the write goes into this memory buffer. After a period of quiet, they are actually written out.

You write to two buffers, then after a period of inactivity they both are flushed (one after the other).


This is caused by a feature in the JVM and unless you make a hack such as the one provided by Marcus A. it's not really that easy to work around. The .flush() works in this case but the reason for this is a lot more complicated to work around.

What is happening here?

When you program in Java you're not telling the computer straight what to do, you're telling the JVM (Java Virtual Machine) what you would want it to do. And it will do that, but in a more efficient manner. Your code isn't exact detailed instructions, in that case you'd only need a compiler like in C and C++, the JVM takes your code as a specification list for what it's supposed to optimise and then do. This is what's happening here. Java sees that you're pushing strings into two different buffer streams. The most efficient way of doing this is by buffering all the strings you want the streams to output and then output it. This happen one stream at the time, essentially transforming your code do something like this (beware: pseudo code):

for(int i = 0; i < 5; i++) {    out.add();    err.add();}out.flush();err.flush();

Because this is more efficient, this is what the JVM will do instead. Adding the .flush() in the loop will signal to the JVM that a flush needs to be done in each loop, which can't be improved with the above method. But if you for the sake of explaining how this works would have left out the loop, the JVM will reorder your code to have the printing done last, because this is more efficient.

System.out.println("out");System.out.flush();System.err.println("err");System.err.flush();System.out.println("out");System.out.flush();System.err.println("err");System.err.flush();

This code will always be re-organized to something like this:

System.out.println("out");*System.err.println("err");*System.out.println("out");*System.err.println("err");*System.out.flush();System.err.flush();

Because buffering many buffers only to flush them right after takes a lot more time than to buffer all the code to be buffered and then flush it all at the same time.

How to solve it

This is where code-design and architecture might come into play; you kinda don't solve this. To work around this, you have to make it more efficient to buffer print/flush, buffer print/flush than buffer all then flush. This will most likely be luring you into bad design. If it is important to you how to output it orderly, I suggest you try a different approach. For-looping with .flush() is one way to hack it, but you're still hacking the JVM's feature to re-arrange and optimize your code for you.

* I can't verify that the buffer you added to first always will print first, but it most likely will.


If you are using the Eclipse console, there seem to be two different phenomena at work:
One, as described by @Gemtastic, is the JVMs handling of the streams and the other is the way Eclipse reads these streams, as mentioned by @DraganBozanovic. Since I'm using Eclipse, the elegant flush()-solution posted by @BillK, which only addresses the JVM-issue, is not sufficient.

I ended up writing myself a helper-class called EclipseTools with the following content (and the required package declaration and imports). It's a bit of a hack but fixes both issues:

public class EclipseTools {    private static List<OutputStream> streams = null;    private static OutputStream lastStream = null;    private static class FixedStream extends OutputStream {        private final OutputStream target;        public FixedStream(OutputStream originalStream) {            target = originalStream;            streams.add(this);        }        @Override        public void write(int b) throws IOException {            if (lastStream!=this) swap();            target.write(b);        }        @Override        public void write(byte[] b) throws IOException {            if (lastStream!=this) swap();            target.write(b);        }        @Override        public void write(byte[] b, int off, int len) throws IOException {            if (lastStream!=this) swap();            target.write(b, off, len);        }        private void swap() throws IOException {            if (lastStream!=null) {                lastStream.flush();                try { Thread.sleep(200); } catch (InterruptedException e) {}            }            lastStream = this;        }        @Override public void close() throws IOException { target.close(); }        @Override public void flush() throws IOException { target.flush(); }    }    /**     * Inserts a 200ms delay into the System.err or System.out OutputStreams     * every time the output switches from one to the other. This prevents     * the Eclipse console from showing the output of the two streams out of     * order. This function only needs to be called once.     */    public static void fixConsole() {        if (streams!=null) return;        streams = new ArrayList<OutputStream>();        System.setErr(new PrintStream(new FixedStream(System.err)));        System.setOut(new PrintStream(new FixedStream(System.out)));    }}

To use, just call EclipseTools.fixConsole() once in the beginning of your code.

Basically, this replaces the two streams System.err and System.out with a custom set of streams that simply forward their data to the original streams, but keep track of which stream was written to last. If the stream that is written to changes, for example a System.err.something(...) followed by a System.out.something(...), it flushes the output of the last stream and waits for 200ms to give the Eclipse console time to complete printing it.

Note: The 200ms are just a rough initial value. If this code reduces, but does not eliminate the problem for you, increase the delay in Thread.sleep from 200 to something higher until it works. Alternatively, if this delay works but impacts performance of your code (if you alternate streams often), you can try reducing it gradually until you start getting errors.