[Перевод] 3200% нагрузки на процессор02.03.2025 16:45

Совсем недавно моя машина была в таком запущенном состоянии, что я едва мог подключиться к ней через ssh. 3200% нагрузки на CPU — полностью использовались все 32 ядра хоста! Сравните это с моим последним багом, когда использовалось всего одно ядро, то есть 100%

К счастью, я использовал среду выполнения Java 17, у которой были дампы потоков с указанием времени CPU! Выполнив сортировку по времени CPU, я обнаружил группу потоков, выглядевших примерно так:

"Thread-0" #22 [14700] prio=5 os_prio=0 cpu=10359.38ms elapsed=11.49s tid=0x000001cdc35aaf60 nid=14700 runnable  [0x00000047cfffe000]
   java.lang.Thread.State: RUNNABLE
	at java.util.TreeMap.put(java.base@17.0.1/TreeMap.java:826)
	at java.util.TreeMap.put(java.base@17.0.1/TreeMap.java:534)
	at BusinessLogic.someFunction(BusinessLogic.java:29)
    ...

Я быстро сделал вывод и решил взглянуть на BusinessLogic:29. Она выглядела так:

public void someFunction(SomeType relatedObject, List unrelatedObjects) {
  ...
  for (SomeOtherType unrelatedObject : unrelatedObjects) {
    treeMap.put(relatedObject.a(), relatedObject.b()); // строка 29
  }
  ...
}

Странный код. Обратите внимание, что мы выполняем итерации с unrelatedObject, но в теле цикла используется только relatedObject. Код можно упростить до такого:

public void someFunction(SomeType relatedObject, List unrelatedObjects) {
  ...
  treeMap.put(relatedObject.a(), relatedObject.b());
  ...
  // unrelatedObjects используется ниже в функции, так что параметр удалить нельзя
}

Похоже, в этом коде выполнили рефакторинг, и unrelatedObject больше не использовался. Я подготовил свой юнит-тест и прогнал его до и после исправления. Я попробовал treeMap и unrelatedObjects с 1000000 элементов, что существенно превосходит любые значения, которые встречались приложению, но не смог воспроизвести проблему. Если допустить, что unrelatedObjects имеет размер N, а treeMap — размер M, то сложность равна O (N lg (M)). Поэтому логично, что я не смог воспроизвести проблему. Программа не будет выполняться минуту и больше, пока не достигнет от 100 миллиона до 1 миллиарда элементов.

Должно быть, дело в другом. Я был уверен, что в treeMap и unrelatedObjects никогда не было больше 1000 элементов. А этого и близко недостаточно для того, чтобы вызвать проблемы у алгоритма O (N lg (M)).

Класс был мне малознаком, поэтому я начал изучать код, проверяя своё предположение о том, что treeMap и unrelatedObjects никогда не превышают 1000 элементов. Возможно ли, что в них хранятся миллионы или даже миллиарды элементов?

А затем я увидел следующее определение TreeMap:

// Поле на самом деле не называлось treeMap.
private final Map treeMap = new TreeMap<>();

Пугающая картина. К TreeMap получает доступ множество потоков, а она никак не защищена. В этот момент меня осенило. Может ли незащищённая (unguarded) TreeMap вызывать использование процессора на 3200%?

Эксперимент

Чтобы воспроизвести проблему, я подготовил небольшой эксперимент: создал группу потоков, случайно обновляющую общую TreeMap.

for (int i = 0; i < numThreads; i++) {
    threads.add(new Thread(() -> {
        Random random = new Random();
        for(int j = 0; j < numUpdates; j++) {
            try {
                treeMap.put(random.nextInt(1000), random.nextInt(1000));
            } catch (NullPointerException e) {
                // допускаем продолжение выполнения, чтобы можно было воспроизвести проблему.
            }
        }
    }));
}

Этот try catch был ключевым моментом. Без try catch я бы не смог воспроизвести проблему. Некоторые потоки вылетали со следующим выводом:

Exception in thread "Thread-0" java.lang.NullPointerException: Cannot read field "right" because "l" is null
        at java.base/java.util.TreeMap.rotateRight(TreeMap.java:2562)
        at java.base/java.util.TreeMap.fixAfterInsertion(TreeMap.java:2594)
        at java.base/java.util.TreeMap.addEntry(TreeMap.java:770)
        at java.base/java.util.TreeMap.put(TreeMap.java:828)
        at java.base/java.util.TreeMap.put(TreeMap.java:534)
        at SimpleRepro.lambda$main$0(SimpleRepro.java:28)
        at java.base/java.lang.Thread.run(Thread.java:833)

