Uploaded image for project: 'Jackrabbit Oak'
  1. Jackrabbit Oak
  2. OAK-2815

Persistent cache may block commit

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 1.2
    • Fix Version/s: 1.0.14, 1.2.2, 1.3.0, 1.4
    • Component/s: None
    • Labels:
      None

      Description

      The persistent cache may block a commit for a rather long time if the generation is switched during the commit. The default configuration tells the persistent cache to compact the store when it is closed. This is exactly what happens when a generation is switched.

      I think it would be best to disable compaction.

      I was able to reproduce it with the ContinuousRevisionGCTest in oak-run with -DgarbageRatio=0.9, but it probably also happens with the default garbage ratio of 0.5.

      Once the MVStore reaches 1GB, the console will show something like this:

      Performed RevisionGC in 6.331 s (VersionGCStats{ignoredGCDueToCheckPoint=false, deletedDocGCCount=54054, splitDocGCCount=0, intermediateSplitDocGCCount=0, timeToCollectDeletedDocs=622.8 ms, timeTakenToDeleteDocs=5.708 s})
      .................
      Performed RevisionGC in 9.232 s (VersionGCStats{ignoredGCDueToCheckPoint=false, deletedDocGCCount=26026, splitDocGCCount=0, intermediateSplitDocGCCount=0, timeToCollectDeletedDocs=6.549 s, timeTakenToDeleteDocs=2.682 s})
      
      Performed RevisionGC in 1.269 s (VersionGCStats{ignoredGCDueToCheckPoint=false, deletedDocGCCount=12012, splitDocGCCount=0, intermediateSplitDocGCCount=0, timeToCollectDeletedDocs=133.5 ms, timeTakenToDeleteDocs=1.134 s})
      
      Performed RevisionGC in 20.49 ms (VersionGCStats{ignoredGCDueToCheckPoint=false, deletedDocGCCount=0, splitDocGCCount=0, intermediateSplitDocGCCount=0, timeToCollectDeletedDocs=19.50 ms, timeTakenToDeleteDocs=0.000 ns})
      .15:19:16.682 [DocumentNodeStore background update thread] INFO  o.a.j.o.p.document.DocumentNodeStore - Background operations stats (clean:0, split:0, lock:35581, write:1, num:5)
      ............
      Performed RevisionGC in 8.449 s (VersionGCStats{ignoredGCDueToCheckPoint=false, deletedDocGCCount=2002, splitDocGCCount=0, intermediateSplitDocGCCount=0, timeToCollectDeletedDocs=8.276 s, timeTakenToDeleteDocs=171.7 ms})
      

      The background update thread had to wait 35 seconds for the backgroundOperations lock, which was held by the committing thread:

      "Thread-2" prio=5 tid=0x00007f986b9a7800 nid=0x6803 runnable [0x0000000112780000]
         java.lang.Thread.State: RUNNABLE
      	at org.h2.compress.CompressLZF.compress(CompressLZF.java:239)
      	at org.h2.mvstore.Page.write(Page.java:754)
      	at org.h2.mvstore.Page.writeUnsavedRecursive(Page.java:816)
      	at org.h2.mvstore.Page.writeUnsavedRecursive(Page.java:822)
      	at org.h2.mvstore.Page.writeUnsavedRecursive(Page.java:822)
      	at org.h2.mvstore.MVStore.storeNowTry(MVStore.java:1065)
      	at org.h2.mvstore.MVStore.storeNow(MVStore.java:981)
      	at org.h2.mvstore.MVStore.commitAndSave(MVStore.java:970)
      	- locked <0x00000007e15cccf0> (a org.h2.mvstore.MVStore)
      	at org.h2.mvstore.MVStore.beforeWrite(MVStore.java:2084)
      	at org.h2.mvstore.MVMap.beforeWrite(MVMap.java:1046)
      	at org.h2.mvstore.MVMap.copy(MVMap.java:1231)
      	at org.h2.mvstore.MVMap.copy(MVMap.java:1248)
      	at org.h2.mvstore.MVMap.copy(MVMap.java:1248)
      	at org.h2.mvstore.MVMap.copyFrom(MVMap.java:1218)
      	at org.h2.mvstore.MVStoreTool.compact(MVStoreTool.java:493)
      	at org.h2.mvstore.MVStoreTool.compact(MVStoreTool.java:458)
      	at org.h2.mvstore.MVStoreTool.compact(MVStoreTool.java:404)
      	at org.apache.jackrabbit.oak.plugins.document.persistentCache.PersistentCache$1.closeStore(PersistentCache.java:235)
      	- locked <0x00000007c0c82760> (a org.apache.jackrabbit.oak.plugins.document.persistentCache.PersistentCache$1)
      	at org.apache.jackrabbit.oak.plugins.document.persistentCache.PersistentCache.switchGenerationIfNeeded(PersistentCache.java:372)
      	- locked <0x00000007c03a6c00> (a org.apache.jackrabbit.oak.plugins.document.persistentCache.PersistentCache)
      	at org.apache.jackrabbit.oak.plugins.document.persistentCache.NodeCache.write(NodeCache.java:85)
      	at org.apache.jackrabbit.oak.plugins.document.persistentCache.NodeCache.put(NodeCache.java:130)
      	at org.apache.jackrabbit.oak.plugins.document.LocalDiffCache$1.done(LocalDiffCache.java:98)
      	at org.apache.jackrabbit.oak.plugins.document.Commit.applyToCache(Commit.java:602)
      	at org.apache.jackrabbit.oak.plugins.document.CommitQueue.afterTrunkCommit(CommitQueue.java:127)
      	- locked <0x00000007c03a46f0> (a org.apache.jackrabbit.oak.plugins.document.CommitQueue)
      	at org.apache.jackrabbit.oak.plugins.document.CommitQueue.done(CommitQueue.java:83)
      	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.done(DocumentNodeStore.java:644)
      	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.persist(DocumentNodeStoreBranch.java:338)
      	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.persist(DocumentNodeStoreBranch.java:304)
      	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.access$200(DocumentNodeStoreBranch.java:52)
      	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch$InMemory.merge(DocumentNodeStoreBranch.java:541)
      	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.merge0(DocumentNodeStoreBranch.java:230)
      	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreBranch.merge(DocumentNodeStoreBranch.java:171)
      	at org.apache.jackrabbit.oak.plugins.document.DocumentRootBuilder.merge(DocumentRootBuilder.java:158)
      	at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore.merge(DocumentNodeStore.java:1490)
      	at org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:247)
      	at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.commit(SessionDelegate.java:341)
      	at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.save(SessionDelegate.java:487)
      	at org.apache.jackrabbit.oak.jcr.session.SessionImpl$8.performVoid(SessionImpl.java:424)
      	at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.performVoid(SessionDelegate.java:268)
      	at org.apache.jackrabbit.oak.jcr.session.SessionImpl.save(SessionImpl.java:421)
      	at org.apache.jackrabbit.oak.ContinuousRevisionGCTest$Writer.run(ContinuousRevisionGCTest.java:72)
      	at java.lang.Thread.run(Thread.java:745)
      

        Attachments

        1. OAK-2815.patch
          2 kB
          Marcel Reutegger

          Issue Links

            Activity

              People

              • Assignee:
                thomasm Thomas Mueller
                Reporter:
                mreutegg Marcel Reutegger
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: