Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Hibernate dirty checking doesn't work and updates are generated for merged objects which haven't changed #39792

Closed
maxant opened this issue Mar 29, 2024 · 9 comments
Labels
area/hibernate-orm Hibernate ORM area/persistence OBSOLETE, DO NOT USE kind/bug Something isn't working triage/upstream Used for issues which are caused by issues in upstream projects/dependency

Comments

@maxant
Copy link

maxant commented Mar 29, 2024

Describe the bug

Similar to #30234 but perhaps different.
I have a versioned entity (optimistic locking) which i persist by making a REST call which responds with a JSON representation of that entity. The response contains version 0. I make a change to a field on that JSON and post it back to the server which does a merge. The field is updated in the database and the version is set to 1, which is expected.

I then post the same JSON, and the response contains version 2. I debugged into org.hibernate.event.internal.DefaultMergedEventListener#markInterceptorDirty and it seems to discover that the field has changed, even though the debugger confirms that the values are identical. The methods which hibernate uses at this stage are generated bytecode, so it isn't possible to debug into them.

Using the DirtyCheckInterceptor class posted in the other issue (linked above) solves the problem.

Reproducer: quarkus-dirty-check.zip

I also created a simple unit test which is similar to this article, to check that hibernate doesn't normally update the version number if no fields have changed when merging the object. https://vladmihalcea.com/jpa-persist-and-merge/

Expected behavior

Version numbers should only be updated if a field changes.
More importantly the update sql statement should only be generated if a field changes.
Otherwise merging a tree of objects causes every row to be unnecessarily updated.

Actual behavior

Version and row are updated every time a detached object is merged.

How to Reproduce?

See the reproducer attached above.
Run the GreetingResourceTest, which also contains documentation about what is going wrong.

Output of uname -a or ver

Linux cronus 6.2.0-39-generic #40-Ubuntu SMP PREEMPT_DYNAMIC Tue Nov 14 14:18:00 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Output of java -version

openjdk 21.0.2 2024-01-16 OpenJDK Runtime Environment GraalVM CE 21.0.2+13.1 (build 21.0.2+13-jvmci-23.1-b30) OpenJDK 64-Bit Server VM GraalVM CE 21.0.2+13.1 (build 21.0.2+13-jvmci-23.1-b30, mixed mode, sharing)

Quarkus version or git rev

3.9.1

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.8.7 Maven home: /usr/share/maven Java version: 21.0.2, vendor: GraalVM Community, runtime: /shared2/graalvm/graalvm-community-openjdk-21.0.2+13.1 Default locale: en_GB, platform encoding: UTF-8 OS name: "linux", version: "6.2.0-39-generic", arch: "amd64", family: "unix"

Additional information

No response

@maxant maxant added the kind/bug Something isn't working label Mar 29, 2024
@quarkus-bot quarkus-bot bot added area/hibernate-orm Hibernate ORM area/persistence OBSOLETE, DO NOT USE labels Mar 29, 2024
Copy link

quarkus-bot bot commented Mar 29, 2024

/cc @gsmet (hibernate-orm), @yrodiere (hibernate-orm)

@maxant
Copy link
Author

maxant commented Mar 29, 2024

here is some hibernate trace logging that might help. it clearly states that the object is dirty. this is logging that happens during the second merge, when the object is the same as it is in the database:

Request method:	POST
Request URI:	http://localhost:8081/entity
Proxy:			<none>
Request params:	<none>
Query params:	<none>
Form params:	<none>
Path params:	<none>
Headers:		Accept=*/*
				Content-Type=application/json
Cookies:		<none>
Multiparts:		<none>
Body:
{
    "id": "54fcd74f-a555-435a-a423-340e3518a2e9",
    "field": "two",
    "version": 1
}
2024-03-29 20:48:01,812 DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-1) `hibernate.connection.provider_disables_autocommit` was enabled.  This setting should only be enabled when you are certain that the Connections given to Hibernate by the ConnectionProvider have auto-commit disabled.  Enabling this setting when the Connections do not have auto-commit disabled will lead to Hibernate executing SQL operations outside of any JDBC/SQL transaction.
2024-03-29 20:48:01,812 DEBUG [org.hib.res.tra.bac.jta.int.JtaTransactionCoordinatorImpl] (executor-thread-1) Hibernate RegisteredSynchronization successfully registered with JTA platform
2024-03-29 20:48:01,812 DEBUG [org.hib.orm.loa.multi] (executor-thread-1) Batch fetching entity `org.acme.MyEntity#54fcd74f-a555-435a-a423-340e3518a2e9`
2024-03-29 20:48:01,812 DEBUG [org.hib.orm.sql.exec] (executor-thread-1) Skipping reading Query result cache data: cache-enabled = true, cache-mode = IGNORE
2024-03-29 20:48:01,812 DEBUG [org.hib.orm.results] (executor-thread-1) Initializer list:
	  org.acme.MyEntity -> EntityResultInitializer(org.acme.MyEntity)@1092496729 (SingleTableEntityPersister(org.acme.MyEntity))

2024-03-29 20:48:01,813 DEBUG [org.hib.SQL] (executor-thread-1) 
    select
        me1_0.ID,
        me1_0.FIELD,
        me1_0.VERSION 
    from
        T_ENTITY me1_0 
    where
        me1_0.ID=?
Hibernate: 
    select
        me1_0.ID,
        me1_0.FIELD,
        me1_0.VERSION 
    from
        T_ENTITY me1_0 
    where
        me1_0.ID=?
2024-03-29 20:48:01,813 TRACE [org.hib.orm.jdb.bind] (executor-thread-1) binding parameter (1:VARCHAR) <- [54fcd74f-a555-435a-a423-340e3518a2e9]
2024-03-29 20:48:01,813 DEBUG [org.hib.orm.res.loa.entity] (executor-thread-1) (EntityResultInitializer) Hydrated EntityKey (org.acme.MyEntity): 54fcd74f-a555-435a-a423-340e3518a2e9
2024-03-29 20:48:01,813 DEBUG [org.hib.orm.res.loa.entity] (executor-thread-1) (EntityResultInitializer) Created new entity instance [org.acme.MyEntity#54fcd74f-a555-435a-a423-340e3518a2e9] : 129613740
2024-03-29 20:48:01,813 DEBUG [org.hib.orm.results] (executor-thread-1) Extracted JDBC value [1] - [two]
2024-03-29 20:48:01,813 DEBUG [org.hib.orm.results] (executor-thread-1) Extracted JDBC value [2] - [1]
2024-03-29 20:48:01,813 DEBUG [org.hib.orm.results] (executor-thread-1) Extracted JDBC value [2] - [1]
2024-03-29 20:48:01,814 DEBUG [org.hib.orm.res.loa.entity] (executor-thread-1) (EntityResultInitializer) Done materializing entityInstance : org.acme.MyEntity#54fcd74f-a555-435a-a423-340e3518a2e9
2024-03-29 20:48:01,814 DEBUG [org.hib.orm.res.loading] (executor-thread-1) Calling top-level assembler (0 / 1) : org.hibernate.sql.results.graph.entity.internal.EntityAssembler@593d8fda
2024-03-29 20:48:01,814 DEBUG [org.hib.eve.int.AbstractFlushingEventListener] (executor-thread-1) Processing flush-time cascades
2024-03-29 20:48:01,814 DEBUG [org.hib.eve.int.AbstractFlushingEventListener] (executor-thread-1) Dirty checking collections
2024-03-29 20:48:01,814 DEBUG [org.hib.eve.int.AbstractFlushingEventListener] (executor-thread-1) Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects
2024-03-29 20:48:01,814 DEBUG [org.hib.eve.int.AbstractFlushingEventListener] (executor-thread-1) Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
2024-03-29 20:48:01,814 DEBUG [org.hib.int.uti.EntityPrinter] (executor-thread-1) Listing entities:
2024-03-29 20:48:01,814 DEBUG [org.hib.int.uti.EntityPrinter] (executor-thread-1) org.acme.MyEntity{field=two, id=54fcd74f-a555-435a-a423-340e3518a2e9, version=1}
2024-03-29 20:48:01,814 DEBUG [org.hib.SQL] (executor-thread-1) 
    update
        T_ENTITY 
    set
        FIELD=?,
        VERSION=? 
    where
        ID=? 
        and VERSION=?
Hibernate: 
    update
        T_ENTITY 
    set
        FIELD=?,
        VERSION=? 
    where
        ID=? 
        and VERSION=?
2024-03-29 20:48:01,815 TRACE [org.hib.orm.jdb.bind] (executor-thread-1) binding parameter (1:VARCHAR) <- [two]
2024-03-29 20:48:01,815 TRACE [org.hib.orm.jdb.bind] (executor-thread-1) binding parameter (2:BIGINT) <- [2]
2024-03-29 20:48:01,815 TRACE [org.hib.orm.jdb.bind] (executor-thread-1) binding parameter (3:VARCHAR) <- [54fcd74f-a555-435a-a423-340e3518a2e9]
2024-03-29 20:48:01,815 TRACE [org.hib.orm.jdb.bind] (executor-thread-1) binding parameter (4:BIGINT) <- [1]
2024-03-29 20:48:01,815 DEBUG [org.hib.cac.int.TimestampsCacheEnabledImpl] (executor-thread-1) Pre-invalidating space [T_ENTITY], timestamp: 1711741741815
2024-03-29 20:48:01,815 DEBUG [org.hib.eng.tra.int.TransactionImpl] (executor-thread-1) On TransactionImpl creation, JpaCompliance#isJpaTransactionComplianceEnabled == false
2024-03-29 20:48:01,815 DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-1) Initiating JDBC connection release from beforeTransactionCompletion
2024-03-29 20:48:01,816 DEBUG [org.hib.res.jdb.int.LogicalConnectionManagedImpl] (executor-thread-1) Initiating JDBC connection release from afterTransaction
2024-03-29 20:48:01,816 DEBUG [org.hib.cac.int.TimestampsCacheEnabledImpl] (executor-thread-1) Invalidating space [T_ENTITY], timestamp: 1711741681816

@maxant
Copy link
Author

maxant commented Mar 29, 2024

quarkus-dirty-check-with-vanilla-jpa.zip

The above also contains a second test, VanillaJpaTest, which shows that with plain Hibernate 6.4.4.Final (hibernate-core, but I also just tried it with hibernate-graalvm), it works as expected.

@yrodiere
Copy link
Member

yrodiere commented Apr 2, 2024

@maxant Thanks for the report.

Did you check with this test, which specifically configures Hibernate ORM in a way that is similar to what Quarkus does?

If this test fails, then it's a bug in Hibernate ORM that should be reported in the Hibernate Jira -- unless there's already a relevant bug report there, in which case just adding a comment there with your reproducer (and a link to this issue) will be enough.

@maxant
Copy link
Author

maxant commented Apr 2, 2024

Those are all JUnit4 dependencies and I don't have the time to make that work with JUnit5 at the moment.

Checking Hibernate Jira: https://hibernate.atlassian.net/jira/software/c/projects/HHH/issues/HHH-13826?filter=allissues&jql=project%20%3D%20%22HHH%22%0Aand%20text%20~%20%22merge%20dirty%20check%22%0Aand%20status%20in%20%28Open%2C%20%22Waiting%20for%20review%22%2C%20%22In%20Progress%22%2C%20%22Awaiting%20Test%20Case%22%2C%20%22Awaiting%20Response%22%2C%20%22Awaiting%20Contribution%22%29%0AORDER%20BY%20created%20DESC

This bug doesn't seem to be known there.

Either way, something isn't right, if Quarkus + Hibernate is always generating an update statement, even when the object being merged hasn't changed compared to the database. That is functionality which should work out of the box, and does, as shown by my second test in the second zip above.

Maybe it is related to bytecode enhancement. The following image shows the JUnit test where I am just using Hibernate without Quarkus - there are no extra fields on the object:

image

Compare that to when I debug in Quarkus:

image

Either way, it isn't right that the developer needs to first select from the DB and then compare all fields in order to decide if they should call merge or not. Something is definitely wrong here.

@maxant
Copy link
Author

maxant commented Apr 2, 2024

I created this: https://hibernate.atlassian.net/browse/HHH-17917

The fact that it works without bytecode enhancement got me thinking and reading more about it.
See https://vladmihalcea.com/how-to-enable-bytecode-enhancement-dirty-checking-in-hibernate/
See but less useful: https://vladmihalcea.com/the-anatomy-of-hibernate-dirty-checking/

OK, I updated my second ZIP and added a maven profile to activate bytecode enhancement and sure enough, that is the problem. With it activated, my vanilla hibernate test also fails with the same problem.

The first page above, from Vlad it says:

When enabling the dirty tracking option, Hibernate will track property changes through the following mechanism.
The $$_hibernate_tracker attribute stores every property change, and every setter method will call the $$_hibernate_trackChange method.

There is no mention of merging, but I guess the problem is, merging doesn't call any setter methods.

An alternative approach might be to add a method to my entity class, to manually set all fields given the deserialised DTO (by calling the setters?), but I actually tried that a few days ago and I failed because optimistic locking then no longer worked.

@maxant
Copy link
Author

maxant commented Apr 2, 2024

quarkus-dirty-check-with-bytecode-enhancement.zip

Run using mvn clean test -Dtbe=true, then both tests fail.

@maxant
Copy link
Author

maxant commented Apr 3, 2024

according to the hibernate bug i posted: this issue should be fixed by hibernate/hibernate-orm#8091

@yrodiere
Copy link
Member

yrodiere commented Jul 8, 2024

Thanks @maxant, in that case I'll close as it's supposedly fixed by the upgrade to Hibernate ORM (#40102) in Quarkus 3.11.
Please open another issue (probably on the Hibernate ORM tracker) if you still experience the problem.

@yrodiere yrodiere closed this as completed Jul 8, 2024
@yrodiere yrodiere added the triage/upstream Used for issues which are caused by issues in upstream projects/dependency label Jul 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/hibernate-orm Hibernate ORM area/persistence OBSOLETE, DO NOT USE kind/bug Something isn't working triage/upstream Used for issues which are caused by issues in upstream projects/dependency
Projects
None yet
Development

No branches or pull requests

2 participants