Одна строка кода, которая заблокировала 102 потока / Хабр

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

Это история о том, как DatatypeFactory.newInstance() поставил на колени наш высокопроизводительный Java-сервис, и об удивительно простом решении, позволившем полностью избавиться от проблемы.

Открытие

В нашей организации есть микросервис отчётности, обрабатывающий примерно 800 запросов в секунду. Время от времени пользователи сообщали о медленной реакции системы, но наши дэшборды показывали, что всё в пределах SLA. Не возникало никаких алертов. Сервис «работал нормально».

В процессе обыденного ревью производительности я изучил дампы потоков из продакшена. Обнаруженное заставило меня напрячься:

"hystrix-SearchProviderGroup-1" #1111 daemon prio=5
   java.lang.Thread.State: BLOCKED (on object monitor)
    at jdk.internal.loader.URLClassPath.getLoader(URLClassPath.java:425)
    - waiting to lock <0x00000000846e4668> (a jdk.internal.loader.URLClassPath)
    ...
    at javax.xml.datatype.FactoryFinder.findServiceProvider(FactoryFinder.java:287)
    at javax.xml.datatype.DatatypeFactory.newInstance(DatatypeFactory.java:169)

102 потока. Все они заблокированы. И все ждут одной и той же блокировки: <0x00000000846e4668>.

Разбираемся в проблеме

Что делает DatatypeFactory.newInstance()?

Вызов DatatypeFactory.newInstance() выглядит довольно просто:

public XMLGregorianCalendar getXMLGregorianCalendarValue(Date date) {
    DatatypeFactory factory = DatatypeFactory.newInstance();
    GregorianCalendar cal = new GregorianCalendar();
    cal.setTime(date);
    return factory.newXMLGregorianCalendar(cal);
}

Но на самом деле этот невинно выглядящий вызов запускает сложную цепочку операций:

DatatypeFactory.newInstance()
    └── FactoryFinder.find()
        └── FactoryFinder.findServiceProvider()
            └── ServiceLoader.load()
                └── ServiceLoader$LazyClassPathLookupIterator.hasNext()
                    └── ClassLoader.getResources("META-INF/services/...")
                        └── URLClassLoader.findResources()
                            └── URLClassPath.getLoader()  ← SYNCHRONIZED

Метод URLClassPath.getLoader() синхронизируется. В Java 11 соответствующий код выглядит так:

// From jdk.internal.loader.URLClassPath
private synchronized Loader getLoader(int index) {
    // ... логика поиска загрузчика
}

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

Налог на ServiceLoader

Механизм ServiceLoader языка Java спроектирован для обеспечения гибкости — он позволяет обнаруживать реализации в среде исполнения при помощи файлов META-INF/services. Но за эту гибкость приходится расплачиваться:

Сканирование путей к классам: ServiceLoader итеративно обходит все JAR в поисках файлов поставщиков сервисов
Синхронизация ClassLoader: поиск ресурсов требует синхронизированного доступа к URLClassPath
Повторяющаяся работа: без кэширования это происходит при каждом вызове newInstance()

В нашем случае, когда выполняется 800 запросов в секунду, и на каждый запрос происходит несколько вызовов DatatypeFactory.newInstance(), мы обращаемся к этому синхронизируемому блоку миллионы раз в час.

Улика в дампе потоков

Изучив полный дамп потоков, я обнаружил два чётких паттерна заблокированных потоков:

Паттерн 1: конфликт DatatypeFactory (большинство заблокированных потоков)

"hystrix-SearchProviderGroup-1" BLOCKED
    at jdk.internal.loader.URLClassPath.getLoader(URLClassPath.java:425)
    - waiting to lock <0x00000000846e4668>
    ...
    at javax.xml.datatype.DatatypeFactory.newInstance(DatatypeFactory.java:169)

Паттерн 2: загрузка ресурсов ClassLoader для чтения файлов

"https-jsse-nio-8443-exec-26" BLOCKED
    at jdk.internal.loader.URLClassPath.getLoader(URLClassPath.java:425)
    - waiting to lock <0x00000000846e4668>
    ...
    at java.net.URLClassLoader.getResourceAsStream(URLClassLoader.java:322)

