Re: TransactionManager ERROR There are now active transactions

[Andy Seaborne]

On 09/08/18 13:20, Mikael Pesonen wrote:

Does Fuseki info level log do?

No. It does not record the POST content.

[3] POST http://semantic-dev.lingsoft.fi:3030/ds


Was the database empty to start with?

It has all the traffic. Ive got a 400Mb log ready, zipped into 8Mb, here: https://www.dropbox.com/s/omig80fqutkkekk/log.zip?dl=0

Only up to the first error is needed.

"Apache Jena Fuseki 3.7.0"
This is odd : "Running in read-only mode for /ds"

    Andy

Br,


On 8.8.2018 12:16, Andy Seaborne wrote:

We need to recreate it with a debugger attached.

If you could collect the HTTP requests the scripts are making, then with a copy of the data, it might be possible to recreate the situation.

Otherwise it's "something happened".  I can't see how to recreate it without a use case.

    Andy


On 07/08/18 10:06, Mikael Pesonen wrote:

Are there any further tests I could do that might help solving this?

On 6.8.2018 14:01, aj...@apache.org wrote:

It tells us that the problem seems more likely to be with TDB than with
Fuseki, which is a step towards isolating it.

Adam

On Mon, Aug 6, 2018, 5:55 AM Mikael Pesonen <mikael.peso...@lingsoft.fi>

wrote:

With in-memory db everything works. Ran ~50000 operations x10 (10
scripts in parallel) and no problems. Mem usage was 3g-5,5g (java
xmx4000) and vm 10g.

So what does this tell? System is upcloud server so there shouldn't be
any issues with disk there...

Br,


On 3.8.2018 16:33, ajs6f wrote:

That seems a bit strange. I would think that the single dataset lock and

multiple-reader-or-single-writer policy would guard against this-- only one thread (request) can mutate the dataset at a time. Or is this a problem

with TDB? Do you see this occurring with in-memory datasets?

ajs6f

On Aug 3, 2018, at 8:01 AM, Mikael Pesonen <mikael.peso...@lingsoft.fi>

wrote:

Easier fix that sleeping was to add system wide semaphore which puts

all concurrent requests to single queue.

So the problem is in the way how Fuseki handles situation where

(concurrent) requests are coming in faster that it can process it. Usually

there are 2 ways to handle that: return error to client or sleep until
there is more space in request queue.

Br

On 2.8.2018 17:18, Andy Seaborne wrote:

On 02/08/18 12:56, Mikael Pesonen wrote:

I dont have any configuration, so it's default?

Command line:

/usr/bin/java -Dlog4j.configuration=file:...log4j.properties

-Xmx5600M -jar fuseki-server.jar --update --port 3030
--loc=...jena_data_test/ /ds

log4j.properties is default except couple of INFO -> WARN



On 2.8.2018 12:56, Andy Seaborne wrote:

Fuseki configuration?

The stacktrace isn't GSP.

Im only calling /ds endpoint with php+curl

It says "SPARQL_Update.perform" so it is not GSP.

https://www.w3.org/TR/sparql11-http-rdf-update/

I'm not able to produce a sendable script that
would case these errors.

It (still) looks like there is an environment factor.

      Andy


On 02/08/18 10:41, Mikael Pesonen wrote:

3.7.0.

On 2.8.2018 12:40, Andy Seaborne wrote:

version?

On 02/08/18 10:06, Mikael Pesonen wrote:

It does happen in our test environment on high load quite often.

More sleep I put in the test script, less frequently error happens.

Most of the time transactions are executed after the error, but

not always. Fuseki never returns error. Rarely below error happens, don't

know if it's related.

I'm not able to produce a sendable script that would case these

errors.

So as a fix I'm planning just to add enough sleep between every

Fuseki call. 50-100ms seems to work.

org.apache.jena.query.QueryException: Secondary index duplicate:

GSPO->GPOS -> [[0000000000A9D430], [0000000015AFB422], [0000000000002602],

[04007E280A6A5DC0]]

           at

org.apache.jena.sparql.lang.ParserARQUpdate._parse(ParserARQUpdate.java:78)

           at

org.apache.jena.sparql.lang.ParserARQUpdate.parse$(ParserARQUpdate.java:45)

           at

