Hello Christian,
I have some small questions over the profile module.
1) The following code declare function local:sequence($nb){for $i in 1 to xs:integer($nb) return $i}; prof:time(fn:count(local:sequence(1000000000000000000))) return 4.94 ms.
It means that you lazy evaluate the query "{for $i in 1 to xs:integer($nb) return $i" ? (I recall that you already mentioned this point that but I would like a confirmation, since it might be a profiler issue)
2) It seems that you somehow call the fn:trace function in the profile module. Is there a way to catch the returned values of these functions ? The motivation is for profiling purposes. To be more specific, I would like to treat the output results as
<output @function = "my_function">{prof:time( "xquery" ) }</output>
to be able to aggregate results at a higher level of call, i.e. something like
for $output in $prof//output let $fun := data($output/@function) group by $fun return element-name{$fun}{sum(data($output) ) }
Thanks
Jean-Marc
Hi Jean-Marc,
- The following code
declare function local:sequence($nb){for $i in 1 to xs:integer($nb) return $i}; prof:time(fn:count(local:sequence(1000000000000000000))) return 4.94 ms.
the InfoView will give you some hints what’s going on. The reason is that your code is compiled and simplified to the following query..
prof:time(fn:count((1 to 1000000000000000000)))
...which can then be evaluated in constant time.
- It seems that you somehow call the fn:trace function in the profile
module. Is there a way to catch the returned values of these functions?
Currently no. You can use the prof:current-ns() function instead:
let $start := prof:current-ns() let $void := prof:void((1 to 10000000)[. = 1]) let $end := prof:current-ns() let $ms := ($end - $start) div 1000000 return $ms || ' ms'
Hope this helps, Christian
Christian,
thx for your answers.
the InfoView will give you some hints what’s going on
oh...I should have thought about it. I still don't have this reflex. thanx
Currently no. You can use the prof:current-ns()
I thought about this one, but isn't this method less accurate than prof:time ?
2013/12/4 Christian Grün christian.gruen@gmail.com
Hi Jean-Marc,
- The following code
declare function local:sequence($nb){for $i in 1 to xs:integer($nb)
return
$i}; prof:time(fn:count(local:sequence(1000000000000000000))) return 4.94 ms.
the InfoView will give you some hints what’s going on. The reason is that your code is compiled and simplified to the following query..
prof:time(fn:count((1 to 1000000000000000000)))
...which can then be evaluated in constant time.
- It seems that you somehow call the fn:trace function in the profile
module. Is there a way to catch the returned values of these functions?
Currently no. You can use the prof:current-ns() function instead:
let $start := prof:current-ns() let $void := prof:void((1 to 10000000)[. = 1]) let $end := prof:current-ns() let $ms := ($end - $start) div 1000000 return $ms || ' ms'
Hope this helps, Christian
Hi Jean-Marc,
Currently no. You can use the prof:current-ns()
I thought about this one, but isn't this method less accurate than prof:time
If your measurements don’t fall below milliseconds, it should make no difference.
Benchmarking is a complex field on its own, however:
• In BaseX, it’s advisable to do all measurements with a running server instance. Otherwise, your measurement will also include the starup time for initializing the JVM and doing just-in-time compilations.
• If you use the GUI, those effects will also be amortized after a while, but the visual processing of the query results may take some additional time.
• You can measure the number of multiple runs via the RUNS option [1]. The following call on command line runs the query "1" for 10,000 times:
basex -o result.txt -r 10000 -V 1
... Parsing: 0.06 ms (avg) Compiling: 0.0 ms (avg) Evaluating: 0.0 ms (avg) Printing: 0.03 ms (avg) Total Time: 0.1 ms (avg) ... Query executed in 0.1 ms (avg).
Please note that only the results of the first run will be output, so this option should only be used when the output is small. As you have probably seen, the output can also be “swallowed” via prof:dump(). Some little experiments will soon give you a feeling on what’s comparable and what’s not.
If you want to compare the timing with other XQuery implementations, it gets even more complicated, because each engine has its own timing output, optimizations to speed up several runs, etc. In this case, a simple call on command line gives you results that may still be best comparable.
Hope this helps, Christian
Hi Jean-Marc,
another note (I just spotted your mail on talk@xquery.com; thanks for making your code public!): it is advisable to remove all trace() calls from the code before doing performance comparisons.
Looking forward to your experiences, Christian ___________________________
On Thu, Dec 5, 2013 at 11:39 AM, Christian Grün christian.gruen@gmail.com wrote:
Hi Jean-Marc,
Currently no. You can use the prof:current-ns()
I thought about this one, but isn't this method less accurate than prof:time
If your measurements don’t fall below milliseconds, it should make no difference.
Benchmarking is a complex field on its own, however:
• In BaseX, it’s advisable to do all measurements with a running server instance. Otherwise, your measurement will also include the starup time for initializing the JVM and doing just-in-time compilations.
• If you use the GUI, those effects will also be amortized after a while, but the visual processing of the query results may take some additional time.
• You can measure the number of multiple runs via the RUNS option [1]. The following call on command line runs the query "1" for 10,000 times:
basex -o result.txt -r 10000 -V 1
... Parsing: 0.06 ms (avg) Compiling: 0.0 ms (avg) Evaluating: 0.0 ms (avg) Printing: 0.03 ms (avg) Total Time: 0.1 ms (avg) ... Query executed in 0.1 ms (avg).
Please note that only the results of the first run will be output, so this option should only be used when the output is small. As you have probably seen, the output can also be “swallowed” via prof:dump(). Some little experiments will soon give you a feeling on what’s comparable and what’s not.
If you want to compare the timing with other XQuery implementations, it gets even more complicated, because each engine has its own timing output, optimizations to speed up several runs, etc. In this case, a simple call on command line gives you results that may still be best comparable.
Hope this helps, Christian
Hi Christian,
Thx for your answer.
it is advisable to remove all trace() calls from the code before doing
performance comparisons.
You're right. From another side, the trace functions are called very few times (68 calls), compared to the time execution (about two minutes to run the entire test). This should be of small impact over the results.
A remark over this test : I noticed that the test is running slower when I disabled the options INLINELIMIT = 0 and TAILCALL = -1.
2013/12/5 Christian Grün christian.gruen@gmail.com
Hi Jean-Marc,
another note (I just spotted your mail on talk@xquery.com; thanks for making your code public!): it is advisable to remove all trace() calls from the code before doing performance comparisons.
Looking forward to your experiences, Christian ___________________________
On Thu, Dec 5, 2013 at 11:39 AM, Christian Grün christian.gruen@gmail.com wrote:
Hi Jean-Marc,
Currently no. You can use the prof:current-ns()
I thought about this one, but isn't this method less accurate than
prof:time
If your measurements don’t fall below milliseconds, it should make no difference.
Benchmarking is a complex field on its own, however:
• In BaseX, it’s advisable to do all measurements with a running server instance. Otherwise, your measurement will also include the starup time for initializing the JVM and doing just-in-time compilations.
• If you use the GUI, those effects will also be amortized after a while, but the visual processing of the query results may take some additional time.
• You can measure the number of multiple runs via the RUNS option [1]. The following call on command line runs the query "1" for 10,000 times:
basex -o result.txt -r 10000 -V 1
... Parsing: 0.06 ms (avg) Compiling: 0.0 ms (avg) Evaluating: 0.0 ms (avg) Printing: 0.03 ms (avg) Total Time: 0.1 ms (avg) ... Query executed in 0.1 ms (avg).
Please note that only the results of the first run will be output, so this option should only be used when the output is small. As you have probably seen, the output can also be “swallowed” via prof:dump(). Some little experiments will soon give you a feeling on what’s comparable and what’s not.
If you want to compare the timing with other XQuery implementations, it gets even more complicated, because each engine has its own timing output, optimizations to speed up several runs, etc. In this case, a simple call on command line gives you results that may still be best comparable.
Hope this helps, Christian
Christian,
Hello.
I was trying to profile code through a client / server as you advised. Thus I installed the module into the basex repository, and launched it through a client.
However I can't find the log left by fn:trace, or prof:time. Do you know where these traces append in this configuration ?
Thx
Jean-Marc
2013/12/5 jean-marc Mercier jeanmarc.mercier@gmail.com
Hi Christian,
Thx for your answer.
it is advisable to remove all trace() calls from the code before doing
performance comparisons.
You're right. From another side, the trace functions are called very few times (68 calls), compared to the time execution (about two minutes to run the entire test). This should be of small impact over the results.
A remark over this test : I noticed that the test is running slower when I disabled the options INLINELIMIT = 0 and TAILCALL = -1.
2013/12/5 Christian Grün christian.gruen@gmail.com
Hi Jean-Marc,
another note (I just spotted your mail on talk@xquery.com; thanks for making your code public!): it is advisable to remove all trace() calls from the code before doing performance comparisons.
Looking forward to your experiences, Christian ___________________________
On Thu, Dec 5, 2013 at 11:39 AM, Christian Grün christian.gruen@gmail.com wrote:
Hi Jean-Marc,
Currently no. You can use the prof:current-ns()
I thought about this one, but isn't this method less accurate than
prof:time
If your measurements don’t fall below milliseconds, it should make no difference.
Benchmarking is a complex field on its own, however:
• In BaseX, it’s advisable to do all measurements with a running server instance. Otherwise, your measurement will also include the starup time for initializing the JVM and doing just-in-time compilations.
• If you use the GUI, those effects will also be amortized after a while, but the visual processing of the query results may take some additional time.
• You can measure the number of multiple runs via the RUNS option [1]. The following call on command line runs the query "1" for 10,000 times:
basex -o result.txt -r 10000 -V 1
... Parsing: 0.06 ms (avg) Compiling: 0.0 ms (avg) Evaluating: 0.0 ms (avg) Printing: 0.03 ms (avg) Total Time: 0.1 ms (avg) ... Query executed in 0.1 ms (avg).
Please note that only the results of the first run will be output, so this option should only be used when the output is small. As you have probably seen, the output can also be “swallowed” via prof:dump(). Some little experiments will soon give you a feeling on what’s comparable and what’s not.
If you want to compare the timing with other XQuery implementations, it gets even more complicated, because each engine has its own timing output, optimizations to speed up several runs, etc. In this case, a simple call on command line gives you results that may still be best comparable.
Hope this helps, Christian
Hi Jean-Marc,
However I can't find the log left by fn:trace, or prof:time. Do you know where these traces append in this configuration ?
The dump/trace output can be viewed when turning on the query info (-V). As the output is generated by the server, it will first be collected and then sent to the clien.t
basex-talk@mailman.uni-konstanz.de
-
Christian Grün -
jean-marc Mercier