Re: Concurrent read with unmatched optional clause causes exception in Jena 3.1.

Andy Seaborne Mon, 17 Oct 2016 13:34:35 -0700


On 17/10/16 21:13, Dick Murray wrote:

Hi.

On 17 Oct 2016 18:16, "Andy Seaborne" <a...@apache.org> wrote:


Are you running with debug tracing on?


No, should I and what should I look for..?


I asked because that point in the code ...


>>>      [java] org.apache.jena.atlas.iterator.Iter.asString(Iter.java:479)
>>>      [java]
>>>

>org.apache.jena.sparql.engine.optimizer.reorder.ReorderTransformationSubstitution.reorder(ReorderTransformationSubstitution.java:85)

>>>

Object field:
private final boolean DEBUG = log.isDebugEnabled() ;

then line 85:

 if ( DEBUG )
   log.debug("Reorder: "+Iter.asString(components, formatter)) ;

The formatter is, mistakenly, shared because it an object field.

But to get there, DEBUG has to be true.

So it seems log.isDebugEnabled() is true.

        Andy


    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$

Re: Concurrent read with unmatched optional clause causes exception in Jena 3.1.

Reply via email to