Restore operation does not end

[folch]

Hi,

We are trying to do an upgrade from Modesahpe 3.8.1 to Modeshape 4.4.0 and we are using the backup/restore API to migrate all the content.

The backup process suceeds in just 2 minutes (backup folder has 650Mb).

The main problem is the restore operation in Modeshape 4.4.0 because it seems never ends (stopped after 8h) and there are not messages in the log appart of "INFO: Running ModeShape 4.0.0.Alpha1 upgrade function..."

The CPU is working (around 86%) and the Java memory is almost full (2Gb).

Infinispan is configured with a JDBC DB (H2 in File System), however we are also doing tests with other DBs.

If I do a Stacktrace I can see the following threads

"persistence-thread--p12-t1" daemon prio=6 tid=0x0000000010f4d000 nid=0x1ce4 runnable [0x0000000015d6e000]

   java.lang.Thread.State: RUNNABLE

        at java.io.RandomAccessFile.seek(Native Method)

        at org.h2.store.fs.FileDisk.position(FilePathDisk.java:461)

        at org.h2.store.FileStore.seek(FileStore.java:294)

        at org.h2.store.PageStore.readPage(PageStore.java:1325)

        at org.h2.store.PageStore.getPage(PageStore.java:750)

        - locked <0x0000000780fa4de0> (a org.h2.store.PageStore)

        at org.h2.index.PageDataIndex.getPage(PageDataIndex.java:234)

        at org.h2.index.PageDataNode.getNextPage(PageDataNode.java:233)

        at org.h2.index.PageDataLeaf.getNextPage(PageDataLeaf.java:400)

        at org.h2.index.PageDataCursor.nextRow(PageDataCursor.java:95)

        at org.h2.index.PageDataCursor.next(PageDataCursor.java:53)

        at org.h2.index.IndexCursor.next(IndexCursor.java:278)

        at org.h2.table.TableFilter.next(TableFilter.java:361)

        at org.h2.command.dml.Delete.update(Delete.java:71)

        at org.h2.command.CommandContainer.update(CommandContainer.java:79)

        at org.h2.command.Command.executeUpdate(Command.java:254)

        - locked <0x0000000780f9be60> (a org.h2.engine.Database)

        at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:158)

        - locked <0x00000007815e7a10> (a org.h2.engine.Session)

        at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:144)

        at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore$1.call(JdbcStringBasedStore.java:282)

        at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore$1.call(JdbcStringBasedStore.java:272)

        at java.util.concurrent.FutureTask.run(FutureTask.java:262)

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)

        at java.util.concurrent.FutureTask.run(FutureTask.java:262)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

        at java.lang.Thread.run(Thread.java:745)

