Consistency between plan "resultSizeActual" and real result size #5129

laurgarn · 2024-09-18T14:39:17Z

laurgarn
Sep 18, 2024

Is it considered acceptable that an explanation (that did not timeout) resultSizeActual can be (far) bigger than the actual result (without explanation) ?
I don't know if I have to report this kind of inconsistency as an issue.

As an example, I get :
Catalog played. #failed:0 #ok:50 timed out:2
2024-09-18T14:16:05.976824548Z querying 'BPd'...... for explanation ...
Order (resultSizeActual=66.8K, totalTimeActual=483ms, selfTimeActual=194ms)
[...]
explained query took 0s for 66 <- real call following an explain that had not timed out and has a resultSizeActual > 0

hmottestad · 2024-09-19T09:01:18Z

hmottestad
Sep 19, 2024
Maintainer

Can you post the SPARQL query and the entire query explanation?

0 replies

laurgarn · 2024-09-19T10:33:09Z

laurgarn
Sep 19, 2024
Author

I hope it will fit in a comment :

select ?nameSjb1 ?idCN1 ?nbTerm ?idTerm3
where {
    {
        select ?nameSjb1 ?idCN1 (count(?idTermOfCN) as ?nbTerm)
        where {
            ?idSjb1 rdf:type cim:BusbarSection .
            ?idTerm1 cim:Terminal.ConductingEquipment ?idSjb1 .
            ?idTerm1 cim:Terminal.ConnectivityNode ?idCN1 .
            ?idTermOfCN cim:Terminal.ConnectivityNode ?idCN1
            OPTIONAL { ?idSjb1 cim:IdentifiedObject.name ?nameSjb1 . }
        }
        group by ?nameSjb1 ?idCN1
        having (?nbTerm < 3)
    }
    ?idTerm3 cim:Terminal.ConnectivityNode ?idCN1
}
order by ?nbTerm ?nameSjb1 ?idTerm3

