Java: System.out.println e System.err.println fora de ordem

Minhas chamadas System.out.println() e System.err.println() não estão sendo impressas no console na ordem que eu as faço.

 public static void main(String[] args) { for (int i = 0; i < 5; i++) { System.out.println("out"); System.err.println("err"); } } 

Isso produz:

 out out out out out err err err err err 

Em vez de alternar e err . Por que é isso?

   

Eles são streams diferentes e são liberados em momentos diferentes.

Se você colocar

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

dentro do seu loop, funcionará como esperado.

Para esclarecer, os streams de saída são armazenados em cache para que toda a gravação entre nesse buffer de memory. Depois de um período de silêncio, eles são realmente escritos.

Você escreve em dois buffers, depois de um período de inatividade, ambos são liberados (um após o outro).

Isso é causado por um recurso na JVM e, a menos que você faça um hack como o fornecido por Marcus A. , não é tão fácil trabalhar por aí. O .flush() funciona neste caso, mas a razão para isso é muito mais complicada de se trabalhar.

O que esta acontecendo aqui?

Quando você programa em Java você não está dizendo ao computador o que fazer, você está dizendo à JVM (Java Virtual Machine) o que você gostaria que ele fizesse. E vai fazer isso, mas de uma maneira mais eficiente. Seu código não é instruções detalhadas exatas, nesse caso você precisaria apenas de um compilador como em C e C ++, a JVM pega seu código como uma lista de especificações para o que ele deveria otimizar e fazer. Isto é o que está acontecendo aqui . Java vê que você está enviando strings para dois streams de buffer diferentes. A maneira mais eficiente de fazer isso é armazenar em buffer todas as strings que você deseja que os streams produzam e, em seguida, enviá-las. Isso acontece um stream no momento, essencialmente transformando seu código fazer algo assim (cuidado: pseudo código) :

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

Como isso é mais eficiente, é o que a JVM fará ao invés disso. Adicionando o .flush() no loop irá sinalizar para a JVM que um flush precisa ser feito em cada loop, que não pode ser melhorado com o método acima. Mas se você explicar como isso funciona teria deixado de fora o loop, a JVM reordenará seu código para que a impressão seja feita por último, porque isso é mais eficiente.

 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(); 

Esse código sempre será reorganizado para algo assim:

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

Porque buffering muitos buffers apenas para liberá-los logo após leva muito mais tempo do que para armazenar todo o código a ser armazenado em buffer e, em seguida, liberar tudo ao mesmo tempo.

Como resolver isso

É aqui que o design de código e a arquitetura podem entrar em ação; você meio que não resolve isso. Para contornar isso, você tem que torná-lo mais eficiente para buffer de impressão / flush, impressão de buffer / flush do que o buffer de todos, em seguida, liberado. Isso provavelmente irá atraí-lo para um design ruim. Se for importante para você como produzir de forma ordenada, sugiro que você tente uma abordagem diferente. For-looping com .flush() é uma maneira de hackeá-lo, mas você ainda está hackeando o recurso da JVM para reorganizar e otimizar seu código para você.

* Não consigo verificar se o buffer adicionado primeiro sempre será impresso primeiro, mas é mais provável que seja.

Se você estiver usando o console do Eclipse, parece haver dois fenômenos diferentes no trabalho:
Um, como descrito por @Gemtastic , é o tratamento de JVMs dos streams e o outro é o modo como o Eclipse lê esses streams, como mencionado por @DraganBozanovic . Como estou usando o Eclipse, a elegante solução flush() publicada pelo @BillK , que apenas aborda o problema da JVM, não é suficiente.

Acabei escrevendo para mim uma class auxiliar chamada EclipseTools com o seguinte conteúdo (e a declaração e importação obrigatórias do pacote). É um pouco de truque, mas corrige os dois problemas:

 public class EclipseTools { private static List 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(); System.setErr(new PrintStream(new FixedStream(System.err))); System.setOut(new PrintStream(new FixedStream(System.out))); } } 

Para usar, basta chamar EclipseTools.fixConsole() uma vez no início do seu código.

Basicamente, isso substitui os dois streams System.err e System.out por um conjunto personalizado de streams que simplesmente encaminham seus dados para os streams originais, mas controlam qual stream foi gravado para durar. Se o stream que é gravado mudar, por exemplo, um System.err.something(...) seguido por um System.out.something(...) , libera a saída do último stream e espera por 200ms para fornecer o tempo do console do Eclipse para concluir a impressão.

Nota: Os 200ms são apenas um valor inicial aproximado. Se esse código reduzir, mas não eliminar o problema, aumente o atraso em Thread.sleep de 200 para algo maior até que funcione. Como alternativa, se esse atraso funcionar, mas afetar o desempenho de seu código (se você alternar streams frequentemente), poderá tentar reduzi-lo gradualmente até começar a receber erros.

Este é um bug no Eclipse . Parece que o Eclipse usa encadeamentos separados para ler o conteúdo de out e err streams sem qualquer synchronization.

Se você compilar a class e executá-la no console (com o java

clássico java
), a ordem será a esperada.

As duas instruções println são manipuladas por dois threads diferentes. A saída novamente depende do ambiente no qual você está executando o código. Por exemplo, eu executei o seguinte código no IntelliJ e a linha de comando 5 vezes cada.

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

Isso resulta na seguinte saída:
Linha de comando

 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 

Eu acho que ambientes diferentes lidam com os buffers de maneira diferente.
Uma maneira de ver que esses streams são tratados de forma diferente por segmentos diferentes é adicionar uma instrução de sleep no loop. Você pode tentar variar o valor que definiu para o sono e ver se eles são tratados de forma diferente por diferentes 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(); } } } } 

A saída neste caso acabou por ser

 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 

Uma maneira de forçá-lo a imprimi-lo na mesma ordem seria usar o .flush() , que funcionou para mim. Mas parece que nem todo mundo está obtendo os resultados certos com isso.

Os dois streams manipulados por dois segmentos diferentes provavelmente é a razão pela qual às vezes vemos a mensagem ERROR impressa por algumas bibliotecas que usamos, sendo impressas antes de algumas declarações de impressão que deveríamos ver de acordo com a ordem de execução.

Eu usei thread para imprimir a saída de System.out e System.err seqüencialmente como:

  for(int i = 0; i< 5; i++){ try { Thread.sleep(100); System.out.print("OUT"); Thread.sleep(100); System.err.print("ERR"); }catch (InterruptedException ex){ System.out.println(ex.getMessage()); } }