"http-bio-9090-exec-1" daemon prio=6 tid=0x0000000010f4b000 nid=0x2530 waiting for monitor entry [0x000000001b4ec000]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at org.h2.command.Command.executeQuery(Command.java:191)

        - waiting to lock <0x0000000780f9be60> (a org.h2.engine.Database)

        at org.h2.jdbc.JdbcPreparedStatement.executeQuery(JdbcPreparedStatement.java:109)

        - locked <0x00000007815dabe0> (a org.h2.engine.Session)

        at org.infinispan.persistence.jdbc.stringbased.JdbcStringBasedStore.load(JdbcStringBasedStore.java:201)

        at org.infinispan.persistence.manager.PersistenceManagerImpl.loadFromAllStores(PersistenceManagerImpl.java:436)

        at org.infinispan.persistence.PersistenceUtil.loadAndCheckExpiration(PersistenceUtil.java:116)

        at org.infinispan.persistence.PersistenceUtil$4.compute(PersistenceUtil.java:100)

        at org.infinispan.container.DefaultDataContainer$BoundedEquivalentConcurrentExtendedMap$2.apply(DefaultDataContainer.java:539)

        at org.infinispan.container.DefaultDataContainer$BoundedEquivalentConcurrentExtendedMap$2.apply(DefaultDataContainer.java:536)

        at org.infinispan.commons.util.concurrent.jdk8backported.BoundedEquivalentConcurrentHashMapV8.compute(BoundedEquivalentConcurrentHashMapV8.java:3430)

        - locked <0x0000000782620330> (a org.infinispan.commons.util.concurrent.jdk8backported.BoundedEquivalentConcurrentHashMapV8$Node)

        at org.infinispan.container.DefaultDataContainer$BoundedEquivalentConcurrentExtendedMap.compute(DefaultDataContainer.java:535)

        at org.infinispan.container.DefaultDataContainer.compute(DefaultDataContainer.java:255)

        at org.infinispan.persistence.PersistenceUtil.loadAndStoreInDataContainer(PersistenceUtil.java:90)

        at org.infinispan.interceptors.CacheLoaderInterceptor.loadIfNeeded(CacheLoaderInterceptor.java:216)

        at org.infinispan.interceptors.CacheLoaderInterceptor.visitDataCommand(CacheLoaderInterceptor.java:147)

        at org.infinispan.interceptors.CacheLoaderInterceptor.visitGetKeyValueCommand(CacheLoaderInterceptor.java:101)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.EntryWrappingInterceptor.visitDataReadCommand(EntryWrappingInterceptor.java:130)

        at org.infinispan.interceptors.EntryWrappingInterceptor.visitGetKeyValueCommand(EntryWrappingInterceptor.java:120)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitDataReadCommand(OptimisticLockingInterceptor.java:98)

        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitGetKeyValueCommand(AbstractLockingInterceptor.java:70)

        at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitGetKeyValueCommand(OptimisticLockingInterceptor.java:109)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)

        at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:86)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:346)

        at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:318)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.CacheMgmtInterceptor.visitDataReadCommand(CacheMgmtInterceptor.java:103)

        at org.infinispan.interceptors.CacheMgmtInterceptor.visitGetKeyValueCommand(CacheMgmtInterceptor.java:91)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:102)

        at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:71)

        at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:86)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)

        at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:430)

        at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:422)

        at org.infinispan.schematic.internal.CacheSchematicDb.get(CacheSchematicDb.java:77)

        at org.modeshape.jcr.cache.document.LocalDocumentStore.get(LocalDocumentStore.java:71)

        at org.modeshape.jcr.cache.document.WorkspaceCache.documentFor(WorkspaceCache.java:188)

        at org.modeshape.jcr.cache.document.WorkspaceCache.documentFor(WorkspaceCache.java:207)

        at org.modeshape.jcr.cache.document.WorkspaceCache.getNode(WorkspaceCache.java:239)

        at org.modeshape.jcr.cache.document.NodeCacheIterator.nextNode(NodeCacheIterator.java:103)

        at org.modeshape.jcr.cache.document.NodeCacheIterator.hasNext(NodeCacheIterator.java:70)

        at org.modeshape.jcr.query.NodeSequence$16.hasNext(NodeSequence.java:1450)

        at org.modeshape.jcr.query.NodeSequence$23.findNext(NodeSequence.java:1863)

        at org.modeshape.jcr.query.NodeSequence$23.hasNext(NodeSequence.java:1849)

        at org.modeshape.jcr.query.NodeSequence$23.findNext(NodeSequence.java:1863)

        at org.modeshape.jcr.query.NodeSequence$23.hasNext(NodeSequence.java:1849)

        at org.modeshape.jcr.query.NodeSequence$SingleWidthBatch.<init>(NodeSequence.java:1920)

        at org.modeshape.jcr.query.NodeSequence.copy(NodeSequence.java:1907)

        at org.modeshape.jcr.query.engine.process.RestartableSequence.loadBatch(RestartableSequence.java:213)

        at org.modeshape.jcr.query.engine.process.RestartableSequence.loadRemaining(RestartableSequence.java:188)

        at org.modeshape.jcr.query.engine.process.RestartableSequence.getRowCount(RestartableSequence.java:107)

        at org.modeshape.jcr.query.JcrQueryResult$QueryResultIterator.getSize(JcrQueryResult.java:275)

        at org.modeshape.jcr.Upgrades$ModeShape_4_0_0_Alpha1.apply(Upgrades.java:266)

        at org.modeshape.jcr.Upgrades.applyUpgradesSince(Upgrades.java:98)

        at org.modeshape.jcr.cache.RepositoryCache$4.call(RepositoryCache.java:474)

        at org.modeshape.jcr.cache.RepositoryCache$4.call(RepositoryCache.java:469)

        at org.modeshape.jcr.cache.RepositoryCache.runInTransaction(RepositoryCache.java:516)

        at org.modeshape.jcr.cache.RepositoryCache.completeUpgrade(RepositoryCache.java:469)

        at org.modeshape.jcr.JcrRepository$RunningState.completeInitialization(JcrRepository.java:1331)

        at org.modeshape.jcr.JcrRepository.doStart(JcrRepository.java:390)

        at org.modeshape.jcr.JcrRepository.start(JcrRepository.java:312)

        at org.modeshape.jcr.JcrRepository.completeRestore(JcrRepository.java:543)

        at org.modeshape.jcr.BackupService.restoreRepository(BackupService.java:161)

        at org.modeshape.jcr.JcrRepositoryManager.restoreRepository(JcrRepositoryManager.java:87)

        at org.modeshape.jcr.JcrRepositoryManager.restoreRepository(JcrRepositoryManager.java:81)

        at org.apache.jsp.console.tools.repository.restore_jsp.restore(restore_jsp.java:93)
        ...

