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 the 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 customize playlists and other features that simplify the life of DJs.

The customer got the application by inheritance and he wanted to expand its functionality and fix the bugs that were identified during the operation of the system. As for me, it is quite a normal and rational desire.


One of my tasks was to fix a data sampling bug. As it turned out, the application wrote records with empty values ​​to the database, and during the selection it was assumed that the data are non-empty. The application uses the JPA implementation from Hibernate 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 object Java model were not simple: 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 in order to determine where the validator is passed.
Use the hibernate.show_sql = true parameter I didn’t really like. 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 database queries (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 associated with my task.

Turning to google for help, I found advice on how to display the real parameters: when using Log4j, I 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 No. 1: query parameters were written to the log, but the logs became excessively large, I had to search for the query I needed for a few 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 request logging.
The current project uses EJB 3 components for working with a database. After reading about Interceptors, the idea arose to write it to turn on and off logging of SQL queries on the fly.

The code is as follows:

// 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; } } 

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)
Because queries are output to the Hiberante log due to org.hibernate.SQL = DEBUG, the need for
hibernate.show_sql = true has disappeared and I have disabled this feature.

Total:
For logging only certain methods it is recommended:
1) disable hibernate.show_sql = true
2) Write a class Interceptor
3) Add an interceptor for the selected method.

Limitations:
1) Tested only with log4j - not sure if it will work with another logger, but I think that it is possible either to add Log4j to the project, or to correct the Interceptor for another logger-framework
2) The proposed solution is relevant only for EJB 3, if the project uses Spring, then it is necessary 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 cursory review of Google search results did not allow me to find such ones, 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 queries, which will help to quickly solve the problem.