Hibernate query cache always have cache miss even if result is retrieved from cache

[akarpavicius]

Hi,

Enabled  L2 cache, including query cache in Wildfly 10.1.0 Final, working with a standard standalone.xml configuration and project with JPA.

        <shared-cache-mode>ENABLE_SELECTIVE</shared-cache-mode>

        <properties>

            <property name="hibernate.cache.use_second_level_cache" value="true" />

            <property name="hibernate.cache.use_query_cache" value="true" />

            <property name="hibernate.generate_statistics" value="true" />

Entity in question is a simple 5-6 field entity with no related entities. Entity is annotated with @Cacheable

The first time I do a query, nothing is found and is cached - thus I see 0 L2C hits and 1 L2C misses and cache is populated.

The second time I do a query, query is recognized as cached - thus I see 2 L2C hits. But I also see 1 L2C miss. And why 2 hits if it returns only a single record?

If I do same, but instead of query I access by ID, on the second call I have 1 hit and 0 miss.

So question - why do I always have a miss on query even though response is cached and why 2 hits instead of 1?

First call by query:

21:55:46,369 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-41) Checking cached query results in region: opencell.war#MeveoAdmin.org.hibernate.cache.internal.StandardQueryCache

21:55:46,374 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-41) key.hashCode=312133735

21:55:46,374 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-41) querySpaces=[adm_title]

21:55:46,374 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-41) unexpected returnTypes is typename=org.meveo.model.shared.Title class="org".meveo.model.shared.Title ! result

21:55:46,374 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-41) Query results were not found in cache

21:55:46,376 DEBUG [org.hibernate.SQL] (default task-41) select title0_.id as id1_33_, title0_.version as version2_33_, title0_.created as created3_33_, title0_.creator as creator4_33_, title0_.updated as updated5_33_, title0_.updater as updater6_33_, title0_.disabled as disabled7_33_, title0_.code as code8_33_, title0_.description as descript9_33_, title0_.description_i18n as descrip10_33_, title0_.is_company as is_comp11_33_ from adm_title title0_ where upper(title0_.code)=? limit ?

21:55:46,381 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-41) acquirePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, 1507164946368)

21:55:46,382 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-41) Region invalidated at -9223372036854775808, this transaction started at 1507164946368

21:55:46,382 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-41) acquirePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, 1507164946368) ended with { PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, valid: true

21:55:46,382 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-41) releasePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, { PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=false})

21:55:46,383 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-41) Caching query results in region: opencell.war#MeveoAdmin.org.hibernate.cache.internal.StandardQueryCache; timestamp=1507164946368

21:55:46,383 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-41) key.hashCode=312133735

21:55:46,383 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-41) querySpaces=null

21:55:46,383 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-41) unexpected returnTypes is typename=org.meveo.model.shared.Title class="org".meveo.model.shared.Title ! result

21:55:46,383 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-41) tuple is Object[1]; returnTypes is Type[1]

21:55:46,396 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-41) Session Metrics {

    1209481 nanoseconds spent acquiring 2 JDBC connections;

    57632 nanoseconds spent releasing 2 JDBC connections;

    1124612 nanoseconds spent preparing 1 JDBC statements;

    2266198 nanoseconds spent executing 1 JDBC statements;

    0 nanoseconds spent executing 0 JDBC batches;

    2484094 nanoseconds spent performing 2 L2C puts;

    0 nanoseconds spent performing 0 L2C hits;

    5127268 nanoseconds spent performing 1 L2C misses;

    962770 nanoseconds spent executing 2 flushes (flushing a total of 2 entities and 0 collections);

    7895 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)

}

Second call by query:

21:57:02,297 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-60) Checking cached query results in region: opencell.war#MeveoAdmin.org.hibernate.cache.internal.StandardQueryCache

21:57:02,297 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-60) key.hashCode=312133735

21:57:02,297 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-60) querySpaces=[adm_title]

21:57:02,297 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-60) unexpected returnTypes is typename=org.meveo.model.shared.Title class="org".meveo.model.shared.Title ! result

21:57:02,297 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-60) Checking query spaces are up-to-date: [adm_title]

21:57:02,297 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-60) Returning cached query results

21:57:02,305 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-60) 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;

    959216 nanoseconds spent performing 2 L2C hits;

    6711 nanoseconds spent performing 1 L2C misses;

    703031 nanoseconds spent executing 2 flushes (flushing a total of 2 entities and 0 collections);

    5527 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)

}

First call by ID

21:59:45,944 DEBUG [org.meveo.admin.action.admin.TitleBean$Proxy$_$$_WeldSubclass] (default task-22) instantiating class org.meveo.admin.action.admin.TitleBean$Proxy$_$$_WeldSubclass with id -6

21:59:45,950 TRACE [org.meveo.service.catalog.impl.TitleService] (default task-22) Find Title by id (id=-6) ..

21:59:45,955 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-22) registerPendingPut(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, 1507165185952) registered using putIfAbsent: { PendingPuts=[R@Session#267656860], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}

21:59:45,958 DEBUG [org.hibernate.SQL] (default task-22) select title0_.id as id1_33_0_, title0_.version as version2_33_0_, title0_.created as created3_33_0_, title0_.creator as creator4_33_0_, title0_.updated as updated5_33_0_, title0_.updater as updater6_33_0_, title0_.disabled as disabled7_33_0_, title0_.code as code8_33_0_, title0_.description as descript9_33_0_, title0_.description_i18n as descrip10_33_0_, title0_.is_company as is_comp11_33_0_ from adm_title title0_ where title0_.id=?

21:59:45,968 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-22) acquirePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, 1507165185952)

21:59:45,968 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-22) acquirePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, 1507165185952) ended with { PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, valid: true

21:59:45,968 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-22) releasePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, { PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=false})

21:59:45,983 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-22) Session Metrics {

    2854754 nanoseconds spent acquiring 1 JDBC connections;

    14210 nanoseconds spent releasing 1 JDBC connections;

    4366605 nanoseconds spent preparing 1 JDBC statements;

    1162901 nanoseconds spent executing 1 JDBC statements;

    0 nanoseconds spent executing 0 JDBC batches;

    905531 nanoseconds spent performing 1 L2C puts;

    0 nanoseconds spent performing 0 L2C hits;

    1124217 nanoseconds spent performing 1 L2C misses;

    1667378 nanoseconds spent executing 2 flushes (flushing a total of 2 entities and 0 collections);

    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)

}

