Unexpected degradation of performance in SPARQL query when xsd:DateTime is used instead of String

Virtuoso Universal Server RDF Data Management
1

There is a SPASQL query to define a view with some maintenance data from the graph DB. That view should give access to the latest available record about asset maintenance.

CREATE VIEW MAINTENANCE_FACT as SPARQL 

prefix rdf: <http://www.w3.org/1999/02/22-rdf-syntax-ns#> 
prefix owl: <http://www.w3.org/2002/07/owl#> 
prefix xsd: <http://www.w3.org/2001/XMLSchema#> 
prefix rdfs: <http://www.w3.org/2000/01/rdf-schema#> 
prefix dc: <http://purl.org/dc/elements/1.1/> 
prefix dm: <https://www.datasource.com/0.0.3.0#> 
prefix mws:     <https://www.datasource.com/model-workshop#> 
SELECT  DISTINCT concat(strafter(str(?datum), "#"), strafter(?Attr_ID,"-") ) as ?ID
                ?asset_name  
                ?item_code 
                ?Attr_ID 
                ?value
                ?t 
                ?maintenance_log_id 
               
                WHERE {
      ?datum         
                     ?pred ?value ;
                     dm:Manufacturing-PA00000003 ?t ;
                     dm:Manufacturing-PA00000005 ?name ;  
                     dm:Maintenance_Common-PA00000082 ?item_code ;
                     dm:Maintenance_Common-PA00000081 ?asset_name;
                     dm:Maintenance_Common-PA00000083 ?item_name;
                     dm:Manufacturing-PA00000005 ?maintenance_log_id ;
                     dm:externalID ?eID.
BIND (strafter(str(?eID), "#") as ?externalID )              
BIND (strafter(str(?pred), "#") as ?predname)
BIND (concat(?predname,'-', ?item_code) as ?Attr_ID )  
              FILTER (?pred != rdf:type and
              ?pred != dm:externalID AND
              ?pred != dm:Maintenance_Common-PA00000083 AND
              ?pred != dm:Maintenance_Common-PA00000081 AND
              ?pred != dm:Maintenance_Common-PA0000008 AND
              ?pred != dm:Manufacturing-PA00000005 AND
              ?pred != dm:dt_modified   AND
              ?pred != dm:Manufacturing-PA00000003)

{
	SELECT  ?name str(MAX(strdt(?modified,xsd:DateTime))) as ?t WHERE {
	?maintenance_log_rec 
	       dm:Manufacturing-PA00000003 ?modified;
	      dm:Manufacturing-PA00000005 ?name.
	} group by ?name 
}
}

Subselect with group by returns the latest available fact for each asset name.
As it may be noticed, the maintenance datetime is retrieved from the triples

?maintenance_log_rec  dm:Manufacturing-PA00000003 ?modified.

The objects in such triples are RDF literals of xsd;String type.

profile('SELECT count(*) from MAINTENANCE_FACT ') gives 5531 msec.

If another predicate is used to get the datetime of maintenance, where RDF literal originally has the type xsd:DateTime,

SELECT  ?name ?t WHERE {
	?maintenance_log_rec 
	       **dm:dt_modified ?t;**
	      dm:Manufacturing-PA00000005 ?name.
	} group by ?name

and the main query is rewritten accordingly:
…

  ?datum         
                     ?pred ?value ;
                     **dm:dt_modified ?t ;**
                     dm:Manufacturing-PA00000005 ?name ;  
                     dm:Maintenance_Common-PA00000082 ?item_code ;
                     dm:Maintenance_Common-PA00000081 ?asset_name;
                     dm:Maintenance_Common-PA00000083 ?item_name;
                     dm:Manufacturing-PA00000005 ?maintenance_log_id ;
                     dm:externalID ?eID.
BIND (strafter(str(?eID), "#") as ?externalID )              
BIND (strafter(str(?pred), "#") as ?predname)
BIND (concat(?predname,'-', ?item_code) as ?Attr_ID )  
              FILTER (?pred != rdf:type and
              ?pred != dm:externalID AND
              ?pred != dm:Maintenance_Common-PA00000083 AND
              ?pred != dm:Maintenance_Common-PA00000081 AND
              ?pred != dm:Maintenance_Common-PA0000008 AND
              ?pred != dm:Manufacturing-PA00000005 AND
              ?pred != dm:dt_modified   AND
              ?pred != dm:Manufacturing-PA00000003)

the profile information gives the following result:

profile('SELECT count(*) from MAINTENANCE_FACT ') gives11365 msec.

It is not clear why execution time is larger if xsd:DateTime is used without any intermediate conversions ?

2

What is the complete profile command output when running both queries from the isql command line tool for comparison, as I would expect the complete query compilation plan to be generated for the SPARQL query being executed ?

3

For the first case profile is the following

  { 
    time   4.3e-05% fanout         1 input         1 rows
    time   0.00051% fanout         1 input         1 rows
    Precode:
      0: DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$28 := Call DB.DBA.RDF_MAKE_LONG_OF_SQLVAL (<c #>)
      7: DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$30 := Call DB.DBA.RDF_MAKE_LONG_OF_SQLVAL (<c ->)
      14: BReturn 0
    time   4.3e-05% fanout         1 input         1 rows
    fork {
        Subquery 44 
          { 
            time    0.0018% fanout         1 input         1 rows
            fork {
                time    0.0064% fanout     15906 input         1 rows
                RDF_QUAD   1.6e+04 rows(t13.S$50, t13.O$49)
                 inlined  P =  IRI_ID"...Manufacturing-PA00000005" 
                time     0.021% fanout         1 input     15906 rows
                RDF_QUAD         1 rows(t12.O$53)
                 inlined  P =  IRI_ID"...Manufacturing-PA00000003"  ,  S = t13.S$50
                time        43% fanout         0 input     15906 rows
                Precode:
                  0: __ro2sq$55 := Call __ro2sq (t12.O$53)
                  5: DB.DBA.rdf_strdt_impl$57 := Call DB.DBA.rdf_strdt_impl (__ro2sq$55, <tag 182 flag 1 c http://www.w3.org/2001/XMLSchema#DateTime>)
                  12: __rdf_sqlval_of_obj$59 := Call __rdf_sqlval_of_obj (DB.DBA.rdf_strdt_impl$57)
                  17: BReturn 0
                Sort (t13.O$49) -> (__rdf_sqlval_of_obj$59)
                
              }
            time    0.0004% fanout        79 input         1 rows
            group by read node  
            (t13.O$49, aggregate$63)
            
            After code:
            0: __rdf_strsqlval$83 := Call __rdf_strsqlval (aggregate$63,  0 )
            5: name$45 :=  := artm t13.O$49
            9: t$46 :=  := artm __rdf_strsqlval$83
            13: BReturn 0
            time   1.3e-05% fanout         0 input        79 rows
            Subquery Select(name$45, t$46)
          }
        time       8.5% fanout   201.342 input        79 rows
        Precode:
          0: DB.DBA.RDF_OBJ_OF_SQLVAL$92 := Call DB.DBA.RDF_OBJ_OF_SQLVAL (t$46)
          7: BReturn 0
        RDF_QUAD_POGS     2e+02 rows(t5.S$95)
         P =  IRI_ID"...Manufacturing-PA00000005"  ,  O = cast$259
        time     0.093% fanout   21.8732 input     15906 rows
        RDF_QUAD_SP       7.1 rows(t3.P$99, t3.S$98)
         inlined  S = t5.S$95
        time      0.97% fanout  0.681198 input    347915 rows
        END Node
        After test:
        0: if (t3.P$99 =  IRI_ID"...Manufacturing-PA00000003" ) then 33 else 4 unkn 33
        4: if (t3.P$99 =  IRI_ID"...modified_time" ) then 33 else 8 unkn 33
        8: if (t3.P$99 =  IRI_ID"...Manufacturing-PA00000005" ) then 33 else 12 unkn 33
        12: if (t3.P$99 =  IRI_ID"...Maintenance_Common-PA0000008" ) then 33 else 16 unkn 33
        16: if (t3.P$99 =  IRI_ID"...Maintenance_Common-PA00000081" ) then 33 else 20 unkn 33
        20: if (t3.P$99 =  IRI_ID"...Maintenance_Common-PA00000083" ) then 33 else 24 unkn 33
        24: if (t3.P$99 =  IRI_ID"...externalID" ) then 33 else 28 unkn 33
        28: if (t3.P$99 =  IRI_ID"...type" ) then 33 else 32 unkn 33
        32: BReturn 1
        33: BReturn 0
        time      0.46% fanout         1 input    236999 rows
        RDF_QUAD       1.2 rows(t3.O$103)
         inlined  P = k_t3.P$304 ,  S = k_t5.S$308
        time       1.5% fanout   0.99873 input    236999 rows
        RDF_QUAD   7.4e-07 rows(t4.S$108, t4.O$107)
         inlined  P =  IRI_ID"...Manufacturing-PA00000003"  ,  S = k_t5.S$320 ,  O = k_DB.DBA.RDF_OBJ_OF_SQLVAL$324
        time      0.18% fanout  0.998623 input    236698 rows
        RDF_QUAD         1 rows(t10.S$111)
         inlined  P =  IRI_ID"...externalID"  ,  S = k_t3.S$337
        time      0.21% fanout         1 input    236372 rows
        RDF_QUAD         1 rows(t9.S$115, t9.O$114)
         inlined  P =  IRI_ID"...Manufacturing-PA00000005"  ,  S = k_t3.S$351
        time      0.21% fanout         1 input    236372 rows
        RDF_QUAD         1 rows(t8.S$118)
         inlined  P =  IRI_ID"...Maintenance_Common-PA00000083"  ,  S = k_t3.S$366
        time      0.22% fanout  0.969235 input    236372 rows
        RDF_QUAD         1 rows(t7.S$122, t7.O$121)
         inlined  P =  IRI_ID"...Maintenance_Common-PA00000081"  ,  S = k_t3.S$380
        time        42% fanout         1 input    229100 rows
        RDF_QUAD         1 rows(t6.O$125)
         inlined  P =  IRI_ID"...Maintenance_Common-PA00000082"  ,  S = k_t3.S$395
        
        After code:
        0: __id2in$127 := Call __id2in (t3.P$99)
        5: __id2in$129 := Call __id2in (t3.S$98)
        10: __bft$131 := Call __bft (__id2in$129,  2 )
        15: DB.DBA.RDF_LONG_OF_SQLVAL$133 := Call DB.DBA.RDF_LONG_OF_SQLVAL (__bft$131)
        22: rdf_strafter_impl$135 := Call rdf_strafter_impl (DB.DBA.RDF_LONG_OF_SQLVAL$133, DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$28)
        27: __bft$137 := Call __bft (__id2in$127,  2 )
        32: DB.DBA.RDF_LONG_OF_SQLVAL$139 := Call DB.DBA.RDF_LONG_OF_SQLVAL (__bft$137)
        39: rdf_strafter_impl$141 := Call rdf_strafter_impl (DB.DBA.RDF_LONG_OF_SQLVAL$139, DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$28)
        44: __ro2sq$143 := Call __ro2sq (t6.O$125)
        49: rdf_concat_impl$145 := Call rdf_concat_impl (rdf_strafter_impl$141, <c ->, __ro2sq$143)
        54: DB.DBA.RDF_LONG_OF_SQLVAL$147 := Call DB.DBA.RDF_LONG_OF_SQLVAL (rdf_concat_impl$145)
        61: rdf_strafter_impl$149 := Call rdf_strafter_impl (DB.DBA.RDF_LONG_OF_SQLVAL$147, DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$30)
        66: rdf_concat_impl$151 := Call rdf_concat_impl (rdf_strafter_impl$135, rdf_strafter_impl$149)
        71: BReturn 0
        time       2.3% fanout         1 input    229100 rows
        Distinct (rdf_concat_impl$151, t7.O$121, t6.O$125, t6.O$125, rdf_concat_impl$145, rdf_concat_impl$145, t3.O$103, t4.O$107, t9.O$114)
        
        After code:
        0: ID$33 :=  := artm rdf_concat_impl$151
        4: tag_number$34 :=  := artm t7.O$121
        8: extID$35 :=  := artm t6.O$125
        12: sourceclassID$36 :=  := artm t6.O$125
        16: sourceAttr_ID$37 :=  := artm rdf_concat_impl$145
        20: Attr_ID$38 :=  := artm rdf_concat_impl$145
        24: value$39 :=  := artm t3.O$103
        28: modification_date$40 :=  := artm t4.O$107
        32: maintenance_log_id$41 :=  := artm t9.O$114
        36: applid$42 :=  := artm <c ERP>
        40: BReturn 0
        time      0.07% fanout         0 input    229100 rows
        Subquery Select(ID$33, tag_number$34, extID$35, sourceclassID$36, sourceAttr_ID$37, Attr_ID$38, value$39, modification_date$40, maintenance_log_id$41, applid$42)
        
        After code:
        0:  sum count$170 1 set no set_ctr$167
        5: BReturn 0
      }
    time   2.8e-05% fanout         0 input         1 rows
    Select (count$170)
  }

And for the case of DateTime

  { 
    time   2.3e-06% fanout         1 input         1 rows
    time   2.4e-05% fanout         1 input         1 rows
    Precode:
      0: DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$28 := Call DB.DBA.RDF_MAKE_LONG_OF_SQLVAL (<c #>)
      7: DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$30 := Call DB.DBA.RDF_MAKE_LONG_OF_SQLVAL (<c ->)
      14: BReturn 0
    time     3e-06% fanout         1 input         1 rows
    fork {
        time   0.00035% fanout     15500 input         1 rows
        RDF_QUAD   1.5e+04 rows(t7.S$46, t7.O$45)
         inlined  P =  IRI_ID"...Maintenance_Common-PA00000081" 
        time    0.0056% fanout   21.8175 input     15500 rows
        RDF_QUAD_SP       7.1 rows(t3.P$50, t3.S$49)
         inlined  S = t7.S$46
        time     0.084% fanout   0.67921 input    338171 rows
        END Node
        After test:
        0: if (t3.P$50 =  IRI_ID"...Manufacturing-PA00000003" ) then 33 else 4 unkn 33
        4: if (t3.P$50 =  IRI_ID"...modified_time" ) then 33 else 8 unkn 33
        8: if (t3.P$50 =  IRI_ID"...Manufacturing-PA00000005" ) then 33 else 12 unkn 33
        12: if (t3.P$50 =  IRI_ID"...Maintenance_Common-PA0000008" ) then 33 else 16 unkn 33
        16: if (t3.P$50 =  IRI_ID"...Maintenance_Common-PA00000081" ) then 33 else 20 unkn 33
        20: if (t3.P$50 =  IRI_ID"...Maintenance_Common-PA00000083" ) then 33 else 24 unkn 33
        24: if (t3.P$50 =  IRI_ID"...externalID" ) then 33 else 28 unkn 33
        28: if (t3.P$50 =  IRI_ID"...type" ) then 33 else 32 unkn 33
        32: BReturn 1
        33: BReturn 0
        time     0.044% fanout         1 input    229689 rows
        RDF_QUAD       1.2 rows(t3.O$54)
         inlined  P = k_t3.P$244 ,  S = k_t7.S$248
        time     0.026% fanout  0.998746 input    229689 rows
        RDF_QUAD         1 rows(t10.S$58)
         inlined  P =  IRI_ID"...externalID"  ,  S = k_t3.S$260
        time     0.016% fanout         1 input    229401 rows
        RDF_QUAD         1 rows(t5.O$62, t5.S$61)
         inlined  P =  IRI_ID"...Manufacturing-PA00000005"  ,  S = k_t3.S$274
        Subquery 64 
          { 
            time      0.37% fanout         1 input    229401 rows
            fork {
                time        25% fanout   201.311 input    229401 rows
                RDF_QUAD     0.012 rows(t13.S$70, t13.O$69)
                 inlined  P =  IRI_ID"...Manufacturing-PA00000005"  O = cast$294
                time        13% fanout         1 input 4.61809e+07 rows
                RDF_QUAD         1 rows(t12.O$73)
                 inlined  P =  IRI_ID"...modified_time"  ,  S = t13.S$70
                time        58% fanout         0 input 4.61809e+07 rows
                Sort (set_no$67, t13.O$69) -> (t12.O$73)
                
              }
            time     0.019% fanout         1 input    229401 rows
            group by read node  
            (gb_set_no$85, t13.O$69, aggregate$77)
            
            After code:
            0: name$65 :=  := artm t13.O$69
            4: t$66 :=  := artm aggregate$77
            8: BReturn 0
            time     3e-06% fanout         0 input    229401 rows
            Subquery Select(name$65, t$66)
          }
        time      0.49% fanout  0.799081 input    229401 rows
        Precode:
          0: DB.DBA.RDF_OBJ_OF_SQLVAL$112 := Call DB.DBA.RDF_OBJ_OF_SQLVAL (t$66)
          7: BReturn 0
        RDF_QUAD   7.4e-07 rows(t4.S$116, t4.O$115)
         inlined  P =  IRI_ID"...modified_time"  ,  S = k_t5.S$351 ,  O = k_DB.DBA.RDF_OBJ_OF_SQLVAL$355
        time     0.022% fanout         1 input    183310 rows
        RDF_QUAD         1 rows(t9.S$120, t9.O$119)
         inlined  P =  IRI_ID"...Manufacturing-PA00000005"  ,  S = k_t3.S$368
        time      0.02% fanout         1 input    183310 rows
        RDF_QUAD         1 rows(t8.S$123)
         inlined  P =  IRI_ID"...Maintenance_Common-PA00000083"  ,  S = k_t3.S$383
        time       2.6% fanout         1 input    183310 rows
        RDF_QUAD         1 rows(t6.O$126)
         inlined  P =  IRI_ID"...Maintenance_Common-PA00000082"  ,  S = k_t3.S$397
        
        After code:
        0: __id2in$128 := Call __id2in (t3.P$50)
        5: __id2in$130 := Call __id2in (t3.S$49)
        10: __bft$132 := Call __bft (__id2in$130,  2 )
        15: DB.DBA.RDF_LONG_OF_SQLVAL$134 := Call DB.DBA.RDF_LONG_OF_SQLVAL (__bft$132)
        22: rdf_strafter_impl$136 := Call rdf_strafter_impl (DB.DBA.RDF_LONG_OF_SQLVAL$134, DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$28)
        27: __bft$138 := Call __bft (__id2in$128,  2 )
        32: DB.DBA.RDF_LONG_OF_SQLVAL$140 := Call DB.DBA.RDF_LONG_OF_SQLVAL (__bft$138)
        39: rdf_strafter_impl$142 := Call rdf_strafter_impl (DB.DBA.RDF_LONG_OF_SQLVAL$140, DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$28)
        44: __ro2sq$144 := Call __ro2sq (t6.O$126)
        49: rdf_concat_impl$146 := Call rdf_concat_impl (rdf_strafter_impl$142, <c ->, __ro2sq$144)
        54: DB.DBA.RDF_LONG_OF_SQLVAL$148 := Call DB.DBA.RDF_LONG_OF_SQLVAL (rdf_concat_impl$146)
        61: rdf_strafter_impl$150 := Call rdf_strafter_impl (DB.DBA.RDF_LONG_OF_SQLVAL$148, DB.DBA.RDF_MAKE_LONG_OF_SQLVAL$30)
        66: rdf_concat_impl$152 := Call rdf_concat_impl (rdf_strafter_impl$136, rdf_strafter_impl$150)
        71: BReturn 0
        time      0.16% fanout         1 input    183310 rows
        Distinct (rdf_concat_impl$152, t7.O$45, t6.O$126, t6.O$126, rdf_concat_impl$146, rdf_concat_impl$146, t3.O$54, t4.O$115, t9.O$119)
        
        After code:
        0: ID$33 :=  := artm rdf_concat_impl$152
        4: tag_number$34 :=  := artm t7.O$45
        8: extID$35 :=  := artm t6.O$126
        12: sourceclassID$36 :=  := artm t6.O$126
        16: sourceAttr_ID$37 :=  := artm rdf_concat_impl$146
        20: Attr_ID$38 :=  := artm rdf_concat_impl$146
        24: value$39 :=  := artm t3.O$54
        28: modification_date$40 :=  := artm t4.O$115
        32: maintenance_log_id$41 :=  := artm t9.O$119
        36: applid$42 :=  := artm <c ERP>
        40: BReturn 0
        time     0.011% fanout         0 input    183310 rows
        Subquery Select(ID$33, tag_number$34, extID$35, sourceclassID$36, sourceAttr_ID$37, Attr_ID$38, value$39, modification_date$40, maintenance_log_id$41, applid$42)
        
        After code:
        0:  sum count$171 1 set no set_ctr$168
        5: BReturn 0
      }
    time   2.8e-06% fanout         0 input         1 rows
    Select (count$171)
  }
4

The profile shows that for the xsd:DateTime query the query optimiser decided to search by index on the modified_time and there are many (4.61809e+07) of them which is where the time is being spent:

RDF_QUAD     1 rows(t12.O$73)
         inlined P = IRI_ID"...modified_time" , S = t13.S$70
       time    58% fanout     0 input 4.61809e+07 rows
5

Thank you for explanation !
In such case what can be recommended for tuning the behavior of the optimizer (extra pragma settings, reordering of statements inside the SPARQL query, etc ) ?

6

The are some SPARQL Query Optimization Pragmas you could try but they are not guaranteed to change the behaviour.