org.apache.jena.sparql.lang.UpdateParser.parse(UpdateParser.java:48)

           at

org.apache.jena.update.UpdateAction.parseExecute(UpdateAction.java:421)

           at

org.apache.jena.update.UpdateAction.parseExecute(UpdateAction.java:380)

           at

org.apache.jena.fuseki.servlets.SPARQL_Update.execute(SPARQL_Update.java:234)

           at

org.apache.jena.fuseki.servlets.SPARQL_Update.executeBody(SPARQL_Update.java:189)

           at

org.apache.jena.fuseki.servlets.SPARQL_Update.perform(SPARQL_Update.java:106)

           at

org.apache.jena.fuseki.servlets.ActionService.executeLifecycle(ActionService.java:192)

           at

org.apache.jena.fuseki.servlets.ActionService.execCommonWorker(ActionService.java:106)

           at

org.apache.jena.fuseki.servlets.ActionBase.doCommon(ActionBase.java:73)

           at

org.apache.jena.fuseki.servlets.FusekiFilter.doFilter(FusekiFilter.java:73)

           at

org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)

           at

org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61)

           at

org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)

           at

org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)

           at

org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)

           at

org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)

           at

org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449)

           at

org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)

           at

org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)

           at

org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)

           at

org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383)

           at

org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)

           at

org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)

           at

org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)

           at

org.apache.jena.fuseki.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:285)

           at

org.apache.jena.fuseki.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:248)

           at

org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1629)

           at

org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)

           at

org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)

           at

org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)

           at

org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

           at

org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)

           at

org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)

           at

org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)

           at

org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)

           at

org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)

           at

org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)

           at

org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)

           at

org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)

           at

org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)

           at

org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

           at

org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:455)

           at

org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

           at

org.eclipse.jetty.server.Server.handle(Server.java:561)

           at

org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:334)

           at

org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)

           at org.eclipse.jetty.io

.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)

           at org.eclipse.jetty.io

.FillInterest.fillable(FillInterest.java:104)

           at org.eclipse.jetty.io

.ChannelEndPoint$2.run(ChannelEndPoint.java:124)

           at

org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)

           at

org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)

           at

org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)

           at

org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:243)

           at

org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)

           at

org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)

           at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.jena.tdb.TDBException: Secondary index

duplicate: GSPO->GPOS -> [[0000000000A9D430], [0000000015AFB422],
[0000000000002602], [04007E280A6A5DC0]]

           at

org.apache.jena.tdb.store.tupletable.TupleTable.add(TupleTable.java:103)

           at

org.apache.jena.tdb.store.nodetupletable.NodeTupleTableConcrete.addRow(NodeTupleTableConcrete.java:88)

           at

org.apache.jena.tdb.store.QuadTable.add(QuadTable.java:60)

           at

org.apache.jena.tdb.store.DatasetGraphTDB.addToNamedGraph(DatasetGraphTDB.java:97)

           at

org.apache.jena.sparql.core.DatasetGraphTriplesQuads.add(DatasetGraphTriplesQuads.java:44)

           at

org.apache.jena.sparql.core.DatasetGraphTriplesQuads.add(DatasetGraphTriplesQuads.java:31)

           at

org.apache.jena.sparql.core.DatasetGraphWrapper.add(DatasetGraphWrapper.java:116)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.addToDatasetGraph(UpdateEngineWorker.java:539)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.lambda$execInsert$4(UpdateEngineWorker.java:532)

           at

java.util.Iterator.forEachRemaining(Iterator.java:116)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.execInsert(UpdateEngineWorker.java:532)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.execInsert(UpdateEngineWorker.java:521)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.visit(UpdateEngineWorker.java:418)

           at

org.apache.jena.sparql.modify.request.UpdateModify.visit(UpdateModify.java:100)

           at

org.apache.jena.sparql.modify.UpdateVisitorSink.send(UpdateVisitorSink.java:46)

           at

org.apache.jena.sparql.modify.UpdateVisitorSink.send(UpdateVisitorSink.java:26)

           at

org.apache.jena.sparql.modify.UsingUpdateSink.send(UsingUpdateSink.java:61)

           at