Оба паттерна соревновались за одну и ту же блокировку. Вызовы DatatypeFactory создавали «пробку», а операции чтения файлов застревали в одной и той же очереди.

Данные: численная оценка проблемы

Я выполнил запрос Splunk, чтобы понять, как часто мы считываем файлы: 34 миллиона операций чтения одних и тех же маленьких файлов JSON за 12 часов. Каждое считывание обращалось к ClassLoader. Каждый доступ к ClassLoader потенциально конкурировал с вызовами DatatypeFactory.newInstance().

Устраняем проблему

Исправление 1: статическая инициализация DatatypeFactory

После создания экземпляра DatatypeFactory он потокобезопасен. Нет никакой причины создавать новый для каждого вызова.

До:

public XMLGregorianCalendar getXMLGregorianCalendarValue(Date date) {
    DatatypeFactory factory = DatatypeFactory.newInstance();
    GregorianCalendar cal = new GregorianCalendar();
    cal.setTime(date);
    return factory.newXMLGregorianCalendar(cal);
}

После:

private static final DatatypeFactory DATATYPE_FACTORY;

static {
    try {
        DATATYPE_FACTORY = DatatypeFactory.newInstance();
    } catch (DatatypeConfigurationException e) {
        throw new RuntimeException("Failed to initialize DatatypeFactory", e);
    }
}

public XMLGregorianCalendar getXMLGregorianCalendarValue(Date date) {
    GregorianCalendar cal = new GregorianCalendar();
    cal.setTime(date);
    return DATATYPE_FACTORY.newXMLGregorianCalendar(cal);
}

Это единственное изменение устранило весь оверхед ServiceLoader после первой инициализации. Фабрика создаётся один раз при загрузке классов, а все последующие вызовы используют кэшированный экземпляр.

Исправление 2: кэш Caffeine для содержимого файлов

Для решения проблемы конкуренции с чтением файлов я реализовал простой кэш на основе Caffeine:

@Component
@Slf4j
public class FileUtil {

    private static final int CACHE_MAX_SIZE = 100;
    private static final int CACHE_EXPIRE_AFTER_WRITE_MINUTES = 60;

    private final Cache<String, String> stringCache;

    public FileUtil() {
        this.stringCache = Caffeine.newBuilder()
                .maximumSize(CACHE_MAX_SIZE)
                .expireAfterWrite(CACHE_EXPIRE_AFTER_WRITE_MINUTES, TimeUnit.MINUTES)
                .build();
    }

    public String readFileAsString(Object classLoaderSource, String fileName) {
        String cachedValue = stringCache.getIfPresent(fileName);
        if (cachedValue != null) {
            return cachedValue;
        }

        String text = null;
        try (InputStream inputStream = classLoaderSource.getClass()
                .getClassLoader().getResourceAsStream(fileName)) {
            if (inputStream != null) {
                text = IOUtils.toString(inputStream, StandardCharsets.UTF_8);
                stringCache.put(fileName, text);
            }
        } catch (Exception e) {
            log.error("Error reading file={}", fileName, e);
        }
        return text;
    }
}

Почему Caffeine?

Внутри Caffeine используется ConcurrentHashMap, обеспечивающая гораздо более детализированную блокировку, чем URLClassPath ClassLoader:

// Из BoundedLocalCache Caffeine
final ConcurrentHashMap<Object, Node<K, V>> data;

Анализ: почему это произошло?

Блокировка URLClassPath

В исходном коде JDK URLClassPath хранит список объектов Loader, которые знают, как загружать ресурсы из разных типов URL (файлов JAR, папок и так далее). Метод getLoader() синхронизируется. потому что он выполняет ленивую инициализацию этих загрузчиков:

// Упрощённая версия кода из jdk.internal.loader.URLClassPath
private synchronized Loader getLoader(int index) {
    if (closed) {
        return null;
    }
    while (loaders.size() < index + 1) {
        // Создание нового загрузчика для следующего URL
        URL url = urls.get(loaders.size());
        Loader loader = getLoader(url);
        loaders.add(loader);
    }
    return loaders.get(index);
}

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

