Introduction

In this article, I’m going to show you how you can log the database transaction id associated with a given SQL statement using the MDC (Mapped Diagnostic Context) feature offered by many logging frameworks.

If you are writing data access code, you have to use logging. As I explained in this article, using a JDBC proxy tool like datasource-proxy or p6spy is the best approach to logging SQL statements.

With datasource-proxy, you can easily build a JUnit extension to automatically detect N+1 query issues. For more details, check out the Hypersistence Utils open-source project.

Since JPA and Hibernate generate SQL statements on your behalf based on the entity state transitions executed by the data access layer, using logging is mandatory as you need to acknowledge that the auto-generated SQL statements are both effective and efficient.

Guide to logging database transaction id with a SQL statement using the MDC (Mapped Diagnostic Context) feature.@vlad_mihalceahttps://t.co/3sfwl6XRpz

— Java (@java) February 27, 2019

Database lock conflict use case

Now, let’s assume we have the following situation:

doInJPA(entityManager -> {
    Post post = entityManager.createQuery("""
        select p
        from Post p
        where p.id = :id
        """, Post.class)
    .setParameter("id", 1L)
    .setLockMode(LockModeType.PESSIMISTIC_WRITE)
    .getSingleResult();

    try {
        executeSync(() -> {
            doInJPA(_entityManager -> {
                Post _post = (Post) _entityManager.createQuery("""
                    select p
                    from Post p
                    where p.id = :id
                    """, Post.class)
                .setParameter("id", 1L)
                .unwrap(org.hibernate.query.Query.class)
                .setLockOptions(
                    new LockOptions()
                    .setLockMode(LockMode.PESSIMISTIC_WRITE)
                    .setTimeOut(LockOptions.NO_WAIT)
                )
                .getSingleResult();
            });
        });
    } catch (Exception expected) {
        assertTrue(
            ExceptionUtil
            .rootCause(expected)
            .getMessage()
            .contains(
                "could not obtain lock on row in relation"
            )
        );
    }
});

The first user, Alice, locks the post record with the identifier value of 1. Afterward, the second user, Bob, tries to lock the same post record, but since he uses the NO_WAIT lock directive, he will get a LockAquisitionException right away.

For more details about the SQL NOWAIT clause, check out this article.

When running the aforementioned test case, Hibernate generates the following log entries:

DEBUG [Alice]: n.t.d.l.SLF4JQueryLoggingListener - 
    Time:3, 
    Success:True, 
    Type:Prepared, 
    Batch:False, 
    QuerySize:1, 
    BatchSize:0, 
    Query:["
        SELECT p.id AS id1_0_,
               p.title AS title2_0_,
               p.version AS version3_0_
        FROM   post p
        WHERE  p.id = ?
        FOR UPDATE OF p
    "], 
    Params:[(
        1
    )]

DEBUG [Bob]: n.t.d.l.SLF4JQueryLoggingListener - 
    Time:0, 
    Success:False, 
    Type:Prepared, 
    Batch:False, 
    QuerySize:1, 
    BatchSize:0, 
    Query:["
        SELECT p.id AS id1_0_,
               p.title AS title2_0_,
               p.version AS version3_0_
        FROM   post p
        WHERE  p.id = ?
        FOR UPDATE OF p NOWAIT
    "], 
    Params:[(
        1
    )]

WARN  [Bob]: o.h.e.j.s.SqlExceptionHelper - 
    SQL Error: 0, SQLState: 55P03

ERROR [Bob]: o.h.e.j.s.SqlExceptionHelper - 
    ERROR: could not obtain lock on row in relation "post"

Notice that the second query has a Success status of False since an SQLException is thrown with the could not obtain lock on row in relation "post" message.

Now, we want to append the database transaction identifier to the SQL statement log messages so that we can correlate the executed SQL queries with their associated transactions.

For this purpose, we can use MDC.

What is MDC

MDC (Mapped Diagnostic Context) is for logging what ThreadLocal is to Java threads. Basically, MDC allows you to register key/value pairs that are confined to the currently running thread and which you can reference when the logging framework builds log messages.

Since SLF4J (Simple Logging Facade) is a very convenient Java logging adaptor, it has become a very popular choice for many Java applications, and it also provides support for MDC via the org.slf4j.MDC class.

So, to set a given log variable using MDC, you can the put method as illustrated by the following example:

MDC.put("txId", String.format(" TxId: [%s]", transactionId(entityManager)));

To get the identifier of the underlying database transaction, you need to use a database-specific query. For more details, check out this article.

To print the “txId” log variable to the log, we need to include this variable in the log appender pattern:

<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>

The %X{txId} pattern is used to reference the txId log variable.

Logging the identifier of the current database transaction

Now, we can modify the previous test case to include the MDC txId log variable:

doInJPA(entityManager -> {
    try(MDC.MDCCloseable closable = MDC
        .putCloseable(
            "txId", 
            String.format(
                " TxId: [%s]", 
                transactionId(entityManager)
            )
        )
    ){      
        Post post = entityManager.createQuery("""
            select p
            from Post p
            where p.id = :id
            """, Post.class)
        .setParameter("id", 1L)
        .setLockMode(LockModeType.PESSIMISTIC_WRITE)
        .getSingleResult();

        try {
            executeSync(() -> {
                doInJPA(_entityManager -> {
                    try(MDC.MDCCloseable _closable = MDC
                        .putCloseable(
                            "txId", 
                            String.format(
                                " TxId: [%s]", 
                                transactionId(_entityManager)
                            )
                        )
                    ) {
                        Post _post = (Post) _entityManager.createQuery("""
                            select p
                            from Post p
                            where p.id = :id
                            """, Post.class)
                        .setParameter("id", 1L)
                        .unwrap(org.hibernate.query.Query.class)
                        .setLockOptions(
                            new LockOptions()
                            .setLockMode(LockMode.PESSIMISTIC_WRITE)
                            .setTimeOut(LockOptions.NO_WAIT)
                        )
                        .getSingleResult();
                    }
                });
            });
        } catch (Exception expected) {
            assertTrue(
                ExceptionUtil
                .rootCause(expected)
                .getMessage()
                .contains("could not obtain lock on row in relation")
            );
        }
    }
});

Notice that we are using the MDC.putCloseable method in a try-with-resources block. This way, we make sure the txId variable is removed from the MDC storage so that it will not be appended to the log after exiting the try-with-resources block.

When running the test case above, Hibernate is going to generate the following log entries:

DEBUG [Alice]: n.t.d.l.SLF4JQueryLoggingListener - 
    Time:1, 
    Success:True, 
    Type:Prepared, 
    Batch:False, 
    QuerySize:1, 
    BatchSize:0, 
    Query:["
        SELECT CAST(txid_current() AS text)
    "], 
    Params:[()]

DEBUG [Alice]: TxId: [796989] n.t.d.l.SLF4JQueryLoggingListener - 
    Name:DATA_SOURCE_PROXY, 
    Time:3, 
    Success:True, 
    Type:Prepared, 
    Batch:False, 
    QuerySize:1, 
    BatchSize:0, 
    Query:["
        SELECT p.id AS id1_0_,
               p.title AS title2_0_,
               p.version AS version3_0_
        FROM   post p
        WHERE  p.id = ?
        FOR UPDATE OF p "], 
    Params:[(
        1
    )]
    
DEBUG [Bob]: n.t.d.l.SLF4JQueryLoggingListener - 
    Time:1, 
    Success:True, 
    Type:Prepared, 
    Batch:False, 
    QuerySize:1, 
    BatchSize:0, 
    Query:["
        SELECT CAST(txid_current() AS text)
    "], 
    Params:[()]
    
DEBUG [Bob]: TxId: [796990] n.t.d.l.SLF4JQueryLoggingListener - 
    Time:0, 
    Success:False, 
    Type:Prepared, 
    Batch:False, 
    QuerySize:1, 
    BatchSize:0, 
    Query:["
        SELECT p.id AS id1_0_,
               p.title AS title2_0_,
               p.version AS version3_0_
        FROM   post p
        WHERE  p.id = ?
        FOR UPDATE OF p NOWAIT  "], 
    Params:[(
        1
    )]
    
WARN  [Bob]: TxId: [796990] o.h.e.j.s.SqlExceptionHelper - 
    SQL Error: 0, SQLState: 55P03
    
ERROR [Bob]: TxId: [796990] o.h.e.j.s.SqlExceptionHelper - 
    ERROR: could not obtain lock on row in relation "post"

As I explained in this article, the SELECT CAST(txid_current() AS text) is used in PostgreSQL to get the underlying database transaction identifier.

Notice that this time, the TxId entry is added for each SQL statement executed after setting the txId MDC log variable.

Awesome, right?

I'm running an online workshop on the 20-21 and 23-24 of November about High-Performance Java Persistence.

If you enjoyed this article, I bet you are going to love my Book and Video Courses as well.

Conclusion

The MDC log variable mechanism is very useful to pass context-specific information to log records. Using MDC, we can easily append the database transaction identifier for each executed SQL statement.

Since this is a cross-cutting concern, we could encapsulate the MDC log variable put and remove method calls in an AOP Aspect that intercepts all data access method calls. For more details about how you could write such an Aspect using Spring AOP support, check out this article.

Insert details about how the information is going to be processed

DOWNLOAD NOW