Этот пост вдохновлен статьей Пьера-Хьюга Шарбонно о том, как загрузка несуществующих классов может серьезно повредить вашей производительности . Это вернуло воспоминания о сеансе отладки, где та же проблема возникла немного по-другому.
Приложение под рукой было «Ещё одно веб-приложение», выполнявшее любые мирские задачи. Пока этого больше нет. Симптомы включали в себя конечных пользователей, жалующихся на медленное применение и прямые тайм-ауты. Файлы журналов, к которым я получил доступ, ничего особенного не выявили, кроме подтверждения того, что пользовательский интерфейс был сильно ухудшен.
Ошибка попала в особенно неприятную категорию — быть среди ошибок, которые вы уверены, что можете воспроизвести, но не по желанию. Ситуация, казалось, возникала несколько случайным образом один или два раза в неделю. Поэтому я попросил ребят из отдела операций, ответственных за это приложение, запускать диагностический сценарий всякий раз, когда возникает такая ситуация. В этом сценарии не было ничего особенного — в основном он собирал несколько дампов потоков вместе с некоторыми дополнительными показателями уровня ОС. И помолился могущественному Богу-отладчику о помощи.
На этот раз, похоже, молитва сработала. Через пару дней я смотрел на дамп потока, заполненный следами, похожими на следующие:
"Thread-96" #106 prio=5 os_prio=31 tid=0x00007fc9b283b800 nid=0x11b03 waiting for monitor entry [0x0000000130133000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
- waiting to lock <0x00000006c022e608> (a java.lang.Object)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:308)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at com.sun.org.apache.xerces.internal.utils.ObjectFactory.findProviderClass(ObjectFactory.java:209)
at com.sun.org.apache.xerces.internal.utils.ObjectFactory.newInstance(ObjectFactory.java:157)
at com.sun.org.apache.xerces.internal.utils.ObjectFactory.newInstance(ObjectFactory.java:143)
at com.sun.org.apache.xerces.internal.impl.dv.DTDDVFactory.getInstance(DTDDVFactory.java:64)
at com.sun.org.apache.xerces.internal.impl.dv.DTDDVFactory.getInstance(DTDDVFactory.java:49)
at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.(XML11Configuration.java:578)
at com.sun.org.apache.xerces.internal.parsers.XIncludeAwareParserConfiguration.(XIncludeAwareParserConfiguration.java:130)
at com.sun.org.apache.xerces.internal.parsers.XIncludeAwareParserConfiguration.(XIncludeAwareParserConfiguration.java:91)
at com.sun.org.apache.xerces.internal.parsers.DOMParser.(DOMParser.java:144)
at com.sun.org.apache.xerces.internal.parsers.DOMParser.(DOMParser.java:128)
at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.(DocumentBuilderImpl.java:138)
at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl.newDocumentBuilder(DocumentBuilderFactoryImpl.java:76)
at ClassloadingLock$Worker.run(ClassloadingLock.java:10)
Подавляющее большинство потоков приложений были заблокированы и ожидали выпуска одного монитора. Интересным было то, что монитор синхронизировал доступ к загрузке классов. Это было то, чего не часто можно увидеть, особенно в приложении, которое было инициализировано и разогрето уже за несколько дней до этого события эскалации блокировки.
Копание в коде выявило проблему. Примерно один раз в неделю работа cron запускает множество служебных потоков. Эти потоки должны были извлекать и преобразовывать данные для загрузки в хранилище данных. Правила преобразования были описаны в XML, загруженном этими потоками с использованием javax.xml.parsers.DocumentBuilder . По какой-то причине каждый поток загружал сам XML-документ каждый раз, когда происходило преобразование.
Как видно из дампа потока, это приводит к загрузке класса провайдера XML каждый раз, когда должно было быть выполнено преобразование:
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at com.sun.org.apache.xerces.internal.utils.ObjectFactory.findProviderClass(ObjectFactory.java:209)
И теперь, если мы проверяем исходный код самого java.lang.ClassLoader.loadClass () , мы действительно можем увидеть синхронизацию перед проверкой, загружен ли уже класс или мы должны обратиться к файловой системе, чтобы загрузить его из файла класса. Теперь, когда несколько потоков обращаются к этому синхронизированному блоку одновременно, нам удалось построить базовую линию для повышения блокировки:
protected Class loadClass(String name, boolean resolve)
throws ClassNotFoundException {
synchronized (getClassLoadingLock(name)) {
// First, check if the class has already been loaded
Class c = findLoadedClass(name);
// ... cut for brevity ...
}
Пытаясь воссоздать проблему, я создал небольшой тестовый пример, чтобы вы лучше поняли проблему блокировки. Пример запускает 100 потоков, которые ничего не делают, но загружают класс javax.xml.parsers.DocumentBuilder :
package eu.plumbr.demo;
import javax.xml.parsers.DocumentBuilder;
import javax.xml.parsers.DocumentBuilderFactory;
import javax.xml.parsers.ParserConfigurationException;
public class ClassloadingLock {
static class Worker extends Thread {
@Override
public void run() {
while (true) {
try {
DocumentBuilder b = DocumentBuilderFactory.newInstance()
.newDocumentBuilder();
} catch (Exception e) {// Do not do this at home, log all
// exceptions
}
}
}
}
public static void main(String[] args) throws Exception {
for (int i = 0; i < 100; i++) {
new Worker().start();
}
}
}
Когда вы выполняете дамп потока во время выполнения приведенного выше кода или визуализируете ситуацию с помощью jvisualvm , вы действительно увидите, что потоки постоянно ожидают за монитором.
Мораль истории? Мы не думаем, что найти причины проблем с производительностью должно быть так сложно. Мы надеемся, что инструменты, которые мы создадим, сделают навыки, необходимые для устранения неполадок в этом случае, неактуальными, поскольку у вас будет гораздо более удобный способ мониторинга и устранения неполадок в ваших JVM.