Second call by ID

22:00:16,398 DEBUG [org.meveo.admin.action.admin.TitleBean$Proxy$_$$_WeldSubclass] (default task-48) instantiating class org.meveo.admin.action.admin.TitleBean$Proxy$_$$_WeldSubclass with id -6

22:00:16,402 TRACE [org.meveo.service.catalog.impl.TitleService] (default task-48) Find Title by id (id=-6) ..

22:00:16,416 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-48) 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;

    1409219 nanoseconds spent performing 1 L2C hits;

    0 nanoseconds spent performing 0 L2C misses;

    1003822 nanoseconds spent executing 2 flushes (flushing a total of 2 entities and 0 collections);

    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)

}

Thanks,

Andrius

[galder.zamarreno]

You need to make sure you call setCacheable() on your query, or if using JPA: query.setHint("org.hibernate.cacheable", Boolean.TRUE);

That will make sure the query is cached. Did you do this?

I don't know about the 2 hits right now, can you show your entity class? If you can upload the full TRACE log we might also be able to find out.

[akarpavicius]

Hi,

Thanks for answering.

Here are full trace logs. I have enabled: org.hibernate.cache=TRACE, org.hibernate.cache.infinispan=TRACE, org.hibernate.SQL=TRACE and org.infinispan=TRACE. If you want me to turn on any other logs, please let me know.

Query is called from JPA:

TypedQuery<Title> query = getEntityManager().createQuery("select be from Title be where lower(code)=:code", Title.class).setParameter("code", code.toLowerCase()).setMaxResults(1).setHint("org.hibernate.cacheable", Boolean.TRUE);

This is cache configuration (standard standalone.xml):

            <cache-container name="hibernate" default-cache="local-query" module="org.hibernate.infinispan">

                <local-cache name="entity" statistics-enabled="false">

                    <transaction mode="NON_XA"/>

                    <eviction strategy="LRU" max-entries="10000"/>

                    <expiration max-idle="100000"/>

                </local-cache>

                <local-cache name="local-query" statistics-enabled="false">

                    <eviction strategy="LRU" max-entries="10000"/>

                    <expiration max-idle="100000"/>

                </local-cache>

                <local-cache name="timestamps"/>

            </cache-container>

Entity:

@Entity
@Cacheable
@Table(name = "adm_title", uniqueConstraints = @UniqueConstraint(columnNames = { "code" }))
@GenericGenerator(name = "ID_GENERATOR", strategy = "org.hibernate.id.enhanced.SequenceStyleGenerator", parameters = {
        @Parameter(name = "sequence_name", value = "adm_title_seq"), })
public class Title implements Serializable, IEntity, IJPAVersionedEntity, IAuditable {

    private static final long serialVersionUID = -6827515878506806536L;

    @Id
    @GeneratedValue(generator = "ID_GENERATOR", strategy = GenerationType.AUTO)
    @Column(name = "id")
    @Access(AccessType.PROPERTY)
    protected Long id;

    @Version
    @Column(name = "version")
    private Integer version;

    @Column(name = "code", nullable = false, length = 255)
    @Size(max = 255, min = 1)
    @NotNull
    protected String code;

    @Column(name = "description", nullable = true, length = 255)
    @Size(max = 255)
    protected String description;

    @Type(type = "numeric_boolean")
    @Column(name = "disabled", nullable = false)
    @NotNull
    private boolean disabled;

    @Embedded
    private Auditable auditable;

    @Type(type = "numeric_boolean")
    @Column(name = "is_company")
    private Boolean isCompany = Boolean.FALSE;

..

}

@Embeddable
public class Auditable implements Serializable {

private static final long serialVersionUID = 1L;

@Temporal(TemporalType.TIMESTAMP)
@Column(name = "created", nullable = false, updatable = false)
private Date created;

@Temporal(TemporalType.TIMESTAMP)
@Column(name = "updated")
private Date updated;

@Column(name = "creator", updatable = false, length = 100)
private String creator;

@Column(name = "updater", length = 100)
private String updater;
..
}

I always see "performing 1 L2C misses" even though results are found in cache.

First call - cache miss