но программа всё равно останавливалась.

Вероятно, эта проблема может возникнуть только в языках, позволяющих отлавливать NullPointerException. Программы на других языках просто вылетят. После нескольких прогонов я наблюдал использование CPU на 500%. Безумие! Я всегда считал, что состояния гонки приводят к повреждениям данных или к взаимной блокировке. Но я никогда не думал, что они могут привести к проблемам с производительностью. Но это логично — можно повредить данные так, что это создаст бесконечный цикл.

Можете изучить мой эксперимент с Java из моего репозитория GitHub java-by-experiments SimpleRepro.java

Чтобы проверить всё ещё раз, я создал ещё один эксперимент, использующий рефлексию TreeMap для выполнения дампа узлов и их цветов. (В Java TreeMap реализована на основе красно-чёрного дерева.) Цикл в TreeMap выделен синим.

Так что если вы ищете или помещаете в map что-то, ещё не находящееся в ней, то можете застрять в бесконечном цикле.

Чтобы воспроизвести показанный выше граф, нужно использовать рефлексию для доступа к корню, а также к левому и правому полям TreeMap.Entry. Мы рекурсивно обходим TreeMap.Entry, начиная с корня и отслеживая посещённые Entry. Если мы зайдём в уже посещённый entry, то будем знать, что попали в цикл. Выведем все узлы из visited, чтобы показать цикл.

private final TreeMap treeMap;
private static final Field treeMapRootField;
private static final Field treeMapEntryLeft;
private static final Field treeMapEntryRight;
private static final Field treeMapEntryKey;
private static final Field treeMapEntryColor;

...

public void print() throws Exception {
    print(treeMapRootField.get(treeMap), "", new IdentityHashMap<>());
}

private void print(
    Object treeMapEntry, String tabs, IdentityHashMap visited
) throws Exception {
    if (treeMapEntry != null && !visited.containsKey(treeMapEntry)) {
        // обход по порядку
        visited.put(treeMapEntry, treeMapEntry);
        print(treeMapEntryLeft.get(treeMapEntry), tabs + "  ", visited);
        System.out.println(tabs + treeMapEntryKey.get(treeMapEntry) + ":"
            + (treeMapEntryColor.getBoolean(treeMapEntry) ? "BLACK" : "RED"));
        print(treeMapEntryRight.get(treeMapEntry), tabs + "  ", visited);
    } else if (treeMapEntry != null && visited.containsKey(treeMapEntry)) {
        System.out.println(tabs + treeMapEntryKey.get(treeMapEntry)  + ":"
            + (treeMapEntryColor.getBoolean(treeMapEntry) ? "BLACK" : "RED")
            + " CYCLE"
        );
    }
}

Работающий код выложен в моём проекте ExploringTreeMap.java и TreeMapExplorer.java GitHub java-by-experiments.

Другие исследования

Я не первый, кто пишет об этой проблеме. В процессе подготовки статьи я нашёл:

Статью Иво Анхо: writing to a java treemap concurrently can lead to an infinite loop during reads
Статью Red Hat по устранению неполадок: High CPU due to multiple Java threads accessing TreeMap simultaneously
- Судя по web archive, впервые об этой проблеме сообщили ещё 20 июня 2011 года
Об этом даже есть вопрос на Stack Overflow: Java Process consumes more than 100% CPU

Однако в моей статье описаны аспекты, о которых раньше не говорили:

Практический код, воспроизводящий проблему.
Предположение о том, что только один класс языков сталкивается с этой проблемой, и эксперименты с этой гипотезой
Обзор языков с целью изучения возможности воспроизведения проблемы
Новый подход к исправлению TreeMap и красно-чёрного дерева с целью предотвращения этой проблемы

Если что-то из вышеперечисленного вам интересно, продолжайте чтение.

Этот код нереалистичен

Кто-то может заявить, что мой экспериментальный код нереалистичен. Кто игнорирует NPE? На практике такая ситуация может возникать в двух случаях: неотловленные исключения в Executor и сервисы на основе пула потоков.

Неотловленные исключения в Executor

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

Приведённый ниже код тоже воспроизводит проблему, но с пулом потоков.

final ExecutorService pool = Executors.newFixedThreadPool(numThreads);
final TreeMap treeMap = new TreeMap<>();

