Difference between revisions of "Profiling Module"

From BaseX Documentation
Jump to navigation Jump to search
(19 intermediate revisions by the same user not shown)
Line 3: Line 3:
 
=Conventions=
 
=Conventions=
  
All functions in this module are assigned to the <code><nowiki>http://basex.org/modules/prof</nowiki></code> namespace, which is statically bound to the {{Code|prof}} prefix.<br/>
+
All functions and errors in this module are assigned to the <code><nowiki>http://basex.org/modules/prof</nowiki></code> namespace, which is statically bound to the {{Code|prof}} prefix.<br/>
All errors are assigned to the <code><nowiki>http://basex.org/errors</nowiki></code> namespace, which is statically bound to the {{Code|bxerr}} prefix.
 
  
=Functions=
+
=Performance Functions=
  
==prof:time==
+
==prof:track==
 +
 
 +
{{Mark|Introduced with Version 9.0:}}
  
 
{| width='100%'
 
{| width='100%'
 
|-
 
|-
 
| width='120' | '''Signatures'''
 
| width='120' | '''Signatures'''
|{{Func|prof:time|$expr as item()|item()*}}<br />{{Func|prof:time|$expr as item(), $cache as xs:boolean|item()*}}<br />{{Func|prof:time|$expr as item(), $cache as xs:boolean, $label as xs:string|item()*}}
+
|{{Func|prof:track|$expression as item()|item()*}}<br/>{{Func|prof:track|$expression as item(), $options as map(*)?|item()*}}
 
|-
 
|-
 
| '''Summary'''
 
| '''Summary'''
|Measures the time needed to evaluate {{Code|$expr}} and sends it to standard error or, if the GUI is used, to the Info View.<br />If {{Code|$cache}} is set to {{Code|true()}}, the result will be temporarily cached. This way, a potential iterative execution of the expression (which often yields different memory usage) is blocked.<br/>A third, optional argument {{Code|$label}} may be specified to tag the profiling result.
+
|Measures the execution time and memory consumption required for evaluating the specified {{Code|$expression}} and returns a map with the results. The following {{Code|$options}} are available:
 +
* {{Code|memory}}: Include memory consumption in result (unit: bytes; default: true).
 +
* {{Code|time}}: Include execution time in result (unit: milliseconds; default: true).
 +
* {{Code|value}}: Include value in result (default: true).
 +
Helpful notes:
 +
* If you are not interested in some of the returned results, you should disable them to save time and memory.
 +
* Profiling might change the execution behavior of your code: An expression that might be executed iteratively will be cached by the profiling function.
 +
* If a value has a compact internal representation, memory consumption will be very low, even if the serialized result may consume much more memory.
 +
* Please note that memory profiling is only approximative, so it can be quite misleading. If the memory option is enabled, main-memory will be garbage-collected before and after evaluation to improve the quality of the measurement.
 
|-
 
|-
 
| '''Properties'''
 
| '''Properties'''
Line 23: Line 32:
 
| '''Examples'''
 
| '''Examples'''
 
|
 
|
* {{Code|prof:time("1 to 100000")}} may output {{Code|25.69 ms}}.
+
* Return a human-readable representation of the memory consumption caused by fetching an XML document (<code>fetch:xml</code> is used, as <code>fn:doc</code> may already be evaluated at compilation time):
* {{Code|prof:time("1 to 100000", true())}} may output {{Code|208.12 ms}}.
+
<pre class="brush:xquery">
 +
prof:track(fetch:xml('factbook.xml'))?memory
 +
=> prof:human()
 +
</pre>
 +
* The function call <code>prof:track((1 to 1000000)[. mod 2 = 0], map { 'time': false() })</code> will return something similar to:
 +
<pre class="brush:xquery">
 +
map {
 +
  "memory": 21548400,
 +
  "value": (2, 4, 6, 8, 10, ...)
 +
}
 +
</pre>
 
|}
 
|}
  
