HHH-12457 Local Infinispan read-write caches become stale on rollback #6010

rvansa · 2018-05-24T10:52:10Z

https://hibernate.atlassian.net/browse/HHH-12457

Backport #5970 already integrated, but this has dependency to #5954 and #5964

https://issues.jboss.org/browse/ISPN-9205 which was introduced in the backport is fixed here.

tristantarrant · 2018-05-25T08:49:21Z

Needs rebase

galderz · 2018-06-14T10:26:04Z

@rvansa Needs rebasing

rvansa · 2018-06-14T10:41:15Z

@galderz Done

galderz

Some comments

galderz · 2018-06-15T13:26:55Z

...main/java/org/infinispan/hibernate/cache/commons/access/InvalidationCacheAccessDelegate.java

@@ -21,7 +21,7 @@
 */
 public abstract class InvalidationCacheAccessDelegate implements AccessDelegate {
 	protected static final InfinispanMessageLogger log = InfinispanMessageLogger.Provider.getLog( InvalidationCacheAccessDelegate.class );
-	protected static final boolean TRACE_ENABLED = log.isTraceEnabled();
+	protected static final boolean trace = log.isTraceEnabled();


Unnecessary ;)

why? trace is used later on...

Unnecessary refactoring of the name ;)

galderz · 2018-06-15T13:27:23Z

...src/main/java/org/infinispan/hibernate/cache/commons/access/InvalidationSynchronization.java

