Упорядочивание исключений во время выполнения с помощью println в выводе консоли

Общая проблема с выводом консоли VM Java заключается в том, что System.out и System.err обычно не синхронизируются должным образом, возможно, потому, что они находятся в разных потоках. Это приводит к перепутанному выводу, например:

вывод отладки перепутан с трассировкой стека исключений во время выполнения

[8, 1, 3, 5, 9, 13, 15, 17, 19]
Exception in thread "main" java.lang.ArrayIndexOutOfBoundsException: 9
scanning xAnswer: 1 xValue: 1 total: 1 [1, 1, 0, 0, 0, 0, 0, 0, 0]
    at cra.common.Group_jsc.listSubsetSum(Group_jsc.java:29)
scanning xAnswer: 2 xValue: 2 total: 4 [2, 1, 2, 0, 0, 0, 0, 0, 0]
    at cra.common.Group_jsc.main(Group_jsc.java:12)
scanning xAnswer: 3 xValue: 3 total: 9 [3, 1, 2, 3, 0, 0, 0, 0, 0]
scanning xAnswer: 4 xValue: 4 total: 18 [4, 1, 2, 3, 4, 0, 0, 0, 0]
scanning xAnswer: 5 xValue: 5 total: 31 [5, 1, 2, 3, 4, 5, 0, 0, 0]
  reset to xAnswer: 4 xValue: 5 total: 26 [4, 1, 2, 3, 5, 5, 0, 0, 0]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
scanning xAnswer: 5 xValue: 6 total: 41 [5, 1, 2, 3, 5, 6, 0, 0, 0]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
  reset to xAnswer: 4 xValue: 6 total: 35 [4, 1, 2, 3, 6, 6, 0, 0, 0]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:601)
    at com.intellij.rt.execution.application.AppMain.main(AppMain.java:120)
scanning xAnswer: 5 xValue: 7 total: 52 [5, 1, 2, 3, 6, 7, 0, 0, 0]
  reset to xAnswer: 4 xValue: 7 total: 45 [4, 1, 2, 3, 7, 7, 0, 0, 0]
scanning xAnswer: 5 xValue: 8 total: 64 [5, 1, 2, 3, 7, 8, 0, 0, 0]
  reset to xAnswer: 4 xValue: 8 total: 56 [4, 1, 2, 3, 8, 8, 0, 0, 0]

Process finished with exit code 1

Поскольку исключение произошло в конце процесса, я ожидаю, что распечатка исключения произойдет ПОСЛЕ всех println в программе. Почему это происходит и что можно сделать, чтобы решить проблему?

(обратите внимание, что этот конкретный пример взят из консоли IntelliJ IDEA, но то же самое происходит в Eclipse и других Java IDE)


java debugging multithreading ide system.out
person Tyler Durden    schedule 14.06.2013    source источник
comment
Я добавил некоторые подробности и ссылки на пакеты ведения журнала в своем ответе @Tyler. Как упоминает @fge, в JVM также встроен java.util.logging.   -  person Gray    schedule 14.06.2013
comment
Можете ли вы показать часть кода @Tyler? Вы уверены, что исключение происходит после запуска сканера? Это не в другой теме?   -  person Gray    schedule 01.12.2016
comment
@Gray Это не какая-то непонятная проблема. Это затрагивает всех, кто когда-либо работал с Java. Если вы хотите продемонстрировать эффект для себя, просто создайте цикл, который выдает много информации на стандартный вывод, а затем вылетает.   -  person Tyler Durden    schedule 01.12.2016
comment
Эм-м-м. Я проделал кучу работы с Java и никогда не видел этого. Не могли бы вы показать код? Это работает для меня, например: pastebin.com/HbeRZXdC   -  person Gray    schedule 01.12.2016
comment
Вы пытались поставить System.out.flush() перед исключением?   -  person Gray    schedule 01.12.2016

Ответы (3)


arrow_upward
2
arrow_downward

Общая проблема с выводом консоли VM Java заключается в том, что System.out и System.err обычно не синхронизируются должным образом,

Нет, они синхронизированы идеально. Проблема в том, что строки перемешаны, потому что они печатаются как отдельные вызовы println(...). Это код от Exception.printStackTrace():

        StackTraceElement[] trace = getOurStackTrace();
        for (int i=0; i < trace.length; i++)
            s.println("\tat " + trace[i]);

Регистраторы (например, log4j) получают полную трассировку стека и превращают несколько строк в один вызов вывода журнала, который затем сохраняется атомарно.

Почему это происходит и что можно сделать, чтобы решить проблему?

Обычно в программах Unix стандартный вывод буферизуется, а стандартный вывод - нет. Я не думал, что это верно для Java, но, возможно, это так. Чтобы прочитать javadocs System.out:

«Стандартный» выходной поток. Этот поток уже открыт и готов принимать выходные данные. Обычно этот поток соответствует выводу на дисплей или другому назначению вывода, указанному хост-средой или пользователем.

По сравнению с System.err:

По соглашению этот поток вывода используется для отображения сообщений об ошибках или другой информации, которая должна немедленно привлечь внимание пользователя, даже если основной поток вывода, значение переменной out, был перенаправлен в файл или другое место назначения, которое обычно не контролируется постоянно.

Подробнее см. в этом ответе: Операторы .err иногда печатаются первыми?

Если это выполняется из командной строки, вы должны перенаправить вывод и вывод ошибок в разные файлы. Вот как это сделать с помощью ~unix:

Как перенаправить stderr и stdout в разные файлы в одной строке bash?

В Java вы можете использовать System.setOut(...) и System.setErr(...) для отправки разных выходных данных на разные PrintStream, чтобы строки не чередовались.

Вы отредактировали вопрос, чтобы отметить, что это происходит внутри IDE. Если вам нужно использовать System.out и err, вы можете перенаправить их, используя приведенный выше код Java.

Однако обычно вместо этого используется код ведения журнала. Распространенными пакетами ведения журналов являются log4j или logback, который атомарно записывает одно многострочное сообщение журнала в выходной файл, чтобы они не чередовались. Как упоминает @fge, в JVM, хотя другие пакеты предоставляют больше возможностей.

person Gray    schedule 14.06.2013
comment
Этот ответ не объясняет основную причину. Поскольку ошибка возникает после вызовов System.out.println, ни одна из строк System.err не должна была быть напечатана до них, но они это сделали. Первая часть моего вопроса состоит в том, чтобы объяснить, почему это происходит. - person Tyler Durden; 01.12.2016
comment
А ты думал, что мой ответ бесполезен @TylerDurden. Хм. - person Gray; 01.12.2016

arrow_upward
0
arrow_downward

Почему это происходит и что можно сделать, чтобы решить проблему?

Поскольку syserr и sysout — это отдельные потоки данных, системная консоль (IDE) пытается отобразить оба одновременно. Это можно исправить, используя Logger, который обычно правильно упорядочивает записи в журнале.

Другой возможностью является вызов System.setErr и назначьте его PrintStream для файла журнала ошибок. Это было бы эквивалентным решением Java для перенаправления потока ошибок.

person Tim Bender    schedule 14.06.2013
comment
Я хотел бы использовать существующую консоль. Что вы подразумеваете под регистратором? Можно ли это установить без проблем или для его использования потребуются дополнительные неудобства? - person Tyler Durden; 14.06.2013
comment
@TylerDurden есть java.util.logging в JDK - person fge; 14.06.2013
comment
Правильно, это моя точка зрения: консоль пытается ОТОБРАЖАТЬ ИХ ОБА ОДНОВРЕМЕННО, чтобы использовать ваши точные слова. Однако в приведенном выше случае исключение возникает ПОСЛЕ того, как вывод в system.out был напечатан, поэтому вся ошибка должна была быть напечатана после того, как system.out был напечатан, поскольку хронологически ошибка произошла после system.out. печать вызова. Это проблема, которую я пытаюсь понять и решить. Я считаю ручную буферизацию потоков обходным путем, а не решением. - person Tyler Durden; 01.12.2016

arrow_upward
0
arrow_downward

PyCharm также имеет эту проблему, которая, как я полагаю, использует тот же движок IDE. Есть исправление, если вы добавите следующую строку в свой файл idea.properties:

output.reader.blocking.mode=true

Получите доступ к idea.properties через Справку | Изменить пользовательские свойства.

person Saul    schedule 07.03.2019