Uploaded image for project: 'Infinispan'
  1. Infinispan
  2. ISPN-15196

SIFS ExpirationCompaction on logFile may not have updated index

    XMLWordPrintable

Details

    Description

      While running SIFSStressTest it was found that if the expiration compaction is ran and a log file is compacted, it can try to "compact" an entry that has been written in the log appender but not yet written to the temporary table in the index. When compacting a log file it should be ignored if the index is not present for a key as it is entirely possible for it to not be present yet.

      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t4:[]) [o.i.p.s.LogAppender] Appending records to 4
      13:25:50,825 TRACE (ForkThread-4,SoftIndexFileStoreStressTest:[]) [o.i.p.s.Compactor] Skipping expiration for file 2 since it is marked for deletion: false or its expiration time -1 is not yet
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t3:[]) [o.i.p.s.Compactor] Finished expiring entries in log file 3, leaving file as is
      13:25:50,825 TRACE (ForkThread-4,SoftIndexFileStoreStressTest:[]) [o.i.p.s.Compactor] Skipping expiration for file 3 since it is marked for deletion: false or its expiration time -1 is not yet
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t2:[]) [o.i.p.s.Index] Indexing IndexRequest{key=org.infinispan.persistence.sifs.Index$$Lambda$661/0x000000080121cef8@683f3d21, serializedKey=null, cacheSegment=-1, file=-1, offset=-1, prevFile=-1, prevOffset=-1, size=-1, type=SYNC_REQUEST}
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t4:[]) [o.i.p.s.LogAppender] Appending record to 4:0
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t2:[]) [o.i.u.c.NonBlockingManagerImpl] Future has no dependent, completing it in invoking thread
      13:25:50,825 TRACE (ForkThread-4,SoftIndexFileStoreStressTest:[]) [o.i.u.c.BlockingManagerImpl] Submitting blocking run operation io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker@1434c1ff with name sifs-compactor to blocking thread
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t5:[]) [o.i.u.c.BlockingManagerImpl] Running blocking operation io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker@1434c1ff with name sifs-compactor on blocking thread
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t5:[]) [o.i.p.s.Compactor] Removing expired entries from file 4 isLogFile true
      13:25:50,825 DEBUG (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t5:[]) [o.i.p.s.FileProvider] openChannel(/home/wburns/RedHat/infinispan/core/target/infinispanTempFiles/SoftIndexFileStoreStressTest/data/stress-test-cache/data/ispn12.4)
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t5:[]) [o.i.p.s.TemporaryTable] Key k21 not present in temporary table
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t5:[]) [o.i.p.s.Compactor] Loading from index for key k21 when processing file 4
      13:25:50,825 TRACE (non-blocking-thread-SoftIndexFileStoreStressTest-NodeA-p2-t16:[]) [o.i.p.s.TemporaryTable] Set key to 4:0
      13:25:50,825 TRACE (non-blocking-thread-SoftIndexFileStoreStressTest-NodeA-p2-t16:[]) [o.i.u.c.NonBlockingManagerImpl] Future has a dependent, completing it in non blocking thread
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t5:[]) [o.i.p.s.IndexNode] Found node on 0:354 but key does not match
      13:25:50,825 TRACE (non-blocking-thread-SoftIndexFileStoreStressTest-NodeA-p2-t16:[]) [o.i.p.a.AsyncNonBlockingStore] Async operations completed for id 2126797469
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.u.c.BlockingManagerImpl] Running blocking operation io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker@65a48602 with name sifs-index on blocking thread
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.p.s.Index] Indexing IndexRequest{key=org.infinispan.persistence.sifs.Index$$Lambda$661/0x000000080121cef8@683f3d21, serializedKey=null, cacheSegment=-1, file=-1, offset=-1, prevFile=-1, prevOffset=-1, size=-1, type=SYNC_REQUEST}
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.u.c.NonBlockingManagerImpl] Future has no dependent, completing it in invoking thread
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.p.s.Index] Indexing IndexRequest{key=k21, serializedKey=ByteBufferImpl{length=13, offset=0, bytes=9801028A01070A05\J03\k\2\1 (13 bytes)}, cacheSegment=66, file=4, offset=0, prevFile=-1, prevOffset=-1, size=2827, type=UPDATE}
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.u.c.NonBlockingManagerImpl] Future has no dependent, completing it in invoking thread
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.p.s.IndexNode] Creating new leafNode for k21 at 4:0
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.p.s.IndexNode] Created 29bd3c40 (length 171) from 19081baa (length 154), stack size 0
      13:25:50,826 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.p.s.IndexNode] Created (1) 1 new nodes, GC 19081baa
      13:25:50,826 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.p.s.IndexNode] Setting new root 29bd3c40 (index has shrunk)
      13:25:50,826 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t6:[]) [o.i.p.s.TemporaryTable] Removed Key k21 was present in temporary table with 4:0
      13:25:50,825 TRACE (blocking-thread-SoftIndexFileStoreStressTest-NodeA-p3-t5:[]) [o.i.p.s.Compactor] Completing compaction for file: 4 due to exception!
      java.lang.NullPointerException: No index info found for key: k21 when processing file 4
      	at java.util.Objects.requireNonNull(Objects.java:233) ~[?:?]
      	at org.infinispan.persistence.sifs.Compactor.compactSingleFile(Compactor.java:550) ~[classes/:?]
      	at org.infinispan.persistence.sifs.Compactor.processRequest(Compactor.java:425) ~[classes/:?]
      	at org.infinispan.persistence.sifs.Compactor.lambda$start$0(Compactor.java:154) ~[classes/:?]
      	at io.reactivex.rxjava3.internal.operators.mixed.FlowableConcatMapCompletable$ConcatMapCompletableObserver.drain(FlowableConcatMapCompletable.java:187) ~[rxjava-3.1.4.jar:?]
      	at io.reactivex.rxjava3.internal.operators.mixed.ConcatMapXMainSubscriber.onNext(ConcatMapXMainSubscriber.java:106) ~[rxjava-3.1.4.jar:?]
      	at io.reactivex.rxjava3.internal.operators.flowable.FlowableObserveOn$ObserveOnSubscriber.runBackfused(FlowableObserveOn.java:445) ~[rxjava-3.1.4.jar:?]
      	at io.reactivex.rxjava3.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:174) ~[rxjava-3.1.4.jar:?]
      	at io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:324) ~[rxjava-3.1.4.jar:?]
      	at io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.runEager(ExecutorScheduler.java:289) ~[rxjava-3.1.4.jar:?]
      	at io.reactivex.rxjava3.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:250) ~[rxjava-3.1.4.jar:?]
      	at org.infinispan.util.concurrent.BlockingManagerImpl.lambda$asExecutor$9(BlockingManagerImpl.java:336) ~[classes/:?]
      	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18) [jboss-threads-3.5.0.Final.jar:3.5.0.Final]
      	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513) [jboss-threads-3.5.0.Final.jar:3.5.0.Final]
      	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538) [jboss-threads-3.5.0.Final.jar:3.5.0.Final]
      	at java.lang.Thread.run(Thread.java:833) [?:?]
      
      

      Attachments

        Issue Links

          Activity

            People

              wburns@redhat.com Will Burns
              wburns@redhat.com Will Burns
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: