Alex Bennée <alex.ben...@linaro.org> writes:
> Markus Armbruster <arm...@redhat.com> 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.