Random random = new Random();
for (int i = 0; i < numThreads*numUpdatesPerThread; i++) {
    pool.submit( () -> {
        treeMap.put(random.nextInt(10000), random.nextInt(10000));
    });
}

pool.shutdown();
pool.awaitTermination(1, TimeUnit.DAYS);

код из ExecutorUncaughtRepro.java

При его запуске он зависнет. Создав дамп потоков, мы увидим те же симптомы:

"pool-1-thread-1" #22 [15356] prio=5 os_prio=0 cpu=17734.38ms elapsed=21.39s tid=0x0000023c45dd3e90 nid=15356 runnable  [0x000000780b4fe000]
   java.lang.Thread.State: RUNNABLE
	at java.util.TreeMap.put(java.base@19.0.1/TreeMap.java:826)
	at java.util.TreeMap.put(java.base@19.0.1/TreeMap.java:534)
	at ExecutorUncaughtRepro.lambda$main$0(ExecutorUncaughtRepro.java:33)
	at ExecutorUncaughtRepro$$Lambda$14/0x00000008010031f0.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(java.base@19.0.1/Executors.java:577)
	at java.util.concurrent.FutureTask.run(java.base@19.0.1/FutureTask.java:317)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@19.0.1/ThreadPoolExecutor.java:1144)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@19.0.1/ThreadPoolExecutor.java:642)
	at java.lang.Thread.run(java.base@19.0.1/Thread.java:1589)

Код застрял на TreeMap и очень активно использует CPU.

Однако при изучении стандартного вывода мы не найдём ничего! Пул потоков поглотил все NPE, никак не сообщая о проблеме. К сожалению, именно это случилось в моей ситуации.

При управлении собственными пулами потоков, обязательно нужно:

Зарегистрировать обработчик неотловленных исключений в потоке при помощи фабрики потоков
Работать с возвращаемыми им future. Если выполнить future.get (), то мы получим ExectionException, обёртывающее NPE!

То же самое с gRPC

Ещё один способ получения этой проблемы — создание сервиса, использующего пул потоков, например, сервис gRPC. Ниже я воспроизвожу реалистичный сценарий gRPC, приводящий к проблеме. Сервис работает на основе незащищённой TreeMap.

@Override
public void addReceipt(
    ReceiptProcessorServiceOuterClass.AddReceiptRequest req,
    StreamObserver responseObserver
) {
    int timestamp = req.getTimestamp();
    int totalPrice = req.getTotalPrice();
    receipts.put(timestamp, totalPrice);
    ReceiptProcessorServiceOuterClass.AddReceiptResponse response = ReceiptProcessorServiceOuterClass.AddReceiptResponse.newBuilder().build();
    responseObserver.onNext(response);
    responseObserver.onCompleted();
}

код из GrpcRepro.java

Создав дамп потоков, мы получим следующее:

"grpc-default-executor-23" #54 [8796] daemon prio=5 os_prio=0 cpu=18671.88ms elapsed=175.50s tid=0x00000168b6c707c0 nid=8796 runnable  [0x000000059fbfe000]
   java.lang.Thread.State: RUNNABLE
	at java.util.TreeMap.put(java.base@19.0.1/TreeMap.java:826)
	at java.util.TreeMap.put(java.base@19.0.1/TreeMap.java:534)
	at ReceiptProcessorServiceImpl.addReceipt(GrpcRepro.java:59)
	at ReceiptProcessorServiceGrpc$MethodHandlers.invoke(ReceiptProcessorServiceGrpc.java:185)
	at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
	at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:346)
	at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:860)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@19.0.1/ThreadPoolExecutor.java:1144)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@19.0.1/ThreadPoolExecutor.java:642)
	at java.lang.Thread.run(java.base@19.0.1/Thread.java:1589)

И здесь мы видим, что TreeMap.put () застревает в бесконечном цикле.

Как это произошло? Повороты

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

Кроме того, я подозреваю, что необходимо NPE. Как я увидел в своих экспериментах с Java, без возникновения NPE проблема не воспроизводится.

Другие языки

Я исследовал предположение о том, что эта проблема возникает только в языках с NPE, попробовав воспроизвести её в максимально возможном количестве языков, на которых я программировал. Если это утверждение истинно, то она должна воспроизводиться только на Java, Kotlin, C#, Ruby, Typescript и Python. Я ожидаю, что она не возникнет в коде на Go, C++, Rust и Elixir.

