Are you running with debug tracing on? Andy
On 17/10/16 11:30, Dick Murray wrote:
Hi. I'm getting odd behaviour in Jena when I execute the same query concurrently. The query has an optional which is unmatched but which appears to cause a java.lang.String exception from the atlas code. This only happens if multiple queries are submitted concurrently and closely. On a "fast" host both queries will typically fail but on a slower host (VirtualBox with throttled cpu) the first query will return but the second will fail. If I siege with 10 threads and a random delay of 2 seconds some queries will succeed. Which makes it seem like a timing issue. The crux appears to be the optional, remove it and I can siege (10 threads, 50 iterations) without any issues, with the optional I get exceptions. I originally thought it was the application/json format but returning text/plain causes the exception and the root cause appears to be something in the atlas code passing in the wrong index to create a new String. To test if I run (Ubuntu 16.04 desktop) i.e. the same query concurrently twice; wget -O q1 --header "accept: text/plain" " http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/> SELECT * WHERE { GRAPH <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { { ?equipment dxf:attribute ?attribute } . OPTIONAL { ?tier_two_containment dxf:no_such_property ?equipment ; dxf:still_no_such_property ?department_area }}}" & wget -O q2 --header "accept: text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/> SELECT * WHERE { GRAPH <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { { ?equipment dxf:attribute ?attribute } . OPTIONAL { ?tier_two_containment dxf:no_such_property ?equipment ; dxf:still_no_such_property ?department_area }}}" the q1 output will show the correct result but q2 will either be 0 bytes or truncated and the following exception is show. dick@Dick-M3800:/media/dick/Backup1/bc$ wget -O q1 --header "accept: text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/> SELECT * WHERE { GRAPH <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { { ?equipment dxf:attribute ?attribute } . OPTIONAL { ?tier_two_containment dxf:no_such_property ?equipment ; dxf:still_no_such_property ?department_area }}}" & wget -O q2 --header "accept: text/plain" " http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/> SELECT * WHERE { GRAPH <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { { ?equipment dxf:attribute ?attribute } . OPTIONAL { ?tier_two_containment dxf:no_such_property ?equipment ; dxf:still_no_such_property ?department_area }}}" [1] 7594 --2016-10-17 11:03:21-- http://localhost:8080/tdb/sparql?query=PREFIX%20dxf:%20%3Curn:iungo:dxf/%3E%20SELECT%20*%20WHERE%20%7B%20GRAPH%20%3Curn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4%3E%20%7B%20%7B%20?equipment%20dxf:attribute%20?attribute%20%20%7D%20.%20OPTIONAL%20%7B%20?tier_two_containment%20dxf:no_such_property%20?equipment%20;%20dxf:still_no_such_property%20?department_area%20%7D%7D%7D Resolving localhost (localhost)... --2016-10-17 11:03:21-- http://localhost:8080/tdb/sparql?query=PREFIX%20dxf:%20%3Curn:iungo:dxf/%3E%20SELECT%20*%20WHERE%20%7B%20GRAPH%20%3Curn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4%3E%20%7B%20%7B%20?equipment%20dxf:attribute%20?attribute%20%20%7D%20.%20OPTIONAL%20%7B%20?tier_two_containment%20dxf:no_such_property%20?equipment%20;%20dxf:still_no_such_property%20?department_area%20%7D%7D%7D Resolving localhost (localhost)... 127.0.0.1127.0.0.1 Connecting to localhost (localhost)|127.0.0.1|:8080... Connecting to localhost (localhost)|127.0.0.1|:8080... connected. connected. HTTP request sent, awaiting response... HTTP request sent, awaiting response... 200 OK 200 OK Length: Length: 00 [text/plain] [text/plain] Saving to: ‘q1’ Saving to: ‘q2’ q1 [ <=> ] 0 --.-KB/s in 0s q2 [ <=> ] 0 --.-KB/s in 0s 2016-10-17 11:03:22 (0.00 B/s) - ‘q1’ saved [0/0] 2016-10-17 11:03:22 (0.00 B/s) - ‘q2’ saved [0/0] and an exception is thrown from java.lang.String Exception java.lang.StringIndexOutOfBoundsException: String index out of range: 247 [java] java.lang.String.<init>(String.java:205) [java] java.lang.StringBuilder.toString(StringBuilder.java:407) [java] org.apache.jena.atlas.iterator.AccString.get(AccString.java:52) [java] org.apache.jena.atlas.iterator.AccString.get(AccString.java:21) [java] org.apache.jena.atlas.iterator.Iter.reduce(Iter.java:165) [java] org.apache.jena.atlas.iterator.Iter.asString(Iter.java:483) [java] org.apache.jena.atlas.iterator.Iter.asString(Iter.java:479) [java] org.apache.jena.sparql.engine.optimizer.reorder.ReorderTransformationSubstitution.reorder(ReorderTransformationSubstitution.java:85) [java] org.apache.jena.sparql.engine.optimizer.reorder.ReorderTransformationSubstitution.reorderIndexes(ReorderTransformationSubstitution.java:69) [java] org.apache.jena.tdb.solver.OpExecutorTDB1.reorder(OpExecutorTDB1.java:276) [java] org.apache.jena.tdb.solver.OpExecutorTDB1.optimizeExecuteQuads(OpExecutorTDB1.java:230) [java] org.apache.jena.tdb.solver.OpExecutorTDB1.execute(OpExecutorTDB1.java:148) [java] org.apache.jena.sparql.engine.main.ExecutionDispatch.visit(ExecutionDispatch.java:66) [java] org.apache.jena.sparql.algebra.op.OpQuadPattern.visit(OpQuadPattern.java:95) [java] org.apache.jena.sparql.engine.main.ExecutionDispatch.exec(ExecutionDispatch.java:46) [java] org.apache.jena.sparql.engine.main.OpExecutor.exec(OpExecutor.java:118) [java] org.apache.jena.tdb.solver.OpExecutorTDB1.exec(OpExecutorTDB1.java:87) [java] org.apache.jena.sparql.engine.main.OpExecutor.execute(OpExecutor.java:89) [java] org.apache.jena.sparql.engine.main.QC.execute(QC.java:52) [java] org.apache.jena.sparql.engine.main.iterator.QueryIterOptionalIndex.nextStage(QueryIterOptionalIndex.java:51) [java] org.apache.jena.sparql.engine.iterator.QueryIterRepeatApply.makeNextStage(QueryIterRepeatApply.java:108) [java] org.apache.jena.sparql.engine.iterator.QueryIterRepeatApply.hasNextBinding(QueryIterRepeatApply.java:65) [java] org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:111) [java] org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:39) [java] org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:111) [java] org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:39) [java] org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:111) [java] org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.hasNextBinding(QueryIteratorWrapper.java:39) [java] org.apache.jena.sparql.engine.iterator.QueryIteratorBase.hasNext(QueryIteratorBase.java:111) [java] org.apache.jena.sparql.engine.ResultSetStream.hasNext(ResultSetStream.java:74) [java] org.apache.jena.sparql.engine.ResultSetCheckCondition.hasNext(ResultSetCheckCondition.java:59) [java] org.apache.jena.sparql.resultset.ResultSetMem.<init>(ResultSetMem.java:86) [java] org.apache.jena.query.ResultSetFactory.makeRewindable(ResultSetFactory.java:404) [java] org.apache.jena.sparql.resultset.TextOutput.write(TextOutput.java:145) [java] org.apache.jena.sparql.resultset.TextOutput.write(TextOutput.java:130) [java] org.apache.jena.sparql.resultset.TextOutput.write(TextOutput.java:118) [java] org.apache.jena.sparql.resultset.TextOutput.format(TextOutput.java:66) However if I run; wget -O q1 --header "accept: text/plain" " http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/> SELECT * WHERE { GRAPH <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { { ?equipment dxf:attribute ?attribute } . }}" & wget -O q2 --header "accept: text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/> SELECT * WHERE { GRAPH <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { { ?equipment dxf:attribute ?attribute } . }}" i.e. I remove the optional clause both queries return... dick@Dick-M3800:/media/dick/Backup1/bc$ wget -O q1 --header "accept: text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/> SELECT * WHERE { GRAPH <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { { ?equipment dxf:attribute ?attribute } . }}" & wget -O q2 --header "accept: text/plain" "http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/> SELECT * WHERE { GRAPH <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { { ?equipment dxf:attribute ?attribute } . }}" [1] 7898 --2016-10-17 11:14:27-- http://localhost:8080/tdb/sparql?query=PREFIX%20dxf:%20%3Curn:iungo:dxf/%3E%20SELECT%20*%20WHERE%20%7B%20GRAPH%20%3Curn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4%3E%20%7B%20%7B%20?equipment%20dxf:attribute%20?attribute%20%20%7D%20.%20%7D%7D Resolving localhost (localhost)... --2016-10-17 11:14:27-- http://localhost:8080/tdb/sparql?query=PREFIX%20dxf:%20%3Curn:iungo:dxf/%3E%20SELECT%20*%20WHERE%20%7B%20GRAPH%20%3Curn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4%3E%20%7B%20%7B%20?equipment%20dxf:attribute%20?attribute%20%20%7D%20.%20%7D%7D Resolving localhost (localhost)... 127.0.0.1 Connecting to localhost (localhost)|127.0.0.1|:8080... connected. HTTP request sent, awaiting response... 127.0.0.1 Connecting to localhost (localhost)|127.0.0.1|:8080... connected. HTTP request sent, awaiting response... 200 OK 200 OK Length: Length: unspecifiedunspecified [text/plain] [text/plain] Saving to: ‘q2’ Saving to: ‘q1’ q2 [<=> ] 0 --.-KB/s qq1 [ <=> ] 438.81K --.-KB/s in 0.05s 2016-10-17 11:14:28 (8.19 MB/s) - ‘q1’ saved [449344] q2 [ <=> ] 438.81K --.-KB/s in 0.05s 2016-10-17 11:14:28 (8.09 MB/s) - ‘q2’ saved [449344] [1]+ Done wget -O q1 --header "accept: text/plain" " http://localhost:8080/tdb/sparql?query=PREFIX dxf: <urn:iungo:dxf/> SELECT * WHERE { GRAPH <urn:iungo:dxf/graph/309ea4ce-dbdf-4d92-9828-1d99d35d0bb4> { { ?equipment dxf:attribute ?attribute } . }}" dick@Dick-M3800:/media/dick/Backup1/bc$