org.apache.jena.sparql.modify.UsingUpdateSink.send(UsingUpdateSink.java:31)

           at

org.apache.jena.sparql.lang.SPARQLParserBase.emitUpdate(SPARQLParserBase.java:189)

           at

org.apache.jena.sparql.lang.arq.ARQParser.Update1(ARQParser.java:1491)

           at

org.apache.jena.sparql.lang.arq.ARQParser.Update(ARQParser.java:1419)

           at

org.apache.jena.sparql.lang.arq.ARQParser.UpdateUnit(ARQParser.java:52)

           at

org.apache.jena.sparql.lang.ParserARQUpdate._parse(ParserARQUpdate.java:62)

           ... 57 more

org.apache.jena.query.QueryException: Secondary index duplicate:

GSPO->GPOS -> [[0000000000A9D430], [0000000015AFB422], [0000000000002602],

[04007E280A6A5DC0]]

           at

org.apache.jena.sparql.lang.ParserARQUpdate._parse(ParserARQUpdate.java:78)

           at

org.apache.jena.sparql.lang.ParserARQUpdate.parse$(ParserARQUpdate.java:45)

           at

org.apache.jena.sparql.lang.UpdateParser.parse(UpdateParser.java:48)

           at

org.apache.jena.update.UpdateAction.parseExecute(UpdateAction.java:421)

           at

org.apache.jena.update.UpdateAction.parseExecute(UpdateAction.java:380)

           at

org.apache.jena.fuseki.servlets.SPARQL_Update.execute(SPARQL_Update.java:234)

           at

org.apache.jena.fuseki.servlets.SPARQL_Update.executeBody(SPARQL_Update.java:189)

           at

org.apache.jena.fuseki.servlets.SPARQL_Update.perform(SPARQL_Update.java:106)

           at

org.apache.jena.fuseki.servlets.ActionService.executeLifecycle(ActionService.java:192)

           at

org.apache.jena.fuseki.servlets.ActionService.execCommonWorker(ActionService.java:106)

           at

org.apache.jena.fuseki.servlets.ActionBase.doCommon(ActionBase.java:73)

           at

org.apache.jena.fuseki.servlets.FusekiFilter.doFilter(FusekiFilter.java:73)

           at

org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)

           at

org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61)

           at

org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108)

           at

org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137)

           at

org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)

           at

org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66)

           at

org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449)

           at

org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)

           at

org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)

           at

org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)

           at

org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383)

           at

org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)

           at

org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)

           at

org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1637)

           at

org.apache.jena.fuseki.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:285)

           at

org.apache.jena.fuseki.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:248)

           at

org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1629)

           at

org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)

           at

org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)

           at

org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)

           at

org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

           at

org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:190)

           at

org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)

           at

org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)

           at

org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1253)

           at

org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)

           at

org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)

           at

org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)

           at

org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)

           at

org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1155)

           at

org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)

           at

org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:455)

           at

org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)

           at

org.eclipse.jetty.server.Server.handle(Server.java:561)

           at

org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:334)

           at

org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)

           at org.eclipse.jetty.io

.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)

           at org.eclipse.jetty.io

.FillInterest.fillable(FillInterest.java:104)

           at org.eclipse.jetty.io

.ChannelEndPoint$2.run(ChannelEndPoint.java:124)

           at

org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)

           at

org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)

           at

org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)

           at

org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:243)

           at

org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)

           at

org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)

           at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.jena.tdb.TDBException: Secondary index

duplicate: GSPO->GPOS -> [[0000000000A9D430], [0000000015AFB422],
[0000000000002602], [04007E280A6A5DC0]]

           at

org.apache.jena.tdb.store.tupletable.TupleTable.add(TupleTable.java:103)

           at

org.apache.jena.tdb.store.nodetupletable.NodeTupleTableConcrete.addRow(NodeTupleTableConcrete.java:88)

           at

org.apache.jena.tdb.store.QuadTable.add(QuadTable.java:60)

           at

org.apache.jena.tdb.store.DatasetGraphTDB.addToNamedGraph(DatasetGraphTDB.java:97)

           at

org.apache.jena.sparql.core.DatasetGraphTriplesQuads.add(DatasetGraphTriplesQuads.java:44)

           at

