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

Поток 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 секунд. Я попытался изменить приоритеты потоков и другие настройки, ничего не получилось.

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

4b9b3361

Ответ 1

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

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

Итак, я призываю -XX:+PrintAssembly во всей красе, чтобы помочь

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

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

UPDATE

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

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

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

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

Существует большое обязательное сообщение в блоге Safepoints: Значение, побочные эффекты и накладные расходы Nitsan Wakart, охватывающий safepoints и эту конкретную проблему.

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

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

  • Вы можете попробовать использовать -XX:+UseCountedLoopSafepoints (это приведет к общему снижению производительности и может привести к сбою JVM JDK-8161147). После использования его C2 компилятор продолжает сохранять safepoints на задних скачках, а оригинальная пауза полностью исчезает.
  • Вы можете явно отключить компиляцию проблемного метода, используя
    -XX:CompileCommand='exclude,binary/class/Name,methodName'

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

Ответ 2

Короче говоря, у цикла, который у вас нет, нет безопасной точки внутри него, кроме тех случаев, когда достигается 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-ядерном компьютере, поэтому нет недостатка в ресурсах процессора.

Ответ 3

Нашел ответ на вопрос почему. Они называются safepoints и наиболее известны как 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

Точка во время выполнения программы, при которой известны все корни GC, и содержимое содержимого кучи согласовано. С глобальной точки зрения все потоки должны блокироваться в безопасном месте до запуска GC. (В качестве особого случая потоки с JNI-кодом могут продолжаться, потому что они используют только дескрипторы. Во время safepoint они должны блокировать, а не загружать содержимое дескриптора.) С локальной точки зрения, safepoint является выделенной точкой в блоке кода, где исполняемый поток может блокировать GC. Большинство сайтов вызовов квалифицируются как safepoints.. Существуют сильные инварианты, которые сохраняются в каждом безопасном месте, что может быть проигнорировано в небезопасных точках. Оба скомпилированных Java-кода и кода C/С++ оптимизируются между безопасными точками, но в меньшей степени - через safepoint. Компилятор JIT испускает карту GC на каждом этапе safepoint. Код C/С++ в VM использует стилизованные соглашения на основе макросов (например, 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, однако, поскольку код, который должен быть скомпилирован (бесконечный цикл), не имеет сайта вызова, no safepoint не был когда-либо достигались.

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

Ответ 4

После непосредственного обсуждения потоков комментариев и некоторых тестов я считаю, что пауза вызвана компилятором 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;
            }
        }
    }

Запустите программу с помощью этого аргумента VM:

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

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