Выборочное логирование SQL запросов в Hibernate

В начале прошлой недели я стал работать на реальном проекте который управляет аудиоконтентом для радиостанции. Обычная админ панель с использованием VAADIN фреймворка (https://vaadin.com/home) предоставляет пользователю веб интерфейс, который позволяет настраивать списки проигрывания и прочие фичи, упрощающие жизнь диджеев.

Заказчику досталось приложение по наследству и он захотел расширить его функционал и исправить баги, которые были выявлены в ходе работы системы. Как по мне, то вполне обычное и рациональное желание.

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

Встал вопрос о логировании SQL для того чтобы определить где пропушен валидатор.
Использовать параметр hibernate.show_sql = true мне не очень нравилось. Я видел две проблемы:

1) Hibernate в System.out пишет только SQL запросы с вопросительными знаками и без реальных параметров;
2) Hibernate пишет абсолютно все запросы к базе данных (Как оказалось на одну загрузку станицы приложение выполняло порядка 50 запросов).

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

Обратившись за помощью к google я нашел совет как мне отображать реальные параметры: при использовании Log4j нужно добавить логгер для параметров (ссылка на статью):

# Hibernate logging options (INFO only shows startup messages)
log4j.logger.org.hibernate=INFO
# Log JDBC bind parameter runtime arguments
log4j.logger.org.hibernate.type=trace

После данных телодвижений я решил проблему № 1: в лог писались параметры запросов, но логи стали чрезмерно большими, мне пришлось несколько минут искать нужный мне запрос. Я сразу понял что так дело не пойдет и тогда родилась идея при работе приложения включать и выключать логирование запросов.
Текущий проект использует EJB 3 компоненты для работы с базой данных, прочитав об Interceptors возникла идея написать его для включения и выключения логирования SQL запросов на лету.

Код следующий:

//Класс Interceptor
public class ShowHibernateSQLInterceptor {
        //аннотированный метод
	@AroundInvoke
	public Object showSQL(InvocationContext ictx) throws Exception {
		//включение логирования SQL запросов
                Logger sqlLogger = Logger.getLogger("org.hibernate.SQL");
		sqlLogger.setLevel(Level.DEBUG);
		//Включение логирования параметров запросов
		Logger descLogger = Logger.getLogger("org.hibernate.type.descriptor.sql.BasicBinder");
		descLogger.setLevel(Level.TRACE);
		//Выполнение аннотированного метода сервиса
		Object res = ictx.proceed();
		//Выключение логирования SQL
		sqlLogger = Logger.getLogger("org.hibernate.SQL");
		sqlLogger.setLevel(Level.INFO);
		//Выключение логирования параметров
		descLogger = Logger.getLogger("org.hibernate.type.descriptor.sql.BasicBinder");
		descLogger.setLevel(Level.INFO);
		return res;
	}
}

Пример использования логирования для выбранного метода из сервиса:

@Override
@Interceptors(ShowHibernateSQLInterceptor.class)
public List<AudioItem> listAllAudioItems() {
	return em.createQuery("select a from AudioItem a").getResultList();
}

При вызове метода в лог пишутся все SQL запросы с параметрами, относяшиеся к выбору сущностей AudioItem из базы данных.
(Если @Interceptors(ShowHibernateSQLInterceptor.class) указать для всего класса сервиса, а не для выбранного метода, то логироваться будут все методы данного класса)
Т.к. запросы выводяться в лог Hiberante-ом из-за org.hibernate.SQL=DEBUG, необходимость в
hibernate.show_sql = true отпала и я отключил данную возможность.

Итог:
Для логирование только отдельных методов рекомендуется:
1) отключить hibernate.show_sql = true
2) Написать класс Interceptor
3) Добавить interceptor для выбранного метода.

Ограничения:
1) Тестировал только с log4j — не уверен что будет работать с другим логгером, но думаю, что возможно либо добавить Log4j в проект, либо подкорректировать Interceptor для другого logger-фреймворка
2) Предложенное решение актуально только для EJB 3, если проект использует Spring, то необходимо написать аспект (Spring AOP) с похожим функционалом.
3) Тестировал на JBoss AS: этот сервер использует свой logger адаптер для Log4j. Поэтому на другом сервере должно работать, но могут быть нюансы…

Возможно есть более элегантные решения для данной проблемы, но беглый обзор результатов поиска в Google не позволил мне найти таких, поэтому решил потратить 20 минут и проблема была решена и, как результат, таск был выполнен в срок.

Если кто-то знает более лучшее решение, готов его выслушать — так как иногда нуждаюсь в иструменте для анализа запросов Hibernate, который поможет быстро решить поставленную задачу.

Автор: nedis