org.apache.jena.sparql.core.DatasetGraphTriplesQuads.add(DatasetGraphTriplesQuads.java:31)

           at

org.apache.jena.sparql.core.DatasetGraphWrapper.add(DatasetGraphWrapper.java:116)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.addToDatasetGraph(UpdateEngineWorker.java:539)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.lambda$execInsert$4(UpdateEngineWorker.java:532)

           at

java.util.Iterator.forEachRemaining(Iterator.java:116)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.execInsert(UpdateEngineWorker.java:532)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.execInsert(UpdateEngineWorker.java:521)

           at

org.apache.jena.sparql.modify.UpdateEngineWorker.visit(UpdateEngineWorker.java:418)

           at

org.apache.jena.sparql.modify.request.UpdateModify.visit(UpdateModify.java:100)

           at

org.apache.jena.sparql.modify.UpdateVisitorSink.send(UpdateVisitorSink.java:46)

           at

org.apache.jena.sparql.modify.UpdateVisitorSink.send(UpdateVisitorSink.java:26)

           at

org.apache.jena.sparql.modify.UsingUpdateSink.send(UsingUpdateSink.java:61)

           at

org.apache.jena.sparql.modify.UsingUpdateSink.send(UsingUpdateSink.java:31)

           at

org.apache.jena.sparql.lang.SPARQLParserBase.emitUpdate(SPARQLParserBase.java:189)

           at

org.apache.jena.sparql.lang.arq.ARQParser.Update1(ARQParser.java:1491)

           at

org.apache.jena.sparql.lang.arq.ARQParser.Update(ARQParser.java:1419)

           at

org.apache.jena.sparql.lang.arq.ARQParser.UpdateUnit(ARQParser.java:52)

           at

org.apache.jena.sparql.lang.ParserARQUpdate._parse(ParserARQUpdate.java:62)

           ... 57 more


On 2.8.2018 11:03, Andy Seaborne wrote:

(subject line changed - this is not the original thread report)

On 01/08/18 10:32, Mikael Pesonen wrote:

Hi,

is it somehow possible to get this error (TransactionManager

ERROR There are now active transactions ) from Fuseki GSP so that client

could sleep and retry later allowing db to finish the transaction?

No - it's an internal consistency check.

Does the transaction still happen?

Do you have a reproducible script to make this happen? I've

never seen it occur.

      Andy

On 19.6.2018 23:56, Andy Seaborne wrote:

On 18/06/18 11:36, Mikael Pesonen wrote:

On 18.6.2018 13:30, Andy Seaborne wrote:

On 18/06/18 10:55, Mikael Pesonen wrote:

Hi Andy,

On 18.6.2018 12:05, Andy Seaborne wrote:

errors occur less than before.

which errors?

     TransactionManager ERROR There are now active transactions

This occurs when Im inserting new data and trying to read it

right away (get empty result), or deleting data and trying to read it to

make sure it's deleted (get data that should be deleted). There are no
other errors in the log.

  From looking at the code, I can't see how that happens - is

it now possible to provide a reproducible script so that I can run it on

machine?

      Andy

-ku
FINLAND

--
Lingsoft - 30 years of Leading Language Management

www.lingsoft.fi

Speech Applications - Language Management - Translation - Reader's and

Writer's Tools - Text Tools - E-books and M-books

Mikael Pesonen
System Engineer

e-mail: mikael.peso...@lingsoft.fi
Tel. +358 2 279 3300

Time zone: GMT+2

Helsinki Office
Eteläranta 10
FI-00130 Helsinki
FINLAND

Turku Office
Kauppiaskatu 5 A
FI-20100 Turku
FINLAND

--
Lingsoft - 30 years of Leading Language Management

www.lingsoft.fi

Speech Applications - Language Management - Translation - Reader's and
Writer's Tools - Text Tools - E-books and M-books

Mikael Pesonen
System Engineer

e-mail: mikael.peso...@lingsoft.fi
Tel. +358 2 279 3300

Time zone: GMT+2

Helsinki Office
Eteläranta 10
FI-00130 Helsinki
FINLAND

Turku Office
Kauppiaskatu 5 A
FI-20100 Turku
FINLAND