Entity put into second level cache with null value for ManyToOne relation

mkomko · January 11, 2023, 12:08pm

After migrating vom Hibernate 5.0.10 (WildFly 10) to Hibernate 6.1.6 (WildFly 27) we are having a strange problem where we are getting NullPointerExceptions for cached entities with other entities. Here is a simplified example:

ApprovalWorkflow.java:

package at.example.model;

import jakarta.persistence.Table;
import jakarta.persistence.*;
import org.hibernate.annotations.Cache;
import org.hibernate.annotations.*;

import java.io.Serializable;

@Entity
@Table(name = "APPROVAL_WORKFLOW")
@BatchSize(size = 500)
@Cacheable
@Cache(usage = CacheConcurrencyStrategy.READ_WRITE)
public class ApprovalWorkflow implements Serializable
{
    private static final long serialVersionUID = 1L;

    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    @Column(name = "ID")
    private Long id;

    @Basic(optional = false)
    @Column(name = "NAME")
    private String name;

    @ManyToOne(optional = false)
    @JoinColumn(name = "APPROVAL_WORKFLOW_TYPE_ID")
    @Fetch(value = FetchMode.SELECT)
    private ApprovalWorkflowType approvalWorkflowType;

    public Long getId()
    {
        return id;
    }

    public void setId(Long id)
    {
        this.id = id;
    }

    public String getName()
    {
        return name;
    }

    public void setName(String name)
    {
        this.name = name;
    }

    public ApprovalWorkflowType getApprovalWorkflowType()
    {
        return approvalWorkflowType;
    }

    public void setApprovalWorkflowType(ApprovalWorkflowType approvalWorkflowType)
    {
        this.approvalWorkflowType = approvalWorkflowType;
    }
}

ApprovalWorkflowType.java:

package at.example.model;

import jakarta.persistence.*;
import org.hibernate.annotations.BatchSize;
import org.hibernate.annotations.Cache;
import org.hibernate.annotations.CacheConcurrencyStrategy;
import org.hibernate.annotations.Immutable;

import java.io.Serializable;

@Entity
@Immutable
@Table(name = "APPROVAL_WORKFLOW_TYPE")
@BatchSize(size = 500)
@Cacheable
@Cache(usage = CacheConcurrencyStrategy.READ_ONLY)
public class ApprovalWorkflowType implements Serializable
{
    private static final long serialVersionUID = 1L;

    @Id
    @Column(name = "ID")
    private Long id;

    @Basic(optional = false)
    @Column(name = "NAME")
    private String name;

    public Long getId()
    {
        return id;
    }

    public void setId(Long id)
    {
        this.id = id;
    }

    public String getName()
    {
        return name;
    }

    public void setName(String name)
    {
        this.name = name;
    }
}

When we retrieve an ApprovalWorkflow entity for the first time, the approvalWorkflowType is set. When we retrieve the entity a second time and it is loaded from the second level cache, the approvalWorkflowType is null.

var approvalWorkflow = em.find(ApprovalWorkflow.class, 1040L)
System.out.println(approvalWorkflow.getApprovalWorkflowType());

Output first run: 2023-01-11 12:37:46,476 INFO [stdout] (default task-1) at.example.model.ApprovalWorkflowType[id=1]

Output second run: 2023-01-11 13:05:23,339 INFO [stdout] (default task-1) null

It also happens if we reduce the annotations to a minimum, but leaving the FetchMode as SELECT means the error happens almost every time. This leads me to suspect that the error may happen if the ApprovalWorkflowType is not a result of the original query (ergo not joined).

This is the debug log of the initial load, where the entities have not been cached yet:

2023-01-11 12:37:46,469 DEBUG [org.hibernate.cache.spi.support.AbstractReadWriteAccess] (default task-1) Getting cached data from region [`at.example.model.ApprovalWorkflow` (AccessType[read-write])] by key [at.example.model.ApprovalWorkflow#1040]
2023-01-11 12:37:46,469 DEBUG [org.hibernate.cache.spi.support.AbstractReadWriteAccess] (default task-1) Cache miss : region = `at.example.model.ApprovalWorkflow`, key = `at.example.model.ApprovalWorkflow#1040`
2023-01-11 12:37:46,469 DEBUG [org.hibernate.orm.sql.ast.create] (default task-1) Created new SQL alias : a1_0
2023-01-11 12:37:46,469 DEBUG [org.hibernate.orm.sql.ast.create] (default task-1) Registration of TableGroup [StandardTableGroup(at.example.model.ApprovalWorkflow)] with identifierForTableGroup [at.example.model.ApprovalWorkflow] for NavigablePath [at.example.model.ApprovalWorkflow] 
2023-01-11 12:37:46,469 DEBUG [org.hibernate.orm.results.graph.AST] (default task-1) DomainResult Graph:
 \-EntityResultImpl [at.example.model.ApprovalWorkflow]
 |  +-EntityFetchSelectImpl [at.example.model.ApprovalWorkflow.approvalWorkflowType]
 |  +-BasicFetch [at.example.model.ApprovalWorkflow.name]
 2023-01-11 12:37:46,469 DEBUG [org.hibernate.orm.sql.ast.tree] (default task-1) SQL AST Tree:%n    SelectStatement {
      FromClause {
        StandardTableGroup (a1 : at.example.model.ApprovalWorkflow) {
          primaryTableReference : APPROVAL_WORKFLOW as a1_0
        }
      }
    }

2023-01-11 12:37:46,469 DEBUG [org.hibernate.orm.sql.exec] (default task-1) Skipping reading Query result cache data: cache-enabled = false, cache-mode = IGNORE
2023-01-11 12:37:46,470 DEBUG [org.hibernate.orm.results] (default task-1) Initializer list
2023-01-11 12:37:46,470 DEBUG [org.hibernate.orm.results] (default task-1)     at.example.model.ApprovalWorkflow.approvalWorkflowType -> BatchEntitySelectFetchInitializer(at.example.model.ApprovalWorkflow.approvalWorkflowType)@903868713 (ToOneAttributeMapping(NavigableRole[at.example.model.ApprovalWorkflow.approvalWorkflowType])@1883431750)
2023-01-11 12:37:46,470 DEBUG [org.hibernate.orm.results] (default task-1)     at.example.model.ApprovalWorkflow -> EntityResultInitializer(at.example.model.ApprovalWorkflow)@1805719896 (SingleTableEntityPersister(at.example.model.ApprovalWorkflow))
2023-01-11 12:37:46,470 DEBUG [org.hibernate.SQL] (default task-1) select a1_0.ID,a1_0.APPROVAL_WORKFLOW_TYPE_ID,a1_0.NAME from APPROVAL_WORKFLOW a1_0 where a1_0.ID=?
2023-01-11 12:37:46,471 TRACE [org.hibernate.orm.jdbc.bind] (default task-1) binding parameter [1] as [BIGINT] - [1040]
2023-01-11 12:37:46,472 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-1) Skipping aggressive release of JDBC Connection after-statement due to held resources
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results] (default task-1) Extracted JDBC value [1] - [1]
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results] (default task-1) Extracted JDBC value [2] - [Default approval]
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results] (default task-1) Extracted JDBC value [0] - [1040]
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results.loading.entity] (default task-1) (ENTITYRESULTINITIALIZER) Adding entityInstance to second-level cache: at.example.model.ApprovalWorkflow#1040
2023-01-11 12:37:46,472 DEBUG [org.hibernate.cache.spi.support.AbstractReadWriteAccess] (default task-1) Caching data from load [region=`at.example.model.ApprovalWorkflow` (AccessType[read-write])] : key[at.example.model.ApprovalWorkflow#1040] -> value[CacheEntry(at.example.model.ApprovalWorkflow)]
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results.loading.entity] (default task-1) (EntityResultInitializer) Done materializing entityInstance : at.example.model.ApprovalWorkflow#1040
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results.loading] (default task-1) Calling top-level assembler (0 / 1) : org.hibernate.sql.results.graph.entity.internal.EntityAssembler@6f49b6f3
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results.loading.entity] (default task-1) (EntityResultInitializer) Found existing loading entry [at.example.model.ApprovalWorkflow#1040] - using loading instance
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.sql.ast.create] (default task-1) Created new SQL alias : a1_0
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.sql.ast.create] (default task-1) Registration of TableGroup [StandardTableGroup(at.example.model.ApprovalWorkflowType)] with identifierForTableGroup [at.example.model.ApprovalWorkflowType] for NavigablePath [at.example.model.ApprovalWorkflowType] 
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results.graph.AST] (default task-1) DomainResult Graph:
 \-EntityResultImpl [at.example.model.ApprovalWorkflowType]
 |  \-BasicFetch [at.example.model.ApprovalWorkflowType.name]

