On 17 Oct 2016 21:33, "Andy Seaborne" <a...@apache.org> wrote:
>
>
>
> 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() ;
Based on the static, it must be set explicitly (and I'm pretty sure I'm not
setting that) or picking up a hierarchical debug...
static public final Logger log =
LoggerFactory.getLogger(ReorderTransformationSubstitution.class) ;
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$
>>>>
>>
