Статьи

Отслеживание операторов SQL в JBoss AS 7 с помощью пользовательского обработчика журналирования

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

Но у этого также есть и обратная сторона: поскольку ORM выполняет большую часть работы за вас, вы в какой-то степени теряете контроль над сгенерированным SQL, и вам приходится полагаться на ORM, чтобы создать для вас высокопроизводительный оператор. Но может случиться так, что SQL, сгенерированный ORM, не тот, который вы могли бы написать от руки и ожидали, что ORM сделает для вас. В этом случае вам нужно вернуть контроль над SQL и снова взять код в свои руки.

В огромных приложениях эта задача не так тривиальна, поскольку в базу данных могут быть выданы сотни операторов, которые основаны на сотнях строк Java-кода, интенсивно использующего функции JPA. Отслеживание оператора SQL, который ваш инструмент профилирования базы данных определил как проблемный вплоть до фактической строки кода, становится утомительным.

Мы знаем, что можем включить ведение журнала операторов SQL для Hibernate с помощью следующих двух строк в нашем файле persistence.xml:

1
2
<property name="hibernate.show_sql" value="true"/>
<property name="hibernate.format_sql" value="true"/>

Но это только выведет уже сгенерированный SQL; фактическая строка кода Java все еще не видна. Для небольших приложений может быть целесообразным подключить отладчик к серверу приложений и выполнять отладку с помощью кода, пока вы не найдете строку, в которой записывается проблемный оператор SQL, но для более крупных приложений это занимает много времени.

Поскольку сам Hibernate не предоставляет никаких средств для перехвата журналирования и расширения его с помощью дополнительной информации, нам придется делать это самостоятельно. Документация JBoss указывает, что можно написать свой собственный обработчик журналирования. Поскольку этот обработчик журналов получает все сообщения журналов, а также сообщения, генерируемые Hibernate с включенным ведением журналов SQL, мы можем попытаться найти искомую строку и затем вывести трассировку стека в наш собственный файл журнала.

Написание собственного обработчика журналов оказывается очень простым. Все, что вам нужно сделать, это настроить небольшой проект с классом, который расширяет класс Handler из пакета JDK java.util.logging:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
package mypackage;
 
import java.util.logging.Handler;
import java.util.logging.LogRecord;
 
public class MyJBossLogger extends Handler {
 
    @Override
    public void publish(LogRecord record) {
     
    }
     
    @Override
    public void flush() {
    }
     
    @Override
    public void close() throws SecurityException {
 
    }
}

Метод publish () получает все выходные данные журнала в виде экземпляра LogRecord. Его метод getMessage () позволяет напрямую обращаться к выводу. Следовательно, мы можем сопоставить это сообщение с некоторыми ключевыми словами, которые мы загрузили из некоторого файла конфигурации:

01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
@Override
public void publish(LogRecord record) {
    String message = record.getMessage();
    buffer.add(message + "\n");
    if (keywords == null) {
        keywords = loadKeywords();
    }
    if (matches(message, keywords)) {
        String stacktrace = "\nStacktrace:\n";
        StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
        for (StackTraceElement element : stackTrace) {
            stacktrace += element.toString() + "\n";
        }
        buffer.add(stacktrace);
        flush();
    }
}

Здесь буфер — это некоторая простая структура данных (например, EvictingQueue в guava ), которая буферизует последние строки, так как метод publish () вызывается для каждой строки (!) Вывода. Поскольку полный оператор SQL занимает более одной строки, мы должны запомнить пару из них. Рядом с буферизованными строками и текущей строкой мы также выводим строковое представление текущей трассировки стека. Это говорит нам позже в файле журнала, откуда мы вызываем, и вместе с тем, какая строка кода Java в нашем проекте вызывает текущую инструкцию.

После того, как мы скомпилировали проект, мы можем скопировать полученный файл jar во вновь созданную структуру папок в: $ JBOSS_HOME / modules / system / слои / base / com / mydomain / mymodule / main (для JBoss AS 7.2). Чтобы сообщить JBoss AS о нашем новом модуле, нам нужно создать файл XML с именем module.xml со следующим содержимым:

1
2
3
4
5
6
<?xml version="1.0" encoding="UTF-8"?>
<module xmlns="urn:jboss:module:1.1" name="com.mydomain.mymodule">
    <resources>
        <resource-root path="MyJBossLogger-0.0.1-SNAPSHOT.jar"/>
    </resources>
</module>

Имя модуля соответствует пути в папке модулей JBoss. Он также будет использоваться в файле конфигурации для настройки нашего пользовательского обработчика журналирования:

1
2
3
4
5
6
...
<subsystem xmlns="urn:jboss:domain:logging:1.2">
    <custom-handler name="CUSTOM" module="com.mydomain.mymodule" class="com.mydomain.mymodule.MyJBossLogger">
        <level name="DEBUG"/>
    </custom-handler>
    ...

Когда мы реализуем метод flush () нашего обработчика журналов, чтобы записать вывод в некоторый файл журнала, мы увидим что-то вроде следующего (конечно, в сжатой форме):

01
02
03
04
05
06
07
08
09
10
11
Hibernate:     select ... from customer ...
Stacktrace:
java.lang.Thread.getStackTrace(Thread.java:1568)
com.mydomain.mymodule.MyJBossLogger.publish(MyJBossLogger.java:20)
org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:292)
org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:300)
org.jboss.logmanager.Logger.logRaw(Logger.java:721)
org.jboss.logmanager.Logger.log(Logger.java:506)
...
com.mydomain.myapp.ArticleEntity.getCustomers(ArticleRepository.java:234)
...

Здесь мы ясно видим, какое отношение OneToMany вызывает проблемный оператор выбора, который мы искали.

Вывод

Использование собственного обработчика ведения журнала для вставки текущей трассировки стека в запись операторов SQL может помочь вам, когда вы хотите найти точное местоположение в исходном коде, где выдается конкретный запрос. Также оказалось, что написание собственного обработчика журналирования для JBoss AS также является простой задачей.