История бага JDK и связанной с ним ошибки разработки, приведшей к нештатной 100%-загрузке CPU. Что пошло не так, что можно было сделать лучше, и кто, в конце концов, оказался виноват?

Благодарю (дополнено позже):

• Omar Elrefaei за его PR, который исправил форматирование данного документа.
• /u/thorn-harvestar/, /u/philipTheDev/ и /u/vips7L/: за определение еще одной фундаментальной причины — мне не стоит продолжать использовать JDK8.
• /u/SirSagramore/ и /u/wot-teh-phuck: за доказательство того, что это действительно была моя вина :(. Преждевременная оптимизация — корень всех зол.

Вой сирен

Пару лет назад мне пришел баг репорт, в котором утверждалось, что я вызвал 100% загрузку CPU на виртуальной машине в ситуации, когда процессор должен находится в покое. Мне стало любопытно, так как при реализации я старался избегать паттернов вроде while(true) и for(;;).
Инженер поддержки, написавший тот самый репорт, приложил доказательство:

$ top
  PID USER      PR  NI    VIRT    RES  %CPU  %MEM     TIME+ S COMMAND
    1 root      20   0 1832.5m  20.6m 100.7   1.0   4:11.04 S java Main
   25 root      20   0    1.6m   1.1m   0.0   0.1   0:00.04 S sh
   38 root      20   0    1.9m   1.2m   0.0   0.1   0:00.00 R  `- top

Действительно, JVM использовала 100% CPU. И все же, как он на меня вышел?

Как меня нашли?

Этот баг отследил разработчик ПО. Сначала через top -H -p ‹pid› он получил список идентификаторов потоков, связанных с процессом Java, используя pid из предыдущей команды top:

$ top -H -p 1
  PID USER      PR  NI    VIRT    RES  %CPU  %MEM     TIME+ S COMMAND
    1 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.02 S java Main
    7 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.32 S  `- java Main
    8 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.00 S  `- java Main
    9 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.00 S  `- java Main
   10 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.01 S  `- java Main
   11 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.00 S  `- java Main
   12 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.00 S  `- java Main
   13 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.00 S  `- java Main
   14 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.03 S  `- java Main
   15 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.05 S  `- java Main
   16 root      20   0 1832.5m  20.6m   0.0   1.0   0:00.00 S  `- java Main
   17 root      20   0 1832.5m  20.6m   0.7   1.0   0:00.42 S  `- java Main
   18 root      20   0 1832.5m  20.6m  99.9   1.0   3:08.69 R  `- java Main

Поток с ID 18 потреблял 100% CPU.

Конвертировав этот ID в шестнадцатеричную систему, он получил 12.

$ printf "%x\n" 18
12

Далее он вывел дамп потока в stdout, используя kill -s QUIT ‹pid›, после чего нашел строку nid=0x12, чтобы выйти на трассировку его стека.

$ kill -s QUIT 1
...
"joseph-mate-pool-1-thread-1" #8 prio=5 os_prio=0 tid=0x0000558708d94000 nid=0x12 runnable [0x00007f23e77fd000]
   java.lang.Thread.State: RUNNABLE
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
...

Черт возьми! Это точно мой поток. Хорошо, что я предоставил соответствующую фабрику, чтобы облегчить возможную отладку для других разработчиков. Похоже, что-то из размещенного мной в ScheduledThreadPoolExecutor полностью занимало CPU.

Моя ли в том вина?

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

executorService.scheduleWithFixedDelay(
    () -> doSomethingReallyCheap(),
    0, // Начальная задержка
    10, // задержка
    TimeUnit.MINUTES
);

Этот скрипт выполнялся раз в 10 минут и привязки к CPU не имел. Были и другие схожие блоки кода, планирующие подобную работу при запуске приложения, но и они не относились к CPU. К тому же я намеренно выбрал scheduleWithFixedDelay на случай, если выполнение внезапно займет дольше 10 минут, чтобы пул потоков не оказался перегружен лишней работой до завершения предыдущего экземпляра задачи. Здесь мои догадки кончились, и я обратился к коллеге, чтобы он меня перепроверил.

Он оценил ситуацию и согласился со мной. Не похоже на проблему с doSomethingReallyCheap(). Однако при более внимательном анализе трассировки стека он заметил, что проблема не в doSomethingReallyCheap(). По факту все стопорилось в DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:809)! Было решено обратиться за помощью к интернету.

Оправдан!

Загуглив по запросу «ScheduledThreadPoolExecutor 100% CPU», я нашел пост на StackOverflow, в котором описывались аналогичные симптомы: "ScheduledExecutorService consumes 100% CPU when corePoolSize = 0"

У автора была точно такая же строка кода, что и у меня:

ScheduledExecutorService executorService = Executors.newScheduledThreadPool(0);

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

Помимо этого, не рекомендуется устанавливать corePoolSize на 0 или использовать allowCoreThreadTimeOut, поскольку тогда пул может остаться без потоков для обработки задач при их готовности к выполнению.

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

corePoolSize – это количество потоков, которое должно присутствовать в пуле даже в случае их бездействия, если только не включена опция allowCoreThreadTimeOut. Поэтому я ожидал, что пул будет хранить потоки временно.

В итоге, чтобы обойти это неожиданное поведение, я решил переключиться на corePoolSize=1. Меня расстраивало, что всегда будет один активный поток, но это лучшее, что я мог сделать за имеющееся время.

Тем не менее это странное поведение меня сильно озадачило. Неужели я ошибочно понял JavaDocs? Промотав тему вниз, я испытал облегчение, прочитав лучший ответ:

Это известный баг: JDK-8129861 https://bugs.openjdk.java.net/browse/JDK-8129861, который устранили в JDK9.

Оправдан!

Почему!?

И все же я не успокоился. Как может corePoolSize=0 приводить к тому, что JDK потребляет 100% CPU? Подробности о названном баге ситуацию не прояснили:

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

Все это говорит о том, что в JDK9 планировалось внесение масштабных изменений в ScheduledThreadPoolExecutor. Также стало понятно, что разработчики вряд ли станут исправлять этот баг в JDK8. В общем, если вы решите проделать аналогичный трюк в последней версии JDK8, то проблема наверняка повторится.

Похоже, без копания в исходном коде не обойтись. Начнем расследование с верхушки стека из полученного ранее дампа: ScheduledThreadPoolExecutor$DelayedWorkQueue.poll(ScheduledThreadPoolExecutor.java:809).Запустив минимальный воссоздаваемый образец в IntelliJ и определив точку останова у DelayedWorkerQueue.poll, можно будет найти этот бесконечный цикл. Просмотрев несколько фреймов стека, мы видим ThreadPoolExecutor.getTask, который им и является:

private Runnable getTask() {
    boolean timedOut = false; // Время последнего poll() истекло?
    for (;;) {
        ...
        int wc = workerCountOf(c);
        // Работники отбрасываются?
        boolean timed = allowCoreThreadTimeOut || wc > corePoolSize;

        if ((wc > maximumPoolSize || (timed && timedOut))
            && (wc > 1 || workQueue.isEmpty())) {
            if (compareAndDecrementWorkerCount(c))
                return null;
            continue;
        }

        try {
            Runnable r = timed ?
                workQueue.poll(keepAliveTime, TimeUnit.NANOSECONDS) :
                workQueue.take();
            if (r != null)
                return r;
            timedOut = true;
        ...
    }
}

1. Заметьте, что здесь keepAliveTime равен 0.
2. Количество воркеров (wc) равно 1, поскольку присутствует один активный поток.
3. corePoolSize равен 0.
4. Это значит, что timed = true.
5. Далее проверяем, можно ли отбросить воркера.
6. Есть 2 условия, которые могут не дать это сделать:
   
   1. wc > 1; но в данном случае у нас всего 1 воркер.
   2. workQueue.isEmpty() пустой быть не может, так как это запланированная задача, и она будет всегда находиться в очереди.
7. Это означает, что мы опрашиваем workerQueue с keepAliveTime=timeout=0!
8. В свою очередь, это значит, что опрос тут-же возвращает.
9. В результате мы вновь оказываемся в начале цикла for(;;), и ни одно из условий последней итерации не меняется.

И наоборот, если corePoolSize равен 1, тогда time=false, и вместо этого возврат происходит из workQueue, что вызывает блокировку. Это объясняет, почему установка corePoolSize=1 позволяет обойти проблему.

Можно это исправить, изменив условие wc > 1 на wc > 0, а также условие isEmpty() на проверку, нужно ли в ближайшее время что-либо выполнять. Однако такой прием создает большую проблему в структуре. Мы используем текущий поток воркера для опроса на наличие задач, и не можем изменить условие отброса воркера на wc > 0. Нужно было изначально прислушаться к предупреждению JavaDoc и не использовать corePoolSize=0.

Для исправления ограничения этой версии JDK, вероятно, можно запланировать создание нового потока при приближении дедлайна запланированной задачи и выйти из текущего потока. Тем не менее здесь еще многое нужно выяснить. Например, кто тогда будет создавать поток, когда потребуется запустить запланированную задачу?

Что можно было сделать лучше?

Прочесть руководство: я никак не мог знать, что corePoolSize=0 не сработает. Можно было прочитать JavaDocs более подробно и прислушаться к предупреждению. Хотя и в случае прочтения этой строки, вряд ли она бы меня остановила, потому что в моем представлении данный вариант был приемлем.

Провести тесты: смущает то, что проблема воссоздается каждый раз, и обнаружить 100% загрузку CPU должно быть просто – достаточно было промониторить процессор при тестировании. Я же делал это только при проверке кода на изменение быстродействия и не предвидел, что данное изменение на него повлияет. Нужно ли мне проверять CPU при всех изменениях? А может есть автоматизированный тест, обнаруживающий существенные отличия в использовании CPU при изменении кода?

Обновиться: если бы я своевременно обновлял JDK, то и проблемы, которая датируется 2018 или 2019 годом, не возникло бы. Примерно в то время вышла версия JDK11, в которой этого бага уже не было.

Не оптимизировать: не стоило заниматься оптимизацией пула потоков. Об этом отчетливо сообщили в двух комментариях, указав на мою ошибку:

Вы виновны в одном из величайших преступлений, которые только можно совершить в сфере компьютерной науки – в превентивной оптимизации. Постоянное потребление одного потока занимает совсем незначительный объем ресурсов. Любая попытка оптимизации этого в лучшем случае была бессмысленна, а в худшем — опасна. Собственно, в этом вы и убедились. — /u/SirSagramore/

Я понял, что преждевременная оптимизация без подтверждающих ее необходимость фактов/чисел редко оказывается хорошей идеей. Это всего лишь один поток ОС, а ОС наверняка лучше разработчика знает, как управлять ресурсами в долгосрочной перспективе. — /u/wot-teh-phuck

Попробуйте сами

Если хотите проэкспериментировать сами, то скомпилируйте и выполните приведенный ниже код, используя JDK8. На момент написания статьи баг продолжает проявляться, так как исправили его только в JDK9.

import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;

public final class Main {

  public static void main(String [] args) throws Exception {
    ScheduledExecutorService executorService = Executors.newScheduledThreadPool(0);
    executorService.scheduleWithFixedDelay(
        () -> System.out.println("Hello World!"),
        0, // Начальная задержка
        10, // задержка
        TimeUnit.MINUTES
    );
    while (true) {
      Thread.sleep(10000);
    }
  }

}

Исключительно в качестве дополнительной проверки я попробовал выполнить этот код в JDK9. Что сказать, загрузка процессора оказалась низкой.

$ top
  PID USER      PR  NI    VIRT    RES  %CPU  %MEM     TIME+ S COMMAND
    1 root      20   0 3008.5m  29.1m   0.0   1.5   0:00.76 S java Main
   27 root      20   0    1.6m   0.0m   0.0   0.0   0:00.02 S sh
   34 root      20   0    7.9m   1.3m   0.0   0.1   0:00.01 R  `- top

Заключительные измышления

Меня успокоило то, что основная вина лежит не на мне. Хотя к проблеме я все равно причастен, ведь мог обнаружить ее, если бы промониторил CPU при тестировании. К счастью, у нас есть сильные инженеры, которые выловили баг до релиза.