@@ -32,7 +30,6 @@ public void beforeCompletion() {}

 	@Override
 	public void afterCompletion(int status) {
-      log.tracef("After completion callback with status %d", status);


Why remove log message?

I didn't find it too useful, and to keep it symmetric with LocalInvalidationSynchronization.

I found it useful when debugging ISPN-8026. PFLValidator's endInvalidatingKey can be called from multiple places. This log message clarified for me what the origin of the end invalidation message was.

Ok, I'll put that back then to both places.

galderz · 2018-06-15T13:40:46Z

.../cache-v53/src/main/java/org/infinispan/hibernate/cache/v53/impl/FutureUpdateInvocation.java

+      // Exceptions in #afterCompletion() are silently ignored, since the transaction
+      // is already committed in DB. However we must not return until we update the cache.
+      FutureUpdate futureUpdate = new FutureUpdate(uuid, region.nextTimestamp(), success ? this.value : null);
+      for (;;) {


Could this get noisy? Couldn't we just remove the remove the entry from the cache if we have any issues (and log those silently) rather than trying until it works?

A removal is as likely to fail as any other update.

galderz · 2018-06-15T13:43:37Z

.../main/java/org/infinispan/hibernate/cache/v53/impl/NonTxInvalidationCacheAccessDelegate.java

+         sync.registerBeforeCommit(future);
+      } else {
+         log.trace("Removal was not applied immediatelly, waiting.");
+         future.join();


How long does this wait for? Endlessly?

As long as any sync command would - a combination of locking timeouts and rpc timeouts. But not endlessly.

galderz · 2018-06-15T13:45:01Z

hibernate/cache-v53/src/main/java/org/infinispan/hibernate/cache/v53/impl/Sync.java

+         Object task = tasks[i];
+         if (task instanceof CompletableFuture) {
+            try {
+               ((CompletableFuture) task).join();


Same thing about this join too

galderz · 2018-06-15T13:45:13Z

hibernate/cache-v53/src/main/java/org/infinispan/hibernate/cache/v53/impl/Sync.java

+         CompletableFuture<?> cf = (CompletableFuture<?>) tasks[i];
+         if (cf != null) {
+            try {
+               cf.join();


galderz · 2018-06-15T13:46:07Z

...cache-v53/src/main/java/org/infinispan/hibernate/cache/v53/impl/TombstoneAccessDelegate.java

+         log.trace("Tombstone was not applied immediatelly, waiting.");
+         // Slow path: there's probably a locking conflict and we need to wait
+         // until the command gets applied (and replicated, too!).
+         future.join();


rvansa · 2018-06-27T13:10:54Z

Rebased, still on top of #5964 (that should go in first).

galderz · 2018-07-10T08:09:33Z

Needs rebasing

rvansa · 2018-07-12T14:24:30Z

Rebased. There's one test failure in 2LC, though it's not in local mode...

galderz · 2018-07-13T14:09:35Z

If there's a failure this is not ready.

galderz · 2018-07-13T14:13:10Z

To be clear: I've spent a lot of time in the past year removing all random failures in 2LC testsuite. Regardless the failure is related to the change or not, the moment one appears it needs to be resolved there and then. Otherwise the changes don't go in.

rvansa · 2018-08-16T06:36:31Z

@galderz Forum reference: https://developer.jboss.org/message/984624

I am scheduled to other tasks right now but if you could get a trace log from the failing test I could take a peek for couple of hours.

galderz · 2018-08-20T12:35:28Z

@rvansa I'll handle this, thx

diegolovison · 2018-08-20T18:33:40Z

...e-v53/src/main/java/org/infinispan/hibernate/cache/v53/impl/LocalInvalidationInvocation.java

+   @Override
+   public CompletableFuture<Void> invoke(boolean success) {
+      if (trace) {
+         log.tracef("After completion callback, success=%d", success);


It should be success=%b

diegolovison · 2018-08-20T18:39:17Z

.../cache-v53/src/main/java/org/infinispan/hibernate/cache/v53/impl/InvalidationInvocation.java

@@ -31,7 +33,9 @@ public InvalidationInvocation(NonTxPutFromLoadInterceptor nonTxPutFromLoadInterc

   @Override
   public CompletableFuture<Void> invoke(boolean success) {
-      log.tracef("After completion callback, success? %s", success);
+      if (trace) {
+         log.tracef("After completion callback, success=%d", success);


It should be success=%b

* Also making sure that we use simple cache and not the async chain directly in local mode Signed-off-by: Radim Vansa <rvansa@redhat.com>

pruivo · 2018-08-24T10:17:25Z

@rvansa @galderz is this ready for this week release? or it will be moved to the next one?

rvansa · 2018-08-24T11:58:58Z

@pruivo Galder has reservations since we've seen random failure in the CI on this PR. There's a good chance that it's not related but Galder gave it red and I was not able to reproduce it.

galderz · 2018-08-24T12:16:23Z

@pruivo @rvansa I've been running the 5.1 testsuite continuously with TRACE for several days and I've not seen it fail. I'll do one last check of the PR and if it looks good integrate it.

galderz added the Needs Rebase label Jun 14, 2018

rvansa force-pushed the HHH-12457 branch from 4c8a60f to 2832c1e Compare June 14, 2018 10:40

rvansa removed the Needs Rebase label Jun 14, 2018

galderz reviewed Jun 15, 2018

View reviewed changes

galderz mentioned this pull request Jun 15, 2018

ISPN-9075 Leverage CacheTransactionSynchronization #5964

Merged

tristantarrant added this to the 9.4.0.Alpha1 milestone Jun 21, 2018

rvansa force-pushed the HHH-12457 branch from 2832c1e to 3933d7f Compare June 27, 2018 13:00

rvansa force-pushed the HHH-12457 branch 4 times, most recently from feb8c27 to 79c7c87 Compare July 11, 2018 15:04

tristantarrant modified the milestones: 9.4.0.Alpha1, 9.4.0.Beta1 Jul 18, 2018

galderz added the Changes Required label Aug 1, 2018

pruivo modified the milestones: 9.4.0.Beta1, 9.4.0.CR1 Aug 3, 2018

diegolovison reviewed Aug 20, 2018

View reviewed changes

This comment has been minimized.

Sign in to view

rvansa added 2 commits August 21, 2018 10:45

HHH-12457 Reproducer

9d76626

HHH-12457 Local Infinispan read-write caches become stale on rollback

18aade2

* Also making sure that we use simple cache and not the async chain directly in local mode Signed-off-by: Radim Vansa <rvansa@redhat.com>

rvansa force-pushed the HHH-12457 branch from 79c7c87 to 18aade2 Compare August 21, 2018 11:19

galderz merged commit 921d082 into infinispan:master Aug 24, 2018

rvansa mentioned this pull request Nov 15, 2018

[9.3.x] ISPN-9075 + HHH-12457 Local Infinispan read-write caches become stale on rollback #6409

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

HHH-12457 Local Infinispan read-write caches become stale on rollback #6010

HHH-12457 Local Infinispan read-write caches become stale on rollback #6010

rvansa commented May 24, 2018 •

edited

tristantarrant commented May 25, 2018

galderz commented Jun 14, 2018

rvansa commented Jun 14, 2018

galderz left a comment

galderz Jun 15, 2018

rvansa Jun 27, 2018

galderz Jun 28, 2018

galderz Jun 15, 2018

rvansa Jun 27, 2018

galderz Jun 28, 2018

rvansa Jun 28, 2018

galderz Jun 15, 2018

rvansa Jun 27, 2018

galderz Jun 28, 2018

galderz Jun 15, 2018

rvansa Jun 27, 2018

galderz Jun 15, 2018

galderz Jun 15, 2018

galderz Jun 15, 2018

rvansa commented Jun 27, 2018

galderz commented Jul 10, 2018

rvansa commented Jul 12, 2018

galderz commented Jul 13, 2018

galderz commented Jul 13, 2018

rvansa commented Aug 16, 2018

galderz commented Aug 20, 2018

diegolovison Aug 20, 2018

diegolovison Aug 20, 2018

This comment has been minimized.

pruivo commented Aug 24, 2018

rvansa commented Aug 24, 2018

galderz commented Aug 24, 2018

HHH-12457 Local Infinispan read-write caches become stale on rollback #6010

HHH-12457 Local Infinispan read-write caches become stale on rollback #6010

Conversation

rvansa commented May 24, 2018 • edited

tristantarrant commented May 25, 2018

galderz commented Jun 14, 2018

rvansa commented Jun 14, 2018

galderz left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rvansa commented Jun 27, 2018

galderz commented Jul 10, 2018

rvansa commented Jul 12, 2018

galderz commented Jul 13, 2018

galderz commented Jul 13, 2018

rvansa commented Aug 16, 2018

galderz commented Aug 20, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

This comment has been minimized.

pruivo commented Aug 24, 2018

rvansa commented Aug 24, 2018

galderz commented Aug 24, 2018

rvansa commented May 24, 2018 •

edited