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

[Markus Armbruster]

We have a couple of related features, and I'd like to get some clarity
on how exactly they should be used.

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

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.

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.

   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.

   Should some of these items be tracepoints instead?

   Do we want a general purpose QEMU log?
   
   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.

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.