==prof:mem==
+
==prof:time==
 +
 
 +
{{Mark|Updated with Version 9.0:}} {{Code|$cache}} argument removed.
  
 
{| width='100%'
 
{| width='100%'
 
|-
 
|-
 
| width='120' | '''Signatures'''
 
| width='120' | '''Signatures'''
|{{Func|prof:mem|$expr as item()|item()*}}<br />{{Func|prof:mem|$expr as item(), $cache as xs:boolean|item()*}}<br />{{Func|prof:mem|$expr as item(), $cache as xs:boolean, $label as xs:string|item()*}}
+
|{{Func|prof:time|$expr as item()|item()*}}<br />{{Func|prof:time|$expr as item(), $label as xs:string|item()*}}
 
|-
 
|-
 
| '''Summary'''
 
| '''Summary'''
|Measures the memory allocated by evaluating {{Code|$expr}} and sends it to standard error or, if the GUI is used, to the Info View.<br />If {{Code|$cache}} is set to {{Code|true()}}, the result will be temporarily cached. This way, a potential iterative execution of the expression (which often yields different memory usage) is blocked.<br/>A third, optional argument {{Code|$label}} may be specified to tag the profiling result.
+
|Measures the time needed to evaluate {{Code|$expr}} and outputs a string to standard error or, if the GUI is used, to the Info View. An optional {{Code|$label}} may be specified to tag the profiling result. See {{Function|Profiling|prof:track}} for further notes.
 
|-
 
|-
 
| '''Properties'''
 
| '''Properties'''
Line 42: Line 63:
 
| '''Examples'''
 
| '''Examples'''
 
|
 
|
* {{Code|prof:mem("1 to 100000")}} may output {{Code|0 Bytes}}.
+
* {{Code|prof:time(prof:sleep(1000))}} outputs something similar to {{Code|1000.99 ms}}.
* {{Code|prof:mem("1 to 100000", true())}} may output {{Code|26.678 mb}}.
 
 
|}
 
|}
  
==prof:sleep==
+
==prof:memory==
 +
 
 +
{{Mark|Updated with Version 9.0:}} Renamed (old name: <code>prof:mem</code>); {{Code|$cache}} argument removed.
  
 
{| width='100%'
 
{| width='100%'
 
|-
 
|-
 
| width='120' | '''Signatures'''
 
| width='120' | '''Signatures'''
|{{Func|prof:sleep|$ms as xs:integer|empty-sequence()}}<br />
+
|{{Func|prof:memory|$expr as item()|item()*}}<br/>{{Func|prof:memory|$expr as item(), $label as xs:string|item()*}}
 
|-
 
|-
 
| '''Summary'''
 
| '''Summary'''
|Sleeps for the specified number of milliseconds.
+
|Measures the memory allocated by evaluating {{Code|$expr}} and outputs a string to standard error or, if the GUI is used, to the Info View. An optional {{Code|$label}} may be specified to tag the profiling result. See {{Function|Profiling|prof:track}} for further notes.
 
|-
 
|-
 
| '''Properties'''
 
| '''Properties'''
 
|The function is ''non-deterministic'': evaluation order will be preserved by the compiler.
 
|The function is ''non-deterministic'': evaluation order will be preserved by the compiler.
 +
|-
 +
| '''Examples'''
 +
|
 +
* {{Code|prof:memory((1 to 100000) ! <a/>)}} will output something similar to {{Code|5620 kB}}.
 
|}
 
|}
  
==prof:human==
+
==prof:current-ms==
  
 
{| width='100%'
 
{| width='100%'
 
|-
 
|-
 
| width='120' | '''Signatures'''
 
| width='120' | '''Signatures'''
|{{Func|prof:human|$number as xs:integer|xs:string}}
+
|{{Func|prof:current-ms||xs:integer}}<br />
 
|-
 
|-
 
| '''Summary'''
 
| '''Summary'''
|Returns a human-readable representation of the specified {{Code|$number}}.
+
|Returns the number of milliseconds passed since 1970/01/01 UTC. The granularity of the value depends on the underlying operating system and may be larger. For example, many operating systems measure time in units of tens of milliseconds.
 +
|-
 +
| '''Properties'''
 +
|In contrast to {{Code|fn:current-time()}}, the function is ''non-deterministic'' and returns different values every time it is called. Its evaluation order will be preserved by the compiler.
 
|-
 
|-
| '''Example'''
+
| '''Examples'''
 
|
 
|
* {{Code|prof:human(16384)}} returns {{Code|16K}}.
+
* {{Code|convert:integer-to-dateTime(prof:current-ms())}} returns the current miliseconds in the {{Code|xs:dateTime}} format.
 +
|}
 +
 
 +
==prof:current-ns==
 +
 
 +
{| width='100%'
 +
|-
 +
| width='120' | '''Signatures'''
 +
|{{Func|prof:current-ns||xs:integer}}<br />
 +
|-
 +
| '''Summary'''
 +
|Returns the current value of the most precise available system timer in nanoseconds.
 +
|-
 +
| '''Properties'''
 +
|In contrast to {{Code|fn:current-time()}}, the function is ''non-deterministic'' and returns different values every time it is called. Its evaluation order will be preserved by the compiler.
 +
|-
 +
| '''Examples'''
 +
| Measures the time of an expression:
 +
<pre class="brush:xquery">
 +
let $ns1 := prof:current-ns()
 +
return (
 +
  (: process to measure :)
 +
  (1 to 1000000)[. = 0],
 +
  let $ns2 := prof:current-ns()
 +
  let $ms := ((($ns2 - $ns1) idiv 10000) div 100)
 +
  return $ms || ' ms'
 +
)
 +
</pre>
 
|}
 
|}
 +
 +
