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

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.

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).

The two println statements are handled by two different threads. The output again depends on what environment you are running the code in. For eg, I executed the following code in IntelliJ and command-line 5 times each.

public class Test {
    public static void main(String[] args) {
        for (int i = 0; i < 10; i++) {
            System.out.print("OUT ");
            System.err.print("ERR ");
        }
    }
}

This resulting in the following output:
Commandline

OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR
OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR
OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR
OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR
OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR OUT ERR

IntelliJ:

ERR ERR ERR ERR ERR ERR ERR ERR ERR ERR OUT OUT OUT OUT OUT OUT OUT OUT OUT OUT 
OUT OUT OUT OUT OUT OUT OUT OUT OUT OUT ERR ERR ERR ERR ERR ERR ERR ERR ERR ERR
ERR ERR ERR ERR ERR ERR ERR ERR ERR ERR OUT OUT OUT OUT OUT OUT OUT OUT OUT OUT 
ERR ERR ERR ERR ERR ERR ERR ERR ERR ERR OUT OUT OUT OUT OUT OUT OUT OUT OUT OUT
OUT OUT OUT OUT OUT OUT OUT OUT OUT OUT ERR ERR ERR ERR ERR ERR ERR ERR ERR ERR

I guess different environments handles the buffers differently.
One way to see that these streams are infact handled by different threads is to add a sleep statement in the loop. You can try varying the value that you set for the sleep and see that these are infact handled by different threads.

public class Test {
    public static void main(String[] args) {
        for (int i = 0; i < 10; i++) {
            System.out.print("OUT ");
            System.err.print("ERR ");
            try {
                Thread.sleep(500);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}

The output in this case turned out to be

OUT ERR ERR OUT ERR OUT OUT ERR OUT ERR ERR OUT OUT ERR ERR OUT OUT ERR OUT ERR
OUT ERR ERR OUT ERR OUT OUT ERR OUT ERR ERR OUT OUT ERR ERR OUT OUT ERR OUT ERR
ERR OUT ERR OUT OUT ERR ERR OUT OUT ERR ERR OUT OUT ERR OUT ERR ERR OUT ERR OUT 
ERR OUT OUT ERR ERR OUT OUT ERR ERR OUT ERR OUT OUT ERR ERR OUT ERR OUT OUT ERR
OUT ERR OUT ERR ERR OUT OUT ERR ERR OUT OUT ERR ERR OUT ERR OUT OUT ERR OUT ERR

One way to force it to print it in the same order would be use the .flush(), which worked for me. But itseems that not everyone is getting the right results with it.

The two streams handled by 2 two different threads is probably the reason why we sometimes see the ERROR message printed by some libraries that we use, getting printed before some print statements that we were supposed to see according to the order of execution.

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.

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

What is happening here?

How to solve it

Tags:

Java

System

Console

Related

Recent Posts