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

[Paolo Bonzini <pbonzini@redhat.com>]

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      999997000              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