Язык	Возникла ли проблема	Объяснение	Код
Java	Да	Вся эта статья	source
C#	Да	В SortedDictionary использовалось красно-чёрное дерево	source
Ruby	Нет	Использовано красно-чёрное дерево из kanwei/algorithms, но мне не удалось воспроизвести проблему. Я считаю, что её не удалось воспроизвести из-за Global Interpreter Lock (GIL) и потому, что он ограничивает переключение контекста потоков, предотвращая чередование потоков, вызывающее бесконечный цикл.	source
C++	Да	Использовалось красно-чёрное дерево. Я ожидал, что код всегда будет сначала уходить в segfault, не позволяя проблеме возникнуть.	source
Go	Да	Имеет популярную библиотеку структур данных. Аналогично C++, я ожидал, что будет возникать только segfault, а бесконечный цикл воспроизводиться не будет. Я ошибался.	source
Rust	Нет	Мне мешал компилятор. Я слишком мало знаю об unsafe-коде, чтобы воспроизвести проблему	source
Kotlin	Да	Использует TreeMap java, ожидалась та же проблема
PHP	Нет	Красно-чёрного дерева нет в стандартной библиотеке и не нашёл ни одной популярной библиотеки с его использованием
JavaScript	Нет	Модель многопоточности не может работать с общими ссылками
Typescript	Нет	То же самое, что и для JavaScript
Python	Нет	Красно-чёрного дерева нет в стандартной библиотеке, а популярные библиотеки наподобие Sorted Containers не используют красно-чёрное дерево. Несмотря на отсутствие красно-чёрного дерева, даже при проведении эксперимента я бы ожидал, что проблему не удастся воспроизвести по той же причине, что и в Ruby: GIL.
Elixir	Нет	Хотя в Elixir (и Erlang) есть множество сторонних реализаций красно-чёрных деревьев, из-за модели разработки программ воспроизвести проблему было бы невозможно: структуры данных неизменяемы, а взаимодействия между потоками ограничены только передачей сообщений.

Самым интересным в таблице оказался C++, потому что из-за моей гипотезы я не ожидал, что в нём получится воспроизвести проблему. Поэтому я добавил в статью подробности эксперимента. Go тоже повёл себя неожиданно, но в статье я его не рассматривал. Почитать о Go можно на Github.

По сути, код такой же, как и код на Java, только в нём используются стандартные библиотеки C++. Ещё я добавил в код дополнительный вывод: меня так поразило, что проблема воспроизвелась, что я хотел быть точно в этом уверен.

// Эквивалент TreeMap в C++ - это std::map
// Использует ту же структуру данных красно-чёрного дерева
std::map sortedMap;

for (int i = 0; i < numThreads; i++) {
    threads.emplace_back([&]() {
        // копируем, чтобы не использовать последнее значение i (5)
        int threadId = threadIdGenerator.fetch_add(1);
        std::random_device rd;
        std::mt19937 gen(rd());
        std::uniform_int_distribution<> dis(0, 999);
                    
        int progressThreshold = numUpdates / progressRatio;
        std::cout << "Thread " << threadId << " started.";
        for (int j = 0; j < numUpdates; j++) {
            try {
                int key = dis(gen);
                int value = dis(gen);

                sortedMap[key] = value;
            } catch (const std::exception& e) {
                std::cerr << "Caught exception on thread " << threadId << ":" << e.what() << std::endl;
            }

            if ((j + 1) % progressThreshold == 0) {
                    std::cout << "Thread " << threadId << ": " 
                            << ((j + 1) * 100 / numUpdates) << "% complete (" 
                            << (j + 1) << "/" << numUpdates << " updates)\n";
            }
        }
        std::cout << "Thread " << threadId << " completed.";
    });
}

Время от времени программа как и ранее вылетала по segfault. Я ожидал, что наихудший сбой должен выглядеть так:

./SimpleRepro
zsh: segmentation fault  ./SimpleRepro

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

./SimpleRepro
Thread 0 started.Thread Thread 0: 10% complete (Thread 10/10012Thread  started.3
started.Thread 4 started.Thread 4: 10% complete (10/100 updates)
 updates)
Thread 0: 20% complete (20/100 updates)
Thread 0: 30% complete (30/100 updates)
Thread 0: 40% complete (40/100 updates)
Thread 1: 10% complete (10/100 updates)
 started.Thread 2: 10% complete (10/100 updates)
Thread 1: 20% complete (20/100 updates)
<в течение пяти минут в выводе нет ничего>