Couple of questions:

1. Is there a way we can monitorize the restore progress to see if it's blocked, it's working and what is the progress? Maybe changing modeshape to DEBUG mode in the logs?

2. What could the problem? Attached you can find Infinispan and modeshape config files.

3. Am I missing something?

Thanks in advance.

Additional info:

Running in DEBUG mode I can see the following lines:

INFO: Running ModeShape 4.0.0.Alpha1 upgrade function...

FINE: There is no explicit cache named 'empower.repository/default' defined in the workspace cache container, using a default cache

FINE: The 'empower.repository/default' workspace cache is using the cache configuration: 'Configuration{clustering=ClusteringConfiguration [asyncConfiguration=AsyncConfiguration [attributes=[asyncMarshalling=false, replicationQueue=null, replicationQueueMaxElements=1000, replicationQueueInterval=10, useReplicationQueue=false]], hashConfiguration=HashConfiguration [attributes=[consistentHashFactory=null, numOwners=2, capacityFactor=1.0, numSegments=60, hash=MurmurHash3]], l1Configuration=L1Configuration [attributes=[enabled=false, invalidationThreshold=0, lifespan=600000, cleanupTaskFrequency=60000]], stateTransferConfiguration=StateTransferConfiguration[fetchInMemoryState=true, timeout=240000, awaitInitialTransfer=true, chunkSize=512], syncConfiguration=SyncConfiguration [attributes=[replTimeout=15000]], partitionHandlingConfiguration=PartitionHandlingConfiguration [attributes=[enabled=false]], attributes=[cacheMode=LOCAL]], customInterceptors=CustomInterceptorsConfiguration [interceptors=[]], dataContainer=DataContainerConfiguration [attributes=[dataContainer=null, keyEquivalence=org.infinispan.commons.equivalence.AnyEquivalence@b64e155, valueEquivalence=org.infinispan.commons.equivalence.AnyEquivalence@b64e155, properties={}]], deadlockDetection=DeadlockDetectionConfiguration [attributes=[enabled=false, spinDuration=100]], eviction=EvictionConfiguration [attributes=[threadPolicy=DEFAULT, strategy=LRU, maxEntries=50000]], expiration=ExpirationConfiguration [attributes=[wakeUpInterval=60000, reaperEnabled=true, maxIdle=6000, lifespan=120000]], indexing=IndexingConfiguration [attributes=[index=NONE, autoConfig=false, properties={}]], invocationBatching=InvocationBatchingConfiguration [attributes=[enabled=false]], jmxStatistics=JMXStatisticsConfiguration [attributes=[enabled=false]], persistence=PersistenceConfiguration [attributes=[passivation=false], stores=[]], locking=LockingConfiguration [attributes=[isolationLevel=READ_COMMITTED, useLockStriping=false, lockAcquisitionTimeout=10000, concurrencyLevel=32, writeSkewCheck=false]], modules={}, security=SecurityConfiguration [authorization=AuthorizationConfiguration [attributes=[enabled=false, roles=[]]]], storeAsBinary=StoreAsBinaryConfiguration [attributes=[enabled=false, storeKeysAsBinary=true, storeValuesAsBinary=true]], transaction=TransactionConfiguration [attributes=[transactionManagerLookup=org.infinispan.transaction.lookup.GenericTransactionManagerLookup@c05994b, transactionSynchronizationRegistryLookup=null, syncRollbackPhase=true, syncCommitPhase=true, cacheStopTimeout=30000, transactionProtocol=DEFAULT, completedTxTimeout=60000, transactionMode=NON_TRANSACTIONAL, reaperWakeUpInterval=30000, lockingMode=OPTIMISTIC, autoCommit=true, useSynchronization=false, useEagerLocking=false, eagerLockingSingleNode=false, use1PcForAutoCommitTransactions=false], recovery=RecoveryConfiguration [attributes=[enabled=false, recoveryInfoCacheName=__recoveryInfoCacheName__]]], versioning=[scheme=NONE, enabled=false], unsafe=[unrealiableReturnValues=false], sites=SitesConfiguration [backupFor=BackupForConfiguration [attributes=[remoteCache=null, remoteSite=null]], allBackups=[], attributes=[disableBackups=false, inUseBackupSites=[]]], compatibility=CompatibilityModeConfiguration [attributes=[enabled=false, marshaller=null]]}'

