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