Re: [Qemu-devel] What's the intended use of log.h logging? (was: [PATCH 2/3] log: report hmp/qmp command and qmp event)

[Alex Bennée]

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.

>
> 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 ;-)

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

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

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.

>    
>    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"?

-- 
Alex Bennée