В инструменте top видно, что проблема воспроизвелась, ведь CPU очень активно используется.

top
PID    COMMAND      %CPU  TIME     ...
59815  SimpleRepro  170.8 08:49.61 ...

Это доказывает, что моё утверждение ложно. Мне удалось воспроизвести проблему на Go и C++. Хотя в них иногда возникал segfault, были и ситуации застревания в бесконечном цикле. В языке наподобие C++ при ссылке на нулевой указатель всегда происходит segfault, поэтому должно существовать чередование потоков, не позволяющее добраться до нулевого указателя! И я понятия не имею, почему. Я ожидал, что код будет вылетать, учитывая то, насколько часто я видел NPE в экспериментах с Java.

Вооружённый этим знанием, я вернулся к своему эксперименту Java SimpleRepro и перестал отлавливать в нём NPE. Запустив его 12 раз, я всё равно мог воспроизводить прблему, хоть и не отлавливал их:

"Thread-4" #17 prio=5 os_prio=31 cpu=18597.02ms elapsed=23.79s tid=0x00007f81051ac200 nid=0x6a03 runnable  [0x000070000bcb5000]
   java.lang.Thread.State: RUNNABLE
        at java.util.TreeMap.put(java.base@17.0.3/TreeMap.java:826)
        at java.util.TreeMap.put(java.base@17.0.3/TreeMap.java:534)
        at SimpleRepro.lambda$main$0(SimpleRepro.java:28)
        at SimpleRepro$$Lambda$1/0x0000000800c00a08.run(Unknown Source)
        at java.lang.Thread.run(java.base@17.0.3/Thread.java:833)

Ещё меня удивило то, что языки наподобие Ruby, в которых удобнее отлавливать NPE, не позволяют воспроизвести проблему. Global Interpreter Lock (GIL) каким-то образом препятствует всем чередованиям исполнения, воспроизводящим эту проблему.

Простой способ исправления: защита от одновременной модификации

Проще всего устранить эту проблему, обернув TreeMap в Collections.synchronizedMap или переключившись на ConcurrentHashMap и выполнять сортировку по необходимости. Однако такие исправления скучны, к тому же не мешают нам делать ошибки и положить хост.

Спорный способ исправления: отслеживание посещённых узлов

Что, если бы мы могли безопасно совершать ошибку, но не входить в цикл?

Я модифицировал красно-чёрное дерево так, чтобы фиксировались уже посещённые узлы. Это только требует дополнительной памяти O (lg (n)). Высота красно-чёрного дерева гарантировано будет O (lg (n)). Если мы встречаем уже посещённый узел, то выбрасываем ConcurrentModificationException. Это не предотвратит повреждения данных, но предотвратит использование CPU на 100% из-за бесконечного цикла, если в будущем кто-то снова совершит эту ошибку. Впрочем, для этого нужно, чтобы такая методика была внедрена в стандартные библиотеки;, но не думаю, что это произойдёт, ведь для неё требуется дополнительная память.

diff --git a/tree_map_corruption/java/src/main/java/ProtectedTreeMap.java b/tree_map_corruption/java/src/main/java/ProtectedTreeMap.java
index 53c15bb..2713d5a 100644
--- a/tree_map_corruption/java/src/main/java/ProtectedTreeMap.java
+++ b/tree_map_corruption/java/src/main/java/ProtectedTreeMap.java
@@ -345,7 +345,9 @@ public class ProtectedTreeMap
         @SuppressWarnings("unchecked")
             Comparable k = (Comparable) key;
         Entry p = root;
+        IdentityHashMap, Boolean> visited = new IdentityHashMap<>();
         while (p != null) {
+            visited.put(p, true);
             int cmp = k.compareTo(p.key);
             if (cmp < 0)
                 p = p.left;
@@ -353,6 +355,10 @@ public class ProtectedTreeMap
                 p = p.right;
             else
                 return p;
+
+            if (visited.containsKey(p)) {
+                throw new ConcurrentModificationException("TreeMap corrupted. Loop detected");
+            }
         }
         return null;
     }
