[hibernate-dev] Regression in AS7 (master) cluster cache invalidation test after moving from Hibernate ORM 4.1.6 to 4.1.9

[Scott Marlow]

I'm now on the path of trying to clean the test up to make fewer 
assumptions about whether loading an entity locally will share the 
loaded value across the cluster with other nodes 2lc.  Perhaps we have 
optimized the cache to only load locally and still invalidate across the 
cluster.

Scott

On 12/14/2012 11:52 AM, Scott Marlow wrote:
> I'll add TRACE logging to
> org.hibernate.cache.infinispan.access.TransactionalAccessDelegate to
> show more information about what is going on in there when we fail to
> invalidate the 2lc on the other node.
>
> Any other ideas?
>
>
> On 12/14/2012 10:13 AM, Scott Marlow wrote:
>> On 12/14/2012 09:46 AM, Scott Marlow wrote:
>>> I enabled org.jboss.as.jpa TRACE logging as well as org.infinispan TRACE
>>> (I know overly verbose) logging.  Output is here
>>> http://dl.dropbox.com/u/35343318/jboss/serverlogs.zip
>>>
>>> In the node1 log, I see that we delete the entity and then try to
>>> perform the remove command.  I don't seem to see this command executed
>>> on node0:
>>>
>>> 09:10:22,416 INFO  [stdout] (http-/127.0.0.1:8180-1) Hibernate: delete
>>> from Employee where id=?
>>> ...
>>> 09:10:22,419 TRACE [org.infinispan.interceptors.CallInterceptor]
>>> (http-/127.0.0.1:8180-1) Executing command:
>>> RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1,
>>> value=null, flags=[CACHE_MODE_LOCAL, SKIP_CACHE_LOAD, SKIP_REMOTE_LOOKUP]}.
>>> ...
>>>
>>> I don't see anything in the node0 log about
>>> "RemoveCommand{key=org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee#1"
>>> being received or executed.
>>>
>>> Are there any other TRACE logging settings that I should enable?
>>>
>>> I'm going to make a small test change to show the 2lc cache statistics
>>> for node1 after the entity is deleted from the database.  The elementCountInMemory went from one to zero (as expected).
>>
>> The 2lc statistics on node1, show that the node1 2lc has been
>> invalidated to remove the deleted entity.
>>
>> 09:56:30,071 INFO  [stdout] (http-/127.0.0.1:8180-1) 2lc for
>> stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee:
>> SecondLevelCacheStatistics[hitCount=1,missCount=0,putCount=1,elementCountInMemory=0,elementCountOnDisk=-1,sizeInMemory=-1]
>>
>> Its node0, that didn't receive the "RemoveCommand" that also still has
>> the elementCountInMemory as one:
>>
>> 09:56:30,172 INFO  [stdout] (http-/127.0.0.1:8080-1) 2lc for
>> stateful.war#mypc.org.jboss.as.test.clustering.cluster.ejb3.xpc.bean.Employee:
>> SecondLevelCacheStatistics[hitCount=0,missCount=0,putCount=1,elementCountInMemory=1,elementCountOnDisk=-1,sizeInMemory=-1]
>>
>>
>>>
>>> Scott
>>>
>>> On 12/14/2012 12:03 AM, Scott Marlow wrote:
>>>> http://hudson.jboss.org/hudson/job/as7-param-pull/5123/ shows a failure
>>>> with the second level cache not being invalidated as expected across a
>>>> two node cluster.
>>>>
>>>> I'm able to reproduce locally, which is good.  We will continue to use
>>>> Hibernate 4.1.6 until we get past this regression (hopefully we can
>>>> understand the test failure cause soon).
>>>>
>>>> https://github.com/jbossas/jboss-as/blob/master/testsuite/integration/clust/src/test/java/org/jboss/as/test/clustering/cluster/ejb3/xpc/StatefulWithXPCFailoverTestCase.java#L276
>>>> is the line that is failing (yeah, the arguments to assertEquals are
>>>> backwards but that isn't the root issue ;)
>>>>
>>>> It is possible that its a bug in the test also.
>>>>
>>>> The cluster has two nodes, each with their own in-memory database.  The
>>>> test assumes that it can create the same entity on both nodes (same
>>>> primary key) and that for the purpose of testing the second level cache,
>>>> we can expect cache invalidation to occur on both nodes when deleting
>>>> the entity on one of the nodes.
>>>>
>>>> I believe that the cache invalidation should be synchronous but I'll
>>>> probably try adding a sleep to see if it could be an async/timing issue.
>>>>
>>>> I hope to have more information soon (probably in the morning on Friday).
>>>>
>>>> Scott
>>>> _______________________________________________
>>>> hibernate-dev mailing list
>>>> hibernate-dev at lists.jboss.org
>>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>>>
>>>
>>> _______________________________________________
>>> hibernate-dev mailing list
>>> hibernate-dev at lists.jboss.org
>>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>>
>>
>> _______________________________________________
>> hibernate-dev mailing list
>> hibernate-dev at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>>
>
> _______________________________________________
> hibernate-dev mailing list
> hibernate-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/hibernate-dev
>