2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.sql.ast.tree] (default task-1) SQL AST Tree:%n    SelectStatement {
      FromClause {
        StandardTableGroup (a1 : at.example.model.ApprovalWorkflowType) {
          primaryTableReference : APPROVAL_WORKFLOW_TYPE as a1_0
        }
      }
    }

2023-01-11 12:37:46,473 DEBUG [org.hibernate.orm.sql.exec] (default task-1) Skipping reading Query result cache data: cache-enabled = false, cache-mode = IGNORE
2023-01-11 12:37:46,473 DEBUG [org.hibernate.orm.results] (default task-1) Initializer list
2023-01-11 12:37:46,473 DEBUG [org.hibernate.orm.results] (default task-1)     at.example.model.ApprovalWorkflowType -> EntityResultInitializer(at.example.model.ApprovalWorkflowType)@859414059 (SingleTableEntityPersister(at.example.model.ApprovalWorkflowType))
2023-01-11 12:37:46,473 DEBUG [org.hibernate.SQL] (default task-1) select a1_0.ID,a1_0.NAME from APPROVAL_WORKFLOW_TYPE a1_0 where a1_0.ID=?
2023-01-11 12:37:46,473 TRACE [org.hibernate.orm.jdbc.bind] (default task-1) binding parameter [1] as [BIGINT] - [1]
2023-01-11 12:37:46,474 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-1) Skipping aggressive release of JDBC Connection after-statement due to held resources
2023-01-11 12:37:46,474 DEBUG [org.hibernate.orm.results.loading.entity] (default task-1) (EntityResultInitializer) Hydrated EntityKey (at.example.model.ApprovalWorkflowType): 1
2023-01-11 12:37:46,474 DEBUG [org.hibernate.orm.results.loading.entity] (default task-1) (EntityResultInitializer) Created new entity instance [at.example.model.ApprovalWorkflowType#1] : at.example.model.ApprovalWorkflowType[id=1]
2023-01-11 12:37:46,474 DEBUG [org.hibernate.orm.results] (default task-1) Extracted JDBC value [1] - [PRIVILEGE]
2023-01-11 12:37:46,474 DEBUG [org.hibernate.orm.results.loading.entity] (default task-1) (ENTITYRESULTINITIALIZER) Adding entityInstance to second-level cache: at.example.model.ApprovalWorkflowType#1
2023-01-11 12:37:46,474 DEBUG [org.hibernate.orm.results.loading.entity] (default task-1) (EntityResultInitializer) Done materializing entityInstance : at.example.model.ApprovalWorkflowType#1
2023-01-11 12:37:46,474 DEBUG [org.hibernate.orm.results.loading] (default task-1) Calling top-level assembler (0 / 1) : org.hibernate.sql.results.graph.entity.internal.EntityAssembler@4695f32a
2023-01-11 12:37:46,474 DEBUG [org.hibernate.orm.results.loading.entity] (default task-1) (EntityResultInitializer) Found existing loading entry [at.example.model.ApprovalWorkflowType#1] - using loading instance
2023-01-11 12:37:46,474 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-1) Processing flush-time cascades
2023-01-11 12:37:46,474 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-1) Dirty checking collections
2023-01-11 12:37:46,475 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-1) Flushed: 0 insertions, 0 updates, 0 deletions to 2 objects
2023-01-11 12:37:46,475 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-1) Listing entities:
2023-01-11 12:37:46,475 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-1) at.example.model.ApprovalWorkflowType{name=PRIVILEGE, id=1}
2023-01-11 12:37:46,475 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-1) at.example.model.ApprovalWorkflow{id=1040, approvalWorkflowType=at.example.model.ApprovalWorkflowType#1, name=Default approval}
2023-01-11 12:37:46,475 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-1) Initiating JDBC connection release from afterStatement
2023-01-11 12:37:46,475 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-1) Session Metrics {
    1025000 nanoseconds spent acquiring 1 JDBC connections;
    21700 nanoseconds spent releasing 1 JDBC connections;
    1114300 nanoseconds spent preparing 2 JDBC statements;
    1752900 nanoseconds spent executing 2 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    49500 nanoseconds spent performing 2 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    59100 nanoseconds spent performing 2 L2C misses;
    486000 nanoseconds spent executing 1 flushes (flushing a total of 2 entities and 18 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2023-01-11 12:37:46,475 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-1) Initiating JDBC connection release from afterTransaction
2023-01-11 12:37:46,476 INFO  [stdout] (default task-1) at.example.model.ApprovalWorkflowType[id=1]

And here is the debug log when loading from cache:

2023-01-11 13:05:23,337 DEBUG [org.hibernate.resource.transaction.backend.jta.internal.JtaTransactionCoordinatorImpl] (default task-1) Hibernate RegisteredSynchronization successfully registered with JTA platform
2023-01-11 13:05:23,337 DEBUG [org.hibernate.cache.spi.support.AbstractReadWriteAccess] (default task-1) Getting cached data from region [`at.example.model.ApprovalWorkflow` (AccessType[read-write])] by key [at.example.model.ApprovalWorkflow#1040]
2023-01-11 13:05:23,338 DEBUG [org.hibernate.cache.spi.support.AbstractReadWriteAccess] (default task-1) Checking readability of read-write cache item [timestamp=`6854398224252929`, version=`null`] : txTimestamp=`6854405010788353`
2023-01-11 13:05:23,338 DEBUG [org.hibernate.cache.spi.support.AbstractReadWriteAccess] (default task-1) Cache hit : region = `at.example.model.ApprovalWorkflow`, key = `at.example.model.ApprovalWorkflow#1040`
2023-01-11 13:05:23,338 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-1) Processing flush-time cascades
2023-01-11 13:05:23,338 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-1) Dirty checking collections
2023-01-11 13:05:23,338 DEBUG [org.hibernate.event.internal.AbstractFlushingEventListener] (default task-1) Flushed: 0 insertions, 0 updates, 0 deletions to 1 objects
2023-01-11 13:05:23,338 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-1) Listing entities:
2023-01-11 13:05:23,338 DEBUG [org.hibernate.internal.util.EntityPrinter] (default task-1) at.example.model.ApprovalWorkflow{id=1040, approvalWorkflowType=null, name=Default approval}
2023-01-11 13:05:23,338 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-1) Initiating JDBC connection release from afterStatement
2023-01-11 13:05:23,339 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-1) Session Metrics {
    0 nanoseconds spent acquiring 0 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    0 nanoseconds spent preparing 0 JDBC statements;
    0 nanoseconds spent executing 0 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    66000 nanoseconds spent performing 1 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    631200 nanoseconds spent executing 1 flushes (flushing a total of 1 entities and 18 collections);
    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)
}
2023-01-11 13:05:23,339 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-1) Initiating JDBC connection release from afterTransaction
2023-01-11 13:05:23,339 INFO  [stdout] (default task-1) null

