MySQL metadata locking and database transaction ending

Introduction

As previously explained, every SQL statement must be executed in the context of a database transaction. For modifying statements (e.g. INSERT, UPDATE, DELETE), row-level locks must be taken to ensure recoverability and avoid the data anomalies.

Next, I’ll demonstrate what can happen when a database transaction is not properly ended.

The test that got blocked

To simplify unit tests, I’ve been using the following unit test utility to enroll a given set of operations in a database transaction:

protected void doInJPA(JPATransactionVoidFunction function) {
    EntityManager entityManager = null;
    EntityTransaction txn = null;
    try {
        entityManager = emf.createEntityManager();
        function.beforeTransactionCompletion();
        txn = entityManager.getTransaction();
        txn.begin();
        function.accept(entityManager);
        txn.commit();
    } catch (RuntimeException e) {
        if ( txn != null && txn.isActive()) txn.rollback();
        throw e;
    } finally {
        function.afterTransactionCompletion();
        if (entityManager != null) {
            entityManager.close();
        }
    }
}

Considering we have the following JPA entity:

@Entity(name = "DateEvent")
public class DateEvent {

    @Id
    @GeneratedValue
    private Long id;

    @Temporal(TemporalType.TIMESTAMP)
    @Column(name = "`timestamp`")
    private Calendar timestamp;

    public DateEvent() {
    }

    public DateEvent(Calendar timestamp) {
        this.timestamp = timestamp;
    }

    public Long getId() {
        return id;
    }

    public Calendar getTimestamp() {
        return timestamp;
    }
}

The unit test looks like this:

@Test
public void testEqualityAfterPersisting() {
    final Calendar calendar = new GregorianCalendar();
    doInJPA(entityManager -> {
        entityManager.persist( new DateEvent( calendar ) );
    } );
    doInJPA(entityManager -> {
        DateEvent dateEvent = entityManager.createQuery(
            "select e from DateEvent e", DateEvent.class )
        .getSingleResult();
        assertEquals( calendar, dateEvent.getTimestamp() );
    } );
}

This test has been running smoothly on HSQLDB, H2, Oracle, and PostgreSQL. On MySQL, the test got stuck, and the log looks like this:

DEBUG [main]: o.h.SQL - select next_val as id_val from hibernate_sequence for update
DEBUG [main]: o.h.SQL - update hibernate_sequence set next_val= ? where next_val=?
DEBUG [main]: o.h.SQL - insert into DateEvent (`timestamp`, id) values (?, ?)
INFO  [main]: o.h.h.i.QueryTranslatorFactoryInitiator - HHH000397: Using ASTQueryTranslatorFactory
DEBUG [main]: o.h.SQL - select calendarwi0_.id as id1_0_, calendarwi0_.`timestamp` as timestam2_0_ from DateEvent calendarwi0_
INFO  [main]: o.h.t.s.i.SchemaDropperImpl$DelayedDropActionImpl - HHH000477: Starting delayed drop of schema as part of SessionFactory shut-down'
DEBUG [main]: o.h.SQL - drop table if exists DateEvent

The last log line indicates where the test got stuck.
For some reason, MySQL cannot drop the DateEvent table.

The explanation

If you take a look at the transaction handling utility, you will find that a transaction is committed when the JPATransactionVoidFunction callback runs without any exception and it rolls back on RuntimeException.

In this case, the following assertion fails:

assertEquals( calendar, dateEvent.getTimestamp() );

But the ComparisonFailure extends AssertionError which in turn extends Error. This way, the assertion failure is not caught by the catch block and the transaction doesn’t get a chance to be rolled back.

The finally block is always executed, even when an Error is thrown. In the finally block, the EntityManager is closed, and, because I’m using hibernate.hbm2ddl.auto set to create-drop, Hibernate tries to delete the current schema.

But why does it block? This would be expected in a Two-Phase Locking Repeatable-Read implementation where a read operation takes a shared lock on a result set. But the InnoDB storage engine uses MVCC so readers should not block writers, and there are no concurrent transactions here.

In this example, the blocking happens when using a single database session. Even if the select statement doesn’t acquire a row-level lock, MySQL still uses metadata locking on every database transaction, and according to the MySQL documentation:

To ensure transaction serializability, the server must not permit one session to perform a data definition language (DDL) statement on a table that is used in an uncompleted explicitly or implicitly started transaction in another session.

Because the transaction is not properly ended (either commit or rollback), the drop table statement is stuck. The fix is simple. We just need to issue a rollback on any Throwable so that we cover any RuntimeException, Error, or other Throwable situations where we might still get a chance to execute the transaction rollback:

catch (Throwable e) {
    if ( txn != null && txn.isActive()) txn.rollback();
    throw e;
}

Now, when executing the test we get the following log:

DEBUG [main]: o.h.SQL - update hibernate_sequence set next_val= ? where next_val=?
DEBUG [main]: o.h.SQL - insert into DateEvent (`timestamp`, id) values (?, ?)
INFO  [main]: o.h.h.i.QueryTranslatorFactoryInitiator - HHH000397: Using ASTQueryTranslatorFactory
DEBUG [main]: o.h.SQL - select calendarwi0_.id as id1_0_, calendarwi0_.`timestamp` as timestam2_0_ from DateEvent calendarwi0_
INFO  [main]: o.h.t.s.i.SchemaDropperImpl$DelayedDropActionImpl - HHH000477: Starting delayed drop of schema as part of SessionFactory shut-down'
DEBUG [main]: o.h.SQL - drop table if exists DateEvent
DEBUG [main]: o.h.SQL - drop table if exists hibernate_sequence

java.lang.AssertionError: 
Expected :java.util.GregorianCalendar[time=1455774800060,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Athens",offset=7200000,dstSavings=3600000,useDaylight=true,transitions=138,lastRule=java.util.SimpleTimeZone[id=Europe/Athens,offset=7200000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2016,MONTH=1,WEEK_OF_YEAR=8,WEEK_OF_MONTH=3,DAY_OF_MONTH=18,DAY_OF_YEAR=49,DAY_OF_WEEK=5,DAY_OF_WEEK_IN_MONTH=3,AM_PM=0,HOUR=7,HOUR_OF_DAY=7,MINUTE=53,SECOND=20,MILLISECOND=60,ZONE_OFFSET=7200000,DST_OFFSET=0]
Actual   :java.util.GregorianCalendar[time=1455774800000,areFieldsSet=true,areAllFieldsSet=true,lenient=true,zone=sun.util.calendar.ZoneInfo[id="Europe/Athens",offset=7200000,dstSavings=3600000,useDaylight=true,transitions=138,lastRule=java.util.SimpleTimeZone[id=Europe/Athens,offset=7200000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=2,startMonth=2,startDay=-1,startDayOfWeek=1,startTime=3600000,startTimeMode=2,endMode=2,endMonth=9,endDay=-1,endDayOfWeek=1,endTime=3600000,endTimeMode=2]],firstDayOfWeek=1,minimalDaysInFirstWeek=1,ERA=1,YEAR=2016,MONTH=1,WEEK_OF_YEAR=8,WEEK_OF_MONTH=3,DAY_OF_MONTH=18,DAY_OF_YEAR=49,DAY_OF_WEEK=5,DAY_OF_WEEK_IN_MONTH=3,AM_PM=0,HOUR=7,HOUR_OF_DAY=7,MINUTE=53,SECOND=20,MILLISECOND=0,ZONE_OFFSET=7200000,DST_OFFSET=0]

The transaction is properly ended and the assertation failure, therefore, gets a chance to be logged.

If you enjoyed this article, I bet you are going to love my book as well.

Conclusion

As a rule of thumb, a database transaction must always be ended (either committed or rolled back), no matter the outcome of a given data access layer operation (either successful or throwing an exception).

If you liked this article, you might want to subscribe to my newsletter too.

Advertisements

4 thoughts on “MySQL metadata locking and database transaction ending

  1. Hi Vlad,

    Great post, as usual!

    If I’m not wrong, when you close a connection without ending the transaction with Oracle JDBC Driver it’ll commit all statements before closing the connection. The interesting fact is it doesn’t happen with MySQL and other drivers.

    (maybe because JDBC spec isn’t clear about what to do when a connection is closed)

    That’s why it’s important to end every open transaction in the app.

    Does it make sense?

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s