FINE: Queries with indexes are enabled for the 'empower.repository' repository. Executing queries may require scanning the repository contents when the query cannot use the defined indexes.

Then nothing else...

[hchiorean]

From the attached thread dump, it seems that the ISPN cache store is waiting on the H2 database to read something from disk (H2 doesn't appear to be blocked). Since the problem seems to be at the persistence level (ISPN + DB) you could try to configure H2 to enable TRACE logging and look for anything suspicious.

From the stack traces, ModeShape is executing a query which is not returning because the ISPN JDBC cache store is not getting back any results from the database.

[folch]

Hi Horia,

I've repeated the same operation using MSSqlServer and similar results. The process is a little bit slower (it took 20 minutes to show "INFO: Running ModeShape 4.0.0.Alpha1 upgrade function..." message) but after this point, nothing else (waiting more than 2h).

Monitoring DB activity I can see an interesting thing.

Between the start of the backup and the message "INFO: Running ModeShape 4.0.0.Alpha1 upgrade function...", the DB tables were growing. But, after that point, zero activity in the DB in terms of number of rows.

I have:

• cache table: 551969 rows
• data cache table: 613309 rows
• metadata cache table: 4465 rows

The index is also quiet since the start of the backup.

If I try to do Stacktraces, in this case, I only see one relevant thread:

"http-bio-9090-exec-1" daemon prio=6 tid=0x00000000123db800 nid=0x376c runnable [0x000000001819c000]

   java.lang.Thread.State: RUNNABLE

        at org.jboss.marshalling.river.RiverUnmarshaller.getBlockUnmarshaller(RiverUnmarshaller.java:141)

        at org.jboss.marshalling.river.RiverUnmarshaller.doInitSerializable(RiverUnmarshaller.java:1609)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadNewObject(RiverUnmarshaller.java:1285)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:276)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:209)

        at org.jboss.marshalling.AbstractObjectInput.readObject(AbstractObjectInput.java:41)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadClassDescriptor(RiverUnmarshaller.java:1011)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadNewObject(RiverUnmarshaller.java:1255)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:276)

        at org.jboss.marshalling.river.RiverUnmarshaller.doReadObject(RiverUnmarshaller.java:209)

        at org.jboss.marshalling.AbstractObjectInput.readObject(AbstractObjectInput.java:41)

        at org.infinispan.commons.marshall.jboss.AbstractJBossMarshaller.objectFromObjectStream(AbstractJBossMarshaller.java:134)

        at org.infinispan.marshall.core.VersionAwareMarshaller.objectFromByteBuffer(VersionAwareMarshaller.java:101)

        at org.infinispan.commons.marshall.AbstractDelegatingMarshaller.objectFromByteBuffer(AbstractDelegatingMarshaller.java:80)

        at org.infinispan.marshall.core.MarshalledEntryImpl.unmarshall(MarshalledEntryImpl.java:114)

        at org.infinispan.marshall.core.MarshalledEntryImpl.getValue(MarshalledEntryImpl.java:61)

        at org.infinispan.persistence.PersistenceUtil.convert(PersistenceUtil.java:136)

        at org.infinispan.persistence.PersistenceUtil$4.compute(PersistenceUtil.java:106)

        at org.infinispan.container.DefaultDataContainer$BoundedEquivalentConcurrentExtendedMap$2.apply(DefaultDataContainer.java:539)

        at org.infinispan.container.DefaultDataContainer$BoundedEquivalentConcurrentExtendedMap$2.apply(DefaultDataContainer.java:536)

        at org.infinispan.commons.util.concurrent.jdk8backported.BoundedEquivalentConcurrentHashMapV8.compute(BoundedEquivalentConcurrentHashMapV8.java:3378)

        - locked <0x00000007d54ae298> (a org.infinispan.commons.util.concurrent.jdk8backported.BoundedEquivalentConcurrentHashMapV8$ReservationNode)

        at org.infinispan.container.DefaultDataContainer$BoundedEquivalentConcurrentExtendedMap.compute(DefaultDataContainer.java:535)

        at org.infinispan.container.DefaultDataContainer.compute(DefaultDataContainer.java:255)

        at org.infinispan.persistence.PersistenceUtil.loadAndStoreInDataContainer(PersistenceUtil.java:90)

        at org.infinispan.interceptors.CacheLoaderInterceptor.loadIfNeeded(CacheLoaderInterceptor.java:216)

        at org.infinispan.interceptors.CacheLoaderInterceptor.visitDataCommand(CacheLoaderInterceptor.java:147)

        at org.infinispan.interceptors.CacheLoaderInterceptor.visitGetKeyValueCommand(CacheLoaderInterceptor.java:101)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.EntryWrappingInterceptor.visitDataReadCommand(EntryWrappingInterceptor.java:130)

        at org.infinispan.interceptors.EntryWrappingInterceptor.visitGetKeyValueCommand(EntryWrappingInterceptor.java:120)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitDataReadCommand(PessimisticLockingInterceptor.java:70)

        at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitGetKeyValueCommand(AbstractLockingInterceptor.java:70)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:111)

        at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:86)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:346)

        at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:318)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.CacheMgmtInterceptor.visitDataReadCommand(CacheMgmtInterceptor.java:103)

        at org.infinispan.interceptors.CacheMgmtInterceptor.visitGetKeyValueCommand(CacheMgmtInterceptor.java:91)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:97)

        at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:102)

        at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:71)

        at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:86)

        at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:40)

        at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:336)

        at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:430)

        at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:422)

        at org.infinispan.schematic.internal.CacheSchematicDb.get(CacheSchematicDb.java:77)

        at org.modeshape.jcr.cache.document.LocalDocumentStore.get(LocalDocumentStore.java:71)

        at org.modeshape.jcr.cache.document.WorkspaceCache.documentFor(WorkspaceCache.java:188)

        at org.modeshape.jcr.cache.document.WorkspaceCache.documentFor(WorkspaceCache.java:207)

        at org.modeshape.jcr.cache.document.WorkspaceCache.getNode(WorkspaceCache.java:239)

        at org.modeshape.jcr.cache.document.NodeCacheIterator.nextNode(NodeCacheIterator.java:103)

        at org.modeshape.jcr.cache.document.NodeCacheIterator.hasNext(NodeCacheIterator.java:70)

        at org.modeshape.jcr.query.NodeSequence$16.hasNext(NodeSequence.java:1450)

        at org.modeshape.jcr.query.NodeSequence$23.findNext(NodeSequence.java:1863)

        at org.modeshape.jcr.query.NodeSequence$23.hasNext(NodeSequence.java:1849)

        at org.modeshape.jcr.query.NodeSequence$23.findNext(NodeSequence.java:1863)

        at org.modeshape.jcr.query.NodeSequence$23.hasNext(NodeSequence.java:1849)

        at org.modeshape.jcr.query.NodeSequence$SingleWidthBatch.<init>(NodeSequence.java:1920)

        at org.modeshape.jcr.query.NodeSequence.copy(NodeSequence.java:1907)

        at org.modeshape.jcr.query.engine.process.RestartableSequence.loadBatch(RestartableSequence.java:213)

        at org.modeshape.jcr.query.engine.process.RestartableSequence.loadRemaining(RestartableSequence.java:188)

        at org.modeshape.jcr.query.engine.process.RestartableSequence.getRowCount(RestartableSequence.java:107)

        at org.modeshape.jcr.query.JcrQueryResult$QueryResultIterator.getSize(JcrQueryResult.java:275)

        at org.modeshape.jcr.Upgrades$ModeShape_4_0_0_Alpha1.apply(Upgrades.java:266)

        at org.modeshape.jcr.Upgrades.applyUpgradesSince(Upgrades.java:98)

        at org.modeshape.jcr.cache.RepositoryCache$4.call(RepositoryCache.java:474)

        at org.modeshape.jcr.cache.RepositoryCache$4.call(RepositoryCache.java:469)

        at org.modeshape.jcr.cache.RepositoryCache.runInTransaction(RepositoryCache.java:516)

        at org.modeshape.jcr.cache.RepositoryCache.completeUpgrade(RepositoryCache.java:469)

        at org.modeshape.jcr.JcrRepository$RunningState.completeInitialization(JcrRepository.java:1331)

        at org.modeshape.jcr.JcrRepository.doStart(JcrRepository.java:390)

        at org.modeshape.jcr.JcrRepository.start(JcrRepository.java:312)

        at org.modeshape.jcr.JcrRepository.completeRestore(JcrRepository.java:543)

        at org.modeshape.jcr.BackupService.restoreRepository(BackupService.java:161)

        at org.modeshape.jcr.JcrRepositoryManager.restoreRepository(JcrRepositoryManager.java:87)

        at org.modeshape.jcr.JcrRepositoryManager.restoreRepository(JcrRepositoryManager.java:81)

        at org.apache.jsp.console.tools.repository.restore_jsp.restore(restore_jsp.java:93)

