Поток Java, выполняющий операцию остатка в цикле, блокирует все другие потоки

Следующий фрагмент кода выполняет два потока, один - это простой таймер, регистрирующий каждую секунду, второй - бесконечный цикл, который выполняет остаточную операцию:

public class TestBlockingThread {
    private static final Logger LOGGER = LoggerFactory.getLogger(TestBlockingThread.class);

    public static final void main(String[] args) throws InterruptedException {
        Runnable task = () -> {
            int i = 0;
            while (true) {
                i++;
                if (i != 0) {
                    boolean b = 1 % i == 0;
                }
            }
        };

        new Thread(new LogTimer()).start();
        Thread.sleep(2000);
        new Thread(task).start();
    }

    public static class LogTimer implements Runnable {
        @Override
        public void run() {
            while (true) {
                long start = System.currentTimeMillis();
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    // do nothing
                }
                LOGGER.info("timeElapsed={}", System.currentTimeMillis() - start);
            }
        }
    }
}

Это дает следующий результат:

[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1003
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=13331
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1006
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1003
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004
[Thread-0] INFO  c.m.c.concurrent.TestBlockingThread - timeElapsed=1004

Я не понимаю, почему бесконечная задача блокирует все остальные потоки на 13,3 секунды. Я пытался изменить приоритеты потоков и другие настройки, ничего не помогло.

Если у вас есть предложения по исправлению этой ситуации (включая настройку параметров переключения контекста ОС), сообщите мне.

После всех приведенных здесь объяснений (благодаря Питеру Лоури ) мы обнаружили, что основным источником этой паузы является то, что точка безопасности внутри цикла достигается довольно редко, поэтому требуется много времени, чтобы остановить все потоки для замены кода, скомпилированного JIT.

Но я решил пойти глубже и выяснить, почему точка сохранения достигается редко. Меня немного сбивает с толку, почему обратный переход whileцикла небезопасен в этом случае.

Поэтому я призываю -XX:+PrintAssemblyво всей красе на помощь

-XX:+UnlockDiagnosticVMOptions \
-XX:+TraceClassLoading \
-XX:+DebugNonSafepoints \
-XX:+PrintCompilation \
-XX:+PrintGCDetails \
-XX:+PrintStubCode \
-XX:+PrintAssembly \
-XX:PrintAssemblyOptions=-Mintel

После некоторого расследования я обнаружил, что после третьей перекомпиляции лямбда- C2компилятора опросы безопасной точки внутри цикла были полностью удалены.

ОБНОВИТЬ

На этапе профилирования переменная iникогда не была равна 0. Вот почему мы C2спекулятивно оптимизировали эту ветвь, чтобы цикл был преобразован во что-то вроде

for (int i = OSR_value; i != 0; i++) {
    if (1 % i == 0) {
        uncommon_trap();
    }
}
uncommon_trap();

Обратите внимание, что изначально бесконечный цикл был преобразован в обычный конечный цикл со счетчиком! Из-за оптимизации JIT для исключения опросов безопасных точек в циклах с конечным числом подсчетов, в этом цикле также не было опросов безопасных точек.

Спустя какое-то время iзавернули обратно 0, и необычная ловушка была взята. Метод был деоптимизирован и продолжил выполнение в интерпретаторе. Во время перекомпиляции с новыми знаниями C2распознал бесконечный цикл и отказался от компиляции. Остальная часть метода продолжилась в интерпретаторе с соответствующими точками сохранения.

Существует большое должен прочитать сообщение в блоге «Safepoints: Значение, побочные эффекты и Накладные» по Ницан Wakart покрывающих safepoints и этот конкретный вопрос.

Известно, что устранение безопасной точки в очень длинных счетных циклах является проблемой. Ошибка JDK-5014723(спасибо Владимиру Иванову ) решает эту проблему.

Обходной путь доступен до тех пор, пока ошибка не будет окончательно исправлена.

1. Вы можете попробовать использовать -XX:+UseCountedLoopSafepoints(это приведет к снижению общей производительности и может привести к сбою JVM JDK-8161147 ). После его использования C2компилятор продолжает сохранять точки сохранения на обратных прыжках, и исходная пауза полностью исчезает.

2. Вы можете явно отключить компиляцию проблемного метода, используя
   -XX:CompileCommand='exclude,binary/class/Name,methodName'

3. Или вы можете переписать свой код, добавив точку сохранения вручную. Например, Thread.yield()вызов в конце цикла или даже изменение int iна long i(спасибо, Nitsan Wakart ) также исправит паузу.

Короче говоря, у вашего цикла нет безопасной точки внутри, кроме тех случаев, когда i == 0она достигается. Когда этот метод компилируется и запускает замену кода, ему необходимо перевести все потоки в безопасную точку, но это занимает очень много времени, блокируя не только поток, выполняющий код, но и все потоки в JVM.

Я добавил следующие параметры командной строки.

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintCompilation

Я также изменил код, чтобы использовать плавающую точку, которая, похоже, занимает больше времени.

boolean b = 1.0 / i == 0;

На выходе я вижу

timeElapsed=100
Application time: 0.9560686 seconds
  41423  280 %     4       TestBlockingThread::lambda$main$0 @ -2 (27 bytes)   made not entrant
Total time for which application threads were stopped: 40.3971116 seconds, Stopping threads took: 40.3967755 seconds
Application time: 0.0000219 seconds
Total time for which application threads were stopped: 0.0005840 seconds, Stopping threads took: 0.0000383 seconds
  41424  281 %     3       TestBlockingThread::lambda$main$0 @ 2 (27 bytes)
timeElapsed=40473
  41425  282 %     4       TestBlockingThread::lambda$main$0 @ 2 (27 bytes)
  41426  281 %     3       TestBlockingThread::lambda$main$0 @ -2 (27 bytes)   made not entrant
timeElapsed=100

Примечание: для замены кода потоки должны быть остановлены в безопасной точке. Однако здесь оказывается, что такая безопасная точка достигается очень редко (возможно, только при i == 0изменении задачи на

Runnable task = () -> {
    for (int i = 1; i != 0 ; i++) {
        boolean b = 1.0 / i == 0;
    }
};

Я вижу аналогичную задержку.

timeElapsed=100
Application time: 0.9587419 seconds
  39044  280 %     4       TestBlockingThread::lambda$main$0 @ -2 (28 bytes)   made not entrant
Total time for which application threads were stopped: 38.0227039 seconds, Stopping threads took: 38.0225761 seconds
Application time: 0.0000087 seconds
Total time for which application threads were stopped: 0.0003102 seconds, Stopping threads took: 0.0000105 seconds
timeElapsed=38100
timeElapsed=100

Если аккуратно добавить код в цикл, вы получите большую задержку.

for (int i = 1; i != 0 ; i++) {
    boolean b = 1.0 / i / i == 0;
}

получает

 Total time for which application threads were stopped: 59.6034546 seconds, Stopping threads took: 59.6030773 seconds

Однако измените код, чтобы использовать собственный метод, который всегда имеет безопасную точку (если это не внутренний метод).

for (int i = 1; i != 0 ; i++) {
    boolean b = Math.cos(1.0 / i) == 0;
}

печать

Total time for which application threads were stopped: 0.0001444 seconds, Stopping threads took: 0.0000615 seconds

Примечание: добавление if (Thread.currentThread().isInterrupted()) { ... }в цикл добавляет безопасную точку.

Примечание. Это произошло на 16-ядерной машине, поэтому ресурсов ЦП нет.

Нашел ответ почему . Они называются безопасными точками и наиболее известны как Stop-The-World, возникающие из-за GC.

См. Эти статьи: Ведение журнала остановок в JVM

Различные события могут заставить JVM приостановить все потоки приложения. Такие паузы называются паузами Stop-The-World (STW). Наиболее частой причиной срабатывания паузы STW является сборка мусора (пример в github), но различные действия JIT (пример), смещенный отзыв блокировки (пример), определенные операции JVMTI и многие другие также требуют остановки приложения.

Точки, в которых потоки приложения могут быть безопасно остановлены, неожиданно называются точками безопасности . Этот термин также часто используется для обозначения всех пауз STW.

Более или менее часто журналы GC включены. Однако это не захватывает информацию обо всех точках безопасности. Чтобы получить все это, используйте следующие параметры JVM:

-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime

Если вам интересно, что именование явно относится к GC, не беспокойтесь - включение этих параметров приводит к регистрации всех точек сохранения, а не только пауз при сборке мусора. Если вы запустите следующий пример (исходный код в github) с указанными выше флагами.

Читая Глоссарий терминов HotSpot , он определяет следующее:

safepoint

Точка во время выполнения программы, в которой известны все корни сборки мусора и согласовано все содержимое объекта кучи. С глобальной точки зрения, все потоки должны блокироваться в безопасной точке, прежде чем сборщик мусора сможет работать. (В качестве особого случая потоки, выполняющие код JNI, могут продолжать работу, поскольку они используют только дескрипторы. Во время точки безопасности они должны блокировать, а не загружать содержимое дескриптора.) С локальной точки зрения точка безопасности - это особенная точка. в блоке кода, где выполняющийся поток может блокироваться для GC. Большинство сайтов для звонков квалифицируются как точки безопасности.Существуют сильные инварианты, которые остаются верными в каждой точке безопасности, которые можно игнорировать в точках, не являющихся безопасными. Как скомпилированный код Java, так и код C / C ++ необходимо оптимизировать между точками сохранения, но в меньшей степени - между точками сохранения. Компилятор JIT генерирует карту GC в каждой точке сохранения. Код C / C ++ в виртуальной машине использует стилизованные макросы (например, TRAPS) для обозначения потенциальных безопасных точек.

Работая с вышеупомянутыми флагами, я получаю следующий результат:

Application time: 0.9668750 seconds
Total time for which application threads were stopped: 0.0000747 seconds, Stopping threads took: 0.0000291 seconds
timeElapsed=1015
Application time: 1.0148568 seconds
Total time for which application threads were stopped: 0.0000556 seconds, Stopping threads took: 0.0000168 seconds
timeElapsed=1015
timeElapsed=1014
Application time: 2.0453971 seconds
Total time for which application threads were stopped: 10.7951187 seconds, Stopping threads took: 10.7950774 seconds
timeElapsed=11732
Application time: 1.0149263 seconds
Total time for which application threads were stopped: 0.0000644 seconds, Stopping threads took: 0.0000368 seconds
timeElapsed=1015

Обратите внимание на третье событие STW:
Общее время остановки: 10,7951187 секунд.
Остановка потоков заняла: 10,7950774 секунды.

Сам JIT практически не занимал времени, но как только JVM решила выполнить JIT-компиляцию, она перешла в режим STW, однако, поскольку код, который должен быть скомпилирован (бесконечный цикл), не имеет места вызова , точка безопасности не была достигнута.

STW завершается, когда JIT в конце концов прекращает ожидание и завершает работу кода в бесконечном цикле.

После того, как я проследил за комментариями и самостоятельно провел некоторое тестирование, я считаю, что пауза вызвана JIT-компилятором. Почему JIT-компилятор занимает так много времени, я не могу отладить.

Однако, поскольку вы спросили только, как этого избежать, у меня есть решение:

Превратите ваш бесконечный цикл в метод, где его можно исключить из JIT-компилятора

public class TestBlockingThread {
    private static final Logger LOGGER = Logger.getLogger(TestBlockingThread.class.getName());

    public static final void main(String[] args) throws InterruptedException     {
        Runnable task = () -> {
            infLoop();
        };
        new Thread(new LogTimer()).start();
        Thread.sleep(2000);
        new Thread(task).start();
    }

    private static void infLoop()
    {
        int i = 0;
        while (true) {
            i++;
            if (i != 0) {
                boolean b = 1 % i == 0;
            }
        }
    }

Запустите вашу программу с этим аргументом виртуальной машины:

-XX: CompileCommand = exclude, PACKAGE.TestBlockingThread :: infLoop (замените PACKAGE информацией о вашем пакете)

Вы должны получить подобное сообщение, чтобы указать, когда метод был бы JIT-скомпилирован:
### Исключая компиляцию: статическая блокировка.TestBlockingThread :: infLoop
вы можете заметить, что я помещаю класс в пакет, называемый блокировкой