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

Andy Seaborne Tue, 18 Oct 2016 03:25:18 -0700


On 18/10/16 10:59, Dick Murray wrote:

Found the cause and I hate log4j...

Log4j was unable to find it's configuration file so was quietly defaulting
the RootLogger to debug. So when static public final Logger log =
LoggerFactory.getLogger(ReorderTransformationSubstitution.class) was called
it's parent is RootLogger and it's level is debug. So private final boolean
DEBUG = log.isDebugEnabled() sets DEBUG to true and under concurrent load
the exception is thrown.

I only found this because I set -Dlog4j.debug to see what was happening
because the logger level gets set "magically" (i.e. Eclipse IDE triggers a
breakpoint on the variable change seemingly randomly) after initialisation,
presumably because there's some delayed code run when the log4j framework
is touched.

The issue is repeatable without the log4j configuration but "fixed"
with -Dlog4j.configuration=file:///{path to configuration
file}/log4j.properties

Is it worth noting this behaviour somewhere?

Thanks for the point in the right direction.


Thanks for the report.  The code was simply doing the "wrong thing".

JENA-1247 completely removes the situation.  Twice over.

    Andy


Dick.

On 17 October 2016 at 21:33, Andy Seaborne <[email protected]> wrote:



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

Hi.

On 17 Oct 2016 18:16, "Andy Seaborne" <[email protected]> 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.ReorderTrans

formationSubstitution.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%3Cur

n: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%3Cur

n: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.ReorderTrans

formationSubstitution.reorder(ReorderTransformationSubstitution.java:85)

     [java]


org.apache.jena.sparql.engine.optimizer.reorder.ReorderTrans

formationSubstitution.reorderIndexes(ReorderTransfor
mationSubstitution.java:69)

     [java]


org.apache.jena.tdb.solver.OpExecutorTDB1.reorder(OpExecutor

TDB1.java:276)

     [java]


org.apache.jena.tdb.solver.OpExecutorTDB1.optimizeExecuteQua

ds(OpExecutorTDB1.java:230)

     [java]


org.apache.jena.tdb.solver.OpExecutorTDB1.execute(OpExecutor

TDB1.java:148)

     [java]


org.apache.jena.sparql.engine.main.ExecutionDispatch.visit(E

xecutionDispatch.java:66)

     [java]


org.apache.jena.sparql.algebra.op.OpQuadPattern.visit(

OpQuadPattern.java:95)

     [java]


org.apache.jena.sparql.engine.main.ExecutionDispatch.exec(Ex

ecutionDispatch.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(OpExec
utor.java:89)
     [java] org.apache.jena.sparql.engine.main.QC.execute(QC.java:52)
     [java]

org.apache.jena.sparql.engine.main.iterator.QueryIterOptiona

lIndex.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.has

Next(QueryIteratorBase.java:111)

     [java]


org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.

hasNextBinding(QueryIteratorWrapper.java:39)

     [java]


org.apache.jena.sparql.engine.iterator.QueryIteratorBase.has

Next(QueryIteratorBase.java:111)

     [java]


org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.

hasNextBinding(QueryIteratorWrapper.java:39)

     [java]


org.apache.jena.sparql.engine.iterator.QueryIteratorBase.has

Next(QueryIteratorBase.java:111)

     [java]


org.apache.jena.sparql.engine.iterator.QueryIteratorWrapper.

hasNextBinding(QueryIteratorWrapper.java:39)

     [java]


org.apache.jena.sparql.engine.iterator.QueryIteratorBase.has

Next(QueryIteratorBase.java:111)

     [java]


org.apache.jena.sparql.engine.ResultSetStream.hasNext(Result

SetStream.java:74)

     [java]


org.apache.jena.sparql.engine.ResultSetCheckCondition.hasNex

t(ResultSetCheckCondition.java:59)

     [java]


org.apache.jena.sparql.resultset.ResultSetMem.<init>(ResultS

etMem.java:86)

     [java]


org.apache.jena.query.ResultSetFactory.makeRewindable(Result

SetFactory.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%3Cur

n: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%3Cur

n: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