Spring MDC Transaction Logging
Imagine having a tool that can automatically detect JPA and Hibernate performance issues. Wouldn’t that be just awesome?
Well, Hypersistence Optimizer is that tool! And it works with Spring Boot, Spring Framework, Jakarta EE, Java EE, Quarkus, or Play Framework.
So, enjoy spending your time on the things you love rather than fixing performance issues in your production system on a Saturday night!
Introduction
In this article, we are going to see how to configure a Spring application to use MDC (Mapped Diagnostic Context) for transaction logging.
This technique is going to help us inject the Persistence Context information as well as the associated database transaction identifier in all the log entries emitted from within a @Transactional
service method.
MDC (Mapped Diagnostic Context)
As I explained in this article, MDC is for application logging what the ThreadLocal
context is to Java threads.
In short, MDC allows us to register key/value sets that are bound to a given thread and can be referenced by the logging framework when printing a given log message.
To use MDC, the logging framework needs to reference the key of the MDC key/value set in the log message pattern, as illustrated by the following example:
<appender name="console" class="ch.qos.logback.core.ConsoleAppender"> <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> <level>TRACE</level> </filter> <encoder> <Pattern>%-5p [%t]:%X{txId} %c{1} - %m%n</Pattern> <charset>UTF-8</charset> </encoder> </appender>
Once we have the txId
MDC variable reference by the Logback message pattern, when running the following code snippet:
try(MDC.MDCCloseable mdc = MDC .putCloseable( "txId", String.format( " Persistence Context Id: [%d], DB Transaction Id: [%s]", 123456, 7890 ) ) ) { LOGGER.info("Fetch Post by title"); }
Logback is going to print the following message:
2022-12-21 14:51:38,823 INFO [main]: Persistence Context Id: [123456], DB Transaction Id: [7890] c.v.b.h.s.t.m.SpringMdcTest - Update Post entity
That’s great, but we need to automate how the Persistence Context identifier and the actual database transaction id are bound to the txId
MDC variable.
Spring MDC Transaction Logging
So, to achieve our goal, we need to intercept the following JPA actions:
- when the JPA Persistence Context is open, we need to assign a Persistence Context identifier
- after a statement is executed, we check whether the relational database has assigned a transaction identifier
- after the JPA transaction ends, we remove the transaction identifier
- after the JPA Persistence Context is closed, we remove the
txId
variable from the MDC logging context
Luckily, both Spring and Hibernate are extremely customizable, so we can intercept all those actions and apply the MDC transition logging.
First, we need to configure the Spring LocalContainerEntityManagerFactoryBean
to use some custom Hibernate settings:
@Bean public LocalContainerEntityManagerFactoryBean entityManagerFactory() { LocalContainerEntityManagerFactoryBean entityManagerFactoryBean = new LocalContainerEntityManagerFactoryBean(); ... entityManagerFactoryBean.setJpaVendorAdapter( new HibernateJpaVendorAdapter() ); entityManagerFactoryBean.setJpaProperties(properties()); return entityManagerFactoryBean; } protected Properties properties() { Properties properties = new Properties(); properties.setProperty( AvailableSettings.CONNECTION_PROVIDER_DISABLES_AUTOCOMMIT, Boolean.TRUE.toString() ); properties.put( AvailableSettings.AUTO_SESSION_EVENTS_LISTENER, TransactionInfoSessionEventListener.class.getName() ); return properties; }
The CONNECTION_PROVIDER_DISABLES_AUTOCOMMIT
property allows Hibernate to acquire the database connection lazily, as opposed to when you enter the @Transactional
method. For more details about this setting, check out this article.
The AUTO_SESSION_EVENTS_LISTENER
setting allows us to provide a SessionEventListener
that can intercept various Hibernate actions.
Next, we are going to see how we can intercept Hibernate actions using the awesome SessionEventListener
mechanism.
Intercepting Hibernate actions using the SessionEventListener
The TransactionInfoSessionEventListener
looks as follows:
public class TransactionInfoSessionEventListener extends BaseSessionEventListener { private final TransactionInfo transactionInfo; private EntityManager entityManager; /** * Executes when a JPA EntityManager is created. */ public TransactionInfoSessionEventListener() { transactionInfo = new TransactionInfo(); } /** * Executes after a JDBC statement was executed. */ @Override public void jdbcExecuteStatementEnd() { if (!transactionInfo.hasTransactionId()) { resolveTransactionId(); } } /** * Executes after the commit or rollback was called * on the JPA EntityTransaction. */ @Override public void transactionCompletion(boolean successful) { transactionInfo.setTransactionId(null); } /** * Executes after JPA EntityManager is closed. */ @Override public void end() { transactionInfo.close(); } private EntityManager getEntityManager() { if (entityManager == null) { entityManager = SpringTransactionUtils.currentEntityManager(); } return entityManager; } private void resolveTransactionId() { EntityManager entityManager = getEntityManager(); SessionFactoryImplementor sessionFactory = entityManager .getEntityManagerFactory() .unwrap(SessionFactoryImplementor.class); entityManager.unwrap(Session.class).doWork(connection -> { try (Statement statement = connection.createStatement(); ResultSet resultSet = statement.executeQuery( Database.of(sessionFactory.getJdbcServices().getDialect()) .dataSourceProvider() .queries() .transactionId() )) { if (resultSet.next()) { transactionInfo.setTransactionId(resultSet.getString(1)); } } }); } }
A new TransactionInfoSessionEventListener
object is created whenever a new JPA EntityManager
is instantiated, so we use this opportunity to create a new TransactionInfo
object, which we are going to use to hold the current transaction information.
In the jdbcExecuteStatementEnd
callback, we check whether the database transaction identifier was previously resolved, and if it was not, we try to resolve it.
In the transactionCompletion
callback, we reset the database transaction identifier since the associated database transaction was ended.
And, in the end
callback, which is called when the JPA EntityManager
is closed, we also close the associated TransactionInfo
object.
The TransactionInfo
object looks as follows:
class TransactionInfo { private final Long persistenceContextId; private String transactionId; private MDC.MDCCloseable mdc; public TransactionInfo() { this.persistenceContextId = TsidUtils.randomTsid().toLong(); setMdc(); } public boolean hasTransactionId() { return transactionId != null; } public TransactionInfo setTransactionId(String transactionId) { this.transactionId = transactionId; setMdc(); return this; } private void setMdc() { this.mdc = MDC.putCloseable( "txId", String.format( " Persistence Context Id: [%d], DB Transaction Id: [%s]", persistenceContextId, transactionId ) ); } public void close() { if(mdc != null) { mdc.close(); } } }
The persistenceContextId
stores the Persistence Context identifier. While we could use the Hibernate Session
UUID
identifier, I prefer using a time-sorted Tsid
instead.
The transactionId
stores the database transaction identifier.
The mdc
variable references the MDC.MDCCloseable
object that we can use to reset the MDC logging variable we bound for the currently executing Thread.
That’s it!
Testing time
Assuming we have the following addComment
service method:
@Transactional public void addComment(Long postId, String review) { Post post = postRepository.lockById( postId, LockModeType.OPTIMISTIC ); postCommentRepository.persist( new PostComment() .setReview(review) .setPost(post) ); postRepository.lockById( postId, LockModeType.PESSIMISTIC_READ ); }
When calling the addComment
method on PostgreSQL:
forumService.addComment(postId, "Awesome");
The following log messages are printed:
Persistence Context Id: [393424039441824927], DB Transaction Id: [null] o.h.e.t.i.TransactionImpl - begin Persistence Context Id: [393424039441824927], DB Transaction Id: [null] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select p1_0.id,p1_0.slug,p1_0.title,p1_0.version from post p1_0 where p1_0.id=?"], Params:[(1)] Persistence Context Id: [393424039441824927], DB Transaction Id: [null] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:0, Success:True, Type:Statement, Batch:False, QuerySize:1, BatchSize:0, Query:["SELECT CAST(pg_current_xact_id_if_assigned() AS text)"], Params:[] Persistence Context Id: [393424039441824927], DB Transaction Id: [null] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select nextval('post_comment_SEQ')"], Params:[()] Persistence Context Id: [393424039441824927], DB Transaction Id: [null] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:0, Success:True, Type:Statement, Batch:False, QuerySize:1, BatchSize:0, Query:["SELECT CAST(pg_current_xact_id_if_assigned() AS text)"], Params:[] Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select id from post where id =? and version =? for share"], Params:[(1, 0)] Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] o.h.e.t.i.TransactionImpl - committing Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:2, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["insert into post_comment (post_id, review, id) values (?, ?, ?)"], Params:[(1, Awesome, 1)] Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] n.t.d.l.l.SLF4JQueryLoggingListener - Name:DATA_SOURCE_PROXY, Connection:6, Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["select version as version_ from post where id =?"], Params:[(1)] Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] o.h.r.j.i.AbstractLogicalConnectionImplementor - LogicalConnection#beforeTransactionCompletion Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] o.h.r.j.i.AbstractLogicalConnectionImplementor - Preparing to commit transaction via JDBC Connection.commit() Persistence Context Id: [393424039441824927], DB Transaction Id: [431894] o.h.r.j.i.AbstractLogicalConnectionImplementor - Transaction committed via JDBC Connection.commit()
While the Persistence Context identifier is available right from the start, the database transaction id is only assigned after PostgreSQL executes an INSERT, UPDATE or DELETE statement.
Awesome, right?
If you enjoyed this article, I bet you are going to love my Book and Video Courses as well.
Conclusion
MDC logging is a very useful feature as it allows you to customize your log messages using context-specific information.
While the article shows you how you can add the transaction information to your logs using a Hibernate SessionEventListener
, this solution is not limited to Spring. You can also use it with Jakarta EE or Java EE. The only thing you need to do is change the way you are passing the AUTO_SESSION_EVENTS_LISTENER
Hibernate property.