Скрытые затраты ServiceLoader

Класс ServiceLoader, используемый DatatypeFactory.newInstance(), итеративно обходит все URL по пути к классам, ища файлы поставщиков сервисов:

// Из java.util.ServiceLoader
private class LazyClassPathLookupIterator implements Iterator<Provider<S>> {
    Enumeration<URL> configs;
    
    private boolean hasNextService() {
        while (configs == null || !configs.hasMoreElements()) {
            // Получение следующего набора URL поставщиков сервисов
            configs = loader.getResources(PREFIX + service.getName());
        }
        // ...
    }
}

Каждый вызов getResources() в процессе поиска по JAR может совершать множество вызовов URLClassPath.getLoader(). В типичном приложении Spring Boot, имеющем сотни JAR в путях к классам, эти затраты быстро накапливаются.

Накопительный эффект

Нашу ситуацию ухудшило сочетание:

Высокой конкурентности: 800 запросов в секунду с множество потоков на каждый запрос
Многократное создание фабрики: DatatypeFactory.newInstance() вызывался при каждом преобразовании даты
Частое чтение файлов: 34 миллиона считываний файлов за 12 часов
Общая блокировка: обе операции конкурировали за одну блокировку URLClassPath

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

Основные выводы

1. Фабричные методы не бесплатны

Методы наподобие DatatypeFactory.newInstance(), DocumentBuilderFactory.newInstance() и TransformerFactory.newInstance() используют внутри ServiceLoader. Они проектировались с расчётом на гибкость, а не на производительность. При вызове их на горячем пути исполнения кода нужно кэшировать результат.

Другие частые причины проблем:

SAXParserFactory.newInstance()
SchemaFactory.newInstance()
XPathFactory.newInstance()
XMLInputFactory.newInstance()

2. Операции ClassLoader синхронизируются

Все операции, затрагивающие ClassLoader (getResource(), getResourceAsStream(), loadClass()), потенциально могут конкурировать за блокировки. В коде обработки запросов высокопроизводительных приложений следует минимизировать эти операции.

3. Информация из дампов потоков

Без анализа дампа потоков эту проблему было бы практически невозможно диагностировать. Её симптомы (периодические резкие скачки задержек) не указывают напрямую на конкуренцию ClassLoader. Регулярный анализ дампа потоков должен быть частью вашего инструментария мониторинга производительности.

4. «Нормальной работы» недостаточно

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

5. Статические ресурсы должны кэшироваться

Если файл запечён в JAR и не меняется в среде исполнения, то считывать его нужно один раз. Это кажется очевидным, но подобное легко упустить, если код разбросан по множеству сервисов и вспомогательных классов.

Как обнаружить подобное в своём приложении

Анализ дампа потоков

Создавайте дампы потоков в период пиковой нагрузки и ищите в них:

Большое количество потоков в состоянии BLOCKED
Трассировки стека, содержащие URLClassPath, ServiceLoader или ClassLoader
Потоки, ожидающие одного объекта блокировки

JFR (Java Flight Recorder)

Включите JFR в продакшене и ищите в нём:

События конкуренции за блокировки
Высокую частоту вызовов ClassLoader.getResource*
Активность ServiceLoader

java -XX:StartFlightRecording=duration=60s,filename=recording.jfr ...

В заключение

Единственная строка кода (DatatypeFactory.newInstance()) вызывала блокировку 102 потоков в нашем продакшен-сервисе. Устранить проблему было столь же просто: инициализировать фабрику один раз, а затем использовать её многократно.

Проблемы производительности часто скрываются у всех на виду. Код выглядит корректным, тесты проходят, сервис «работает». Но под нагрузкой выглядящие невинно паттерны могут становиться узкими местами.

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

Описанные в этом посте изменения снизили конкуренцию ClassLoader в нашем среде продакшена более чем на 99%. Если у вас есть высокопроизводительный Java-сервис, советую проверить свои дампы потоков на предмет похожих паттернов.