Re: [Qemu-devel] What's the intended use of log.h logging?

[Markus Armbruster]

Alex Bennée <address@hidden> writes:

> Markus Armbruster <address@hidden> writes:
>
>> We have a couple of related features, and I'd like to get some clarity
>> on how exactly they should be used.
>
> FWIW this is how I view them.
>
>>
>> 1. Tracing
>>
>>    Documented in docs/tracing.txt.
>>
>>    Each trace event can be individually controlled with -trace and with
>>    monitor command trace-event.  Wildcards work.  Monitor command "info
>>    trace-event" shows their status.
>>
>>    Supports a wealth of tracing backends: nop (compiles out tracing
>>    completely), stderr (prints trace to stderr), "simple", "ftrace",
>>    "dtrace", ...  Range from "trivially easy" to "complex power tool".
>
> While not enabled by default this is the sort of thing that can be
> enabled by distros to enable non-invasive tracing of complex behaviour
> and performance bottle-necks. Ignoring nop/stderr backends the others
> can be used when your looking as system-wide behaviour and interactions
> between QEMU, KVM and the kernel.
>
>>
>> 2. Ad hoc printing
>>
>>    We have 108 files with some #define DPRINTF(), and probably some more
>>    sailing under different flags.  The ones that aren't useless should
>>    probably be tracepoints.
>
> These are basically debug crutches for individual files that are
> currently in development or particularly tricky bits of code that
> the relevant developer would enable when debugging.

Modern code should probably use tracing for this purpose except where
its (small!) overhead can't be tolerated.

>> 3. "qemu/log.h" logging
>>
>>    Sports a "mask", where each bit enables a certain set of log
>>    messages.  Control the mask with "-d item,..."  Try "-d help" to see
>>    acceptable items.
>>
>>    Logs to stderr by default, can be redirected with "-D <logfile>".
>>
>>    Odd for a log file: no timestamp, but proposed "[PATCH 3/3] log: adds
>>    a timestamp to each log entry" adds one.
>>
>>    Log message format is unclear.
>>
>>    There are no locks beyond the one provided by stdio, and log entries
>>    appear to be build with multiple calls in places.  I suspect logging
>>    from more than one thread can mess up the log.
>
> As you note bellow most of these are TCG related and currently unlikely
> to race with each other due to TCG being single threaded (for now ;-)

Argument against proliferation to subsystems that can run in other
threads.

>>    Currently defined items are:
>>
>>     const QEMULogItem qemu_log_items[] = {
>>         { CPU_LOG_TB_OUT_ASM, "out_asm",
>>           "show generated host assembly code for each compiled TB" },
>>         { CPU_LOG_TB_IN_ASM, "in_asm",
>>           "show target assembly code for each compiled TB" },
>>         { CPU_LOG_TB_OP, "op",
>>           "show micro ops for each compiled TB" },
>>         { CPU_LOG_TB_OP_OPT, "op_opt",
>>           "show micro ops (x86 only: before eflags optimization) and\n"
>>           "after liveness analysis" },
>>         { CPU_LOG_INT, "int",
>>           "show interrupts/exceptions in short format" },
>>         { CPU_LOG_EXEC, "exec",
>>           "show trace before each executed TB (lots of logs)" },
>>         { CPU_LOG_TB_CPU, "cpu",
>>           "show CPU state before block translation" },
>>         { CPU_LOG_MMU, "mmu",
>>           "log MMU-related activities" },
>>         { CPU_LOG_PCALL, "pcall",
>>           "x86 only: show protected mode far calls/returns/exceptions" },
>>         { CPU_LOG_RESET, "cpu_reset",
>>           "show CPU state before CPU resets" },
>>         { CPU_LOG_IOPORT, "ioport",
>>           "show all i/o ports accesses" },
>>         { LOG_UNIMP, "unimp",
>>           "log unimplemented functionality" },
>>         { LOG_GUEST_ERROR, "guest_errors",
>>           "log when the guest OS does something invalid (eg accessing a\n"
>>           "non-existent register)" },
>>         { 0, NULL, NULL },
>>     };
>>
>>    Looks like this is basically TCG with a couple of random LOG_UNIMP
>>    and LOG_GUEST_ERROR thrown in.  It's definitely not a general purpose
>>    QEMU log in its current state.
>
> However it is useful when users find broken TCG stuff and you want a log
> of what happened. Having said that I'm not sure how often that happens
> because any non-trivial stuff generates huge logs.
>
> It is the logging I use the most though.
>
>>    Should some of these items be tracepoints instead?
>
> IMHO no because stitching together tracepoints with the log file would
> be a pain.

Should *all* of them use tracepoints?

If not, sufficiently fine-grained timestamps could reduce the pain.

Alternatively, we could have a "trace to text file" backend that uses
the same file as log.h.

>>    Do we want a general purpose QEMU log?
>
> It depends. If you are talking about a standardised log style thing then
> maybe but all the current TCG reporting is very specialised and often
> over multiple lines.

My current understanding of the TCG reporting is that it's a debugging
aid, not a log for users.

> To my mind a general purpose log should be fairly quiet and just log
> extraordinary events (maybe via syslog). The sort of stuff that would be
> useful for a user to report when tailing a log before something went
> wrong.

Yes.

>>    
>>    If yes, should this TCG-ish log become the general purpose QEMU log?
>>
>>    I'm asking because "[PATCH 2/3] log: report hmp/qmp command and qmp
>>    event" proposes to log QMP traffic here.  I understand the need for
>>    logging QMP traffic, but I'm not sure it fits here.
>
> Yeah I'm unsure about this as well. To my mind as the QMP is a whole
> separate API I'd be tempted to log it separately. 
>
>> 4. Error messages with timestamps
>>
>>    "-msg timestamp" adds timestamps to the error messages that use the
>>    proper error reporting interfaces.
>>
>>    I suspect this is basically a poor work-around for not having a log
>>    file.
>
> Aren't these meant to be user visible errors? "I died because of X"?

If we had a general purpose log, then errors would also go there, and
get timestamped there like everything else.  No real need to optionally
timestamp them on stderr then.