Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log

[Paolo Bonzini <pbonzini@redhat.com>]

Il 26/10/2013 06:52, Alex Bligh ha scritto:
> 
> On 26 Oct 2013, at 00:00, Paolo Bonzini wrote:
> 
>> his is a bug in the distro, if it is Linux.  There is no reason not to
>> enable the stap trace format when running on Linux (Fedora does for
>> other packages than QEMU, too---most notably glib and glibc).
>>
>> If it is useful, adding debugging information to timer_new_ns (please
>> make file and line two separate arguments, though) can definitely be
>> done unconditionally and added to the traces.  I think adding a
>> tracepoint in timerlist_run_timers would provide very similar
>> information to that in your file.
> 
> I read the tracepoint information. Doesn't that require the end
> user to have far more skills (and far more stuff installed) to
> get things like "average expiry delta"? Especially as that's
> not something we'd normally calculate as we don't get the clock
> value when setting a timer normally.

The simple trace backend includes a nanosecond value that is the same as
rt_clock, so you can correlate the last timer_mod with the next
iteration in timerlist_run_timers (I would put the tracepoint inside the
loop, just before the callback is done).  Similarly, in systemtap you
can just use the builtin gettimeofday_ns() function

All clocks are basically in nanoseconds (the only difference between
vm_clock and rt_clock is that the former stops when the VM is stopped),
so you can get the average expiry delta from there.

Of course it requires some postprocessing or a systemtap script, but we
can put that into scripts/ or give it to the user.  See
https://sourceware.org/ml/systemtap/2011-q3/txt00003.txt for an example,
I suppose the "expiry time" computation would look like this:

global modtime, expirytot, firedcnt

probe qemu.system.x86_64.timer_mod {
   loc = sprintf("%s:%d", timer_file, timer_line)
   modtime[pid(), loc] = gettimeofday_ns()
}
probe qemu.system.x86_64.timer_run {
   loc = sprintf("%s:%d", timer_file, timer_line)
   expirytot[pid(), loc] += gettimeofday_ns() - modtime[pid(), loc]
   firedcnt[pid(), loc]++
}

probe end
{
  printf("\n%8s %28s %8s %8s\n", "pid", "loc", "avg expiry", "cnt")
  foreach([p+, loc] in firedcnt) {
    printf("%8d %28s %8d %8d\n", p, loc,
        expirytot[p, loc] / firedcnt[p, loc],
        firedcnt[p, loc])
  }
}

which I wrote based on the example at
http://cygwin.com/ml/systemtap/2011-q3/msg00316.html

I understand your usecase, but it's not really feasible to add a logging
option for each tracing need; it's much better to add new tracepoints
and distribute sample systemtap scripts.  And please "lobby" your distro
for enabling systemtap support and distributing the .stp file!

Paolo