[hchiorean]

Actually, looking at your configuration files, your binary & data config are not ok at all: you've configured to store binary data in the exact same table and columns as the main cache data. Never do this; always use a separate table for the binary data (even if it's the same datasource). Also, you've configured OPTIMISTIC locking which is pretty sure to corrupt repository data under concurrent scenarios. This is explained in the ModeShape documentation: Configuration - ModeShape 4 - Project Documentation Editor

The latest version of ModeShape is 4.5.0.Final, so after fixing your configuration you should try with that version.

[folch]

Thanks for your reply Horia,

About OPTIMISTIC and PESSIMISTIC locking we've tried both. In both cases we have the same result. However I will keep it PESSIMISTIC. Thanks for your advice.

About same table, I don't understand your suggestion. Actually we are using different tables if I'm not wrong.

Please, correct me if I'm wrong, but in modeshape_config.json we configured

• the storage cache: empower.cache
• the binaryStorage with 2 local caches:
  • dataCache:  empower.data_cache
  • metadataCacheName: empower.metadata_cache

In infinispan_config.xml both are configured like this:

     <string-keyed-table prefix="ISPN" create-on-start="true" drop-on-exit="false">

         <id-column name="ID_COLUMN" type="VARCHAR(255)"/>

         <data-column name="DATA_COLUMN" type="BINARY"/>

         <timestamp-column name="TIMESTAMP_COLUMN" type="BIGINT"/>

      </string-keyed-table>