When debugging the Hibernate code I saw that:

AbstractEntityInitializer#initializeEntity(): The entity instance in the variable toInitialize does not yet contain the approvalWorkflowType when cacheAccess.putFromLoad() is called.
BatchEntitySelectFetchInitializer#setInstance(): This method is called on the ApprovalWorkflow#approvalWorkflowType only after the ApprovalWorkflow entity has been put in the second level cache using the method above!

As you can imagine, this is a huge problem for us and our application and I would greatly appreciate your assistance! I fear it would be very difficult to create a reproducer, so maybe you can help me to debug or already know what the problem could be?

Thank you very much in advance!

beikov · January 11, 2023, 2:30pm

Your logs look a bit fishy.

2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results] (default task-1) Extracted JDBC value [1] - [1]
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results] (default task-1) Extracted JDBC value [2] - [Default approval]

This does not fit the SQL query of the lines before select a1_0.ID,a1_0.APPROVAL_WORKFLOW_TYPE_ID,a1_0.NAME from APPROVAL_WORKFLOW a1_0 where a1_0.ID=?.

It should extract 1040 for position 1, 1 for position 2 and Default approval for position 3, so something is not right there. Since the approvalWorkflowType association is apparently eager, it will load the entity and the final ApprovalWorkflow with correct data should end up in the cache.

As far as I can see from the logs right now, I can’t explain what is happening, especially since the logs don’t seem to reflect the actual situation.

mkomko · January 11, 2023, 2:58pm

Thanks for taking a look so quickly. I have to admit I edited the log, because our entities contain other properties as well that I edited out for more clarity. I mistakenly deleted the following line, I have edited it back in above:
2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results] (default task-1) Extracted JDBC value [0] - [1040]
The JDBC value collection seems to be zero-based, so everything else should be in order.

