Sparql query execution time breakdown into essential steps

Virtuoso Universal Server RDF Data Management
1

Hi,
isql shows 1 msec as the execution time for a simple query (output is copied below; it is a fresh copy of virtuoso with no data loaded)

query:
sparql select * where {?s ?p ?o} limit 1;
#########################################################################
./isql 1111 dba dba …/…/q1
OpenLink Virtuoso Interactive SQL (Virtuoso)
Version 07.20.3230 as of Mar 1 2020
Type HELP; for help and EXIT; to exit.
Connected to OpenLink Virtuoso
Driver: 07.20.3230 OpenLink Virtuoso ODBC Driver
s p o
LONG VARCHAR LONG VARCHAR LONG VARCHAR

h tt p://w ww .openlinksw. com / virtr df-data-for ma ts#de fault -iid h tt p:/ /www .w3. org/1999/ 02/22-rdf-syntax-ns#type http:/ /www .openli nksw .com /sch emas/vi rtrdf# QuadMapFo rmat

1 Rows. – 1 msec.

#########################################################################

but when I run the same query and calculate the run-time using the OS tools, the calculated execution time is more (my OS commands and the output is copied)

ts=$(date +%s%N) ; ./isql 1111 dba dba …/…/q1 ; tt=$((($(date +%s%N) - $ts)/1000000)) ; echo “Time taken: $tt milliseconds”
OpenLink Virtuoso Interactive SQL (Virtuoso)
Version 07.20.3230 as of Mar 1 2020
Type HELP; for help and EXIT; to exit.
Connected to OpenLink Virtuoso
Driver: 07.20.3230 OpenLink Virtuoso ODBC Driver
s p o
LONG VARCHAR LONG VARCHAR LONG VARCHAR

http :confused: /www .ope nlinksw. com/virtrdf -data-formats#default-iid h t tp :confused: /www .w3 .org/1999/02/22-rdf-syntax-ns#type htt p :confused: /www. o penlin ksw. com/schemas/virtrdf#Quad MapFormat

1 Rows. – 1 msec.
Time taken: 11 milliseconds

#########################################################################

It would be great if Virtuoso’s experts (eg, @imikhailov) could answer the following questions:

  1. What might be the probable reasons behind these execution time differences? (did I make a mistake?)
  2. Would you please explain (in further details) that how exactly the query execution time is calculated and outputted in virtuoso (i.e., isql’s query execution time breakdown)?

Thanks

(P. S.: I did not use any emojis, but added some extra spaces between above URIs, because the website does not allow me to create a topic with more than two links)

2

The Virtuoso isql command output is showing the query execution time in the Virtuoso engine, whereas you timing from the command line would also include the OS time for processing the query and displaying the result.

You can also use the OS time function to time the queries running time in the terminal session which breaks the time down into real, user & system times:

De-iMac-2692:~ hwilliams$ time isql 1111 dba dba exec="sparql select * where {?s ?p ?o} limit 1;"
Connected to OpenLink Virtuoso
Driver: 07.20.3214 OpenLink Virtuoso ODBC Driver
OpenLink Interactive SQL (Virtuoso), version 0.9849b.
Type HELP; for help and EXIT; to exit.
s                                                                                 p                                                                                 o
LONG VARCHAR                                                                      LONG VARCHAR                                                                      LONG VARCHAR
_______________________________________________________________________________

http://www.w3.org/1999/02/22-rdf-syntax-ns#type                                   http://www.w3.org/1999/02/22-rdf-syntax-ns#type                                   http://www.w3.org/1999/02/22-rdf-syntax-ns#Property

1 Rows. -- 0 msec.

real	0m0.006s
user	0m0.002s
sys	0m0.002s
De-iMac-2692:~ hwilliams$

Note the Virtuoso profile function can provide the query compilation and execution times in the Virtuoso engine as detailed in the How can I get full explain and profile plans for a simple SPARQL query documentation.

1 Like