which means that infinispan is creating the following tables:

   ISPN_empower_cache -> main cache data

   ISPN_empower_data_cache -> binary cache data

   ISPN_empower_metadata_cache -> binary metadata cache

Am I wrong??

Thanks

[hchiorean]

In infinispan_config.xml both are configured like this:

     <string-keyed-table prefix="ISPN" create-on-start="true" drop-on-exit="false">

         <id-column name="ID_COLUMN" type="VARCHAR(255)"/>

         <data-column name="DATA_COLUMN" type="BINARY"/>

         <timestamp-column name="TIMESTAMP_COLUMN" type="BIGINT"/>

      </string-keyed-table>

which means that infinispan is creating the following tables:

   ISPN_empower_cache -> main cache data

   ISPN_empower_data_cache -> binary cache data

   ISPN_empower_metadata_cache -> binary metadata cache

Am I wrong??

Thanks

right, I missed the fact that you have different cache names.

In that case, your configuration seems fine. You can try using not JDBC, but another cache store (LevelDB or FS) and see if the problem still persists. If it doesn't, then it's most likely a problem with ISPN's JDBC cache store (you should ask the ISPN community)

From ModeShape's perspective, I don't see anything wrong: i.e. ModeShape is executing a query which subsequently loads data from the ISPN cache and waits for this data to be returned. There doesn't seem to be a deadlock anywhere (the thread that loads data is RUNNABLE), but I can't tell why it would be taking this long.

