Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log
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/txt3.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
Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log
Paolo,
On 26 Oct 2013, at 08:18, Paolo Bonzini wrote:
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/txt3.txt for an example,
I suppose the expiry time computation would look like this:
OK I need to look at the tracepoint stuff a bit more it seems :-)
If we can do this without a patch (save to put some tracepoints in),
that's obviously better than doing it with a patch. I don't like
the file particularly either.
global modtime, expirytot, firedcnt
probe qemu.system.x86_64.timer_mod {
loc = sprintf(%s:%d, timer_file, timer_line)
How do timer_file and timer_line get filled in? If those still
need to be put in through code changes, how about taking
patch 1 of the series (that fills in timer-dbg with this
information), save for the unnecessary additions to the structure,
plus whatever is necessary to put the tracepoints in?
Alex
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])
}
}
--
Alex Bligh
Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log
Il 26/10/2013 10:24, Alex Bligh ha scritto: How do timer_file and timer_line get filled in? If those still need to be put in through code changes, how about taking patch 1 of the series (that fills in timer-dbg with this information), save for the unnecessary additions to the structure, plus whatever is necessary to put the tracepoints in? Sure! Paolo
Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log
Il 25/10/2013 23:30, Alex Bligh ha scritto: This patch set adds facilities for debugging timers using the additional command line option -timer-debug-log=FILE. If this option is selected, a debugging file will be written showing information about the current state of timers in the system, which the author feels will be useful for debugging in the field. Note that the option is a command line option rather than a configure time option. This is because users in the field having issues are unlikely to have a compile time option enabled. It would be useful to get this feature in prior to 1.7 as it has little impact other than making a major change to a subsystem more debuggable. This patch has been lightly test. Impact of changes whether or not -timer-debug-log is specified: 1. QEMUTimer is expanded to hold additional debugging information. Some of this is unused when the command line option is unspecified. 2. The file and line number of the caller that allocated the timer are recorded. This is useful for debugging in gdb. It is felt these are minimal in nature. Additional impact of changes only when -timer-debug-log is specified: 1. On every timer modification, the current clock time for that timer is read, and the additional debug information filled in. 2. Every second (roughly) a file is written (atomically) containing the timer debug information. The debug information includes information on the number of timer expiries since the timer was created, the average expiry time (in nanoseconds), and the number of short expiries, being the number of times the timer was asked to expire in less than one microsecond (these usually but not always indicate a bug). The file format is designed to be useful both to a mailing list and to a user armed with gdb. An example of the output follows: Timer list at 0x7f4d6cf0d6e0 clock 0: Address Expiries AvgLength NumShort Source Timer list at 0x7f4d6cf0cbc0 clock 0: Address Expiries AvgLength NumShort Source Timer list at 0x7f4d6cf0d750 clock 1: Address Expiries AvgLength NumShort Source Timer list at 0x7f4d6cf0cc30 clock 1: Address Expiries AvgLength NumShort Source 0x7f4d6cf51550 1 27462700 0 i8254.c:333 Timer list at 0x7f4d6cf0d7c0 clock 2: Address Expiries AvgLength NumShort Source Timer list at 0x7f4d6cf0cca0 clock 2: Address Expiries AvgLength NumShort Source 0x7f4d6cf6eed0 1 97000 0 mc146818rtc.c:858 Note that the somewhat strange choice to output to a file has been taken because the tracing infrastructure is unlikely to be enabled in a distro environment. This 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. Paolo
Re: [Qemu-devel] [PATCHv1 0/4] Timers: add timer debugging through -timer-debug-log
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. -- Alex Bligh
