Time out acquiring tx lock

Support Bug
1

We are seeing these errors repeated many times (once they occur) which hangs our entire db. Our transaction.isolation level is SERIALIZABLE with "LAST COMMIT WINS".

Stardog will not stop (server stop ran for over 1 minute with no resolution). To resolve this, I had to reboot our server, delete the db in problem and restart everything.

How should this be handled vs reboot?

Andrea

WARN  2020-08-05 21:41:07,227 [stardog-user-7] com.complexible.stardog.protocols.http.server.StardogUndertowErrorHandler:accept(64): Unexpected exception was handled by the server
com.complexible.stardog.db.DatabaseException: Timed out while waiting to acquire the tx lock
	at com.complexible.stardog.db.DatabaseConnectionImpl.acquireTxLock(DatabaseConnectionImpl.java:345) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseConnectionImpl.begin(DatabaseConnectionImpl.java:395) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DelegatingDatabaseConnection.begin(DelegatingDatabaseConnection.java:274) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseImpl$MonitoredDbConnection.begin(DatabaseImpl.java:1640) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseImpl$DBConnectionWrapper.begin(DatabaseImpl.java:1317) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DelegatingDatabaseConnection.begin(DelegatingDatabaseConnection.java:274) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.StardogKernel$KernelDbConnection.begin(StardogKernel.java:3151) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DelegatingDatabaseConnection.begin(DelegatingDatabaseConnection.java:274) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.StardogKernel$NotifyingDatabaseConnection.begin(StardogKernel.java:3333) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.TransactionService.begin(TransactionService.java:249) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.TransactionService.begin(TransactionService.java:121) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.stardog.http.server.undertow.jaxrs.ExtractRoutes.lambda$handleIt$5(ExtractRoutes.java:192) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at org.apache.shiro.subject.support.SubjectRunnable.doRun(SubjectRunnable.java:120) [shiro-core-1.3.0.jar:1.3.0]
	at org.apache.shiro.subject.support.SubjectRunnable.run(SubjectRunnable.java:108) [shiro-core-1.3.0.jar:1.3.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
WARN  2020-08-05 21:58:05,451 [stardog-user-6] com.complexible.stardog.protocols.http.server.StardogUndertowErrorHandler:accept(64): Unexpected exception was handled by the server
com.complexible.stardog.db.DatabaseException: Timed out while waiting to acquire the tx lock
	at com.complexible.stardog.db.DatabaseConnectionImpl.acquireTxLock(DatabaseConnectionImpl.java:345) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseConnectionImpl.begin(DatabaseConnectionImpl.java:395) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DelegatingDatabaseConnection.begin(DelegatingDatabaseConnection.java:274) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseImpl$MonitoredDbConnection.begin(DatabaseImpl.java:1640) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseImpl$DBConnectionWrapper.begin(DatabaseImpl.java:1317) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DelegatingDatabaseConnection.begin(DelegatingDatabaseConnection.java:274) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.StardogKernel$KernelDbConnection.begin(StardogKernel.java:3151) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DelegatingDatabaseConnection.begin(DelegatingDatabaseConnection.java:274) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.StardogKernel$NotifyingDatabaseConnection.begin(StardogKernel.java:3333) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.TransactionService.begin(TransactionService.java:249) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.TransactionService.begin(TransactionService.java:121) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.stardog.http.server.undertow.jaxrs.ExtractRoutes.lambda$handleIt$5(ExtractRoutes.java:192) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at org.apache.shiro.subject.support.SubjectRunnable.doRun(SubjectRunnable.java:120) [shiro-core-1.3.0.jar:1.3.0]
	at org.apache.shiro.subject.support.SubjectRunnable.run(SubjectRunnable.java:108) [shiro-core-1.3.0.jar:1.3.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
2

Do you have other concurrently executing transactions? Why are you using serialization isolation mode?

3

Yes we do. In SNAPSHOT mode, we had problems with write conflicts updating a "lastAccessed" field.

WARN  2020-08-03 18:50:00,001 [efd2bbc5-2c7a-49f3-85ee-b171a9ede53d_Worker-10] com.complexible.stardog.db.DatabaseImpl:lambda$null$0(1259): Closing connection to database logx due to inactivity for 10m
ERROR 2020-08-03 21:41:06,234 [stardog-user-8] com.complexible.stardog.db.DatabaseConnectionImpl:apply(780): There was an error adding data
com.complexible.mvcc.api.WriteConflictException: Operation aborted: Write Conflict detected
	at com.stardog.starrocks.index.NativePipelineBuffer.submitInternal(Native Method) ~[stardog-7.3.2.jar:?]
	at com.stardog.starrocks.index.NativePipelineBuffer.submit(NativePipelineBuffer.java:107) ~[stardog-7.3.2.jar:?]
	at com.stardog.starrocks.index.NativePipelineWriter.writeInternal(NativePipelineWriter.java:138) ~[stardog-7.3.2.jar:?]
	at com.stardog.starrocks.index.NativePipelineWriter.write(NativePipelineWriter.java:66) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.mvcc.rocks.NativeSingleThreadedUpdater.flush(NativeSingleThreadedUpdater.java:140) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.mvcc.rocks.NativeSingleThreadedUpdater.flush(NativeSingleThreadedUpdater.java:152) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.mvcc.rocks.NativeSingleThreadedUpdater.finish(NativeSingleThreadedUpdater.java:166) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.IndexUpdaters.update(IndexUpdaters.java:200) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.BaseIndexWriter.updateWithIteration(BaseIndexWriter.java:88) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.BaseIndexWriter.remove(BaseIndexWriter.java:142) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.Indexes.remove(Indexes.java:387) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.index.ConnectableIndexRWConnectionImpl$IndexResourceTransaction.apply(ConnectableIndexRWConnectionImpl.java:651) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.index.ConnectableIndexRWConnectionImpl.apply(ConnectableIndexRWConnectionImpl.java:366) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.ConnectableConnectionCollection.apply(ConnectableConnectionCollection.java:197) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseConnectionImpl.apply(DatabaseConnectionImpl.java:773) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseConnectionImpl.remove(DatabaseConnectionImpl.java:840) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.ModifyOperatorImpl.delete(ModifyOperatorImpl.java:226) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.ModifyOperatorImpl.computeNext(ModifyOperatorImpl.java:187) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.ModifyOperatorImpl.computeNext(ModifyOperatorImpl.java:72) ~[stardog-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.tryToComputeNext(AbstractSkippingIterator.java:147) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.hasNext(AbstractSkippingIterator.java:134) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.base.CloseableIterator.size(CloseableIterator.java:233) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.UpdateSequenceOperatorImpl.computeNext(UpdateSequenceOperatorImpl.java:76) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.UpdateSequenceOperatorImpl.computeNext(UpdateSequenceOperatorImpl.java:29) ~[stardog-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.tryToComputeNext(AbstractSkippingIterator.java:147) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.hasNext(AbstractSkippingIterator.java:134) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.util.AutoCloseOperator.computeNext(AutoCloseOperator.java:154) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.util.AutoCloseOperator.computeNext(AutoCloseOperator.java:28) ~[stardog-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.tryToComputeNext(AbstractSkippingIterator.java:147) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.hasNext(AbstractSkippingIterator.java:134) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.base.CloseableIterator.size(CloseableIterator.java:233) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.QueryEngine.executeUpdatePlan(QueryEngine.java:350) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.QueryEngine.executeUpdate(QueryEngine.java:364) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.DefaultQueryFactory$UpdateQueryImpl.execute(DefaultQueryFactory.java:338) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.DefaultQueryFactory$UpdateQueryImpl.execute(DefaultQueryFactory.java:317) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.DelegatingQuery.execute(DelegatingQuery.java:55) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.DelegatingQuery.execute(DelegatingQuery.java:55) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.Query.execute(Query.java:58) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.StardogKernel$SecuredUpdateQuery.execute(StardogKernel.java:4386) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.StardogKernel$SecuredUpdateQuery.execute(StardogKernel.java:4373) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.ProtocolUtils.executeUpdateQuery(ProtocolUtils.java:712) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.SPARQLUpdate.executeQuery(SPARQLUpdate.java:79) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.SPARQLUpdate.updatePost(SPARQLUpdate.java:65) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.stardog.http.server.undertow.jaxrs.ExtractRoutes.lambda$handleIt$5(ExtractRoutes.java:192) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at org.apache.shiro.subject.support.SubjectRunnable.doRun(SubjectRunnable.java:120) [shiro-core-1.3.0.jar:1.3.0]
	at org.apache.shiro.subject.support.SubjectRunnable.run(SubjectRunnable.java:108) [shiro-core-1.3.0.jar:1.3.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
ERROR 2020-08-03 21:41:06,238 [stardog-user-8] com.complexible.stardog.db.DatabaseConnectionImpl:remove(849): There was an error removing data
com.complexible.stardog.db.DatabaseException: Operation aborted: Write Conflict detected
	at com.complexible.stardog.db.DatabaseConnectionImpl.apply(DatabaseConnectionImpl.java:781) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseConnectionImpl.remove(DatabaseConnectionImpl.java:840) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.ModifyOperatorImpl.delete(ModifyOperatorImpl.java:226) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.ModifyOperatorImpl.computeNext(ModifyOperatorImpl.java:187) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.ModifyOperatorImpl.computeNext(ModifyOperatorImpl.java:72) ~[stardog-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.tryToComputeNext(AbstractSkippingIterator.java:147) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.hasNext(AbstractSkippingIterator.java:134) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.base.CloseableIterator.size(CloseableIterator.java:233) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.UpdateSequenceOperatorImpl.computeNext(UpdateSequenceOperatorImpl.java:76) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.impl.UpdateSequenceOperatorImpl.computeNext(UpdateSequenceOperatorImpl.java:29) ~[stardog-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.tryToComputeNext(AbstractSkippingIterator.java:147) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.hasNext(AbstractSkippingIterator.java:134) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.util.AutoCloseOperator.computeNext(AutoCloseOperator.java:154) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.operator.util.AutoCloseOperator.computeNext(AutoCloseOperator.java:28) ~[stardog-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.tryToComputeNext(AbstractSkippingIterator.java:147) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.collect.AbstractSkippingIterator.hasNext(AbstractSkippingIterator.java:134) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.common.base.CloseableIterator.size(CloseableIterator.java:233) ~[stardog-utils-common-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.QueryEngine.executeUpdatePlan(QueryEngine.java:350) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.plan.eval.QueryEngine.executeUpdate(QueryEngine.java:364) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.DefaultQueryFactory$UpdateQueryImpl.execute(DefaultQueryFactory.java:338) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.DefaultQueryFactory$UpdateQueryImpl.execute(DefaultQueryFactory.java:317) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.DelegatingQuery.execute(DelegatingQuery.java:55) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.DelegatingQuery.execute(DelegatingQuery.java:55) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.query.Query.execute(Query.java:58) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.StardogKernel$SecuredUpdateQuery.execute(StardogKernel.java:4386) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.StardogKernel$SecuredUpdateQuery.execute(StardogKernel.java:4373) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.ProtocolUtils.executeUpdateQuery(ProtocolUtils.java:712) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.SPARQLUpdate.executeQuery(SPARQLUpdate.java:79) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.complexible.stardog.protocols.http.server.SPARQLUpdate.updatePost(SPARQLUpdate.java:65) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at com.stardog.http.server.undertow.jaxrs.ExtractRoutes.lambda$handleIt$5(ExtractRoutes.java:192) ~[stardog-protocols-http-server-7.3.2.jar:?]
	at org.apache.shiro.subject.support.SubjectRunnable.doRun(SubjectRunnable.java:120) [shiro-core-1.3.0.jar:1.3.0]
	at org.apache.shiro.subject.support.SubjectRunnable.run(SubjectRunnable.java:108) [shiro-core-1.3.0.jar:1.3.0]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
Caused by: com.complexible.mvcc.api.WriteConflictException: Operation aborted: Write Conflict detected
	at com.stardog.starrocks.index.NativePipelineBuffer.submitInternal(Native Method) ~[stardog-7.3.2.jar:?]
	at com.stardog.starrocks.index.NativePipelineBuffer.submit(NativePipelineBuffer.java:107) ~[stardog-7.3.2.jar:?]
	at com.stardog.starrocks.index.NativePipelineWriter.writeInternal(NativePipelineWriter.java:138) ~[stardog-7.3.2.jar:?]
	at com.stardog.starrocks.index.NativePipelineWriter.write(NativePipelineWriter.java:66) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.mvcc.rocks.NativeSingleThreadedUpdater.flush(NativeSingleThreadedUpdater.java:140) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.mvcc.rocks.NativeSingleThreadedUpdater.flush(NativeSingleThreadedUpdater.java:152) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.mvcc.rocks.NativeSingleThreadedUpdater.finish(NativeSingleThreadedUpdater.java:166) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.IndexUpdaters.update(IndexUpdaters.java:200) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.BaseIndexWriter.updateWithIteration(BaseIndexWriter.java:88) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.BaseIndexWriter.remove(BaseIndexWriter.java:142) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.index.Indexes.remove(Indexes.java:387) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.index.ConnectableIndexRWConnectionImpl$IndexResourceTransaction.apply(ConnectableIndexRWConnectionImpl.java:651) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.index.ConnectableIndexRWConnectionImpl.apply(ConnectableIndexRWConnectionImpl.java:366) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.ConnectableConnectionCollection.apply(ConnectableConnectionCollection.java:197) ~[stardog-7.3.2.jar:?]
	at com.complexible.stardog.db.DatabaseConnectionImpl.apply(DatabaseConnectionImpl.java:773) ~[stardog-7.3.2.jar:?]
	... 34 more

Andrea

4

I am happy to try something else.
Andrea

5

How long are your transactions? Are you holding them open during interactive user sessions?

6

Unfortunately, these queries are coupled with virtual graph queries of a large Postgres DB. And there are SPARQL Updates that we need to run ... and they run across millions of records. Lastly, we run data adds that involve thousands/a few million records.

So, the transactions can take some time.

I have recently moved the updates out of SPARQL and into code as we are constructing our named graphs.

Andrea

7

Ok, and one more question. Why were you using abort-on-commit? Are you using edge properties?

8

I was not aware that I was using abort-on-commit ... The updates were executed via pystardog. Is this something that I could/should change?

And, yes, we have edge properties.

Andrea

9

Any further replies on this?

Andrea

10

You will need to retry the transaction which fails due to a conflict. Alternatively you can append a new lastUpdated triple in each transaction and use the maximum value to reflect the most recent update. This would require periodic maintenance if you wish to avoid an ever-growing set of lastUpdated triples.