Order (resultSizeActual=66.8K, totalTimeActual=776ms, selfTimeActual=490ms)
   OrderElem (ASC)
      Var (name=nbTerm)
   OrderElem (ASC)
      Var (name=nameSjb1)
   OrderElem (ASC)
      Var (name=idTerm3)
   Projection (resultSizeActual=66.8K, totalTimeActual=286ms, selfTimeActual=18.7ms)
   ├── ProjectionElemList
   │     ProjectionElem "nameSjb1"
   │     ProjectionElem "idCN1"
   │     ProjectionElem "nbTerm"
   │     ProjectionElem "idTerm3"
   └── Join (JoinIterator) (resultSizeActual=66.8K, totalTimeActual=267ms, selfTimeActual=19.9ms)
      ╠══ Projection (new scope) (resultSizeActual=12.2K, totalTimeActual=221ms, selfTimeActual=7.13ms) [left]
      ║  ├── ProjectionElemList
      ║  │     ProjectionElem "nameSjb1"
      ║  │     ProjectionElem "idCN1"
      ║  │     ProjectionElem "nbTerm"
      ║  └── Extension (resultSizeActual=12.2K, totalTimeActual=214ms, selfTimeActual=3.42ms)
      ║     ╠══ Extension (resultSizeActual=12.2K, totalTimeActual=210ms, selfTimeActual=4.6ms)
      ║     ║     Group (nameSjb1, idCN1) (resultSizeActual=12.2K, totalTimeActual=206ms, selfTimeActual=34.3ms)
      ║     ║     ╠══ LeftJoin (LeftJoinIterator) (resultSizeActual=66.8K, totalTimeActual=171ms, selfTimeActual=43.6ms)
      ║     ║     ║  ├── Join (JoinIterator) (resultSizeActual=66.8K, totalTimeActual=109ms, selfTimeActual=20.7ms) [left]
      ║     ║     ║  │  ╠══ StatementPattern (costEstimate=6.1K, resultSizeEstimate=12.3K, resultSizeActual=12.2K, totalTimeActual=4.58ms, selfTimeActual=4.58ms) [left]
      ║     ║     ║  │  ║     s: Var (name=idSjb1)
      ║     ║     ║  │  ║     p: Var (name=_const_f5e5585a_uri, value=http://www.w3.org/1999/02/22-rdf-syntax-ns#type, anonymous)
      ║     ║     ║  │  ║     o: Var (name=_const_6965b017_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#BusbarSection, anonymous)
      ║     ║     ║  │  ╚══ Join (JoinIterator) (resultSizeActual=66.8K, totalTimeActual=83.8ms, selfTimeActual=22.4ms) [right]
      ║     ║     ║  │     ├── StatementPattern (costEstimate=215, resultSizeEstimate=184.4K, resultSizeActual=12.2K, totalTimeActual=6.29ms, selfTimeActual=6.29ms) [left]
      ║     ║     ║  │     │     s: Var (name=idTerm1)
      ║     ║     ║  │     │     p: Var (name=_const_c6e40399_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#Terminal.ConductingEquipment, anonymous)
      ║     ║     ║  │     │     o: Var (name=idSjb1)
      ║     ║     ║  │     └── Join (JoinIterator) (resultSizeActual=66.8K, totalTimeActual=55.1ms, selfTimeActual=22.4ms) [right]
      ║     ║     ║  │        ╠══ StatementPattern (costEstimate=215, resultSizeEstimate=184.4K, resultSizeActual=12.2K, totalTimeActual=6.43ms, selfTimeActual=6.43ms) [left]
      ║     ║     ║  │        ║     s: Var (name=idTerm1)
      ║     ║     ║  │        ║     p: Var (name=_const_4395d870_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#Terminal.ConnectivityNode, anonymous)
      ║     ║     ║  │        ║     o: Var (name=idCN1)
      ║     ║     ║  │        ╚══ StatementPattern (costEstimate=429, resultSizeEstimate=184.4K, resultSizeActual=66.8K, totalTimeActual=26.3ms, selfTimeActual=26.3ms) [right]
      ║     ║     ║  │              s: Var (name=idTermOfCN)
      ║     ║     ║  │              p: Var (name=_const_4395d870_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#Terminal.ConnectivityNode, anonymous)
      ║     ║     ║  │              o: Var (name=idCN1)
      ║     ║     ║  └── StatementPattern (resultSizeEstimate=2.7M, resultSizeActual=66.8K, totalTimeActual=18.8ms, selfTimeActual=18.8ms) [right]
      ║     ║     ║        s: Var (name=idSjb1)
      ║     ║     ║        p: Var (name=_const_857da984_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#IdentifiedObject.name, anonymous)
      ║     ║     ║        o: Var (name=nameSjb1)
      ║     ║     ╚══ GroupElem (nbTerm)
      ║     ║           Count
      ║     ║              Var (name=idTermOfCN)
      ║     ╚══ ExtensionElem (nbTerm)
      ║           Count
      ║              Var (name=idTermOfCN)
      ╚══ StatementPattern (costEstimate=184.4K, resultSizeEstimate=184.4K, resultSizeActual=66.8K, totalTimeActual=26.6ms, selfTimeActual=26.6ms) [right]
            s: Var (name=idTerm3)
            p: Var (name=_const_4395d870_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#Terminal.ConnectivityNode, anonymous)
            o: Var (name=idCN1)

 explained query took 0s for 66

4 replies

hmottestad Sep 19, 2024
Maintainer

We have a known issue with query explanations for queries using ORDER BY that might be relevant for your query: #4772

What is the real result size for that query?

hmottestad Sep 19, 2024
Maintainer

Also, could you try running the query without order by ?nbTerm ?nameSjb1 ?idTerm3 just to see if that makes the query explanation correct?

laurgarn Sep 19, 2024
Author

The last line shows how long it took to give how many rows, in "real". So 66 is the right answer and 66.8K the (over)estimate.

Projection (resultSizeActual=66.8K, totalTimeActual=453ms, selfTimeActual=20.7ms)
╠══ ProjectionElemList
║     ProjectionElem "nameSjb1"
║     ProjectionElem "idCN1"
║     ProjectionElem "nbTerm"
║     ProjectionElem "idTerm3"
╚══ Join (JoinIterator) (resultSizeActual=66.8K, totalTimeActual=432ms, selfTimeActual=18.8ms)
   ├── Projection (new scope) (resultSizeActual=12.2K, totalTimeActual=385ms, selfTimeActual=8.05ms) [left]
   │  ╠══ ProjectionElemList
   │  ║     ProjectionElem "nameSjb1"
   │  ║     ProjectionElem "idCN1"
   │  ║     ProjectionElem "nbTerm"
   │  ╚══ Extension (resultSizeActual=12.2K, totalTimeActual=377ms, selfTimeActual=3.28ms)
   │     ├── Extension (resultSizeActual=12.2K, totalTimeActual=373ms, selfTimeActual=4.51ms)
   │     │     Group (nameSjb1, idCN1) (resultSizeActual=12.2K, totalTimeActual=369ms, selfTimeActual=107ms)
   │     │     ├── LeftJoin (LeftJoinIterator) (resultSizeActual=66.8K, totalTimeActual=262ms, selfTimeActual=81.9ms)
   │     │     │  ╠══ Join (JoinIterator) (resultSizeActual=66.8K, totalTimeActual=152ms, selfTimeActual=29.9ms) [left]
   │     │     │  ║  ├── StatementPattern (costEstimate=6.1K, resultSizeEstimate=12.3K, resultSizeActual=12.2K, totalTimeActual=8.89ms, selfTimeActual=8.89ms) [left]
   │     │     │  ║  │     s: Var (name=idSjb1)
   │     │     │  ║  │     p: Var (name=_const_f5e5585a_uri, value=http://www.w3.org/1999/02/22-rdf-syntax-ns#type, anonymous)
   │     │     │  ║  │     o: Var (name=_const_6965b017_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#BusbarSection, anonymous)
   │     │     │  ║  └── Join (JoinIterator) (resultSizeActual=66.8K, totalTimeActual=113ms, selfTimeActual=29.7ms) [right]
   │     │     │  ║     ╠══ StatementPattern (costEstimate=215, resultSizeEstimate=184.4K, resultSizeActual=12.2K, totalTimeActual=8.51ms, selfTimeActual=8.51ms) [left]
   │     │     │  ║     ║     s: Var (name=idTerm1)
   │     │     │  ║     ║     p: Var (name=_const_c6e40399_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#Terminal.ConductingEquipment, anonymous)
   │     │     │  ║     ║     o: Var (name=idSjb1)
   │     │     │  ║     ╚══ Join (JoinIterator) (resultSizeActual=66.8K, totalTimeActual=74.7ms, selfTimeActual=29.3ms) [right]
   │     │     │  ║        ├── StatementPattern (costEstimate=215, resultSizeEstimate=184.4K, resultSizeActual=12.2K, totalTimeActual=8.1ms, selfTimeActual=8.1ms) [left]
   │     │     │  ║        │     s: Var (name=idTerm1)
   │     │     │  ║        │     p: Var (name=_const_4395d870_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#Terminal.ConnectivityNode, anonymous)
   │     │     │  ║        │     o: Var (name=idCN1)
   │     │     │  ║        └── StatementPattern (costEstimate=429, resultSizeEstimate=184.4K, resultSizeActual=66.8K, totalTimeActual=37.2ms, selfTimeActual=37.2ms) [right]
   │     │     │  ║              s: Var (name=idTermOfCN)
   │     │     │  ║              p: Var (name=_const_4395d870_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#Terminal.ConnectivityNode, anonymous)
   │     │     │  ║              o: Var (name=idCN1)
   │     │     │  ╚══ StatementPattern (resultSizeEstimate=2.7M, resultSizeActual=66.8K, totalTimeActual=28.2ms, selfTimeActual=28.2ms) [right]
   │     │     │        s: Var (name=idSjb1)
   │     │     │        p: Var (name=_const_857da984_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#IdentifiedObject.name, anonymous)
   │     │     │        o: Var (name=nameSjb1)
   │     │     └── GroupElem (nbTerm)
   │     │           Count
   │     │              Var (name=idTermOfCN)
   │     └── ExtensionElem (nbTerm)
   │           Count
   │              Var (name=idTermOfCN)
   └── StatementPattern (costEstimate=184.4K, resultSizeEstimate=184.4K, resultSizeActual=66.8K, totalTimeActual=28.4ms, selfTimeActual=28.4ms) [right]
         s: Var (name=idTerm3)
         p: Var (name=_const_4395d870_uri, value=http://iec.ch/TC57/2013/CIM-schema-cim16#Terminal.ConnectivityNode, anonymous)
         o: Var (name=idCN1)

 explained query took 0s for 66

hmottestad Sep 19, 2024
Maintainer

I'm not sure why this is happening. Any chance you can share the part of your java code that does the query explain and then prints how long it took and how many results there were?

laurgarn · 2024-09-19T14:52:39Z

laurgarn
Sep 19, 2024
Author

SailRepository sailRepository = (SailRepository) storeRDF4J.getRepository();
TupleQuery tupleQuery;
try {
	tupleQuery = sailRepository.getConnection().prepareTupleQuery(prefixesStr + queryText);
} catch (RepositoryException | MalformedQueryException e) {
	System.err.println(queryText);
	return;
}
tupleQuery.setMaxExecutionTime(timeOutSeconds);
Explanation explanation = tupleQuery.explain(Explanation.Level.Timed);
if (explanation.toGenericPlanNode().getResultSizeActual() == null)
	explanation = tupleQuery.explain(Explanation.Level.Executed);
System.out.println(explanation);
GenericPlanNode plan = explanation.toGenericPlanNode();
Long resultSizeActual = plan.getResultSizeActual();
if (resultSizeActual != null && resultSizeActual != 0 && !Boolean.TRUE.equals(plan.getTimedOut())) {
	Instant before = Instant.now();
	PropertyBags pbs = ts.query(queryText); // <-- a library we use "daily" to give back kinda list of maps 
	Instant after = Instant.now();
	System.out.println(" explained query took " + Duration.between(before, after).toSeconds() + "s for " + pbs.size());
}

1 reply

hmottestad Sep 19, 2024
Maintainer

I have another theory.

Reading through the query explanation I can't find anything related to the having (?nbTerm < 3) line. I wonder if that could somehow be the issue. If you remove the having (?nbTerm < 3) line, do you get ~66800 results?

laurgarn · 2024-09-23T07:37:28Z

laurgarn
Sep 23, 2024
Author

You are 100% on target :
explained query took 0s for 66893
;-)

0 replies

hmottestad · 2024-10-01T13:17:52Z

hmottestad
Oct 1, 2024
Maintainer

Created an issue for this: #5134

1 reply

hmottestad Oct 21, 2024
Maintainer

@laurgarn I'm not able to reproduce this using RDF4J 5.0.2. What version are you using?

laurgarn · 2024-10-22T07:14:42Z

laurgarn
Oct 22, 2024
Author

Hi
We are currently using 4.3.12.
Can not upgrade yet to 5.0.2, because the leading project has not yet migrated

2 replies

hmottestad Oct 22, 2024
Maintainer

Ok. Any chance you can test it out on 5.0.2 to see if it works as expected there? If it doesn't then I would need to keep digging a bit more.

laurgarn Oct 22, 2024
Author

Not so soon, sadly :-/

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Consistency between plan "resultSizeActual" and real result size #5129

{{title}}

Replies: 6 comments 8 replies

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Consistency between plan "resultSizeActual" and real result size #5129

laurgarn Sep 18, 2024

Replies: 6 comments · 8 replies

hmottestad Sep 19, 2024 Maintainer

laurgarn Sep 19, 2024 Author

hmottestad Sep 19, 2024 Maintainer

hmottestad Sep 19, 2024 Maintainer

laurgarn Sep 19, 2024 Author

hmottestad Sep 19, 2024 Maintainer

laurgarn Sep 19, 2024 Author

hmottestad Sep 19, 2024 Maintainer

laurgarn Sep 23, 2024 Author

hmottestad Oct 1, 2024 Maintainer

hmottestad Oct 21, 2024 Maintainer

laurgarn Oct 22, 2024 Author

hmottestad Oct 22, 2024 Maintainer

laurgarn Oct 22, 2024 Author

laurgarn
Sep 18, 2024

Replies: 6 comments 8 replies

hmottestad
Sep 19, 2024
Maintainer

laurgarn
Sep 19, 2024
Author

hmottestad Sep 19, 2024
Maintainer

hmottestad Sep 19, 2024
Maintainer

laurgarn Sep 19, 2024
Author

hmottestad Sep 19, 2024
Maintainer

laurgarn
Sep 19, 2024
Author

hmottestad Sep 19, 2024
Maintainer

laurgarn
Sep 23, 2024
Author

hmottestad
Oct 1, 2024
Maintainer

hmottestad Oct 21, 2024
Maintainer

laurgarn
Oct 22, 2024
Author

hmottestad Oct 22, 2024
Maintainer

laurgarn Oct 22, 2024
Author