The approvalWorkflowType is eager, but is not fetched in the original query due to the FetchMode SELECT. As the debug log shows, the entity is added to the cache first:

2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.results.loading.entity] (default task-1) (ENTITYRESULTINITIALIZER) Adding entityInstance to second-level cache: at.example.model.ApprovalWorkflow#1040

The missing entity is not even loaded at that point and is loaded later:

2023-01-11 12:37:46,472 DEBUG [org.hibernate.orm.sql.ast.create] (default task-1) Registration of TableGroup [StandardTableGroup(at.example.model.ApprovalWorkflowType)] with identifierForTableGroup [at.example.model.ApprovalWorkflowType] for NavigablePath [at.example.model.ApprovalWorkflowType]

beikov · January 11, 2023, 3:08pm

Alright, now I see the problem. The batch fetching is causing this, because batching only happens at the end of the whole initialization process, so it might be null until N elements have been processed.
Given that I understand this issue now, I currently can’t imagine how you could run into this with any fetch mode other than SELECT. Are you sure that you saw this problem with other fetch modes as well?

mkomko · January 11, 2023, 3:20pm

Thank you very much for yet another quick reply

Our code base originally didn’t have any FetchMode annotations, so we stumbled upon the problem right after the migration to Hibernate 6.1.6. We only added the FetchMode later for performance optimization. I left the FetchMode in, because then the problem even occurs when a simple em.find() puts the entity into the cache.

We also observed the problem without the FetchMode annotation under the following circumstances:

All ApprovalWorkflow entities are loaded using a named query
The query does not join the ApprovalWorkflowType
The entities end up in the cache this way
Again, loading the ApprovalWorkflow from the cache results in entities without the ApprovalWorkflowType

beikov · January 11, 2023, 3:29pm

Since SELECT is kind of the default, unless you use an entity graph or explicitly join fetch an association, you will always see the problem due to the use of the @BatchSize annotation on your entity, as that is what trigger the use of the BatchEntitySelectFetchInitializer.

So if you want a temporary workaround, remove the uses of @BatchSize. I created [HHH-16025] - Hibernate JIRA for this bug, so you can track that.

mkomko · January 12, 2023, 7:25am

Isn’t the default FetchMode for ManyToOne associations JOIN? Removing the BatchSize annotations (and the hibernate.default_batch_fetch_size property) does indeed fix the problem.

Thank you very much for creating a Jira issue, we’re looking forward to its resolution!

beikov · January 12, 2023, 9:27am

No, the default fetch mode is SELECT for lazy associations. Joins are only used for eager associations or if you provide an entity graph or fetch profile for an association.

mkomko · January 12, 2023, 9:29am

Yeah, so JOIN is the default fetch mode for ManyToOne because the default fetch type is EAGER?

PS: Grüße aus Wien

beikov · January 12, 2023, 9:44am

Exactly, it uses a join for fetching the approvalWorkflowType association when you load a ApprovalWorkflow, because the association is marked as eager.

PS: Grüße zurück
PPS: Besuch mich mal bei einem JUG Event in Wien wenn du mal persönlich über Hibernate reden willst.

papegaaij · January 13, 2023, 9:18pm

I should have checked Jira and here first, before spending an entire day tracking down this issue The good news is, I did manage to construct a testcase demonstrating the problem. I’ve attached it to the ticket. During my debugging session, I’ve also spotted that this also affects the @PostLoad events, which get triggered when the references are still null.

mkomko · January 16, 2023, 7:58am

Took us a lot longer than that ;-).
Good job on the reproducer, thanks! I didn’t think the second level cache was available in the reproducer-sample, or I would have given it a shot.

Topic		Replies	Views
Error if defining a ManyToAny in the child classes which references a @MappedSuperclass Hibernate ORM	6	124	March 26, 2024
OneToMany CascadeType.REMOVE Hibernate ORM	3	140	January 23, 2024
ManyToMany Correct implementation Hibernate ORM	3	478	June 19, 2020
Associated entity with OneToOne mapping coming in as null - Hibernate Hibernate ORM	2	1038	May 17, 2022
Cascading options for updating parent-child entity Hibernate ORM	0	7143	March 12, 2020

Entity put into second level cache with null value for ManyToOne relation

Related Topics