[folch]

Thanks again Horia,

I'll try with FS and also I will try upgrading to 4.5.0, if I'm not wrong you upgrade Infinispan to 7.2.4.

Just a question. What is doing Modeshape after the line:

INFO: Running ModeShape 4.0.0.Alpha1 upgrade function...

[hchiorean]

You can see the code that's running the query here: https://github.com/ModeShape/modeshape/blob/modeshape-4.5.0.Final/modeshape-jcr/src/main/java/org/modeshape/jcr/Upgrades.java#L266

ModeShape is running a SQL2 query in order to find how many nodes of a certain type are in the repository in order to be able to correct some ACL bugs when moving from 3.x to 4.x. In fact, all the upgrade functions are an attempt to fix data corruption bugs caused by various ModeShape bugs with earlier versions.

[folch]

Hi Horia,

I'm still trying to test the same with FS instead of JDBC, but in the meanwhile I was looking the Upgrades.java code, and I've a couple of questions.

1)

Based on the debug log, the last "restoring entry" is the following:

     restoring 551946 doc { "metadata" : { "id" : "48f1104317f1e7jcr:system/mode:metadata" , "contentType" : "application/json" } , "content" : { "key" : "48f1104317f1e7jcr:system/mode:metadata" , "properties" : { "" : { "workspaces" : [ "default" ] , "accessControl" : false } } } }

I guess, we've restored 551,946 nodes and we are doing the following query; Query query = queryManager.createQuery("select [jcr:name] from [" + ModeShapeLexicon.ACCESS_CONTROLLABLE_STRING + "]", JcrQuery.JCR_SQL2);

