Update query doesn't terminate in 5.3.2 (works fine in 5.1.0)

hmottestad · August 1, 2018, 8:25am

Hi,

The following query does not terminate in 5.3.2.

WITH <http://data.einnsyn.no/innsynskravGraph>
DELETE {?endNode rdf:rest rdf:nil}
INSERT {
       ?endNode rdf:rest _:b1.
       _:b1 rdf:first ?statusObjekt ;
            rdf:rest rdf:nil.
       ?statusObjekt bruker:status ?status;
           a bruker:Statusobjekt ;
           bruker:systemgenerert false ;
           virksomhet:opprettetDato ?now .
} WHERE {

        BIND(now() as ?now)

        { #pragma group.joins
                
                { #pragma group.joins
                

                        BIND(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> as ?status)
                        BIND(<http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347> as ?statusObjekt)
        
                       <http://data.einnsyn.no/bruker/46d97807-d54f-4d2c-a34b-e7de22aa3c91> bruker:innsynskrav / bruker:innsynskravdel <http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b>.
                       <http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b> bruker:statusobjekt ?list.
       
                       ?list rdf:rest* ?endNode .
                }
    
                ?endNode rdf:rest rdf:nil .
       }
}

It also does not terminate if I remove the gourp.joins pragma. I added them to try to make it terminate, but it didnt help.

Here is the query plan:

From all
Insert Into <http://data.einnsyn.no/innsynskravGraph>
Remove From <http://data.einnsyn.no/innsynskravGraph>
From all
DELETE
`─ Projection(?endNode AS ?subject, ?zkzqrhyr AS ?predicate, ?xxvahyeq AS ?object, ?fayiyltv AS ?context)
   `─ Bind(<http://data.einnsyn.no/innsynskravGraph> AS ?fayiyltv) (rdf:rest AS ?zkzqrhyr) (rdf:nil AS ?xxvahyeq)
INSERT
`─ Projection(?endNode AS ?subject, ?zkzqrhyr AS ?predicate, ?_anon_1 AS ?object, ?fayiyltv AS ?context;
   +─         ?_anon_1 AS ?subject, ?qmveeagd AS ?predicate, ?statusObjekt AS ?object, ?fayiyltv AS ?context;
   +─         ?_anon_1 AS ?subject, ?zkzqrhyr AS ?predicate, ?xxvahyeq AS ?object, ?fayiyltv AS ?context;
   +─         ?statusObjekt AS ?subject, ?ewkthsnp AS ?predicate, ?status AS ?object, ?fayiyltv AS ?context;
   +─         ?statusObjekt AS ?subject, ?qsbydapu AS ?predicate, ?ujsiylfx AS ?object, ?fayiyltv AS ?context;
   +─         ?statusObjekt AS ?subject, ?vcgqodri AS ?predicate, ?yqysrfbw AS ?object, ?fayiyltv AS ?context;
   +─         ?statusObjekt AS ?subject, ?vrfanwmp AS ?predicate, ?now AS ?object, ?fayiyltv AS ?context)
   `─ Bind(rdf:type AS ?qsbydapu) (<http://data.einnsyn.no/brukermeta/Statusobjekt> AS ?ujsiylfx) (<http://data.einnsyn.no/brukermeta/systemgenerert> AS ?vcgqodri) ("false"^^xsd:boolean AS ?yqysrfbw) (<http://data.einnsyn.no/virksomhetmeta/opprettetDato> AS ?vrfanwmp) (rdf:rest AS ?zkzqrhyr) (rdf:nil AS ?xxvahyeq) (<http://data.einnsyn.no/innsynskravGraph> AS ?fayiyltv) (BNODE() AS ?_anon_1) (rdf:first AS ?qmveeagd) (<http://data.einnsyn.no/brukermeta/status> AS ?ewkthsnp)
WHERE
`─ LoopJoin(_) [#33052448.3M]
   +─ Bind(NOW() AS ?now) [#1]
   `─ LoopJoin(_) [#33052448.3M]
      +─ Scan[SPO](?endNode, rdf:rest, rdf:nil){<http://data.einnsyn.no/innsynskravGraph>} [#118K]
      `─ LoopJoin(_) [#279.6M]
         +─ LoopJoin(_) [#1]
         │  +─ LoopJoin(_) [#1]
         │  │  +─ LoopJoin(_) [#1]
         │  │  │  +─ Scan[SPO](<http://data.einnsyn.no/bruker/46d97807-d54f-4d2c-a34b-e7de22aa3c91>, <http://data.einnsyn.no/brukermeta/innsynskrav>, ?ltuyjfnf){<http://data.einnsyn.no/innsynskravGraph>} [#1]
         │  │  │  `─ Scan[SPO](?ltuyjfnf, <http://data.einnsyn.no/brukermeta/innsynskravdel>, <http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b>){<http://data.einnsyn.no/innsynskravGraph>} [#1]
         │  │  `─ Scan[SPO](<http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b>, <http://data.einnsyn.no/brukermeta/statusobjekt>, ?list){<http://data.einnsyn.no/innsynskravGraph>} [#1]
         │  `─ Bind(<http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347> AS ?statusObjekt) [#1]
         │     `─ Bind(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> AS ?status) [#1]
         `─ PropertyPath(?list -> ?endNode in <http://data.einnsyn.no/innsynskravGraph>, minLength=0) [#279.6M]
            `─ Scan[SPO](?list, rdf:rest, ?endNode){<http://data.einnsyn.no/innsynskravGraph>} [#239K]

Removing the delete/insert part and running it as a select * work fine (50ish ms).

Cheers,
Håvard M. Ottestad

pavel · August 1, 2018, 9:42am

Hi Håvard,

Unfortunately the plan won’t help us here. One of the known problems with Update queries is that they’re optimized at runtime, not prior to it (as other types of queries), so the output of query explain command shows basically the query parser output. There’re multiple reasons for that, mostly due to update sequences where queries in the sequence can change the database in a way that precomputed plans for subsequent queries become useless.

For now you could enable DEBUG logging for com.complexible.stardog.plan.eval.operator.impl.ModifyOperatorImpl and com.complexible.stardog.plan.eval.ExecutablePlanFactory loggers, restart the server, and share the log contents with us (assuming you cannot share the obfuscated data). The we should see the plans as executed in the log and make sure the problem is in the WHERE part, and not in the DELETE or INSERT parts.

Also, is there anything like search or spatial enabled for the database? Or reasoning for the query?

Thanks,
Pavel

hmottestad · August 1, 2018, 7:51pm

I’ll see if I can’t configure that in Stardog tomorrow.

But here is another teaser. I split the query into a select query which returns the endNode of the list, and then a second query for inserting at the end node. Both queries run fine by themselves. But once I start at transaction the selection query doesn’t even timeout, just hangs and ramps up CPU on stardog.

pavel · August 2, 2018, 6:50am

That’s interesting and could be due to a query plan differences. In Stardog 5 some indexes are unavailable to read queries within a write transaction. We can examine the query plans for that rogue query inside and outside of a transaction.

Cheers,
Pavel

hmottestad · August 6, 2018, 8:41am

@pavel Here is the plan for the query from the logs (Stardog 5.3.2):

8/6/2018 10:34:43 AMDEBUG 2018-08-06 10:34:42,944 [stardog-user-2] com.complexible.stardog.plan.eval.ExecutablePlanFactory:optimizePlan(133): Unoptimized plan:
8/6/2018 10:34:43 AMFROM Dataset(ALL)
8/6/2018 10:34:43 AMDELETE
8/6/2018 10:34:43 AM    Projection([Var(9) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], sort keys=[2, 3, 1], card=UNKNOWN[PROBABLY_OFF], cost=Infinity)
8/6/2018 10:34:43 AM    Bind(<http://data.einnsyn.no/innsynskravGraph> AS 12, rdf:rest AS 10, rdf:nil AS 11)
8/6/2018 10:34:43 AM      Singleton
8/6/2018 10:34:43 AMINSERT
8/6/2018 10:34:43 AM    Projection([Var(9) as 0, Var(10) as 1, Var(13) as 2, Var(12) as 3], [Var(13) as 0, Var(14) as 1, Var(6) as 2, Var(12) as 3], [Var(13) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], [Var(6) as 0, Var(15) as 1, Var(5) as 2, Var(12) as 3], [Var(6) as 0, Var(16) as 1, Var(17) as 2, Var(12) as 3], [Var(6) as 0, Var(18) as 1, Var(19) as 2, Var(12) as 3], [Var(6) as 0, Var(20) as 1, Var(4) as 2, Var(12) as 3], sort keys=[3, 1], card=UNKNOWN[PROBABLY_OFF], cost=Infinity)
8/6/2018 10:34:43 AM    Bind(rdf:type AS 16, <http://data.einnsyn.no/brukermeta/Statusobjekt> AS 17, <http://data.einnsyn.no/brukermeta/systemgenerert> AS 18, "false"^^xsd:boolean AS 19, <http://data.einnsyn.no/virksomhetmeta/opprettetDato> AS 20, rdf:rest AS 10, rdf:nil AS 11, <http://data.einnsyn.no/innsynskravGraph> AS 12, BNODE() AS 13, rdf:first AS 14, <http://data.einnsyn.no/brukermeta/status> AS 15)
8/6/2018 10:34:43 AM      Singleton
8/6/2018 10:34:43 AMWHERE
8/6/2018 10:34:43 AM  Scope[UNKNOWN[PROBABLY_OFF]]
8/6/2018 10:34:43 AM    Bind(NOW() AS 4)
8/6/2018 10:34:43 AM      Singleton
8/6/2018 10:34:43 AM    Hint( group.joins: )
8/6/2018 10:34:43 AM      Scope[UNKNOWN[PROBABLY_OFF]]
8/6/2018 10:34:43 AM        Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], Var(9), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, http://www.w3.org/1999/02/22-rdf-syntax-ns#nil, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM        Hint( group.joins: )
8/6/2018 10:34:43 AM          Scope[UNKNOWN[PROBABLY_OFF]]
8/6/2018 10:34:43 AM            Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], http://data.einnsyn.no/bruker/46d97807-d54f-4d2c-a34b-e7de22aa3c91, http://data.einnsyn.no/brukermeta/innsynskrav, Var(7), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM            Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], Var(7), http://data.einnsyn.no/brukermeta/innsynskravdel, http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM            Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/brukermeta/statusobjekt, Var(8), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM            Bind(<http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347> AS 6)
8/6/2018 10:34:43 AM              Bind(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> AS 5)
8/6/2018 10:34:43 AM                Singleton
8/6/2018 10:34:43 AM            PropertyPath[UNKNOWN[PROBABLY_OFF]](Var(8) -> Var(9) in http://data.einnsyn.no/innsynskravGraph 0+, cost=Infinity)
8/6/2018 10:34:43 AM              Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], Var(8), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, Var(9), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM
8/6/2018 10:34:43 AMDEBUG 2018-08-06 10:34:42,969 [stardog-user-2] com.complexible.stardog.plan.eval.ExecutablePlanFactory:optimizePlan(139): Optimized plan:
8/6/2018 10:34:43 AMFROM Dataset(ALL)
8/6/2018 10:34:43 AMDELETE
8/6/2018 10:34:43 AM    Projection([Var(9) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], sort keys=[2, 3, 1], card=UNKNOWN[PROBABLY_OFF], cost=Infinity)
8/6/2018 10:34:43 AM    Bind(<http://data.einnsyn.no/innsynskravGraph> AS 12, rdf:rest AS 10, rdf:nil AS 11)
8/6/2018 10:34:43 AM      Singleton
8/6/2018 10:34:43 AMINSERT
8/6/2018 10:34:43 AM    Projection([Var(9) as 0, Var(10) as 1, Var(13) as 2, Var(12) as 3], [Var(13) as 0, Var(14) as 1, Var(6) as 2, Var(12) as 3], [Var(13) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], [Var(6) as 0, Var(15) as 1, Var(5) as 2, Var(12) as 3], [Var(6) as 0, Var(16) as 1, Var(17) as 2, Var(12) as 3], [Var(6) as 0, Var(18) as 1, Var(19) as 2, Var(12) as 3], [Var(6) as 0, Var(20) as 1, Var(4) as 2, Var(12) as 3], sort keys=[3, 1], card=UNKNOWN[PROBABLY_OFF], cost=Infinity)
8/6/2018 10:34:43 AM    Bind(rdf:type AS 16, <http://data.einnsyn.no/brukermeta/Statusobjekt> AS 17, <http://data.einnsyn.no/brukermeta/systemgenerert> AS 18, "false"^^xsd:boolean AS 19, <http://data.einnsyn.no/virksomhetmeta/opprettetDato> AS 20, rdf:rest AS 10, rdf:nil AS 11, <http://data.einnsyn.no/innsynskravGraph> AS 12, BNODE() AS 13, rdf:first AS 14, <http://data.einnsyn.no/brukermeta/status> AS 15)
8/6/2018 10:34:43 AM      Singleton
8/6/2018 10:34:43 AMWHERE
8/6/2018 10:34:43 AM  LoopJoin(card=33929332.4M[ACCURATE] cost=4.2659281135399557E18)
8/6/2018 10:34:43 AM    Bind(NOW() AS 4)
8/6/2018 10:34:43 AM      Singleton
8/6/2018 10:34:43 AM    Hint( group.joins: )
8/6/2018 10:34:43 AM      LoopJoin(card=33929332.4M[ACCURATE] cost=8.531842655346952E16)
8/6/2018 10:34:43 AM        Scan[121K[ACCURATE]](SPO[SortType[-3]], Var(9), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, http://www.w3.org/1999/02/22-rdf-syntax-ns#nil, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM        Hint( group.joins: )
8/6/2018 10:34:43 AM          LoopJoin(card=280.1M[ACCURATE] cost=1.4087126929800001E10)
8/6/2018 10:34:43 AM            LoopJoin(card=1[ACCURATE] cost=101.60000000000001)
8/6/2018 10:34:43 AM              LoopJoin(card=1[ACCURATE] cost=101.4)
8/6/2018 10:34:43 AM                LoopJoin(card=1[ACCURATE] cost=51.2)
8/6/2018 10:34:43 AM                  Scan[1[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/bruker/46d97807-d54f-4d2c-a34b-e7de22aa3c91, http://data.einnsyn.no/brukermeta/innsynskrav, Var(7), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM                  Scan[1[ACCURATE]](SPO[SortType[-3]], Var(7), http://data.einnsyn.no/brukermeta/innsynskravdel, http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM                Scan[1[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/brukermeta/statusobjekt, Var(8), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM              Bind(<http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347> AS 6)
8/6/2018 10:34:43 AM                Bind(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> AS 5)
8/6/2018 10:34:43 AM                  Singleton
8/6/2018 10:34:43 AM            PropertyPath[280.1M[PROBABLY_ACCURATE]](Var(8) -> Var(9) in http://data.einnsyn.no/innsynskravGraph 0+, cost=2.80622017E8)
8/6/2018 10:34:43 AM              Scan[246K[ACCURATE]](SPO[SortType[-3]], Var(8), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, Var(9), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM
8/6/2018 10:34:43 AMDEBUG 2018-08-06 10:34:43,055 [stardog-user-2] com.complexible.stardog.plan.eval.ExecutablePlanFactory:optimizePlan(133): Unoptimized plan:
8/6/2018 10:34:43 AMFROM Dataset(ALL)
8/6/2018 10:34:43 AMDELETE
8/6/2018 10:34:43 AM    Projection([Var(9) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], sort keys=[2, 3, 1], card=UNKNOWN[PROBABLY_OFF], cost=Infinity)
8/6/2018 10:34:43 AM    Bind(<http://data.einnsyn.no/innsynskravGraph> AS 12, rdf:rest AS 10, rdf:nil AS 11)
8/6/2018 10:34:43 AM      Singleton
8/6/2018 10:34:43 AMINSERT
8/6/2018 10:34:43 AM    Projection([Var(9) as 0, Var(10) as 1, Var(13) as 2, Var(12) as 3], [Var(13) as 0, Var(14) as 1, Var(6) as 2, Var(12) as 3], [Var(13) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], [Var(6) as 0, Var(15) as 1, Var(5) as 2, Var(12) as 3], [Var(6) as 0, Var(16) as 1, Var(17) as 2, Var(12) as 3], [Var(6) as 0, Var(18) as 1, Var(19) as 2, Var(12) as 3], [Var(6) as 0, Var(20) as 1, Var(4) as 2, Var(12) as 3], sort keys=[3, 1], card=UNKNOWN[PROBABLY_OFF], cost=Infinity)
8/6/2018 10:34:43 AM    Bind(rdf:type AS 16, <http://data.einnsyn.no/brukermeta/Statusobjekt> AS 17, <http://data.einnsyn.no/brukermeta/systemgenerert> AS 18, "false"^^xsd:boolean AS 19, <http://data.einnsyn.no/virksomhetmeta/opprettetDato> AS 20, rdf:rest AS 10, rdf:nil AS 11, <http://data.einnsyn.no/innsynskravGraph> AS 12, BNODE() AS 13, rdf:first AS 14, <http://data.einnsyn.no/brukermeta/status> AS 15)
8/6/2018 10:34:43 AM      Singleton
8/6/2018 10:34:43 AMWHERE
8/6/2018 10:34:43 AM  Scope[UNKNOWN[PROBABLY_OFF]]
8/6/2018 10:34:43 AM    Bind(NOW() AS 4)
8/6/2018 10:34:43 AM      Singleton
8/6/2018 10:34:43 AM    Hint( group.joins: )
8/6/2018 10:34:43 AM      Scope[UNKNOWN[PROBABLY_OFF]]
8/6/2018 10:34:43 AM        Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], Var(9), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, http://www.w3.org/1999/02/22-rdf-syntax-ns#nil, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM        Hint( group.joins: )
8/6/2018 10:34:43 AM          Scope[UNKNOWN[PROBABLY_OFF]]
8/6/2018 10:34:43 AM            Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], http://data.einnsyn.no/bruker/46d97807-d54f-4d2c-a34b-e7de22aa3c91, http://data.einnsyn.no/brukermeta/innsynskrav, Var(7), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM            Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], Var(7), http://data.einnsyn.no/brukermeta/innsynskravdel, http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM            Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/brukermeta/statusobjekt, Var(8), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM            Bind(<http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347> AS 6)
8/6/2018 10:34:43 AM              Bind(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> AS 5)
8/6/2018 10:34:43 AM                Singleton
8/6/2018 10:34:43 AM            PropertyPath[UNKNOWN[PROBABLY_OFF]](Var(8) -> Var(9) in http://data.einnsyn.no/innsynskravGraph 0+, cost=Infinity)
8/6/2018 10:34:43 AM              Scan[UNKNOWN[PROBABLY_OFF]](SPO[SortType[-3]], Var(8), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, Var(9), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:43 AM
8/6/2018 10:34:44 AMDEBUG 2018-08-06 10:34:43,104 [stardog-user-2] com.complexible.stardog.plan.eval.ExecutablePlanFactory:optimizePlan(139): Optimized plan:
8/6/2018 10:34:44 AMFROM Dataset(ALL)
8/6/2018 10:34:44 AMDELETE
8/6/2018 10:34:44 AM    Projection([Var(9) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], sort keys=[2, 3, 1], card=UNKNOWN[PROBABLY_OFF], cost=Infinity)
8/6/2018 10:34:44 AM    Bind(<http://data.einnsyn.no/innsynskravGraph> AS 12, rdf:rest AS 10, rdf:nil AS 11)
8/6/2018 10:34:44 AM      Singleton
8/6/2018 10:34:44 AMINSERT
8/6/2018 10:34:44 AM    Projection([Var(9) as 0, Var(10) as 1, Var(13) as 2, Var(12) as 3], [Var(13) as 0, Var(14) as 1, Var(6) as 2, Var(12) as 3], [Var(13) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], [Var(6) as 0, Var(15) as 1, Var(5) as 2, Var(12) as 3], [Var(6) as 0, Var(16) as 1, Var(17) as 2, Var(12) as 3], [Var(6) as 0, Var(18) as 1, Var(19) as 2, Var(12) as 3], [Var(6) as 0, Var(20) as 1, Var(4) as 2, Var(12) as 3], sort keys=[3, 1], card=UNKNOWN[PROBABLY_OFF], cost=Infinity)
8/6/2018 10:34:44 AM    Bind(rdf:type AS 16, <http://data.einnsyn.no/brukermeta/Statusobjekt> AS 17, <http://data.einnsyn.no/brukermeta/systemgenerert> AS 18, "false"^^xsd:boolean AS 19, <http://data.einnsyn.no/virksomhetmeta/opprettetDato> AS 20, rdf:rest AS 10, rdf:nil AS 11, <http://data.einnsyn.no/innsynskravGraph> AS 12, BNODE() AS 13, rdf:first AS 14, <http://data.einnsyn.no/brukermeta/status> AS 15)
8/6/2018 10:34:44 AM      Singleton
8/6/2018 10:34:44 AMWHERE
8/6/2018 10:34:44 AM  LoopJoin(card=33929332.4M[ACCURATE] cost=4.2659281135399557E18)
8/6/2018 10:34:44 AM    Bind(NOW() AS 4)
8/6/2018 10:34:44 AM      Singleton
8/6/2018 10:34:44 AM    Hint( group.joins: )
8/6/2018 10:34:44 AM      LoopJoin(card=33929332.4M[ACCURATE] cost=8.531842655346952E16)
8/6/2018 10:34:44 AM        Scan[121K[ACCURATE]](SPO[SortType[-3]], Var(9), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, http://www.w3.org/1999/02/22-rdf-syntax-ns#nil, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM        Hint( group.joins: )
8/6/2018 10:34:44 AM          LoopJoin(card=280.1M[ACCURATE] cost=1.4087126929800001E10)
8/6/2018 10:34:44 AM            LoopJoin(card=1[ACCURATE] cost=101.60000000000001)
8/6/2018 10:34:44 AM              LoopJoin(card=1[ACCURATE] cost=101.4)
8/6/2018 10:34:44 AM                LoopJoin(card=1[ACCURATE] cost=51.2)
8/6/2018 10:34:44 AM                  Scan[1[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/bruker/46d97807-d54f-4d2c-a34b-e7de22aa3c91, http://data.einnsyn.no/brukermeta/innsynskrav, Var(7), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM                  Scan[1[ACCURATE]](SPO[SortType[-3]], Var(7), http://data.einnsyn.no/brukermeta/innsynskravdel, http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM                Scan[1[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/brukermeta/statusobjekt, Var(8), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM              Bind(<http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347> AS 6)
8/6/2018 10:34:44 AM                Bind(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> AS 5)
8/6/2018 10:34:44 AM                  Singleton
8/6/2018 10:34:44 AM            PropertyPath[280.1M[PROBABLY_ACCURATE]](Var(8) -> Var(9) in http://data.einnsyn.no/innsynskravGraph 0+, cost=2.80622017E8)
8/6/2018 10:34:44 AM              Scan[246K[ACCURATE]](SPO[SortType[-3]], Var(8), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, Var(9), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM
8/6/2018 10:34:44 AMDEBUG 2018-08-06 10:34:43,153 [stardog-user-2] com.complexible.stardog.plan.eval.ExecutablePlanFactory:optimizePlan(133): Unoptimized plan:
8/6/2018 10:34:44 AMFROM Dataset(ALL), insert=http://data.einnsyn.no/innsynskravGraph, remove=[http://data.einnsyn.no/innsynskravGraph]
8/6/2018 10:34:44 AMLoopJoin(card=33929332.4M[ACCURATE] cost=4.2659281135399557E18)
8/6/2018 10:34:44 AM  Bind(NOW() AS 4)
8/6/2018 10:34:44 AM    Singleton
8/6/2018 10:34:44 AM  Hint( group.joins: )
8/6/2018 10:34:44 AM    LoopJoin(card=33929332.4M[ACCURATE] cost=8.531842655346952E16)
8/6/2018 10:34:44 AM      Scan[121K[ACCURATE]](SPO[SortType[-3]], Var(9), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, http://www.w3.org/1999/02/22-rdf-syntax-ns#nil, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM      Hint( group.joins: )
8/6/2018 10:34:44 AM        LoopJoin(card=280.1M[ACCURATE] cost=1.4087126929800001E10)
8/6/2018 10:34:44 AM          LoopJoin(card=1[ACCURATE] cost=101.60000000000001)
8/6/2018 10:34:44 AM            LoopJoin(card=1[ACCURATE] cost=101.4)
8/6/2018 10:34:44 AM              LoopJoin(card=1[ACCURATE] cost=51.2)
8/6/2018 10:34:44 AM                Scan[1[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/bruker/46d97807-d54f-4d2c-a34b-e7de22aa3c91, http://data.einnsyn.no/brukermeta/innsynskrav, Var(7), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM                Scan[1[ACCURATE]](SPO[SortType[-3]], Var(7), http://data.einnsyn.no/brukermeta/innsynskravdel, http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM              Scan[1[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/brukermeta/statusobjekt, Var(8), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM            Bind(<http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347> AS 6)
8/6/2018 10:34:44 AM              Bind(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> AS 5)
8/6/2018 10:34:44 AM                Singleton
8/6/2018 10:34:44 AM          PropertyPath[280.1M[PROBABLY_ACCURATE]](Var(8) -> Var(9) in http://data.einnsyn.no/innsynskravGraph 0+, cost=2.80622017E8)
8/6/2018 10:34:44 AM            Scan[246K[ACCURATE]](SPO[SortType[-3]], Var(8), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, Var(9), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM
8/6/2018 10:34:44 AMDEBUG 2018-08-06 10:34:43,207 [stardog-user-2] com.complexible.stardog.plan.eval.ExecutablePlanFactory:optimizePlan(139): Optimized plan:
8/6/2018 10:34:44 AMFROM Dataset(ALL), insert=http://data.einnsyn.no/innsynskravGraph, remove=[http://data.einnsyn.no/innsynskravGraph]
8/6/2018 10:34:44 AMLoopJoin(card=5.8M[ACCURATE] cost=7.445690454327346E7)
8/6/2018 10:34:44 AM  Hint( group.joins: )
8/6/2018 10:34:44 AM    MergeJoin(key=9 card=5.8M[POSSIBLY_OFF] cost=1273809.651375459)
8/6/2018 10:34:44 AM      Scan[121K[ACCURATE]](POS[SortType[9]], Var(9), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, http://www.w3.org/1999/02/22-rdf-syntax-ns#nil, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM      Sort(key=9 card=139[ACCURATE] cost=1718.1083185996076)
8/6/2018 10:34:44 AM        Hint( group.joins: )
8/6/2018 10:34:44 AM          LoopJoin(card=139[ACCURATE] cost=1520.2017567778942)
8/6/2018 10:34:44 AM            LoopJoin(card=1[ACCURATE] cost=2.4017567778941524)
8/6/2018 10:34:44 AM              MergeJoin(key=8 card=1[POSSIBLY_OFF] cost=2.2017567778941523)
Unknown Date
8/6/2018 10:34:44 AM                Scan[1[ACCURATE]](SPO[SortType[8]], http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/brukermeta/statusobjekt, Var(8), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM                PropertyPath[280.1M[PROBABLY_ACCURATE]](Var(8) -> Var(9) in http://data.einnsyn.no/innsynskravGraph sort=[8] 0+, cost=2.80622017E8)
8/6/2018 10:34:44 AM                  Scan[246K[ACCURATE]](PSO[SortType[8]], Var(8), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, Var(9), http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM              Bind(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> AS 5, <http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347> AS 6)
8/6/2018 10:34:44 AM                Singleton
8/6/2018 10:34:44 AM            MergeJoin(key=7 card=139[POSSIBLY_OFF] cost=29.8)
8/6/2018 10:34:44 AM              Scan[1[ACCURATE]](SPO[SortType[7]], http://data.einnsyn.no/bruker/46d97807-d54f-4d2c-a34b-e7de22aa3c91, http://data.einnsyn.no/brukermeta/innsynskrav, Var(7), http://data.einnsyn.no/innsynskravGraph, scope=Named)
Unknown Date
8/6/2018 10:34:44 AM              Scan[1[ACCURATE]](POS[SortType[7]], Var(7), http://data.einnsyn.no/brukermeta/innsynskravdel, http://data.einnsyn.no/innsynskrav/0c3b3f05-9d07-44ad-a75d-4580b544202b, http://data.einnsyn.no/innsynskravGraph, scope=Named)
8/6/2018 10:34:44 AM  Bind(NOW() AS 4)
8/6/2018 10:34:44 AM    Singleton
8/6/2018 10:34:44 AM
8/6/2018 10:34:48 AMDEBUG 2018-08-06 10:34:48,060 [stardog-user-4] com.complexible.stardog.plan.eval.ExecutablePlanFactory:optimizePlan(133): Unoptimized plan:

hmottestad · August 6, 2018, 11:46am

Here is the plan from Stardog 5.1.0.

DEBUG 2018-08-06 13:13:07,325 [XNIO-1 task-12] com.complexible.stardog.plan.eval.ExecutablePlanFactory:optimizePlan(133): Unoptimized plan:
FROM Dataset(ALL)
DELETE
    Projection([Var(9) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], card=0[ACCURATE], cost=Infinity)
    Bind(<http://data.einnsyn.no/innsynskravGraph> AS 12, rdf:rest AS 10, rdf:nil AS 11)
      Singleton
INSERT
    Projection([Var(9) as 0, Var(10) as 1, Var(13) as 2, Var(12) as 3], [Var(13) as 0, Var(14) as 1, Var(6) as 2, Var(12) as 3], [Var(13) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], [Var(6) as 0, Var(15) as 1, Var(5) as 2, Var(12) as 3], [Var(6) as 0, Var(16) as 1, Var(17) as 2, Var(12) as 3], [Var(6) as 0, Var(18) as 1, Var(19) as 2, Var(12) as 3], [Var(6) as 0, Var(20) as 1, Var(4) as 2, Var(12) as 3], card=0[ACCURATE], cost=Infinity)
    Bind(rdf:type AS 16, <http://data.einnsyn.no/brukermeta/Statusobjekt> AS 17, <http://data.einnsyn.no/brukermeta/systemgenerert> AS 18, "false"^^xsd:boolean AS 19, <http://data.einnsyn.no/virksomhetmeta/opprettetDato> AS 20, rdf:rest AS 10, rdf:nil AS 11, <http://data.einnsyn.no/innsynskravGraph> AS 12, BNODE() AS 13, rdf:first AS 14, <http://data.einnsyn.no/brukermeta/status> AS 15)
      Singleton
WHERE
  Scope[0[ACCURATE]]
    Bind(NOW() AS 4)
      Singleton
    Hint( group.joins: )
      Scope[0[ACCURATE]]
        Scan[0[ACCURATE]](SPO[SortType[-3]], Var(9), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, http://www.w3.org/1999/02/22-rdf-syntax-ns#nil, http://data.einnsyn.no/innsynskravGraph, scope=Named)
        Hint( group.joins: )
          Scope[0[ACCURATE]]
            Scan[0[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/bruker/9e2092a2-6e44-406f-a059-7f353e249e76, http://data.einnsyn.no/brukermeta/innsynskrav, Var(7), http://data.einnsyn.no/innsynskravGraph, scope=Named)
            Scan[0[ACCURATE]](SPO[SortType[-3]], Var(7), http://data.einnsyn.no/brukermeta/innsynskravdel, http://data.einnsyn.no/innsynskrav/46634121-a9b5-4504-bf88-cd551df15177, http://data.einnsyn.no/innsynskravGraph, scope=Named)
            Scan[0[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/innsynskrav/46634121-a9b5-4504-bf88-cd551df15177, http://data.einnsyn.no/brukermeta/statusobjekt, Var(8), http://data.einnsyn.no/innsynskravGraph, scope=Named)
            Bind(<http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347_4> AS 6)
              Bind(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> AS 5)
                Singleton
            PropertyPath[0[ACCURATE]](Var(8) -> Var(9) in http://data.einnsyn.no/innsynskravGraph 0+, cost=Infinity)
              Scan[0[ACCURATE]](SPO[SortType[-3]], Var(8), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, Var(9), http://data.einnsyn.no/innsynskravGraph, scope=Named)

DEBUG 2018-08-06 13:13:07,329 [XNIO-1 task-12] com.complexible.stardog.plan.eval.ExecutablePlanFactory:optimizePlan(139): Optimized plan:
FROM Dataset(ALL)
DELETE
    Projection([Var(9) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], card=0[ACCURATE], cost=Infinity)
    Bind(<http://data.einnsyn.no/innsynskravGraph> AS 12, rdf:rest AS 10, rdf:nil AS 11)
      Singleton
INSERT
    Projection([Var(9) as 0, Var(10) as 1, Var(13) as 2, Var(12) as 3], [Var(13) as 0, Var(14) as 1, Var(6) as 2, Var(12) as 3], [Var(13) as 0, Var(10) as 1, Var(11) as 2, Var(12) as 3], [Var(6) as 0, Var(15) as 1, Var(5) as 2, Var(12) as 3], [Var(6) as 0, Var(16) as 1, Var(17) as 2, Var(12) as 3], [Var(6) as 0, Var(18) as 1, Var(19) as 2, Var(12) as 3], [Var(6) as 0, Var(20) as 1, Var(4) as 2, Var(12) as 3], card=0[ACCURATE], cost=Infinity)
    Bind(rdf:type AS 16, <http://data.einnsyn.no/brukermeta/Statusobjekt> AS 17, <http://data.einnsyn.no/brukermeta/systemgenerert> AS 18, "false"^^xsd:boolean AS 19, <http://data.einnsyn.no/virksomhetmeta/opprettetDato> AS 20, rdf:rest AS 10, rdf:nil AS 11, <http://data.einnsyn.no/innsynskravGraph> AS 12, BNODE() AS 13, rdf:first AS 14, <http://data.einnsyn.no/brukermeta/status> AS 15)
      Singleton
WHERE
  LoopJoin( card=237505366.6M[ACCURATE] cost=4.7501073326834E13)
    Bind(NOW() AS 4)
      Singleton
    Hint( group.joins: )
      LoopJoin( card=237505366.6M[ACCURATE] cost=1.2038718105569278E16)
        Scan[121K[ACCURATE]](SPO[SortType[-3]], Var(9), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, http://www.w3.org/1999/02/22-rdf-syntax-ns#nil, http://data.einnsyn.no/innsynskravGraph, scope=Named)
        Hint( group.joins: )
          LoopJoin( card=1960.9M[ACCURATE] cost=9.900278258079999E10)
            LoopJoin( card=7[ACCURATE] cost=351.4)
              LoopJoin( card=7[ACCURATE] cost=709.8)
                LoopJoin( card=7[ACCURATE] cost=358.4)
                  Scan[7[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/bruker/9e2092a2-6e44-406f-a059-7f353e249e76, http://data.einnsyn.no/brukermeta/innsynskrav, Var(7), http://data.einnsyn.no/innsynskravGraph, scope=Named)
                  Scan[1[ACCURATE]](SPO[SortType[-3]], Var(7), http://data.einnsyn.no/brukermeta/innsynskravdel, http://data.einnsyn.no/innsynskrav/46634121-a9b5-4504-bf88-cd551df15177, http://data.einnsyn.no/innsynskravGraph, scope=Named)
                Scan[1[ACCURATE]](SPO[SortType[-3]], http://data.einnsyn.no/innsynskrav/46634121-a9b5-4504-bf88-cd551df15177, http://data.einnsyn.no/brukermeta/statusobjekt, Var(8), http://data.einnsyn.no/innsynskravGraph, scope=Named)
              Bind(<http://data.einnsyn.no/innsynskrav/bac6123d-a26f-48fa-975d-a3833ebae347_4> AS 6)
                Bind(<http://data.einnsyn.no/brukermeta/avslåttInnsyn> AS 5)
                  Singleton
            PropertyPath[280.1M[PROBABLY_ACCURATE]](Var(8) -> Var(9) in http://data.einnsyn.no/innsynskravGraph 0+, cost=2.80622084E8)
              Scan[246K[ACCURATE]](SPO[SortType[-3]], Var(8), http://www.w3.org/1999/02/22-rdf-syntax-ns#rest, Var(9), http://data.einnsyn.no/innsynskravGraph, scope=Named)

DEBUG 2018-08-06 13:13:07,332 [XNIO-1 task-12] com.complexible.stardog.plan.eval.operator.impl.ModifyOperatorImpl:computeNext(143): UPDATE is going to process 1 results

Those “ACCURATE” estimations are way off. Query executes in 1.69 seconds.

pavel · August 7, 2018, 10:34am

So you’re saying 5.3.2 hangs but 5.1.0 runs this update query in 1.69 sec? That’s odd, the plan for 5.3.2 looks OK to me.

If you enabled DEBUG logging for 5.3.2, do you see something like UPDATE is going to process XXX results when you run this query? This would indicate that the WHERE part finished execution.

In either case, if 5.3.2 consistently hangs our next (and last, assuming you cannot share the data) option is to look at the server’s thread dump when it happens.

Best,
Pavel

PS. The log for 5.1.0 seems truncated, it shows the plan for the Update query but there should be another one for its WHERE clause, similarly to 5.3.2.

Topic		Replies	Views
SPARQL queries run forever and cannot be terminated Support	7	983	June 1, 2018
Insert with blank node failing - There was an error while generating the plan Bug	2	567	February 8, 2017
Query time blows out > 1000x moving from 5.0.3 => 5.0.4 Bug	7	605	November 8, 2017
Virtual graph + `NOW()` results in error Bug	2	170	July 24, 2023
BIND in ruleset not working properly Support	3	401	March 21, 2017

Update query doesn't terminate in 5.3.2 (works fine in 5.1.0)

Related Topics