11:05:28,860 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-2) Checking cached query results in region: opencell.war#MeveoAdmin.org.hibernate.cache.internal.StandardQueryCache
11:05:28,864 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-2) key.hashCode=1031932438
11:05:28,864 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-2) querySpaces=[adm_title]
11:05:28,864 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-2) unexpected returnTypes is typename=org.meveo.model.shared.Title class="org".meveo.model.shared.Title ! result
11:05:28,864 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-2) Query results were not found in cache
11:05:28,866 DEBUG [org.hibernate.SQL] (default task-2) select title0_.id as id1_34_, title0_.created as created2_34_, title0_.creator as creator3_34_, title0_.updated as updated4_34_, title0_.updater as updater5_34_, title0_.code as code6_34_, title0_.description as descript7_34_, title0_.disabled as disabled8_34_, title0_.is_company as is_compa9_34_, title0_.version as version10_34_ from adm_title title0_ where upper(title0_.code)=? limit ?
11:05:29,026 TRACE [org.infinispan.transaction.impl.TransactionTable] (default task-2) Created a new local transaction: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@7
11:05:29,030 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-2) Invoked with command GetKeyValueCommand {key=-6, flags=null} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@37305868]
11:05:29,034 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Exists in context? null
11:05:29,037 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Retrieved from container null (ignoreOwnership=false, isLocal=true)
11:05:29,037 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Wrap -6 for read. Entry=null
11:05:29,038 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-2) Executing command: GetKeyValueCommand {key=-6, flags=null}.
11:05:29,039 TRACE [org.infinispan.commands.read.GetKeyValueCommand] (default task-2) Entry not found
11:05:29,042 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-2) acquirePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, 1508940328742)
11:05:29,043 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-2) Invoked with command GetKeyValueCommand {key=-6, flags=null} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@28b69328]
11:05:29,043 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Exists in context? null
11:05:29,043 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Retrieved from container null (ignoreOwnership=false, isLocal=true)
11:05:29,043 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Wrap -6 for read. Entry=null
11:05:29,043 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-2) Executing command: GetKeyValueCommand {key=-6, flags=null}.
11:05:29,043 TRACE [org.infinispan.commands.read.GetKeyValueCommand] (default task-2) Entry not found
11:05:29,044 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-2) Release locks for keys=[]. owner=null
11:05:29,046 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-2) Region invalidated at -9223372036854775808, this transaction started at 1508940328742
11:05:29,050 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-2) Invoked with command PutKeyValueCommand{key=-6, value={ PendingPuts=[R@Session#549316938], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, flags=null, putIfAbsent=true, valueMatcher=MATCH_EXPECTED, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@35d91669]
11:05:29,051 TRACE [org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor] (default task-2) Are (Local Address) we the lock owners for key '-6'? true
11:05:29,057 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-2) Lock key=-6 for owner=CommandUUID{address=Local Address, id=214}. timeout=10000 (MILLISECONDS)
11:05:29,065 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Acquire lock for CommandUUID{address=Local Address, id=214}. Timeout=10000 (MILLISECONDS)
11:05:29,065 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Created a new one: LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=214}}
11:05:29,065 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=214}}. Current=null
11:05:29,066 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Lock Owner CAS(null, LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=214}}) => true
11:05:29,066 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) State changed for LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=214}}. WAITING => ACQUIRED
11:05:29,066 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=214}} successfully acquired the lock.
11:05:29,066 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-2) Wrapping entry '-6'? true
11:05:29,066 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Exists in context? null
11:05:29,066 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Retrieved from container null (ignoreOwnership=false, isLocal=true)
11:05:29,066 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Creating new entry for key -6
11:05:29,066 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Updated context entry ReadCommittedEntry(256ba4d1){key=-6, value=null, oldValue=null, isCreated=true, isChanged=false, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=null}
11:05:29,066 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-2) Executing command: PutKeyValueCommand{key=-6, value={ PendingPuts=[R@Session#549316938], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, flags=null, putIfAbsent=true, valueMatcher=MATCH_EXPECTED, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}, successful=true}.
11:05:29,069 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-2) About to commit entry ReadCommittedEntry(256ba4d1){key=-6, value={ PendingPuts=[R@Session#549316938], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}}
11:05:29,070 TRACE [org.infinispan.statetransfer.CommitManager] (default task-2) Trying to commit. Key=-6. Operation Flag=null, L1 invalidation=false
11:05:29,070 TRACE [org.infinispan.statetransfer.CommitManager] (default task-2) Committing key=-6. It is a L1 invalidation or a normal put and no tracking is enabled!
11:05:29,070 TRACE [org.infinispan.container.entries.ReadCommittedEntry] (default task-2) Updating entry (key=-6 removed=false valid=true changed=true created=true value={ PendingPuts=[R@Session#549316938], Invalidators=[], LastInvalidationEnd=<none>, Removed=false} metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null})
11:05:29,070 TRACE [org.infinispan.container.DefaultDataContainer] (default task-2) Creating new ICE for writing. Existing=null, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}, new value={ PendingPuts=[R@Session#549316938], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}
11:05:29,070 TRACE [org.infinispan.container.DefaultDataContainer] (default task-2) Store TransientCacheEntry{key=-6, value={ PendingPuts=[R@Session#549316938], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}} in container
11:05:29,077 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-2) The return value is null
11:05:29,077 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-2) Release locks for keys=[-6]. owner=CommandUUID{address=Local Address, id=214}
11:05:29,077 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Release lock for CommandUUID{address=Local Address, id=214}.
11:05:29,077 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) State changed for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=214}}. ACQUIRED => RELEASED
11:05:29,077 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Release lock for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=214}}? true
11:05:29,077 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Try acquire. Next in queue=null. Current=LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=214}}
11:05:29,077 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Lock Owner CAS(LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=214}}, null) => true
11:05:29,077 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Try acquire. Next in queue=null. Current=null
11:05:29,078 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-2) acquirePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, 1508940328742) ended with { PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, valid: true
11:05:29,078 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-2) Invoked with command PutKeyValueCommand{key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@10ad4b0c,DR,Dr,false,false,1], flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, FAIL_SILENTLY, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ, IGNORE_RETURN_VALUES], putIfAbsent=true, valueMatcher=MATCH_EXPECTED, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@c9eb5e2]
11:05:29,079 TRACE [org.infinispan.interceptors.locking.PessimisticLockingInterceptor] (default task-2) Are (Local Address) we the lock owners for key '-6'? true
11:05:29,079 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-2) Lock key=-6 for owner=CommandUUID{address=Local Address, id=215}. timeout=0 (MILLISECONDS)
11:05:29,079 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Acquire lock for CommandUUID{address=Local Address, id=215}. Timeout=0 (MILLISECONDS)
11:05:29,079 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Created a new one: LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=215}}
11:05:29,079 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=215}}. Current=null
11:05:29,079 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Lock Owner CAS(null, LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=215}}) => true
11:05:29,079 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) State changed for LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=215}}. WAITING => ACQUIRED
11:05:29,079 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=215}} successfully acquired the lock.
11:05:29,079 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-2) Wrapping entry '-6'? true
11:05:29,079 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Exists in context? null
11:05:29,079 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Retrieved from container null (ignoreOwnership=false, isLocal=true)
11:05:29,079 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Creating new entry for key -6
11:05:29,079 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Updated context entry ReadCommittedEntry(71898046){key=-6, value=null, oldValue=null, isCreated=true, isChanged=false, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=null}
11:05:29,079 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-2) Executing command: PutKeyValueCommand{key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@10ad4b0c,DR,Dr,false,false,1], flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, FAIL_SILENTLY, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ, IGNORE_RETURN_VALUES], putIfAbsent=true, valueMatcher=MATCH_EXPECTED, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true}.
11:05:29,080 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-2) About to commit entry ReadCommittedEntry(71898046){key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@10ad4b0c,DR,Dr,false,false,1], oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}}
11:05:29,080 TRACE [org.infinispan.statetransfer.CommitManager] (default task-2) Trying to commit. Key=-6. Operation Flag=null, L1 invalidation=false
11:05:29,080 TRACE [org.infinispan.statetransfer.CommitManager] (default task-2) Committing key=-6. It is a L1 invalidation or a normal put and no tracking is enabled!
11:05:29,080 TRACE [org.infinispan.container.entries.ReadCommittedEntry] (default task-2) Updating entry (key=-6 removed=false valid=true changed=true created=true value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@10ad4b0c,DR,Dr,false,false,1] metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null})
11:05:29,080 TRACE [org.infinispan.container.DefaultDataContainer] (default task-2) Creating new ICE for writing. Existing=null, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, new value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@10ad4b0c,DR,Dr,false,false,1]
11:05:29,082 TRACE [org.infinispan.container.DefaultDataContainer] (default task-2) Store TransientCacheEntry{key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@10ad4b0c,DR,Dr,false,false,1]} in container
11:05:29,090 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-2) The return value is null
11:05:29,090 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-2) Release locks for keys=[-6]. owner=CommandUUID{address=Local Address, id=215}
11:05:29,090 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Release lock for CommandUUID{address=Local Address, id=215}.
11:05:29,090 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) State changed for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=215}}. ACQUIRED => RELEASED
11:05:29,090 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Release lock for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=215}}? true
11:05:29,090 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Try acquire. Next in queue=null. Current=LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=215}}
11:05:29,090 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Lock Owner CAS(LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=215}}, null) => true
11:05:29,090 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Try acquire. Next in queue=null. Current=null
11:05:29,091 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-2) releasePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, { PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=false})
11:05:29,092 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-2) Invoked with command RemoveCommand{key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, flags=null, valueMatcher=MATCH_EXPECTED} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@9bcef8a]
11:05:29,092 TRACE [org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor] (default task-2) Are (Local Address) we the lock owners for key '-6'? true
11:05:29,092 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-2) Lock key=-6 for owner=CommandUUID{address=Local Address, id=216}. timeout=10000 (MILLISECONDS)
11:05:29,092 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Acquire lock for CommandUUID{address=Local Address, id=216}. Timeout=10000 (MILLISECONDS)
11:05:29,092 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Created a new one: LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=216}}
11:05:29,092 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=216}}. Current=null
11:05:29,094 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Lock Owner CAS(null, LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=216}}) => true
11:05:29,094 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) State changed for LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=216}}. WAITING => ACQUIRED
11:05:29,094 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=216}} successfully acquired the lock.
11:05:29,097 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-2) Wrapping entry '-6'? true
11:05:29,097 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Exists in context? null
11:05:29,097 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Retrieved from container TransientCacheEntry{key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}} (ignoreOwnership=false, isLocal=true)
11:05:29,097 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Creating new entry for key -6
11:05:29,097 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-2) Updated context entry ReadCommittedEntry(7333309a){key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, oldValue=null, isCreated=false, isChanged=false, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedMaxIdleExpirableMetadata{maxIdle=60000, version=null}}
11:05:29,097 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-2) Executing command: RemoveCommand{key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, flags=null, valueMatcher=MATCH_EXPECTED}.
11:05:29,097 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-2) About to commit entry ReadCommittedEntry(7333309a){key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, oldValue={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, isCreated=false, isChanged=true, isRemoved=true, isValid=false, isExpired=false, skipRemoteGet=false, metadata=EmbeddedMaxIdleExpirableMetadata{maxIdle=60000, version=null}}
11:05:29,097 TRACE [org.infinispan.statetransfer.CommitManager] (default task-2) Trying to commit. Key=-6. Operation Flag=null, L1 invalidation=false
11:05:29,098 TRACE [org.infinispan.statetransfer.CommitManager] (default task-2) Committing key=-6. It is a L1 invalidation or a normal put and no tracking is enabled!
11:05:29,098 TRACE [org.infinispan.container.entries.ReadCommittedEntry] (default task-2) Updating entry (key=-6 removed=true valid=false changed=true created=false value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true} metadata=EmbeddedMaxIdleExpirableMetadata{maxIdle=60000, version=null}, providedMetadata=null)
11:05:29,098 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-2) The return value is true
11:05:29,098 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-2) Release locks for keys=[-6]. owner=CommandUUID{address=Local Address, id=216}
11:05:29,098 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Release lock for CommandUUID{address=Local Address, id=216}.
11:05:29,098 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) State changed for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=216}}. ACQUIRED => RELEASED
11:05:29,098 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Release lock for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=216}}? true
11:05:29,098 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Try acquire. Next in queue=null. Current=LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=216}}
11:05:29,098 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Lock Owner CAS(LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=216}}, null) => true
11:05:29,099 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-2) Try acquire. Next in queue=null. Current=null
11:05:29,108 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-2) Caching query results in region: opencell.war#MeveoAdmin.org.hibernate.cache.internal.StandardQueryCache; timestamp=1508940328742
11:05:29,108 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-2) key.hashCode=1031932438
11:05:29,108 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-2) querySpaces=null
11:05:29,108 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-2) unexpected returnTypes is typename=org.meveo.model.shared.Title class="org".meveo.model.shared.Title ! result
11:05:29,111 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-2) tuple is Object[1]; returnTypes is Type[1]
11:05:29,129 TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] (default task-2) beforeCompletion called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@7
11:05:29,129 TRACE [org.infinispan.transaction.impl.TransactionCoordinator] (default task-2) Received prepare for tx: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@7. Skipping call as 1PC will be used.
11:05:29,132 TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] (default task-2) afterCompletion(3) called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@7.
11:05:29,133 TRACE [org.infinispan.transaction.impl.TransactionCoordinator] (default task-2) Committing transaction GlobalTransaction:<null>:7:local
11:05:29,133 TRACE [org.infinispan.transaction.impl.TransactionCoordinator] (default task-2) Doing an 1PC prepare call on the interceptor chain
11:05:29,133 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-2) Invoked with command PrepareCommand {modifications=null, onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<null>:7:local, cacheName='opencell.war#MeveoAdmin.org.meveo.model.shared.Title', topologyId=-1} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@374d8012]
11:05:29,134 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-2) Suppressing invocation of method handlePrepareCommand.
11:05:29,134 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-2) Release locks for keys=[]. owner=GlobalTransaction:<null>:7:local
11:05:29,134 TRACE [org.infinispan.transaction.impl.AbstractCacheTransaction] (default task-2) Clearing locked keys: []
11:05:29,134 TRACE [org.infinispan.transaction.impl.TransactionTable] (default task-2) Removed LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@7 from transaction table.
11:05:29,134 TRACE [org.infinispan.transaction.impl.AbstractCacheTransaction] (default task-2) Transaction GlobalTransaction:<null>:7:local has completed, notifying listening threads.
11:05:29,134 TRACE [org.infinispan.transaction.impl.AbstractEnlistmentAdapter] (default task-2) Committed in onePhase? true isOptimistic? false
11:05:29,136 TRACE [org.infinispan.container.DefaultDataContainer] (default task-2) Store TransientCacheEntry{key=sql: select title0_.id as id1_34_, title0_.created as created2_34_, title0_.creator as creator3_34_, title0_.updated as updated4_34_, title0_.updater as updater5_34_, title0_.code as code6_34_, title0_.description as descript7_34_, title0_.disabled as disabled8_34_, title0_.is_company as is_compa9_34_, title0_.version as version10_34_ from adm_title title0_ where upper(title0_.code)=?; parameters: ; named parameters: {code=DR}; max rows: 1; transformer: org.hibernate.transform.CacheableResultTransformer@110f2, value=[1508940328742, -6]} in container
11:05:29,139 DEBUG [org.meveo.api.logging.WsRestApiInterceptor] (default task-2) Finished method org.meveo.api.ws.impl.AccountWsImpl.findTitle
11:05:29,139 DEBUG [org.meveo.api.logging.WsRestApiInterceptor] (default task-2) Finished method org.meveo.api.ws.impl.AccountWsImpl.findTitle
11:05:29,273 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-2) Session Metrics {
    19672611 nanoseconds spent acquiring 2 JDBC connections;
    4788185 nanoseconds spent releasing 2 JDBC connections;
    23667370 nanoseconds spent preparing 1 JDBC statements;
    109154433 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    83715474 nanoseconds spent performing 2 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    3815548 nanoseconds spent performing 1 L2C misses;
    17255623 nanoseconds spent executing 2 flushes (flushing a total of 2 entities and 0 collections);
    30790 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Second call - cache hit

11:05:44,808 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-3) Checking cached query results in region: opencell.war#MeveoAdmin.org.hibernate.cache.internal.StandardQueryCache
11:05:44,810 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-3) key.hashCode=1031932438
11:05:44,810 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-3) querySpaces=[adm_title]
11:05:44,810 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-3) unexpected returnTypes is typename=org.meveo.model.shared.Title class="org".meveo.model.shared.Title ! result
11:05:44,810 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-3) Checking query spaces are up-to-date: [adm_title]
11:05:44,817 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-3) Returning cached query results
11:05:44,821 TRACE [org.infinispan.transaction.impl.TransactionTable] (default task-3) Created a new local transaction: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@8
11:05:44,821 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-3) Invoked with command GetKeyValueCommand {key=-6, flags=null} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@f7033e9]
11:05:44,821 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-3) Exists in context? null
11:05:44,821 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-3) Retrieved from container TransientCacheEntry{key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@10ad4b0c,DR,Dr,false,false,1]} (ignoreOwnership=false, isLocal=true)
11:05:44,829 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-3) Wrap -6 for read. Entry=TransientCacheEntry{key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@10ad4b0c,DR,Dr,false,false,1]}
11:05:44,829 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-3) Executing command: GetKeyValueCommand {key=-6, flags=null}.
11:05:44,835 TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] (default task-3) beforeCompletion called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@8
11:05:44,835 TRACE [org.infinispan.transaction.impl.TransactionCoordinator] (default task-3) Received prepare for tx: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@8. Skipping call as 1PC will be used.
11:05:44,835 TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] (default task-3) afterCompletion(3) called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@8.
11:05:44,835 TRACE [org.infinispan.transaction.impl.TransactionCoordinator] (default task-3) Committing transaction GlobalTransaction:<null>:8:local
11:05:44,835 TRACE [org.infinispan.transaction.impl.TransactionCoordinator] (default task-3) Doing an 1PC prepare call on the interceptor chain
11:05:44,835 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-3) Invoked with command PrepareCommand {modifications=null, onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<null>:8:local, cacheName='opencell.war#MeveoAdmin.org.meveo.model.shared.Title', topologyId=-1} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@14741e72]
11:05:44,835 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-3) Suppressing invocation of method handlePrepareCommand.
11:05:44,838 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-3) Entry for key -6 is not changed(TransientCacheEntry{key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@10ad4b0c,DR,Dr,false,false,1]}): not calling commitUpdate
11:05:44,838 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-3) Release locks for keys=[]. owner=GlobalTransaction:<null>:8:local
11:05:44,839 TRACE [org.infinispan.transaction.impl.AbstractCacheTransaction] (default task-3) Clearing locked keys: []
11:05:44,839 TRACE [org.infinispan.transaction.impl.TransactionTable] (default task-3) Removed LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@8 from transaction table.
11:05:44,839 TRACE [org.infinispan.transaction.impl.AbstractCacheTransaction] (default task-3) Transaction GlobalTransaction:<null>:8:local has completed, notifying listening threads.
11:05:44,839 TRACE [org.infinispan.transaction.impl.AbstractEnlistmentAdapter] (default task-3) Committed in onePhase? true isOptimistic? false
11:05:44,839 DEBUG [org.meveo.api.logging.WsRestApiInterceptor] (default task-3) Finished method org.meveo.api.ws.impl.AccountWsImpl.findTitle
11:05:44,839 DEBUG [org.meveo.api.logging.WsRestApiInterceptor] (default task-3) Finished method org.meveo.api.ws.impl.AccountWsImpl.findTitle
11:05:44,842 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-3) 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;
    9873608 nanoseconds spent performing 2 L2C hits;
    2056196 nanoseconds spent performing 1 L2C misses;
    795795 nanoseconds spent executing 2 flushes (flushing a total of 2 entities and 0 collections);
    5921 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Third call - cache miss 2 minutes later