If I'm not wrong, as we don't have any index defined on the jcr:name for accescontrollable nodetype, the system is trying to iterate over the entire repository looking for this.

My question is, with 551,946 nodes, could it be an issue that query?

2)

My second question is, we are not using ACLs. Our repository is not using any kind of permission as we always login without credentials. Can we, somehow, avoid executing the "ModeShape_4_0_0_Alpha1" upgrade operation?

Do you see any side effect?

Thanks

[hchiorean]

My question is, with 551,946 nodes, could it be an issue that query?

well, that query should run just like any other default (non indexed) query. Yes, since there are 500k nodes in the repository it may take longer to load all the nodes, but certainly not hours IMO. The fact that it's taking this long doesn't seem right.

One thing you may try to "work around" the query and force it to return is to define a node-type index on the mode:accessControllable node (i.e. "kind" : "nodetype", "nodeType" : "mode:accessControllable"). Hopefully by doing this the query will use this particular index which should have no nodes defined and not attempt to walk the entire repository.

My second question is, we are not using ACLs. Our repository is not using any kind of permission as we always login without credentials. Can we, somehow, avoid executing the "ModeShape_4_0_0_Alpha1" upgrade operation

upgrades are being run at repository startup when going from an older repo version to a newer repository version and, as mentioned previously, attempt to correct possibly corrupt repository data (corrupt due to bugs). You can't select which upgrades to run and which not to run, they all have to be run in a certain order.

In the case of ACLs, unfortunately there is no "configuration switch" which tells whether a repository is using ACLs or not. You start using ACLs by simply calling some JCR methods. Actually, that's exactly what that query is trying to do: count the number of nodes which are of type [mode:accessControllable] (which is ModeShape's internal structure for storing ACL data) in order to determine is ACLs are being used or not.

[folch]

Hi Horia,

I've tried 3 different approachs, as you suggested.

1) Upgrading to Modeshape 4.5.0 + Infinispan 7.2.4. Same results. I didn't see any difference.

2) Adding a node-type index to workaround the query. I tried your suggestion addig the following index:

        "modeshapeError" : {

            "kind" : "nodetype",

            "provider" : "local",

            "nodeType" : "mode:accessControllable"

        }

However, it fails whe repository starts as the local index provider does not accept "multi column" indexing. What index provider should I have to use?

Instead, I tried the following index definition:

        "modeshapeError" : {

            "kind" : "value",

            "provider" : "local",

            "nodeType" : "mode:accessControllable",

            "columns" : "jcr:name( NAME )"

      }

But I've seen any difference.

3) Changing the binary storage and using a Filesystem:

    "storage" : {

          "cacheConfiguration" : "empower/infinispan_config.xml",

          "cacheName" : "empower.cache",

          "binaryStorage" : {

                "type" : "file",

                "directory": "C:/target/content/binaries",

                "minimumBinarySizeInBytes" : 1000

              }

      }

And, in this case, it works. It took 40 minutes, but at the end of the restore operation the repository was migrated.

What do you think? Do you think that we still can workaround the problem defining an index using a different provider? Is there any other workaround that we can try?

Thanks

[hchiorean]

If changing the binary storage makes a difference, then this has nothing to do with querying and the upgrade functions.

In this case, you can configure the restore to not restore binaries, just the repository data (see Backup and restore - ModeShape 4 - Project Documentation Editor). The binaries can remain in their original location (as used by ModeShape 3.x) and the repository should still work. This is because binaries are simply referenced by a UUID which should not change.

[folch]

Hi Horia,

If I try to start the old repository with new Modeshape 4.4.0 version I canno see content. The repository is totally empty (but not the DB).

When I try to restore without binaries I have same results. After "INFO: Running ModeShape 4.0.0.Alpha1 upgrade function..." nothing else during hours.