History | Log In     View a printable version of the current page. Get help!  
Issue Details [XML]

Key: SES-657
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Major Major
Assignee: Arjohn Kampman
Reporter: Nick Giles
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
Sesame

FILTER in a SPARQL query can stop it timing out properly

Created: 12/Jan/09 05:37 PM   Updated: 04/Jun/09 08:24 AM
Component/s: SPARQL
Affects Version/s: 2.2.2
Fix Version/s: 2.3-pr1


 Description   
Running a query with a FILTER section in can cause it to continue beyond the timeout set in the query. It appears this is because the FILTER operation may be long running, and will not check against the timeout.

 All   Comments   Change History      Sort Order:
Comment by Arjohn Kampman [16/Jan/09 09:02 AM]
Scheduling for investigation in 2.2.4.

Comment by Arjohn Kampman [16/Jan/09 09:03 AM]
I assume the 'long runnig FILTER operation' is a sub-query?

Comment by Nick Giles [16/Jan/09 11:07 AM]
Particular cases:

PREFIX foo: <http://foo.bar/someOntology#>
PREFIX xsd: <http://www.w3.org/2001/XMLSchema#>

SELECT ?node1 ?node2 ?nid1 WHERE {
 ?circuit1 a foo:Circuit .
 ?circuit2 a foo:Circuit .
 FILTER ( ?circuit1 != ?circuit2) .

 ?circuit1 foo:circuitId ?cid1 .
 ?circuit2 foo:circuitId ?cid2 .
 FILTER ( ?cid1 = ?cid2 )
}

PREFIX foo: <http://foo.bar/someOntology#>
PREFIX xsd: <http://www.w3.org/2001/XMLSchema#>

SELECT ?circuit1 ?circuit2 ?cid1 WHERE {
 ?circuit1 a foo:Circuit .
 ?circuit2 a foo:Circuit .
 FILTER ( ?circuit1 != ?circuit2) .

 ?circuit1 foo:circuitId ?cid1 .
 ?circuit2 foo:circuitId ?cid2 .
 FILTER ( ?cid1 = ?cid2 )
}

PREFIX foo: <http://foo.bar/someOntology#>
PREFIX xsd: <http://www.w3.org/2001/XMLSchema#>

SELECT ?interface1 ?interface2 ?ifnr ?nodeId WHERE {
 ?interface1 a foo:Interface .
 ?interface2 a foo:Interface .
 FILTER ( ?interface1 != ?interface2) .

 ?interface1 foo:interfaceNumber ?ifnr .
 ?interface2 foo:interfaceNumber ?ifnr .

 ?node1 foo:hasInterface ?interface1 .
 ?node2 foo:hasInterface ?interface2 .
 
 ?node1 foo:nodeId ?nodeId .
 ?node2 foo:nodeId ?nodeId

}


What is hopefully the relevant piece of stack trace from the first query:

 at java.util.HashMap.size(HashMap.java:268)
        at java.util.HashMap.putAll(HashMap.java:498)
        at org.openrdf.query.algebra.evaluation.QueryBindingSet.addAll(QueryBindingSet.java:61)
        at org.openrdf.query.algebra.evaluation.QueryBindingSet.<init>(QueryBindingSet.java:52)
        at org.openrdf.query.algebra.evaluation.impl.EvaluationStrategyImpl$3.convert(EvaluationStrategyImpl.java:299)
        at org.openrdf.query.algebra.evaluation.impl.EvaluationStrategyImpl$3.convert(EvaluationStrategyImpl.java:295)
        at info.aduna.iteration.ConvertingIteration.next(ConvertingIteration.java:77)
        at org.openrdf.query.algebra.evaluation.iterator.JoinIterator.getNextElement(JoinIterator.java:60)
        at org.openrdf.query.algebra.evaluation.iterator.JoinIterator.getNextElement(JoinIterator.java:19)
        at info.aduna.iteration.LookAheadIteration.lookAhead(LookAheadIteration.java:80)
        at info.aduna.iteration.LookAheadIteration.hasNext(LookAheadIteration.java:49)
        at info.aduna.iteration.IterationWrapper.hasNext(IterationWrapper.java:57)
        at info.aduna.iteration.FilterIteration.findNextElement(FilterIteration.java:68)
        at info.aduna.iteration.FilterIteration.hasNext(FilterIteration.java:43)
        at info.aduna.iteration.IterationWrapper.hasNext(IterationWrapper.java:57)
        at info.aduna.iteration.FilterIteration.findNextElement(FilterIteration.java:68)
        at info.aduna.iteration.FilterIteration.hasNext(FilterIteration.java:43)
        at org.openrdf.query.algebra.evaluation.iterator.JoinIterator.getNextElement(JoinIterator.java:58)
        at org.openrdf.query.algebra.evaluation.iterator.JoinIterator.getNextElement(JoinIterator.java:19)
        at info.aduna.iteration.LookAheadIteration.lookAhead(LookAheadIteration.java:80)
        at info.aduna.iteration.LookAheadIteration.hasNext(LookAheadIteration.java:49)
        at info.aduna.iteration.ConvertingIteration.hasNext(ConvertingIteration.java:62)
        at info.aduna.iteration.IterationWrapper.hasNext(IterationWrapper.java:57)
        at info.aduna.iteration.LockingIteration.hasNext(LockingIteration.java:61)
        - locked <0x00007ff5a9ba83e8> (a info.aduna.iteration.LockingIteration)
        at info.aduna.iteration.IterationWrapper.hasNext(IterationWrapper.java:57)
        at org.openrdf.sail.helpers.SailBaseIteration.hasNext(SailBaseIteration.java:50)
        at info.aduna.iteration.IterationWrapper.hasNext(IterationWrapper.java:57)
        at info.aduna.iteration.TimeLimitIteration.hasNext(TimeLimitIteration.java:57)
        - locked <0x00007ff5a9bb81e0> (a org.openrdf.repository.sail.SailQuery$QueryInterruptIteration)
        at org.openrdf.query.impl.TupleQueryResultImpl.hasNext(TupleQueryResultImpl.java:90)

Comment by Nick Giles [16/Jan/09 11:09 AM]
The interrupt thread that goes with that:

Comment by Nick Giles [16/Jan/09 11:09 AM]
"TimeLimitIteration" daemon prio=10 tid=0x00007ff5047cdc00 nid=0x288d waiting for monitor entry [0x0000000042feb000..0x0000000042febc20]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at info.aduna.iteration.TimeLimitIteration.interrupt(TimeLimitIteration.java:103)
        - waiting to lock <0x00007ff5a9bb81e0> (a org.openrdf.repository.sail.SailQuery$QueryInterruptIteration)
        at info.aduna.iteration.TimeLimitIteration.access$000(TimeLimitIteration.java:19)
        at info.aduna.iteration.TimeLimitIteration$1.run(TimeLimitIteration.java:45)
        at java.util.TimerThread.mainLoop(Timer.java:512)
        at java.util.TimerThread.run(Timer.java:462)

Comment by Arjohn Kampman [02/Feb/09 09:04 PM]
TimeLimitIterator, which is responsible for stopping the query evaluation, used a bad synchronization scheme causing the time-out to block until the evaluation returned from referenced iteration.