@@ -779,6 +785,7 @@ public class ProtectedTreeMap
     }
 
     private V put(K key, V value, boolean replaceOld) {
+        IdentityHashMap, Boolean> visited = new IdentityHashMap<>();
         Entry t = root;
         if (t == null) {
             addEntryToEmptyMap(key, value);
@@ -790,6 +797,7 @@ public class ProtectedTreeMap
         Comparator cpr = comparator;
         if (cpr != null) {
             do {
+                visited.put(t, true);
                 parent = t;
                 cmp = cpr.compare(key, t.key);
                 if (cmp < 0)
@@ -803,12 +811,17 @@ public class ProtectedTreeMap
                     }
                     return oldValue;
                 }
+
+                if (visited.containsKey(t)) {
+                    throw new ConcurrentModificationException("TreeMap corrupted. Loop detected");
+                }
             } while (t != null);
         } else {
             Objects.requireNonNull(key);
             @SuppressWarnings("unchecked")
             Comparable k = (Comparable) key;
             do {
+                                                               visited.put(t, true);
                 parent = t;
                 cmp = k.compareTo(t.key);
                 if (cmp < 0)
@@ -822,6 +835,10 @@ public class ProtectedTreeMap
                     }
                     return oldValue;
                 }
+
+                if (visited.containsKey(t)) {
+                    throw new ConcurrentModificationException("TreeMap corrupted. Loop detected");
+                }
             } while (t != null);
         }
         addEntry(key, value, parent, cmp < 0);

diff моего ProtectedTreeMap.java

В приведённом выше коде видно, что я изменил методы get и put так, чтобы они хранили множество посещённых узлов и выбрасывали ConcurrentModificationException, если в множестве есть уже посещённый узел.

Ошибки случаются: делаем швейцарский сыр

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

Алерты при NPE

Во всех случаях NPE мне не хватало уведомлений. У нас есть только уведомления о частоте ошибок. Этот NPE возникал только в каждом рабочем потоке обработчика API, чего недостаточно для срабатывания наших уведомлений частоты ошибок. Кроме того, ни один из NPE не записывался в логи, потому что в Executor у нас было необрабатываемое исключение.

Алерты об аномалиях использования ресурсов

Нужно мониторить уровень использования ресурсов CPU и использовать наивные пороговые значения. Когда уровень превышает это значение, мы создаём уведомление, потому что это указывает на ненормальное поведение. Именно так мы обнаружили проблему.

Неотловленные исключения в Executor

При добавлении задачи в executor нужно обеспечить наличие обработчика неотловленных исключений.

AtomicInteger threadNumber = new AtomicInteger(1);
ThreadFactory customThreadFactory = new ThreadFactory() {
    @Override
    public Thread newThread(Runnable r) {
        Thread thread = new Thread(r);
        thread.setName("my-thread-pool-" + threadNumber.getAndIncrement());
        thread.setUncaughtExceptionHandler(
          (dyingThread, throwable) -> {
            logger.error("uncaught exception!", throwable);
          }
        );
        return thread;
    }
};

ExecutorService executor = Executors.newFixedThreadPool(2, customThreadFactory);

Этот код довольно уродлив, так что лучше использовать

Apache Commons BasicThreadFactory:

new BasicThreadFactory.Builder()
  .namingPattern("my-thread-pool-%d")
  .uncaughtExceptionHandler(
    (dyingThread, throwable) -> {
      logger.error("uncaught exception!", throwable);
    }
  )
  .build();

или ThreadFactoryBuilder guava:

new ThreadFactoryBuilder()
  .setNameFormat("my-thread-pool-%d")
  .setUncaughtExceptionHandler(
    (dyingThread, throwable) -> {
      logger.error("uncaught exception!", throwable);
    }
  )
  .build()

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

Код-ревью

Иногда внимательный к деталям разработчик может заметить сочетание потоков и TreeMap или даже предложить не использовать TreeMap, если упорядоченные элементы не нужны. К сожалению, в данном случае этого не случилось.

Статический анализ кода

Инструменты статического анализа кода наподобие SpotBugs (ранее известный как FindBugs), JLint и Chord могут обнаруживать подобные проблемы на этапе сборки. См. статью How Good is Static Analysis at Finding Concurrency Bugs?. К сожалению, мы начали использовать их только после выявления бага.

Тесты

Ваши тесты должны поддерживать случай с многопоточностью! В моём случае для этой части кода многопоточные тесты отсутствовали.

Заключение

Ошибки случаются. Будьте внимательны, повреждение данных из-за незащищённой одновременной модификации может проявляться в виде бесконечных циклов! Несмотря на множество сделанных ошибок, это сокрыло проблему на многих слоях, но не на всех. Если вы реализуете многослойный подход, то сможете быстро реагировать или полностью избегать таких багов.