=Debugging Functions=
  
 
==prof:dump==
 
==prof:dump==
Line 107: Line 165:
 
|}
 
|}
  
==prof:current-ms==
+
==prof:type==
  
 
{| width='100%'
 
{| width='100%'
 
|-
 
|-
 
| width='120' | '''Signatures'''
 
| width='120' | '''Signatures'''
|{{Func|prof:current-ms||xs:integer}}<br />
+
|{{Func|prof:type|$expr as item()*|item()*}}
 
|-
 
|-
 
| '''Summary'''
 
| '''Summary'''
|Returns the number of milliseconds passed since 1970/01/01 UTC. The granularity of the value depends on the underlying operating system and may be larger. For example, many operating systems measure time in units of tens of milliseconds.
+
|Similar to {{Code|fn:trace($expr, $msg)}}, but instead of a user-defined message, it emits the compile-time type and estimated result size of its argument.
|-
 
| '''Properties'''
 
|In contrast to {{Code|fn:current-time()}}, the function is ''non-deterministic'', as it returns different values every time it is called. Its evaluation order will be preserved by the compiler.
 
 
|}
 
|}
  
==prof:current-ns==
+
=Helper Functions=
 +
 
 +
==prof:void==
  
 
{| width='100%'
 
{| width='100%'
 
|-
 
|-
 
| width='120' | '''Signatures'''
 
| width='120' | '''Signatures'''
|{{Func|prof:current-ns||xs:integer}}<br />
+
|{{Func|prof:void|$value as item()*|empty-sequence()}}
 
|-
 
|-
 
| '''Summary'''
 
| '''Summary'''
|Returns the current value of the most precise available system timer in nanoseconds.
+
|Swallows all items of the specified {{Code|$value}} and returns an empty sequence. This function is helpful if some code needs to be evaluated and if the actual result is irrelevant.
 
|-
 
|-
 
| '''Properties'''
 
| '''Properties'''
|In contrast to {{Code|fn:current-time()}}, the function is ''non-deterministic'', as it returns different values every time it is called. Its evaluation order will be preserved by the compiler.
+
|The function is ''non-deterministic'': evaluation order will be preserved by the compiler.
 
|-
 
|-
 
| '''Examples'''
 
| '''Examples'''
| Measures the time of an expression:
+
|
<pre class="brush:xquery">
+
* {{Code|prof:void(fetch:binary('http://my.rest.service'))}} performs an HTTP request and ignores the result.
let $ns1 := prof:current-ns()
 
return (
 
  (: process to measure :)
 
  (1 to 1000000)[. = 0],
 
  let $ns2 := prof:current-ns()
 
  let $ms := ((($ns2 - $ns1) idiv 10000) div 100)
 
  return $ms || ' ms'
 
)
 
</pre>
 
 
|}
 
|}
  
==prof:void==
+
==prof:sleep==
  
 
{| width='100%'
 
{| width='100%'
 
|-
 
|-
 
| width='120' | '''Signatures'''
 
| width='120' | '''Signatures'''
|{{Func|prof:void|$value as item()*|empty-sequence()}}
+
|{{Func|prof:sleep|$ms as xs:integer|empty-sequence()}}<br />
 
|-
 
|-
 
| '''Summary'''
 
| '''Summary'''
|Swallows all items of the specified {{Code|$value}} and returns an empty sequence. This function is helpful if some code needs to be evaluated and if the actual result is irrelevant.
+
|Sleeps for the specified number of milliseconds.
 
|-
 
|-
 
| '''Properties'''
 
| '''Properties'''
 
|The function is ''non-deterministic'': evaluation order will be preserved by the compiler.
 
|The function is ''non-deterministic'': evaluation order will be preserved by the compiler.
|-
 
| '''Examples'''
 
|
 
* {{Code|prof:void(fetch:binary('http://my.rest.service'))}} performs an HTTP request and ignores the result.
 
 
|}
 
|}
  