11:08:32,441 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-4) Checking cached query results in region: opencell.war#MeveoAdmin.org.hibernate.cache.internal.StandardQueryCache
11:08:32,441 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-4) key.hashCode=1031932438
11:08:32,441 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-4) querySpaces=[adm_title]
11:08:32,441 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-4) unexpected returnTypes is typename=org.meveo.model.shared.Title class="org".meveo.model.shared.Title ! result
11:08:32,441 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-4) Query results were not found in cache
11:08:32,441 DEBUG [org.hibernate.SQL] (default task-4) select title0_.id as id1_34_, title0_.created as created2_34_, title0_.creator as creator3_34_, title0_.updated as updated4_34_, title0_.updater as updater5_34_, title0_.code as code6_34_, title0_.description as descript7_34_, title0_.disabled as disabled8_34_, title0_.is_company as is_compa9_34_, title0_.version as version10_34_ from adm_title title0_ where upper(title0_.code)=? limit ?
11:08:32,445 TRACE [org.infinispan.transaction.impl.TransactionTable] (default task-4) Created a new local transaction: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@9
11:08:32,445 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-4) Invoked with command GetKeyValueCommand {key=-6, flags=null} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@53a95fb2]
11:08:32,445 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Exists in context? null
11:08:32,445 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Retrieved from container null (ignoreOwnership=false, isLocal=true)
11:08:32,445 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Wrap -6 for read. Entry=null
11:08:32,445 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-4) Executing command: GetKeyValueCommand {key=-6, flags=null}.
11:08:32,445 TRACE [org.infinispan.commands.read.GetKeyValueCommand] (default task-4) Entry not found
11:08:32,445 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-4) acquirePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, 1508940512440)
11:08:32,445 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-4) Invoked with command GetKeyValueCommand {key=-6, flags=null} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@1ef6a4]
11:08:32,446 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Exists in context? null
11:08:32,446 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Retrieved from container null (ignoreOwnership=false, isLocal=true)
11:08:32,446 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Wrap -6 for read. Entry=null
11:08:32,446 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-4) Executing command: GetKeyValueCommand {key=-6, flags=null}.
11:08:32,446 TRACE [org.infinispan.commands.read.GetKeyValueCommand] (default task-4) Entry not found
11:08:32,446 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-4) Release locks for keys=[]. owner=null
11:08:32,446 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-4) Region invalidated at -9223372036854775808, this transaction started at 1508940512440
11:08:32,446 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-4) Invoked with command PutKeyValueCommand{key=-6, value={ PendingPuts=[R@Session#1545005284], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, flags=null, putIfAbsent=true, valueMatcher=MATCH_EXPECTED, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@7fb3d52d]
11:08:32,446 TRACE [org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor] (default task-4) Are (Local Address) we the lock owners for key '-6'? true
11:08:32,446 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-4) Lock key=-6 for owner=CommandUUID{address=Local Address, id=217}. timeout=10000 (MILLISECONDS)
11:08:32,446 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Acquire lock for CommandUUID{address=Local Address, id=217}. Timeout=10000 (MILLISECONDS)
11:08:32,446 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Created a new one: LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=217}}
11:08:32,447 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=217}}. Current=null
11:08:32,447 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Lock Owner CAS(null, LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=217}}) => true
11:08:32,447 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) State changed for LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=217}}. WAITING => ACQUIRED
11:08:32,447 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=217}} successfully acquired the lock.
11:08:32,447 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-4) Wrapping entry '-6'? true
11:08:32,447 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Exists in context? null
11:08:32,447 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Retrieved from container null (ignoreOwnership=false, isLocal=true)
11:08:32,447 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Creating new entry for key -6
11:08:32,447 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Updated context entry ReadCommittedEntry(6e40e475){key=-6, value=null, oldValue=null, isCreated=true, isChanged=false, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=null}
11:08:32,447 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-4) Executing command: PutKeyValueCommand{key=-6, value={ PendingPuts=[R@Session#1545005284], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, flags=null, putIfAbsent=true, valueMatcher=MATCH_EXPECTED, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}, successful=true}.
11:08:32,447 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-4) About to commit entry ReadCommittedEntry(6e40e475){key=-6, value={ PendingPuts=[R@Session#1545005284], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}}
11:08:32,447 TRACE [org.infinispan.statetransfer.CommitManager] (default task-4) Trying to commit. Key=-6. Operation Flag=null, L1 invalidation=false
11:08:32,447 TRACE [org.infinispan.statetransfer.CommitManager] (default task-4) Committing key=-6. It is a L1 invalidation or a normal put and no tracking is enabled!
11:08:32,447 TRACE [org.infinispan.container.entries.ReadCommittedEntry] (default task-4) Updating entry (key=-6 removed=false valid=true changed=true created=true value={ PendingPuts=[R@Session#1545005284], Invalidators=[], LastInvalidationEnd=<none>, Removed=false} metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null})
11:08:32,448 TRACE [org.infinispan.container.DefaultDataContainer] (default task-4) Creating new ICE for writing. Existing=null, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=60000, version=null}, new value={ PendingPuts=[R@Session#1545005284], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}
11:08:32,448 TRACE [org.infinispan.container.DefaultDataContainer] (default task-4) Store TransientCacheEntry{key=-6, value={ PendingPuts=[R@Session#1545005284], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}} in container
11:08:32,448 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-4) The return value is null
11:08:32,448 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-4) Release locks for keys=[-6]. owner=CommandUUID{address=Local Address, id=217}
11:08:32,448 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Release lock for CommandUUID{address=Local Address, id=217}.
11:08:32,448 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) State changed for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=217}}. ACQUIRED => RELEASED
11:08:32,448 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Release lock for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=217}}? true
11:08:32,448 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Try acquire. Next in queue=null. Current=LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=217}}
11:08:32,448 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Lock Owner CAS(LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=217}}, null) => true
11:08:32,448 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Try acquire. Next in queue=null. Current=null
11:08:32,448 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-4) acquirePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, 1508940512440) ended with { PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=false}, valid: true
11:08:32,449 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-4) Invoked with command PutKeyValueCommand{key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@778d62c0,DR,Dr,false,false,1], flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, FAIL_SILENTLY, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ, IGNORE_RETURN_VALUES], putIfAbsent=true, valueMatcher=MATCH_EXPECTED, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@511143]
11:08:32,449 TRACE [org.infinispan.interceptors.locking.PessimisticLockingInterceptor] (default task-4) Are (Local Address) we the lock owners for key '-6'? true
11:08:32,449 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-4) Lock key=-6 for owner=CommandUUID{address=Local Address, id=218}. timeout=0 (MILLISECONDS)
11:08:32,449 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Acquire lock for CommandUUID{address=Local Address, id=218}. Timeout=0 (MILLISECONDS)
11:08:32,449 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Created a new one: LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=218}}
11:08:32,449 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=218}}. Current=null
11:08:32,449 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Lock Owner CAS(null, LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=218}}) => true
11:08:32,449 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) State changed for LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=218}}. WAITING => ACQUIRED
11:08:32,449 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=218}} successfully acquired the lock.
11:08:32,449 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-4) Wrapping entry '-6'? true
11:08:32,449 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Exists in context? null
11:08:32,449 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Retrieved from container null (ignoreOwnership=false, isLocal=true)
11:08:32,449 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Creating new entry for key -6
11:08:32,450 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Updated context entry ReadCommittedEntry(61aab6d9){key=-6, value=null, oldValue=null, isCreated=true, isChanged=false, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=null}
11:08:32,450 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-4) Executing command: PutKeyValueCommand{key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@778d62c0,DR,Dr,false,false,1], flags=[ZERO_LOCK_ACQUISITION_TIMEOUT, FORCE_ASYNCHRONOUS, SKIP_CACHE_LOAD, FAIL_SILENTLY, SKIP_REMOTE_LOOKUP, PUT_FOR_EXTERNAL_READ, IGNORE_RETURN_VALUES], putIfAbsent=true, valueMatcher=MATCH_EXPECTED, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, successful=true}.
11:08:32,450 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-4) About to commit entry ReadCommittedEntry(61aab6d9){key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@778d62c0,DR,Dr,false,false,1], oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}}
11:08:32,450 TRACE [org.infinispan.statetransfer.CommitManager] (default task-4) Trying to commit. Key=-6. Operation Flag=null, L1 invalidation=false
11:08:32,450 TRACE [org.infinispan.statetransfer.CommitManager] (default task-4) Committing key=-6. It is a L1 invalidation or a normal put and no tracking is enabled!
11:08:32,450 TRACE [org.infinispan.container.entries.ReadCommittedEntry] (default task-4) Updating entry (key=-6 removed=false valid=true changed=true created=true value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@778d62c0,DR,Dr,false,false,1] metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null})
11:08:32,450 TRACE [org.infinispan.container.DefaultDataContainer] (default task-4) Creating new ICE for writing. Existing=null, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=100000, version=null}, new value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@778d62c0,DR,Dr,false,false,1]
11:08:32,450 TRACE [org.infinispan.container.DefaultDataContainer] (default task-4) Store TransientCacheEntry{key=-6, value=CacheEntry(org.meveo.model.shared.Title)[[Ljava.lang.Object;@778d62c0,DR,Dr,false,false,1]} in container
11:08:32,450 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-4) The return value is null
11:08:32,450 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-4) Release locks for keys=[-6]. owner=CommandUUID{address=Local Address, id=218}
11:08:32,450 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Release lock for CommandUUID{address=Local Address, id=218}.
11:08:32,450 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) State changed for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=218}}. ACQUIRED => RELEASED
11:08:32,450 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Release lock for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=218}}? true
11:08:32,450 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Try acquire. Next in queue=null. Current=LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=218}}
11:08:32,450 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Lock Owner CAS(LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=218}}, null) => true
11:08:32,451 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Try acquire. Next in queue=null. Current=null
11:08:32,451 TRACE [org.hibernate.cache.infinispan.access.PutFromLoadValidator] (default task-4) releasePutFromLoadLock(opencell.war#MeveoAdmin.org.meveo.model.shared.Title#-6, { PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=false})
11:08:32,451 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-4) Invoked with command RemoveCommand{key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, flags=null, valueMatcher=MATCH_EXPECTED} and InvocationContext [org.infinispan.context.SingleKeyNonTxInvocationContext@82085d5]
11:08:32,451 TRACE [org.infinispan.interceptors.locking.NonTransactionalLockingInterceptor] (default task-4) Are (Local Address) we the lock owners for key '-6'? true
11:08:32,451 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-4) Lock key=-6 for owner=CommandUUID{address=Local Address, id=219}. timeout=10000 (MILLISECONDS)
11:08:32,451 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Acquire lock for CommandUUID{address=Local Address, id=219}. Timeout=10000 (MILLISECONDS)
11:08:32,451 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Created a new one: LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=219}}
11:08:32,451 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Try acquire. Next in queue=LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=219}}. Current=null
11:08:32,451 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Lock Owner CAS(null, LockPlaceHolder{lockState=WAITING, owner=CommandUUID{address=Local Address, id=219}}) => true
11:08:32,451 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) State changed for LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=219}}. WAITING => ACQUIRED
11:08:32,451 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) LockPlaceHolder{lockState=ACQUIRED, owner=CommandUUID{address=Local Address, id=219}} successfully acquired the lock.
11:08:32,451 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-4) Wrapping entry '-6'? true
11:08:32,451 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Exists in context? null
11:08:32,451 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Retrieved from container TransientCacheEntry{key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}} (ignoreOwnership=false, isLocal=true)
11:08:32,451 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Creating new entry for key -6
11:08:32,451 TRACE [org.infinispan.container.EntryFactoryImpl] (default task-4) Updated context entry ReadCommittedEntry(14a77d73){key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, oldValue=null, isCreated=false, isChanged=false, isRemoved=false, isValid=true, isExpired=false, skipRemoteGet=false, metadata=EmbeddedMaxIdleExpirableMetadata{maxIdle=60000, version=null}}
11:08:32,451 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-4) Executing command: RemoveCommand{key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, flags=null, valueMatcher=MATCH_EXPECTED}.
11:08:32,451 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-4) About to commit entry ReadCommittedEntry(14a77d73){key=-6, value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, oldValue={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true}, isCreated=false, isChanged=true, isRemoved=true, isValid=false, isExpired=false, skipRemoteGet=false, metadata=EmbeddedMaxIdleExpirableMetadata{maxIdle=60000, version=null}}
11:08:32,452 TRACE [org.infinispan.statetransfer.CommitManager] (default task-4) Trying to commit. Key=-6. Operation Flag=null, L1 invalidation=false
11:08:32,452 TRACE [org.infinispan.statetransfer.CommitManager] (default task-4) Committing key=-6. It is a L1 invalidation or a normal put and no tracking is enabled!
11:08:32,452 TRACE [org.infinispan.container.entries.ReadCommittedEntry] (default task-4) Updating entry (key=-6 removed=true valid=false changed=true created=false value={ PendingPuts=[], Invalidators=[], LastInvalidationEnd=<none>, Removed=true} metadata=EmbeddedMaxIdleExpirableMetadata{maxIdle=60000, version=null}, providedMetadata=null)
11:08:32,452 TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] (default task-4) The return value is true
11:08:32,452 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-4) Release locks for keys=[-6]. owner=CommandUUID{address=Local Address, id=219}
11:08:32,452 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Release lock for CommandUUID{address=Local Address, id=219}.
11:08:32,452 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) State changed for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=219}}. ACQUIRED => RELEASED
11:08:32,452 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Release lock for LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=219}}? true
11:08:32,452 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Try acquire. Next in queue=null. Current=LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=219}}
11:08:32,452 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Lock Owner CAS(LockPlaceHolder{lockState=RELEASED, owner=CommandUUID{address=Local Address, id=219}}, null) => true
11:08:32,452 TRACE [org.infinispan.util.concurrent.locks.impl.InfinispanLock] (default task-4) Try acquire. Next in queue=null. Current=null
11:08:32,452 DEBUG [org.hibernate.cache.internal.StandardQueryCache] (default task-4) Caching query results in region: opencell.war#MeveoAdmin.org.hibernate.cache.internal.StandardQueryCache; timestamp=1508940512440
11:08:32,452 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-4) key.hashCode=1031932438
11:08:32,452 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-4) querySpaces=null
11:08:32,453 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-4) unexpected returnTypes is typename=org.meveo.model.shared.Title class="org".meveo.model.shared.Title ! result
11:08:32,453 TRACE [org.hibernate.cache.internal.StandardQueryCache] (default task-4) tuple is Object[1]; returnTypes is Type[1]
11:08:32,454 TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] (default task-4) beforeCompletion called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@9
11:08:32,454 TRACE [org.infinispan.transaction.impl.TransactionCoordinator] (default task-4) Received prepare for tx: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@9. Skipping call as 1PC will be used.
11:08:32,455 TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] (default task-4) afterCompletion(3) called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@9.
11:08:32,455 TRACE [org.infinispan.transaction.impl.TransactionCoordinator] (default task-4) Committing transaction GlobalTransaction:<null>:9:local
11:08:32,455 TRACE [org.infinispan.transaction.impl.TransactionCoordinator] (default task-4) Doing an 1PC prepare call on the interceptor chain
11:08:32,455 TRACE [org.infinispan.interceptors.InvocationContextInterceptor] (default task-4) Invoked with command PrepareCommand {modifications=null, onePhaseCommit=true, retried=false, gtx=GlobalTransaction:<null>:9:local, cacheName='opencell.war#MeveoAdmin.org.meveo.model.shared.Title', topologyId=-1} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@285cdc94]
11:08:32,455 TRACE [org.infinispan.interceptors.CallInterceptor] (default task-4) Suppressing invocation of method handlePrepareCommand.
11:08:32,455 TRACE [org.infinispan.util.concurrent.locks.impl.DefaultLockManager] (default task-4) Release locks for keys=[]. owner=GlobalTransaction:<null>:9:local
11:08:32,455 TRACE [org.infinispan.transaction.impl.AbstractCacheTransaction] (default task-4) Clearing locked keys: []
11:08:32,455 TRACE [org.infinispan.transaction.impl.TransactionTable] (default task-4) Removed LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[], backupKeyLocks=[], topologyId=-1, stateTransferFlag=null} org.infinispan.transaction.synchronization.SyncLocalTransaction@9 from transaction table.
11:08:32,456 TRACE [org.infinispan.transaction.impl.AbstractCacheTransaction] (default task-4) Transaction GlobalTransaction:<null>:9:local has completed, notifying listening threads.
11:08:32,456 TRACE [org.infinispan.transaction.impl.AbstractEnlistmentAdapter] (default task-4) Committed in onePhase? true isOptimistic? false
11:08:32,456 TRACE [org.infinispan.container.DefaultDataContainer] (default task-4) Store TransientCacheEntry{key=sql: select title0_.id as id1_34_, title0_.created as created2_34_, title0_.creator as creator3_34_, title0_.updated as updated4_34_, title0_.updater as updater5_34_, title0_.code as code6_34_, title0_.description as descript7_34_, title0_.disabled as disabled8_34_, title0_.is_company as is_compa9_34_, title0_.version as version10_34_ from adm_title title0_ where upper(title0_.code)=?; parameters: ; named parameters: {code=DR}; max rows: 1; transformer: org.hibernate.transform.CacheableResultTransformer@110f2, value=[1508940512440, -6]} in container
11:08:32,456 DEBUG [org.meveo.api.logging.WsRestApiInterceptor] (default task-4) Finished method org.meveo.api.ws.impl.AccountWsImpl.findTitle
11:08:32,457 DEBUG [org.meveo.api.logging.WsRestApiInterceptor] (default task-4) Finished method org.meveo.api.ws.impl.AccountWsImpl.findTitle
11:08:32,458 INFO  [org.hibernate.engine.internal.StatisticalLoggingSessionEventListener] (default task-4) Session Metrics {
    1017638 nanoseconds spent acquiring 2 JDBC connections;
    89211 nanoseconds spent releasing 2 JDBC connections;
    1009743 nanoseconds spent preparing 1 JDBC statements;
    1600273 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    7635043 nanoseconds spent performing 2 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    21710 nanoseconds spent performing 1 L2C misses;
    1320401 nanoseconds spent executing 2 flushes (flushing a total of 2 entities and 0 collections);
    6711 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

[galder.zamarreno]

Hey, don't see what could be wrong here. One thing to note about stats is that they're cumulative unless you reset them, so if you do a get and you get 1 miss, next time you do a get you'll get a hit but the miss will still be there. The easiest thing here might be for you to walk through the code with a remote debugger and see why/where counts are incremented.

[entwik]

We had the same issue and managed to resolve it as follows:

* Add transaction configuration to infinispan

* Make sure query runs within a transaction

The reason is that Infinispan Hibernate cache uses a post-tx hook to actually put value in cache. This is to ensure the value isn't put to cache on TX rollback. So, if there's no TX, the value never goes into cache.

Checked against org.infinispan:infinispan-hibernate-cache-v53:9.4.1.Final. See org.infinispan.hibernate.cache.v53.impl.QueryResultsRegionImpl.PostTransactionQueryUpdate.

[galder.zamarreno]

Your issue is different but also known ( ISPN-9677 ) will be fixed in 9.4.2

[galder.zamarreno]

Actually, there was an oversight and didn't go into 9.4.2. It'll be part of 9.4.3. If you want to try the fix today, you can try to use 10.0.0.Alpha1