100% загрузка CPU: моя вина?

Kate

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

 
Сверху