==prof:type==
+
==prof:human==
  
 
{| width='100%'
 
{| width='100%'
 
|-
 
|-
 
| width='120' | '''Signatures'''
 
| width='120' | '''Signatures'''
|{{Func|prof:type|$expr as item()*|item()*}}
+
|{{Func|prof:human|$number as xs:integer|xs:string}}
 
|-
 
|-
 
| '''Summary'''
 
| '''Summary'''
|Similar to {{Code|fn:trace($expr, $msg)}}, but instead of a user-defined message, it emits the compile-time type and estimated result size of its argument.
+
|Returns a human-readable representation of the specified {{Code|$number}}.
 +
|-
 +
| '''Example'''
 +
|
 +
* {{Code|prof:human(16384)}} returns {{Code|16K}}.
 
|}
 
|}
  
 
=Changelog=
 
=Changelog=
 +
 +
;Version 9.0
 +
 +
* Added: [[#prof:track|prof:track]]
 +
* Updated: renamed prof:mem to [[#prof:memory|prof:memory]]
  
 
;Version 8.5
 
;Version 8.5
  
* Added: <code>[[#prof:type|prof:type]]</code> (moved from [[XQuery Module]])
+
* Added: [[#prof:type|prof:type]] (moved from [[XQuery Module]])
  
 
;Version 8.1
 
;Version 8.1
  
* Added: <code>[[#prof:variables|prof:variables]]</code>
+
* Added: [[#prof:variables|prof:variables]]
  
 
;Version 7.7
 
;Version 7.7
  
* Added: <code>[[#prof:void|prof:void]]</code>
+
* Added: [[#prof:void|prof:void]]
  
 
;Version 7.6
 
;Version 7.6
  
* Added: <code>[[#prof:human|prof:human]]</code>
+
* Added: [[#prof:human|prof:human]]
  
 
;Version 7.5
 
;Version 7.5
  
* Added: <code>[[#prof:dump|prof:dump]]</code>, <code>[[#prof:current-ms|prof:current-ms]]</code>, <code>[[#prof:current-ns|prof:current-ns]]</code>
+
* Added: [[#prof:dump|prof:dump]], [[#prof:current-ms|prof:current-ms]], [[#prof:current-ns|prof:current-ns]]
  
 
This module was introduced with Version 7.3.
 
This module was introduced with Version 7.3.

Revision as of 12:47, 23 March 2018

This XQuery Module contains various functions to test and profile code, and to dump information to standard output.

Conventions

All functions and errors in this module are assigned to the http://basex.org/modules/prof namespace, which is statically bound to the prof prefix.

Performance Functions

prof:track

Template:Mark

Signatures prof:track($expression as item()) as item()*
prof:track($expression as item(), $options as map(*)?) as item()*
Summary Measures the execution time and memory consumption required for evaluating the specified $expression and returns a map with the results. The following $options are available:
  • memory: Include memory consumption in result (unit: bytes; default: true).
  • time: Include execution time in result (unit: milliseconds; default: true).
  • value: Include value in result (default: true).

Helpful notes:

  • If you are not interested in some of the returned results, you should disable them to save time and memory.
  • Profiling might change the execution behavior of your code: An expression that might be executed iteratively will be cached by the profiling function.
  • If a value has a compact internal representation, memory consumption will be very low, even if the serialized result may consume much more memory.
  • Please note that memory profiling is only approximative, so it can be quite misleading. If the memory option is enabled, main-memory will be garbage-collected before and after evaluation to improve the quality of the measurement.
Properties The function is non-deterministic: evaluation order will be preserved by the compiler.
Examples
  • Return a human-readable representation of the memory consumption caused by fetching an XML document (fetch:xml is used, as fn:doc may already be evaluated at compilation time):
prof:track(fetch:xml('factbook.xml'))?memory
=> prof:human()
  • The function call prof:track((1 to 1000000)[. mod 2 = 0], map { 'time': false() }) will return something similar to:
map {
  "memory": 21548400,
  "value": (2, 4, 6, 8, 10, ...)
}

prof:time

Template:Mark $cache argument removed.

Signatures prof:time($expr as item()) as item()*
prof:time($expr as item(), $label as xs:string) as item()*
Summary Measures the time needed to evaluate $expr and outputs a string to standard error or, if the GUI is used, to the Info View. An optional $label may be specified to tag the profiling result. See prof:track for further notes.
Properties The function is non-deterministic: evaluation order will be preserved by the compiler.
Examples
  • prof:time(prof:sleep(1000)) outputs something similar to 1000.99 ms.

prof:memory

Template:Mark Renamed (old name: prof:mem); $cache argument removed.

Signatures prof:memory($expr as item()) as item()*
prof:memory($expr as item(), $label as xs:string) as item()*
Summary Measures the memory allocated by evaluating $expr and outputs a string to standard error or, if the GUI is used, to the Info View. An optional $label may be specified to tag the profiling result. See prof:track for further notes.
Properties The function is non-deterministic: evaluation order will be preserved by the compiler.
Examples
  • prof:memory((1 to 100000) ! <a/>) will output something similar to 5620 kB.

prof:current-ms

Signatures prof:current-ms() as xs:integer
Summary Returns the number of milliseconds passed since 1970/01/01 UTC. The granularity of the value depends on the underlying operating system and may be larger. For example, many operating systems measure time in units of tens of milliseconds.
Properties In contrast to fn:current-time(), the function is non-deterministic and returns different values every time it is called. Its evaluation order will be preserved by the compiler.
Examples
  • convert:integer-to-dateTime(prof:current-ms()) returns the current miliseconds in the xs:dateTime format.

prof:current-ns

Signatures prof:current-ns() as xs:integer
Summary Returns the current value of the most precise available system timer in nanoseconds.
Properties In contrast to fn:current-time(), the function is non-deterministic and returns different values every time it is called. Its evaluation order will be preserved by the compiler.
Examples Measures the time of an expression:
let $ns1 := prof:current-ns()
return (
  (: process to measure :)
  (1 to 1000000)[. = 0],
  let $ns2 := prof:current-ns()
  let $ms := ((($ns2 - $ns1) idiv 10000) div 100)
  return $ms || ' ms'
)

Debugging Functions

prof:dump

Signatures prof:dump($expr as item()) as empty-sequence()
prof:dump($expr as item(), $label as xs:string) as empty-sequence()
Summary Dumps a serialized representation of $expr to STDERR, optionally prefixed with $label, and returns an empty sequence. If the GUI is used, the dumped result is shown in the Info View.
Properties In contrast to fn:trace(), the consumed expression will not be passed on.

prof:variables

Signatures prof:variables() as empty-sequence()
Summary Prints a list of all current local and global variable assignments to standard error or, if the GUI is used, to the Info View.
As every query is optimized before being evaluated, not all of the original variables may be visible in the output. Moreover, many variables of function calls will disappear because functions are inlined. Function inlining can be turned off by setting the INLINELIMIT option to 0.
Properties The function is non-deterministic: evaluation order will be preserved by the compiler.
Examples
  • for $x in 1 to 2 return prof:variables() will dump the values of $x to standard error.

prof:type

Signatures prof:type($expr as item()*) as item()*
Summary Similar to fn:trace($expr, $msg), but instead of a user-defined message, it emits the compile-time type and estimated result size of its argument.

Helper Functions

prof:void

Signatures prof:void($value as item()*) as empty-sequence()
Summary Swallows all items of the specified $value and returns an empty sequence. This function is helpful if some code needs to be evaluated and if the actual result is irrelevant.
Properties The function is non-deterministic: evaluation order will be preserved by the compiler.
Examples

prof:sleep

Signatures prof:sleep($ms as xs:integer) as empty-sequence()
Summary Sleeps for the specified number of milliseconds.
Properties The function is non-deterministic: evaluation order will be preserved by the compiler.

prof:human

Signatures prof:human($number as xs:integer) as xs:string
Summary Returns a human-readable representation of the specified $number.
Example
  • prof:human(16384) returns 16K.

Changelog

Version 9.0
Version 8.5
Version 8.1
Version 7.7
Version 7.6
Version 7.5

This module was introduced with Version 7.3.