Thanks, I will have to try the Java profiling, it could already help.

I would think it would be easier to wrap the function bodies before the static rewrite, but in any case it will always interfere with the optimizations so it's quite hard to know what to do...

For the streaming, let's say you've added your prof:time around function bodies, right now it would output to stderr with a format like "Tag: 0.12 ms".
If you could instead somehow process the result of prof:time like a normal xquery function, then you could output it to any place you want (stderr, file, database) and in the format you want.
Then you could have another program to read that output and transform it.

An example with a made up option for prof:time:

declare function local:process-prof-time($result, $time, $tag) {
  file:write('/tmp/profile.txt',
    <profile>
      <timestamp>{prof:current-ns()}</timestamp>
      <tag>{$tag}</tag>
      <time>{$time}</time>
    </profile>
  )
};

for $i in 1 to 10000
return prof:time($i * $i, false(), "Tag",
  (: A callback to process the result of prof:time :)
  local:process-prof-time
  )

Which would make it easy to transform the profiling by reading /tmp/profile.txt, and you could also stream it to avoid creating huge output.

In this example I use a callback directly in the code but you could imagine other ways to implement it. Maybe some special debug module which can implement the callbacks.

Cheers,
Iwan

Le vendredi 19 mai 2017 à 23:15 +0200, Christian Grün a écrit :
Dear Iwan,

I see you have already found the Profiling Module. Currently, it’s the
only way in fact to profile your code within XQuery. Another
alternative is to do some Java profiling (e.g. via -Xrunhprof), but
this will only allow in general which XQuery expressions are
expensive.

Thanks for your suggestions on how to improve the processing of
debugging information. We could indeed think about adding a profiling
flag, which will summarize the evaluation time of each function by
wrapping the bodies with something like prof:time. My immediate though
(among others) would be how to profile functions that will be
rewritten and inlined. An example:

  declare function local:inc($n) { 1 + $n };
  for $i in (1, 2)
  let $j := local:inc($i)
  return $j

…will be statically rewritten to…

  for $i in (1, 2)
  return (1 + $i)

We could probably either suppress function inlining if code is
profiled, or discard profiling of inlined functions. Both approaches
have their advantages and drawbacks.

I didn’t the concept of streaming the results; could you give us a
little example on how this could look like, or describe this in more
detail?

Thanks & cheers,
Christian


I was wondering if there are ways to access how much time is spent in
parts of a query/program, to find out inefficient functions or
expressions?
Something like the total time spent in functions would be quite useful.

I saw the Profiling module, but it requires you to change the code and
it also won't aggregate results when you run it in a loop.
It's still doable if you add labels and then do some parsing on stderr
to aggregate the results yourself, but it's quite cumbersome.

Some thoughts as a side note:
A nice way to avoid having to change the code to do profiling (or other
debugging like breakpoints) would be to change or add hooks into the
AST of the query. That way you could for example add a prof:time()
around all the function bodies, with the function name as label.

And to help interpret the results of debugging functions like prof:time
or trace, it would be nice to have a way to format them and output them
as a stream of items (or even multiple streams). Then you could create
XQuery scripts that consume the streams to aggregate the information in
a human readable way.

Best regards,
Iwan