Search code examples
hibernatejpaspring-data-jpaversionbatchsize

Hibernate batch breaks versioning for optimistic_force_increment

TL;DR: I'm using hibernate 6.2.0.Final. When I ...

  1. Enable batching
  2. Use versioning for an entity
  3. In a transaction, use an optimistic_force_increment lock on that versioned entity
  4. Make no other changes to that or any other entities during the transaction

... then the version of the versioned entity is not actually incremented. The necessary update statement is created and added to a batch just before committing, but it is not actually sent to the DB and remains in the batch after committing, which Hibernate then warns about in an INFO log message.

Example:

I have an entity Calendar which is versioned with a simple Integer version:

@Entity
@Table(name = "calendar")
public class Calendar implements Serializable {

    @Id
    @GeneratedValue
    @Column(name = "id")
    private UUID id;

    @NotNull
    @Size(min = 3, max = 3)
    @Column(name = "system_code", length = 3, nullable = false)
    private String systemCode;

    @NotNull
    @Column(name = "name", nullable = false)
    private String name;


    @Version
    @NotNull
    @Column(name = "version", nullable = false)
    private Integer version = 1;

When I change one of the attributes, the version gets automatically updated, as I would expect.

When I fetch the entity with a lock type OPTIMISTIC_FORCE_INCREMENT, I also expect the entity to get an incremented version, even if I didn't change the entity:

@Repository
public interface CalendarRepository extends JpaRepository<Calendar, UUID> {

    @Lock(LockModeType.OPTIMISTIC_FORCE_INCREMENT)
    @Query("SELECT c FROM Calendar c " +
            "WHERE c.systemCode = :systemCode " +
            "  AND c.name = :name")
    Optional<Calendar> findBySystemCodeAndNameWithOptimisticForceIncrement(
            @Param("systemCode") String systemCode,
            @Param("name") String name);
}

And indeed, that is exactly what happens.

But, if I now turn on batching...

spring:
  jpa:
    properties:
      hibernate:      
        jdbc:
          batch_size: 20
        order_updates: true
        order_inserts: true

Then something weird happens. While logging indicates that it is still attempting to increment the version, the increment doesn't actually happen. (I may have a bit too much trace logging on, but when you're digging...) You'll notice that AFTER the committing messsage, a new batch is still being created to do the update for the calendar entity. However, the batch is not actually executed, as shown by the informational warning HHH100503: On release of batch it still contained JDBC statements.

2023-07-12T14:29:34+02:00 [main] DEBUG o.h.e.t.internal.TransactionImpl - committing
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.t.b.j.i.JdbcResourceLocalTransactionCoordinatorImpl - ResourceLocalTransactionCoordinatorImpl#beforeCompletionCallback
2023-07-12T14:29:34+02:00 [main] TRACE o.h.e.jdbc.internal.JdbcCoordinatorImpl - Starting after statement execution processing [ON_CLOSE]
2023-07-12T14:29:34+02:00 [main] TRACE org.hibernate.orm.jdbc.batch - Created Batch (20) - `com.***.domain.Calendar#UPDATE`
2023-07-12T14:29:34+02:00 [main] TRACE org.hibernate.orm.jdbc.batch - Adding to JDBC batch (1) - `com.***.domain.Calendar#UPDATE`
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.ResourceRegistryStandardImpl - Registering statement [HikariProxyPreparedStatement@2037475545 wrapping update ibl_***.calendar set version=? where id=? and version=?]
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.ResourceRegistryStandardImpl - Registering result set [null]
2023-07-12T14:29:34+02:00 [main] DEBUG org.hibernate.SQL - update ibl_***.calendar set version=? where id=? and version=?
2023-07-12T14:29:34+02:00 [main] TRACE org.hibernate.orm.jdbc.bind - binding parameter [1] as [INTEGER] - [2]
2023-07-12T14:29:34+02:00 [main] TRACE org.hibernate.orm.jdbc.bind - binding parameter [2] as [UUID] - [cf2027c2-1212-4d14-88d4-00c6de0500d8]
2023-07-12T14:29:34+02:00 [main] TRACE org.hibernate.orm.jdbc.bind - binding parameter [3] as [INTEGER] - [1]
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.AbstractLogicalConnectionImplementor - LogicalConnection#beforeTransactionCompletion
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.t.i.SynchronizationRegistryStandardImpl - SynchronizationRegistryStandardImpl.notifySynchronizationsBeforeTransactionCompletion
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.AbstractLogicalConnectionImplementor - Preparing to commit transaction via JDBC Connection.commit()
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.AbstractLogicalConnectionImplementor - Transaction committed via JDBC Connection.commit()
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.AbstractLogicalConnectionImplementor - LogicalConnection#afterTransaction
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.ResourceRegistryStandardImpl - Releasing JDBC resources
2023-07-12T14:29:34+02:00 [main] INFO  org.hibernate.orm.jdbc.batch - HHH100503: On release of batch it still contained JDBC statements
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.ResourceRegistryStandardImpl - Releasing statement [HikariProxyPreparedStatement@2037475545 wrapping update ibl_***a.calendar set version=2 where id='cf2027c2-1212-4d14-88d4-00c6de0500d8'::uuid and version=1]
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.ResourceRegistryStandardImpl - Closing result set [null]
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.ResourceRegistryStandardImpl - Closing prepared statement [HikariProxyPreparedStatement@2037475545 wrapping update ibl_***.calendar set version=2 where id='cf2027c2-1212-4d14-88d4-00c6de0500d8'::uuid and version=1]
2023-07-12T14:29:34+02:00 [main] TRACE o.h.e.jdbc.internal.JdbcCoordinatorImpl - Starting after statement execution processing [ON_CLOSE]
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.t.b.j.i.JdbcResourceLocalTransactionCoordinatorImpl - ResourceLocalTransactionCoordinatorImpl#afterCompletionCallback(true)
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.t.i.SynchronizationRegistryStandardImpl - SynchronizationRegistryStandardImpl.notifySynchronizationsAfterTransactionCompletion(3)
2023-07-12T14:29:34+02:00 [main] TRACE o.h.e.jdbc.internal.JdbcCoordinatorImpl - Closing JDBC container [org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl@1561e62e]
2023-07-12T14:29:34+02:00 [main] DEBUG o.h.e.jdbc.internal.JdbcCoordinatorImpl - HHH000420: Closing un-released batch
2023-07-12T14:29:34+02:00 [main] DEBUG org.hibernate.orm.jdbc.batch - PreparedStatementDetails did not contain PreparedStatement on #releaseStatements : update ibl_***.calendar set version=? where id=? and version=?
2023-07-12T14:29:34+02:00 [main] TRACE o.h.e.jdbc.internal.JdbcCoordinatorImpl - Starting after statement execution processing [ON_CLOSE]
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.ResourceRegistryStandardImpl - Releasing JDBC resources
2023-07-12T14:29:34+02:00 [main] DEBUG org.hibernate.orm.jdbc.batch - PreparedStatementDetails did not contain PreparedStatement on #releaseStatements : update ibl_***.calendar set version=? where id=? and version=?
2023-07-12T14:29:34+02:00 [main] TRACE o.h.e.jdbc.internal.JdbcCoordinatorImpl - Starting after statement execution processing [ON_CLOSE]
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.LogicalConnectionManagedImpl - Closing logical connection
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.ResourceRegistryStandardImpl - Releasing JDBC resources
2023-07-12T14:29:34+02:00 [main] DEBUG org.hibernate.orm.jdbc.batch - PreparedStatementDetails did not contain PreparedStatement on #releaseStatements : update ibl_***.calendar set version=? where id=? and version=?
2023-07-12T14:29:34+02:00 [main] TRACE o.h.e.jdbc.internal.JdbcCoordinatorImpl - Starting after statement execution processing [ON_CLOSE]
2023-07-12T14:29:34+02:00 [main] TRACE o.h.r.j.i.LogicalConnectionManagedImpl - Logical connection closed

By stepping through debugger sessions, I've reached the tentative conclusion that

  1. On committing (JdbcResourceLocalTransactionCoordinatorImpl.commit), before the actual commit, a beforeCompletionCallback is called.
  2. This beforeCompletionCallback will go over things that need to be done in the beforeTransactionCompletion method of the BeforeTransactionCompletionProcessQueue class. It will correctly see that the version increment needs to be done and call doBeforeTransactionCompletion of the EntityIncrementVersionProcess class.
  3. This doBeforeTransactionCompletion method calls for a MutationExecutor. If batching is explicitly set to 1, the returned executor is of the type MutationExecutorSingleNonBatched. But if batching is set to > 1, the returned executor is of the type MutationExecutorSingleBatched instead.
  4. When afterwards the execute method of the executor is called, in the case of the MutationExecutorSingleNonBatched, it seems to actually execute the statement. However in the case of the MutationExecutorSingleBatched, it only adds the statement to the batch, but it doesn't get executed before the actual commit is sent.

Testing method:

@Test
    @Order(1)
    void findBySystemCodeAndNameWithOptimisticForceIncrement() {

        // Prepare the environment
        transactionTemplate.execute(new TransactionCallbackWithoutResult() {
            @Override
            protected void doInTransactionWithoutResult(TransactionStatus status) {
                calendarRepository.save(new Calendar()
                        .name("Calendar for AAA")
                        .systemCode("AAA"));
            }
        });

        // Call the tested method in a transaction
        transactionTemplate.execute(new TransactionCallbackWithoutResult() {
            @Override
            protected void doInTransactionWithoutResult(TransactionStatus status){
                calendarRepository
                        .findBySystemCodeAndNameWithOptimisticForceIncrement("AAA", "Calendar for AAA")
                        .orElseThrow()
            }
        });


        // Verify the result
        Calendar savedCalendar = transactionTemplate.execute(status -> calendarRepository
                .findBySystemCodeAndName("AAA", "Calendar for AAA")
                .orElseThrow()
        );

        assertThat(savedCalendar.getVersion()).isEqualTo(2);
    }

Did anyone else run into this strange behaviour when combining versioning with batching in Hibernate? What would be a way to resolve this without resorting to disabling batching as a whole?

Solution

  • I have been able to reproduce what you are seeing. I found this question while trying to figure out what was causing this message in my Spring Boot 3.1.1 project.

    HHH100503: On release of batch it still contained JDBC statements

    My project uses pessimistic force increment and I was noticing that some but not all of the rows, were missing their @Version column updates.

    From the test case I am working on, there is nothing obviously wrong with the @Version column itself. It works in 5.6.17 and 6.1.7 but 6.2.0 and above fails.

    I have linked this question to Hibernate ORM issue https://hibernate.atlassian.net/browse/HHH-16939, which will include the above test case PR once it is finished.