You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@jena.apache.org by om...@wellsfargo.com.INVALID on 2021/06/04 03:09:00 UTC
possible SPARQL performance regression Fuseki 3.14/3.16 -> 3.17
We have observed some surprising performance behavior with different versions of fuseki.
The versions used in this example are 3.14.0 (referred to as "f14" henceforth), 3.16.0 ("f16" henceforth), and 3.17.0 ("f17" henceforth) .
We have a large database in TDB1 (built using Jena TDB version 3.14.0). There are roughly 140 million triples in the dataset.
We discovered that many of our queries take much longer using f17 than using f14 or f16; that's right, the newer fuseki is much slower than the older one.
We tested more with f14, but noticed that perhaps the change in performance wasn't realized till after f16 after lightly testing.
We isolated a simple query that exhibits this behavior; this query reliable runs 4x slower in f17 than f14.
select *
WHERE { ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
FILTER (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) = xsd:integer(1002) )
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?CONSUMERID .
}
The modular arithmetic calculation in the filter is used to limit the number of records processed at any one time, and is an essential part of the query.
Here are some sample run stats.
Using f14:
time curl -k --data-urlencode query@canary.rq http://localhost:3030/kg/sparql > /dev/null
real 0m7.159s
user 0m0.008s
sys 0m0.002s
Using f17:
time curl -k --data-urlencode query@canary.rq http://localhost:3030/kg/sparql > /dev/null
real 0m23.192s
user 0m0.004s
sys 0m0.009s
We ran this test several times, and got essentially the same result (within about 5% on each end).
We also ran this with JENA_HOME and JENAROOT set to a 3.15 Jena installation and a 3.17 Jena installation when we started fuseki; this made no difference in the timing.
We asked tdbquery to explain the query; the result was not very illuminating:
16:54:06 INFO exec :: ALGEBRA
(filter (= (<http://www.w3.org/2001/XMLSchema#integer> (- (<http://www.w3.org/2001/XMLSchema#integer> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer> 1002\
))
(quadpattern
(quad <urn:x-arq:DefaultGraphNode> ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix)
(quad <urn:x-arq:DefaultGraphNode> ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?CONSUMERID)
))
16:54:06 INFO exec :: TDB
(filter (= (<http://www.w3.org/2001/XMLSchema#integer> (- (<http://www.w3.org/2001/XMLSchema#integer> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer> 1002\
))
(quadpattern
(quad <urn:x-arq:DefaultGraphNode> ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix)
(quad <urn:x-arq:DefaultGraphNode> ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?CONSUMERID)
))
Any suggestions on how we could get the same level of performance as we were with f14(f16) in f17?
Kind regards,
Omar
RE: possible SPARQL performance regression Fuseki 3.14/3.16 -> 3.17
Posted by om...@wellsfargo.com.INVALID.
Hi Andy,
A SPARQL MOD operator / fn:numeric-mod would be really excellent as a syntax extension, in a further release & probably would help out others for various use cases.
I appreciate the confirmation on xsd:double, as being the fastest for our scenario.
Omar
Re: possible SPARQL performance regression Fuseki 3.14/3.16 -> 3.17
Posted by Andy Seaborne <an...@apache.org>.
On 08/06/2021 22:47, Andy Seaborne wrote:
> Hi Omar,
>
> Thanks for the detail. I've created an example locally.
>
> The change is JENA-1943 (Increase Precision of Decimal Calculation
> Results) and partly involved is JENA-1984 (XSD casting fixes). The
> division isn't exact in xsd:decimal (factor of 3 in 7200) so the
> precision was causing an exception.
>
> Using xsd:double, and no further casting is the right way to achieve the
> task ... except I now don't understand why it costs more than the
> xsd:decimal way (using jena development after fixes)
Turns out this was an artifact of the test set and unrelated to the
reported situation.
FILTER (((?pix)-FLOOR((xsd:double(?pix))/7200)*7200) = (1002) )
should be the fastest way, on 3.16.0, 3.17.0, and 4.*
Implementing fn:numeric-mod would be useful and maybe a syntax extension
for A MOD B.
Andy
>
> Recorded as: JENA-2116
>
> Andy
>
> On 08/06/2021 02:34, omar.khan@wellsfargo.com wrote:
>> Hi Andy,
>>
>> The datatype of ?pix is normally an integer.
>>
>> I also found out that division was twice as slow for integers here in
>> f17 as f14/16, the below filter may not make a lot of sense. That
>> said, I was using it to see if it had to do with fundamental
>> arithmetic operations.
>>
>> FILTER (((?pix)/(?pix)) = 1002 )
>>
>> Takes ~ 2-3 seconds in f16
>>
>> Takes ~ 6 seconds in f17
>>
>> It led me to try what follows and could be telling. I cast the
>> numerator to double and it was much faster for the set and yielded the
>> same results of when I ran with an integer.
>>
>> This takes ~ 3 seconds in BOTH f16/f17
>>
>> FILTER (((?pix)-FLOOR((xsd:double(?pix))/7200)*7200) = (1002) )
>>
>> F16
>>
>> real 0m2.794s
>>
>> user 0m0.005s
>>
>> sys 0m0.004s
>>
>> F17
>>
>> real 0m2.783s
>>
>> user 0m0.006s
>>
>> sys 0m0.004s
>>
>> This takes ~ 20 s in f17 ~ 6 seconds in F16
>>
>> FILTER (((?pix)-FLOOR(((?pix))/7200)*7200) = (1002) )
>>
>> F16
>>
>> real 0m5.774s
>>
>> user 0m0.006s
>>
>> sys 0m0.004s
>>
>> F17
>>
>> real 0m20.020s
>>
>> user 0m0.006s
>>
>> sys 0m0.004s
>>
>> What follows are the timings on the query you asked for:
>>
>> For this query
>>
>> select (count(*) AS ?C)
>>
>> WHERE {
>>
>> ?record
>> <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
>>
>> FILTER
>> (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) =
>> xsd:integer(1002) )
>>
>> }
>>
>> F16
>>
>> bash-4.2$ time curl -k --data-urlencode query@canary5.rq -H
>> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>>
>> <?xml version="1.0"?>
>>
>> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>>
>> <head>
>>
>> <variable name="C"/>
>>
>> </head>
>>
>> <results>
>>
>> <result>
>>
>> <binding name="C">
>>
>> <literal
>> datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
>>
>> </binding>
>>
>> </result>
>>
>> </results>
>>
>> </sparql>
>>
>> real 0m7.668s
>>
>> user 0m0.005s
>>
>> sys 0m0.004s
>>
>> F17
>>
>> bash-4.2$ time curl -k --data-urlencode query@canary5.rq -H
>> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>>
>> <?xml version="1.0"?>
>>
>> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>>
>> <head>
>>
>> <variable name="C"/>
>>
>> </head>
>>
>> <results>
>>
>> <result>
>>
>> <binding name="C">
>>
>> <literal
>> datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
>>
>> </binding>
>>
>> </result>
>>
>> </results>
>>
>> </sparql>
>>
>> real 0m23.995s
>>
>> user 0m0.004s
>>
>> sys 0m0.005s
>>
>> F16
>>
>> bash-4.2$ time curl -k --data-urlencode query@canary6.rq -H
>> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>>
>> <?xml version="1.0"?>
>>
>> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>>
>> <head>
>>
>> <variable name="C"/>
>>
>> </head>
>>
>> <results>
>>
>> <result>
>>
>> <binding name="C">
>>
>> <literal
>> datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
>>
>> </binding>
>>
>> </result>
>>
>> </results>
>>
>> </sparql>
>>
>> real 0m6.347s
>>
>> user 0m0.006s
>>
>> sys 0m0.003s
>>
>> F17
>>
>> bash-4.2$ time curl -k --data-urlencode query@canary6.rq -H
>> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>>
>> <?xml version="1.0"?>
>>
>> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>>
>> <head>
>>
>> <variable name="C"/>
>>
>> </head>
>>
>> <results>
>>
>> <result>
>>
>> <binding name="C">
>>
>> <literal
>> datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
>>
>> </binding>
>>
>> </result>
>>
>> </results>
>>
>> </sparql>
>>
>> real 0m20.952s
>>
>> user 0m0.004s
>>
>> sys 0m0.005s
>>
>> stats about the data:
>>
>> select (count(*) AS ?C)
>>
>> WHERE {
>>
>> ?record
>> <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
>>
>> }
>>
>> time curl -k --data-urlencode query@canary7.rq -H
>> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>>
>> <?xml version="1.0"?>
>>
>> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>>
>> <head>
>>
>> <variable name="C"/>
>>
>> </head>
>>
>> <results>
>>
>> <result>
>>
>> <binding name="C">
>>
>> <literal
>> datatype="http://www.w3.org/2001/XMLSchema#integer">1000000</literal>
>>
>> </binding>
>>
>> </result>
>>
>> </results>
>>
>> </sparql>
>>
>> real 0m0.546s
>>
>> user 0m0.004s
>>
>> sys 0m0.004s
>>
>> select (count(distinct ?record) AS ?R)
>>
>> WHERE {
>>
>> ?record
>> <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
>>
>> }
>>
>> time curl -k --data-urlencode query@canary8.rq -H
>> 'Accept:application/n-triples' http://localhost:3030/kg/sparql >
>> canary8.out
>>
>> % Total % Received % Xferd Average Speed Time Time
>> Time Current
>>
>> Dload Upload Total Spent
>> Left Speed
>>
>> 100 104k 0 313 100 104k 0 228 0:07:48 0:07:47
>> 0:00:01 0
>>
>> real 7m47.731s
>>
>> user 0m0.034s
>>
>> sys 0m0.041s
>>
>> <?xml version="1.0"?>
>>
>> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>>
>> <head>
>>
>> <variable name="R"/>
>>
>> </head>
>>
>> <results>
>>
>> <result>
>>
>> <binding name="R">
>>
>> <literal
>> datatype="http://www.w3.org/2001/XMLSchema#integer">1000000</literal>
>>
>> </binding>
>>
>> </result>
>>
>> </results>
>>
>> </sparql>
>>
>> Best,
>> Omar
>>
>> *From:*Andy Seaborne <an...@apache.org>
>> *Sent:* Friday, June 04, 2021 8:03 AM
>> *To:* users@jena.apache.org
>> *Subject:* Re: possible SPARQL performance regression Fuseki 3.14/3.16
>> -> 3.17
>>
>> Hi Omar,
>>
>> Thank for the detailed report.
>>
>> It might be the casting -JENA-1984
>> <https://urldefense.com/v3/__https:/issues.apache.org/jira/browse/JENA-1984__;!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFVRlY2LI$>
>> - which was a change
>>
>> 3.16.0->3.17.0
>>
>> Could you time these queries please on a fast and on a slow system?
>>
>> It is checking it is the filter.
>>
>> select (count(*) AS ?C)
>>
>> WHERE {
>>
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID>
>> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?pix .
>>
>> FILTER
>> (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) =
>> xsd:integer(1002) )
>>
>> }
>>
>> and (less casting):
>>
>> select (count(*) AS ?C)
>>
>> WHERE {
>>
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID>
>> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?pix .
>>
>> FILTER (xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200 = 1002 )
>>
>> }
>>
>> It would be useful to know some count stats about the data:
>>
>> select (count(*) AS ?C)
>>
>> WHERE {
>>
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID>
>> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?pix .
>>
>> }
>>
>> select (count(distinct ?record) AS ?R)
>>
>> WHERE {
>>
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID>
>> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?pix .
>>
>> }
>>
>> and what is the datatype of ?pix normally?
>>
>> Andy
>>
>> On 04/06/2021 04:09, omar.khan@wellsfargo.com.INVALID
>> <ma...@wellsfargo.com.INVALID> wrote:
>>
>> We have observed some surprising performance behavior with
>> different versions of fuseki.
>>
>> The versions used in this example are 3.14.0 (referred to as "f14"
>> henceforth), 3.16.0 ("f16" henceforth), and 3.17.0 ("f17" henceforth) .
>>
>> We have a large database in TDB1 (built using Jena TDB version
>> 3.14.0). There are roughly 140 million triples in the dataset.
>>
>> We discovered that many of our queries take much longer using f17
>> than using f14 or f16; that's right, the newer fuseki is much slower
>> than the older one.
>>
>> We tested more with f14, but noticed that perhaps the change in
>> performance wasn't realized till after f16 after lightly testing.
>>
>> We isolated a simple query that exhibits this behavior; this query
>> reliable runs 4x slower in f17 than f14.
>>
>> select *
>>
>> WHERE {
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?pix .
>>
>> FILTER
>> (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) =
>> xsd:integer(1002) )
>>
>>
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?CONSUMERID .
>>
>> }
>>
>> The modular arithmetic calculation in the filter is used to limit
>> the number of records processed at any one time, and is an essential
>> part of the query.
>>
>> Here are some sample run stats.
>>
>> Using f14:
>>
>> time curl -k --data-urlencodequery@canary.rq
>> <ma...@canary.rq> http://localhost:3030/kg/sparql
>> <https://urldefense.com/v3/__http:/localhost:3030/kg/sparql__;!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF-cMtJ6c$>
>> > /dev/null
>>
>> real 0m7.159s
>>
>> user 0m0.008s
>>
>> sys 0m0.002s
>>
>> Using f17:
>>
>> time curl -k --data-urlencodequery@canary.rq
>> <ma...@canary.rq> http://localhost:3030/kg/sparql
>> <https://urldefense.com/v3/__http:/localhost:3030/kg/sparql__;!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF-cMtJ6c$>
>> > /dev/null
>>
>> real 0m23.192s
>>
>> user 0m0.004s
>>
>> sys 0m0.009s
>>
>> We ran this test several times, and got essentially the same
>> result (within about 5% on each end).
>>
>> We also ran this with JENA_HOME and JENAROOT set to a 3.15 Jena
>> installation and a 3.17 Jena installation when we started fuseki; this
>> made no difference in the timing.
>>
>> We asked tdbquery to explain the query; the result was not very
>> illuminating:
>>
>> 16:54:06 INFO exec :: ALGEBRA
>>
>> (filter (= (<http://www.w3.org/2001/XMLSchema#integer>
>> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$>
>> (- (<http://www.w3.org/2001/XMLSchema#integer>
>> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$>
>> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer>
>> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$>
>> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer>
>> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$>
>> 1002\
>>
>> ))
>>
>> (quadpattern
>>
>> (quad <urn:x-arq:DefaultGraphNode%3E
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?pix)
>>
>> (quad <urn:x-arq:DefaultGraphNode%3E
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?CONSUMERID)
>>
>> ))
>>
>> 16:54:06 INFO exec :: TDB
>>
>> (filter (= (<http://www.w3.org/2001/XMLSchema#integer>
>> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$>
>> (- (<http://www.w3.org/2001/XMLSchema#integer>
>> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$>
>> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer>
>> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$>
>> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer>
>> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$>
>> 1002\
>>
>> ))
>>
>> (quadpattern
>>
>> (quad <urn:x-arq:DefaultGraphNode%3E
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?pix)
>>
>> (quad <urn:x-arq:DefaultGraphNode%3E
>> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$>
>> ?CONSUMERID)
>>
>> ))
>>
>> Any suggestions on how we could get the same level of performance
>> as we were with f14(f16) in f17?
>>
>> Kind regards,
>>
>> Omar
>>
Re: possible SPARQL performance regression Fuseki 3.14/3.16 -> 3.17
Posted by Andy Seaborne <an...@apache.org>.
Hi Omar,
Thanks for the detail. I've created an example locally.
The change is JENA-1943 (Increase Precision of Decimal Calculation
Results) and partly involved is JENA-1984 (XSD casting fixes). The
division isn't exact in xsd:decimal (factor of 3 in 7200) so the
precision was causing an exception.
Using xsd:double, and no further casting is the right way to achieve the
task ... except I now don't understand why it costs more than the
xsd:decimal way (using jena development after fixes)
Recorded as: JENA-2116
Andy
On 08/06/2021 02:34, omar.khan@wellsfargo.com wrote:
> Hi Andy,
>
> The datatype of ?pix is normally an integer.
>
> I also found out that division was twice as slow for integers here in
> f17 as f14/16, the below filter may not make a lot of sense. That said,
> I was using it to see if it had to do with fundamental arithmetic
> operations.
>
> FILTER (((?pix)/(?pix)) = 1002 )
>
> Takes ~ 2-3 seconds in f16
>
> Takes ~ 6 seconds in f17
>
> It led me to try what follows and could be telling. I cast the numerator
> to double and it was much faster for the set and yielded the same
> results of when I ran with an integer.
>
> This takes ~ 3 seconds in BOTH f16/f17
>
> FILTER (((?pix)-FLOOR((xsd:double(?pix))/7200)*7200) = (1002) )
>
> F16
>
> real 0m2.794s
>
> user 0m0.005s
>
> sys 0m0.004s
>
> F17
>
> real 0m2.783s
>
> user 0m0.006s
>
> sys 0m0.004s
>
> This takes ~ 20 s in f17 ~ 6 seconds in F16
>
> FILTER (((?pix)-FLOOR(((?pix))/7200)*7200) = (1002) )
>
> F16
>
> real 0m5.774s
>
> user 0m0.006s
>
> sys 0m0.004s
>
> F17
>
> real 0m20.020s
>
> user 0m0.006s
>
> sys 0m0.004s
>
> What follows are the timings on the query you asked for:
>
> For this query
>
> select (count(*) AS ?C)
>
> WHERE {
>
> ?record
> <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
>
> FILTER
> (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) =
> xsd:integer(1002) )
>
> }
>
> F16
>
> bash-4.2$ time curl -k --data-urlencode query@canary5.rq -H
> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>
> <?xml version="1.0"?>
>
> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>
> <head>
>
> <variable name="C"/>
>
> </head>
>
> <results>
>
> <result>
>
> <binding name="C">
>
> <literal
> datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
>
> </binding>
>
> </result>
>
> </results>
>
> </sparql>
>
> real 0m7.668s
>
> user 0m0.005s
>
> sys 0m0.004s
>
> F17
>
> bash-4.2$ time curl -k --data-urlencode query@canary5.rq -H
> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>
> <?xml version="1.0"?>
>
> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>
> <head>
>
> <variable name="C"/>
>
> </head>
>
> <results>
>
> <result>
>
> <binding name="C">
>
> <literal
> datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
>
> </binding>
>
> </result>
>
> </results>
>
> </sparql>
>
> real 0m23.995s
>
> user 0m0.004s
>
> sys 0m0.005s
>
> F16
>
> bash-4.2$ time curl -k --data-urlencode query@canary6.rq -H
> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>
> <?xml version="1.0"?>
>
> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>
> <head>
>
> <variable name="C"/>
>
> </head>
>
> <results>
>
> <result>
>
> <binding name="C">
>
> <literal
> datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
>
> </binding>
>
> </result>
>
> </results>
>
> </sparql>
>
> real 0m6.347s
>
> user 0m0.006s
>
> sys 0m0.003s
>
> F17
>
> bash-4.2$ time curl -k --data-urlencode query@canary6.rq -H
> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>
> <?xml version="1.0"?>
>
> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>
> <head>
>
> <variable name="C"/>
>
> </head>
>
> <results>
>
> <result>
>
> <binding name="C">
>
> <literal
> datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
>
> </binding>
>
> </result>
>
> </results>
>
> </sparql>
>
> real 0m20.952s
>
> user 0m0.004s
>
> sys 0m0.005s
>
> stats about the data:
>
> select (count(*) AS ?C)
>
> WHERE {
>
> ?record
> <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
>
> }
>
> time curl -k --data-urlencode query@canary7.rq -H
> 'Accept:application/n-triples' http://localhost:3030/kg/sparql
>
> <?xml version="1.0"?>
>
> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>
> <head>
>
> <variable name="C"/>
>
> </head>
>
> <results>
>
> <result>
>
> <binding name="C">
>
> <literal
> datatype="http://www.w3.org/2001/XMLSchema#integer">1000000</literal>
>
> </binding>
>
> </result>
>
> </results>
>
> </sparql>
>
> real 0m0.546s
>
> user 0m0.004s
>
> sys 0m0.004s
>
> select (count(distinct ?record) AS ?R)
>
> WHERE {
>
> ?record
> <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
>
> }
>
> time curl -k --data-urlencode query@canary8.rq -H
> 'Accept:application/n-triples' http://localhost:3030/kg/sparql >
> canary8.out
>
> % Total % Received % Xferd Average Speed Time Time Time
> Current
>
> Dload Upload Total Spent Left
> Speed
>
> 100 104k 0 313 100 104k 0 228 0:07:48 0:07:47
> 0:00:01 0
>
> real 7m47.731s
>
> user 0m0.034s
>
> sys 0m0.041s
>
> <?xml version="1.0"?>
>
> <sparql xmlns="http://www.w3.org/2005/sparql-results#">
>
> <head>
>
> <variable name="R"/>
>
> </head>
>
> <results>
>
> <result>
>
> <binding name="R">
>
> <literal
> datatype="http://www.w3.org/2001/XMLSchema#integer">1000000</literal>
>
> </binding>
>
> </result>
>
> </results>
>
> </sparql>
>
> Best,
> Omar
>
> *From:*Andy Seaborne <an...@apache.org>
> *Sent:* Friday, June 04, 2021 8:03 AM
> *To:* users@jena.apache.org
> *Subject:* Re: possible SPARQL performance regression Fuseki 3.14/3.16
> -> 3.17
>
> Hi Omar,
>
> Thank for the detailed report.
>
> It might be the casting -JENA-1984 <https://urldefense.com/v3/__https:/issues.apache.org/jira/browse/JENA-1984__;!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFVRlY2LI$> - which was a change
>
> 3.16.0->3.17.0
>
> Could you time these queries please on a fast and on a slow system?
>
> It is checking it is the filter.
>
> select (count(*) AS ?C)
>
> WHERE {
>
> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
>
> FILTER (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) = xsd:integer(1002) )
>
> }
>
> and (less casting):
>
> select (count(*) AS ?C)
>
> WHERE {
>
> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
>
> FILTER (xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200 = 1002 )
>
> }
>
> It would be useful to know some count stats about the data:
>
> select (count(*) AS ?C)
>
> WHERE {
>
> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
>
> }
>
> select (count(distinct ?record) AS ?R)
>
> WHERE {
>
> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
>
> }
>
> and what is the datatype of ?pix normally?
>
> Andy
>
> On 04/06/2021 04:09, omar.khan@wellsfargo.com.INVALID
> <ma...@wellsfargo.com.INVALID> wrote:
>
> We have observed some surprising performance behavior with different versions of fuseki.
>
> The versions used in this example are 3.14.0 (referred to as "f14" henceforth), 3.16.0 ("f16" henceforth), and 3.17.0 ("f17" henceforth) .
>
> We have a large database in TDB1 (built using Jena TDB version 3.14.0). There are roughly 140 million triples in the dataset.
>
> We discovered that many of our queries take much longer using f17 than using f14 or f16; that's right, the newer fuseki is much slower than the older one.
>
> We tested more with f14, but noticed that perhaps the change in performance wasn't realized till after f16 after lightly testing.
>
> We isolated a simple query that exhibits this behavior; this query reliable runs 4x slower in f17 than f14.
>
> select *
>
> WHERE { ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
>
> FILTER (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) = xsd:integer(1002) )
>
> ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?CONSUMERID .
>
> }
>
> The modular arithmetic calculation in the filter is used to limit the number of records processed at any one time, and is an essential part of the query.
>
> Here are some sample run stats.
>
> Using f14:
>
> time curl -k --data-urlencodequery@canary.rq <ma...@canary.rq> http://localhost:3030/kg/sparql <https://urldefense.com/v3/__http:/localhost:3030/kg/sparql__;!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF-cMtJ6c$> > /dev/null
>
> real 0m7.159s
>
> user 0m0.008s
>
> sys 0m0.002s
>
> Using f17:
>
> time curl -k --data-urlencodequery@canary.rq <ma...@canary.rq> http://localhost:3030/kg/sparql <https://urldefense.com/v3/__http:/localhost:3030/kg/sparql__;!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF-cMtJ6c$> > /dev/null
>
> real 0m23.192s
>
> user 0m0.004s
>
> sys 0m0.009s
>
> We ran this test several times, and got essentially the same result (within about 5% on each end).
>
> We also ran this with JENA_HOME and JENAROOT set to a 3.15 Jena installation and a 3.17 Jena installation when we started fuseki; this made no difference in the timing.
>
> We asked tdbquery to explain the query; the result was not very illuminating:
>
> 16:54:06 INFO exec :: ALGEBRA
>
> (filter (= (<http://www.w3.org/2001/XMLSchema#integer> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> (- (<http://www.w3.org/2001/XMLSchema#integer> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> 1002\
>
> ))
>
> (quadpattern
>
> (quad <urn:x-arq:DefaultGraphNode%3E ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix)
>
> (quad <urn:x-arq:DefaultGraphNode%3E ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?CONSUMERID)
>
> ))
>
> 16:54:06 INFO exec :: TDB
>
> (filter (= (<http://www.w3.org/2001/XMLSchema#integer> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> (- (<http://www.w3.org/2001/XMLSchema#integer> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer> <https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> 1002\
>
> ))
>
> (quadpattern
>
> (quad <urn:x-arq:DefaultGraphNode%3E ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix)
>
> (quad <urn:x-arq:DefaultGraphNode%3E ?record<https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> <https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?CONSUMERID)
>
> ))
>
> Any suggestions on how we could get the same level of performance as we were with f14(f16) in f17?
>
> Kind regards,
>
> Omar
>
RE: possible SPARQL performance regression Fuseki 3.14/3.16 -> 3.17
Posted by om...@wellsfargo.com.INVALID.
Hi Andy,
The datatype of ?pix is normally an integer.
I also found out that division was twice as slow for integers here in f17 as f14/16, the below filter may not make a lot of sense. That said, I was using it to see if it had to do with fundamental arithmetic operations.
FILTER (((?pix)/(?pix)) = 1002 )
Takes ~ 2-3 seconds in f16
Takes ~ 6 seconds in f17
It led me to try what follows and could be telling. I cast the numerator to double and it was much faster for the set and yielded the same results of when I ran with an integer.
This takes ~ 3 seconds in BOTH f16/f17
FILTER (((?pix)-FLOOR((xsd:double(?pix))/7200)*7200) = (1002) )
F16
real 0m2.794s
user 0m0.005s
sys 0m0.004s
F17
real 0m2.783s
user 0m0.006s
sys 0m0.004s
This takes ~ 20 s in f17 ~ 6 seconds in F16
FILTER (((?pix)-FLOOR(((?pix))/7200)*7200) = (1002) )
F16
real 0m5.774s
user 0m0.006s
sys 0m0.004s
F17
real 0m20.020s
user 0m0.006s
sys 0m0.004s
What follows are the timings on the query you asked for:
For this query
select (count(*) AS ?C)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
FILTER (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) = xsd:integer(1002) )
}
F16
bash-4.2$ time curl -k --data-urlencode query@canary5.rq -H 'Accept:application/n-triples' http://localhost:3030/kg/sparql
<?xml version="1.0"?>
<sparql xmlns="http://www.w3.org/2005/sparql-results#">
<head>
<variable name="C"/>
</head>
<results>
<result>
<binding name="C">
<literal datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
</binding>
</result>
</results>
</sparql>
real 0m7.668s
user 0m0.005s
sys 0m0.004s
F17
bash-4.2$ time curl -k --data-urlencode query@canary5.rq -H 'Accept:application/n-triples' http://localhost:3030/kg/sparql
<?xml version="1.0"?>
<sparql xmlns="http://www.w3.org/2005/sparql-results#">
<head>
<variable name="C"/>
</head>
<results>
<result>
<binding name="C">
<literal datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
</binding>
</result>
</results>
</sparql>
real 0m23.995s
user 0m0.004s
sys 0m0.005s
F16
bash-4.2$ time curl -k --data-urlencode query@canary6.rq -H 'Accept:application/n-triples' http://localhost:3030/kg/sparql
<?xml version="1.0"?>
<sparql xmlns="http://www.w3.org/2005/sparql-results#">
<head>
<variable name="C"/>
</head>
<results>
<result>
<binding name="C">
<literal datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
</binding>
</result>
</results>
</sparql>
real 0m6.347s
user 0m0.006s
sys 0m0.003s
F17
bash-4.2$ time curl -k --data-urlencode query@canary6.rq -H 'Accept:application/n-triples' http://localhost:3030/kg/sparql
<?xml version="1.0"?>
<sparql xmlns="http://www.w3.org/2005/sparql-results#">
<head>
<variable name="C"/>
</head>
<results>
<result>
<binding name="C">
<literal datatype="http://www.w3.org/2001/XMLSchema#integer">142</literal>
</binding>
</result>
</results>
</sparql>
real 0m20.952s
user 0m0.004s
sys 0m0.005s
stats about the data:
select (count(*) AS ?C)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
}
time curl -k --data-urlencode query@canary7.rq -H 'Accept:application/n-triples' http://localhost:3030/kg/sparql
<?xml version="1.0"?>
<sparql xmlns="http://www.w3.org/2005/sparql-results#">
<head>
<variable name="C"/>
</head>
<results>
<result>
<binding name="C">
<literal datatype="http://www.w3.org/2001/XMLSchema#integer">1000000</literal>
</binding>
</result>
</results>
</sparql>
real 0m0.546s
user 0m0.004s
sys 0m0.004s
select (count(distinct ?record) AS ?R)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
}
time curl -k --data-urlencode query@canary8.rq -H 'Accept:application/n-triples' http://localhost:3030/kg/sparql > canary8.out
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 104k 0 313 100 104k 0 228 0:07:48 0:07:47 0:00:01 0
real 7m47.731s
user 0m0.034s
sys 0m0.041s
<?xml version="1.0"?>
<sparql xmlns="http://www.w3.org/2005/sparql-results#">
<head>
<variable name="R"/>
</head>
<results>
<result>
<binding name="R">
<literal datatype="http://www.w3.org/2001/XMLSchema#integer">1000000</literal>
</binding>
</result>
</results>
</sparql>
Best,
Omar
From: Andy Seaborne <an...@apache.org>
Sent: Friday, June 04, 2021 8:03 AM
To: users@jena.apache.org
Subject: Re: possible SPARQL performance regression Fuseki 3.14/3.16 -> 3.17
Hi Omar,
Thank for the detailed report.
It might be the casting - JENA-1984<https://urldefense.com/v3/__https:/issues.apache.org/jira/browse/JENA-1984__;!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFVRlY2LI$> - which was a change
3.16.0->3.17.0
Could you time these queries please on a fast and on a slow system?
It is checking it is the filter.
select (count(*) AS ?C)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
FILTER (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) = xsd:integer(1002) )
}
and (less casting):
select (count(*) AS ?C)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
FILTER (xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200 = 1002 )
}
It would be useful to know some count stats about the data:
select (count(*) AS ?C)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
}
select (count(distinct ?record) AS ?R)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
}
and what is the datatype of ?pix normally?
Andy
On 04/06/2021 04:09, omar.khan@wellsfargo.com.INVALID<ma...@wellsfargo.com.INVALID> wrote:
We have observed some surprising performance behavior with different versions of fuseki.
The versions used in this example are 3.14.0 (referred to as "f14" henceforth), 3.16.0 ("f16" henceforth), and 3.17.0 ("f17" henceforth) .
We have a large database in TDB1 (built using Jena TDB version 3.14.0). There are roughly 140 million triples in the dataset.
We discovered that many of our queries take much longer using f17 than using f14 or f16; that's right, the newer fuseki is much slower than the older one.
We tested more with f14, but noticed that perhaps the change in performance wasn't realized till after f16 after lightly testing.
We isolated a simple query that exhibits this behavior; this query reliable runs 4x slower in f17 than f14.
select *
WHERE { ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix .
FILTER (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) = xsd:integer(1002) )
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?CONSUMERID .
}
The modular arithmetic calculation in the filter is used to limit the number of records processed at any one time, and is an essential part of the query.
Here are some sample run stats.
Using f14:
time curl -k --data-urlencode query@canary.rq<ma...@canary.rq> http://localhost:3030/kg/sparql<https://urldefense.com/v3/__http:/localhost:3030/kg/sparql__;!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF-cMtJ6c$> > /dev/null
real 0m7.159s
user 0m0.008s
sys 0m0.002s
Using f17:
time curl -k --data-urlencode query@canary.rq<ma...@canary.rq> http://localhost:3030/kg/sparql<https://urldefense.com/v3/__http:/localhost:3030/kg/sparql__;!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF-cMtJ6c$> > /dev/null
real 0m23.192s
user 0m0.004s
sys 0m0.009s
We ran this test several times, and got essentially the same result (within about 5% on each end).
We also ran this with JENA_HOME and JENAROOT set to a 3.15 Jena installation and a 3.17 Jena installation when we started fuseki; this made no difference in the timing.
We asked tdbquery to explain the query; the result was not very illuminating:
16:54:06 INFO exec :: ALGEBRA
(filter (= (<http://www.w3.org/2001/XMLSchema#integer><https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> (- (<http://www.w3.org/2001/XMLSchema#integer><https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer><https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer><https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> 1002\
))
(quadpattern
(quad <urn:x-arq:DefaultGraphNode%3E ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix)
(quad <urn:x-arq:DefaultGraphNode%3E ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?CONSUMERID)
))
16:54:06 INFO exec :: TDB
(filter (= (<http://www.w3.org/2001/XMLSchema#integer><https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> (- (<http://www.w3.org/2001/XMLSchema#integer><https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer><https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer><https://urldefense.com/v3/__http:/www.w3.org/2001/XMLSchema*integer__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvF2e1vfJA$> 1002\
))
(quadpattern
(quad <urn:x-arq:DefaultGraphNode%3E ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?pix)
(quad <urn:x-arq:DefaultGraphNode%3E ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID><https://urldefense.com/v3/__https:/data.morelyacmewidgets.com/mappings/WIDGET*CONSUMERID__;Iw!!F9svGWnIaVPGSwU!7S3HzuAWctDmhv6KWMcNsYoSva_cSekBT2FUSSKtPvYu6YKX95pawAjKajvFGIZWxbk$> ?CONSUMERID)
))
Any suggestions on how we could get the same level of performance as we were with f14(f16) in f17?
Kind regards,
Omar
Re: possible SPARQL performance regression Fuseki 3.14/3.16 -> 3.17
Posted by Andy Seaborne <an...@apache.org>.
Hi Omar,
Thank for the detailed report.
It might be the casting -JENA-1984 <https://issues.apache.org/jira/browse/JENA-1984> - which was a change
3.16.0->3.17.0
Could you time these queries please on a fast and on a slow system?
It is checking it is the filter.
select (count(*) AS ?C)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
FILTER (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) = xsd:integer(1002) )
}
and (less casting):
select (count(*) AS ?C)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
FILTER (xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200 = 1002 )
}
It would be useful to know some count stats about the data:
select (count(*) AS ?C)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
}
select (count(distinct ?record) AS ?R)
WHERE {
?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
}
and what is the datatype of ?pix normally?
Andy
On 04/06/2021 04:09, omar.khan@wellsfargo.com.INVALID wrote:
> We have observed some surprising performance behavior with different versions of fuseki.
> The versions used in this example are 3.14.0 (referred to as "f14" henceforth), 3.16.0 ("f16" henceforth), and 3.17.0 ("f17" henceforth) .
>
> We have a large database in TDB1 (built using Jena TDB version 3.14.0). There are roughly 140 million triples in the dataset.
>
> We discovered that many of our queries take much longer using f17 than using f14 or f16; that's right, the newer fuseki is much slower than the older one.
>
> We tested more with f14, but noticed that perhaps the change in performance wasn't realized till after f16 after lightly testing.
>
> We isolated a simple query that exhibits this behavior; this query reliable runs 4x slower in f17 than f14.
>
> select *
> WHERE { ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix .
> FILTER (xsd:integer(xsd:integer(?pix)-FLOOR(xsd:integer(?pix)/7200)*7200) = xsd:integer(1002) )
> ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?CONSUMERID .
> }
>
> The modular arithmetic calculation in the filter is used to limit the number of records processed at any one time, and is an essential part of the query.
>
> Here are some sample run stats.
>
> Using f14:
>
> time curl -k --data-urlencode query@canary.rq http://localhost:3030/kg/sparql > /dev/null
> real 0m7.159s
> user 0m0.008s
> sys 0m0.002s
>
>
> Using f17:
>
> time curl -k --data-urlencode query@canary.rq http://localhost:3030/kg/sparql > /dev/null
> real 0m23.192s
> user 0m0.004s
> sys 0m0.009s
>
>
> We ran this test several times, and got essentially the same result (within about 5% on each end).
>
> We also ran this with JENA_HOME and JENAROOT set to a 3.15 Jena installation and a 3.17 Jena installation when we started fuseki; this made no difference in the timing.
>
> We asked tdbquery to explain the query; the result was not very illuminating:
>
>
> 16:54:06 INFO exec :: ALGEBRA
> (filter (= (<http://www.w3.org/2001/XMLSchema#integer> (- (<http://www.w3.org/2001/XMLSchema#integer> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer> 1002\
> ))
> (quadpattern
> (quad <urn:x-arq:DefaultGraphNode> ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix)
> (quad <urn:x-arq:DefaultGraphNode> ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?CONSUMERID)
> ))
> 16:54:06 INFO exec :: TDB
> (filter (= (<http://www.w3.org/2001/XMLSchema#integer> (- (<http://www.w3.org/2001/XMLSchema#integer> ?pix) (* (floor (/ (<http://www.w3.org/2001/XMLSchema#integer> ?pix) 7200)) 7200))) (<http://www.w3.org/2001/XMLSchema#integer> 1002\
> ))
> (quadpattern
> (quad <urn:x-arq:DefaultGraphNode> ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?pix)
> (quad <urn:x-arq:DefaultGraphNode> ?record <https://data.morelyacmewidgets.com/mappings/WIDGET#CONSUMERID> ?CONSUMERID)
> ))
>
> Any suggestions on how we could get the same level of performance as we were with f14(f16) in f17?
>
> Kind regards,
> Omar
>