Selective logging of SQL queries in Hibernate
At the beginning of last week, I began working on a real project that manages audio content for a radio station. The usual admin panel using the VAADIN framework ( https://vaadin.com/home ) provides the user with a web interface that allows you to configure playlists and other features that simplify the life of DJs.
The customer inherited the application and he wanted to expand its functionality and fix bugs that were identified during the operation of the system. As for me, it’s a completely ordinary and rational desire.
One of my tasks was to fix a data sampling bug. As it turned out, the application wrote to the database records with empty values, and when fetching, it was assumed that the data was not empty. The application uses Hibernate's JPA implementation to work with the database. Well, in principle, nothing surprising, because Hibernate is a fairly common framework. I have been working with him for several years, but I am not a professional. In addition, the database model and the Java object model were not easy: using cyclic dependencies, inheritance, many-to-many relationships, etc. In general, immediately, looking at the model, I did not understand where to look for the cause of the error.
There was a question about SQL logging to determine where the validator is skipped.
Use hibernate.show_sql = true parameterI didn’t really like it. I saw two problems:
1) Hibernate in System.out writes only SQL queries with question marks and without real parameters;
2) Hibernate writes absolutely all queries to the database (As it turned out, on one page load the application performed about 50 queries).
Looking at the displayed queries, I realized that I need to display only queries to those tables that are related to my task.
Turning to google for help, I found advice on how to display real parameters: when using Log4j you need to add a logger for the parameters ( link to the article ):
# 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
After these gestures, I solved problem number 1: query parameters were written to the log, but the logs became too large, I had to look for the query I needed for several minutes. I immediately realized that this would not work and then the idea was born when the application was running to turn on and off query logging.
The current project uses EJB 3 components to work with the database, after reading about Interceptors the idea arose to write it to enable and disable SQL query logging on the fly.
The code is as follows:
An example of using logging for the selected method from the service:
When the method is called, all SQL queries with parameters related to the selection of AudioItem entities from the database are written to the log.
(If @Interceptors (ShowHibernateSQLInterceptor.class) is specified for the entire service class, and not for the selected method, then all methods of this class will be logged)
. queries are displayed in the Hiberante log due to org.hibernate.SQL = DEBUG, the need for
hibernate.show_sql = true is gone and I turned off this feature.
Bottom line:
To log only individual methods, it is recommended:
1) disable hibernate.show_sql = true
2) Write an Interceptor class
3) Add an interceptor for the selected method.
Limitations:
1) Tested only with log4j - I'm not sure that it will work with another logger, but I think it is possible to either add Log4j to the project or adjust the Interceptor for another logger framework
2) The proposed solution is relevant only for EJB 3, if the project uses Spring, then you need to write an aspect (Spring AOP) with similar functionality.
3) Tested on JBoss AS: this server uses its logger adapter for Log4j. Therefore, it should work on another server, but there may be nuances ...
Perhaps there are more elegant solutions for this problem, but a quick review of the search results on Google did not allow me to find such, so I decided to spend 20 minutes and the problem was solved and, as a result, the task was completed on time.
If someone knows a better solution, I’m ready to listen to it - because sometimes I need a tool to analyze Hibernate requests, which will help to quickly solve the task.
The customer inherited the application and he wanted to expand its functionality and fix bugs that were identified during the operation of the system. As for me, it’s a completely ordinary and rational desire.
One of my tasks was to fix a data sampling bug. As it turned out, the application wrote to the database records with empty values, and when fetching, it was assumed that the data was not empty. The application uses Hibernate's JPA implementation to work with the database. Well, in principle, nothing surprising, because Hibernate is a fairly common framework. I have been working with him for several years, but I am not a professional. In addition, the database model and the Java object model were not easy: using cyclic dependencies, inheritance, many-to-many relationships, etc. In general, immediately, looking at the model, I did not understand where to look for the cause of the error.
There was a question about SQL logging to determine where the validator is skipped.
Use hibernate.show_sql = true parameterI didn’t really like it. I saw two problems:
1) Hibernate in System.out writes only SQL queries with question marks and without real parameters;
2) Hibernate writes absolutely all queries to the database (As it turned out, on one page load the application performed about 50 queries).
Looking at the displayed queries, I realized that I need to display only queries to those tables that are related to my task.
Turning to google for help, I found advice on how to display real parameters: when using Log4j you need to add a logger for the parameters ( link to the article ):
# 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
After these gestures, I solved problem number 1: query parameters were written to the log, but the logs became too large, I had to look for the query I needed for several minutes. I immediately realized that this would not work and then the idea was born when the application was running to turn on and off query logging.
The current project uses EJB 3 components to work with the database, after reading about Interceptors the idea arose to write it to enable and disable SQL query logging on the fly.
The code is as follows:
//Класс InterceptorpublicclassShowHibernateSQLInterceptor{
//аннотированный метод@AroundInvokepublic 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;
}
}
An example of using logging for the selected method from the service:
@Override@Interceptors(ShowHibernateSQLInterceptor.class)
public List<AudioItem> listAllAudioItems(){
return em.createQuery("select a from AudioItem a").getResultList();
}
When the method is called, all SQL queries with parameters related to the selection of AudioItem entities from the database are written to the log.
(If @Interceptors (ShowHibernateSQLInterceptor.class) is specified for the entire service class, and not for the selected method, then all methods of this class will be logged)
. queries are displayed in the Hiberante log due to org.hibernate.SQL = DEBUG, the need for
hibernate.show_sql = true is gone and I turned off this feature.
Bottom line:
To log only individual methods, it is recommended:
1) disable hibernate.show_sql = true
2) Write an Interceptor class
3) Add an interceptor for the selected method.
Limitations:
1) Tested only with log4j - I'm not sure that it will work with another logger, but I think it is possible to either add Log4j to the project or adjust the Interceptor for another logger framework
2) The proposed solution is relevant only for EJB 3, if the project uses Spring, then you need to write an aspect (Spring AOP) with similar functionality.
3) Tested on JBoss AS: this server uses its logger adapter for Log4j. Therefore, it should work on another server, but there may be nuances ...
Perhaps there are more elegant solutions for this problem, but a quick review of the search results on Google did not allow me to find such, so I decided to spend 20 minutes and the problem was solved and, as a result, the task was completed on time.
If someone knows a better solution, I’m ready to listen to it - because sometimes I need a tool to analyze Hibernate requests, which will help to quickly solve the task.