The different ways QEMU logs stuff

The different ways QEMU logs stuff

[Markus Armbruster]

I fell into another rabbit hole: logging.  Here's my trip report.

We have:

* util/error-report.c

  - To stderr (or current monitor, but that's not relevant here)

  - Format:
        [TIME ][GUEST-NAME ]PROGNAME:LOCATION: (|warning: |info: )MESSAGE
    where the optional parts are controlled by -msg

  - Maintained: see MAINTAINERS "Error reporting"

* util/log.c

  - Control:

    · Some logging is always on

    · Some logging is off by default, enabled per "log item" with -d

    · Some can additionally be limited to address ranges with -dfilter

  - To the file given by -D (default stderr), or with -d tid to files
    with names derived from the pattern given by -D (%d is replaced by
    the thread ID)

  - Format:
        [TIME ]MESSAGE
    where the optional part is controlled by -msg timestamp (-msg
    guest-name has no effect here)

  - Not covered by MAINTAINERS

* Tracing

  - Control: off by default, enabled with -trace per trace point (and
    also -d trace: --- I find that duplication bizarre)

  - Run time control with HMP commands trace-event, trace-file, QMP
    commands trace-event-get-state, trace-event-set-state

  - To whatever backends are compiled in:

    · "log" wraps around util/log.c's always-on logging

    · "simple" logs to a binary file given by -trace file=

    · "syslog" logs to POSIX syslog

    · "ftrace", "dtrace", "ust" integrate with Linux ftrace, DTrace /
      SystemTap, and LTTng userspace tracing, respectively

  - Maintained: see MAINTAINERS "Traicing"

* Unstructured ad hoc printing to stdout or stderr

I think that's it.

Observations:

* Mixing logs with different formats in one destination makes them
  needlessly hard to read and parse.

  Daniel's "util: sync error_report & qemu_log output more closely"
  series makes util/error-report.c and util/log.c use a common message
  prefix

      [TIME ][GUEST-NAME ]PROGNAME\(THREAD-NAME\):...

  where the optional parts are controlled by -msg.  Continues prior work
  in that direction: commit 012842c0755 (log: make '-msg timestamp=on'
  apply to all qemu_log usage).

* Spreading logs over multiple destinations can make the order hard to
  determine.

  -D splits util/log.c from util/error-report.c.

  -d tid further splits per thread.

  Splitting per thread feels fairly redundant once the prefix includes
  the thread name.  Thread names is easier to make sense of than numeric
  thread IDs in the split filenames.

  To keep the complete log in one place, avoid -D, and enable trace
  backend "log".

* In my view, util/log.c consists of three layers.  Form bottom to top:

  * Logging messages: qemu_log()

  * Control of what to log ("log items"): qemu_log_mask()

  * Address filtering: qemu_log_in_addr_range()

  The bottom layer is also used by trace backend "log".

* Tracing vs. "log items"

  Tracing and "log items" both provide opt-in logging.

  Why do we have two?  Feels like an accident to me.

  When to use which?  I guess people pick whatever they're familiar
  with.

  Would we be better off with just one?  I wish...

  Which one?  Clearly tracing, because tracing backends provide plenty
  of useful functionality "log items" lack.

  "Log items" support per-thread log files.  With tracing, you could
  instead split by thread names once Daniel's series is in.

  Address range filtering is only used with "log items".  It could just
  as easily be used with tracing.

Thoughts?

Re: The different ways QEMU logs stuff

[Daniel P. Berrangé]

On Thu, Sep 11, 2025 at 02:10:15PM +0200, Markus Armbruster wrote:
> I fell into another rabbit hole: logging.  Here's my trip report.
> 
> We have:
> 
> * util/error-report.c
> 
>   - To stderr (or current monitor, but that's not relevant here)
> 
>   - Format:
>         [TIME ][GUEST-NAME ]PROGNAME:LOCATION: (|warning: |info: )MESSAGE
>     where the optional parts are controlled by -msg
> 
>   - Maintained: see MAINTAINERS "Error reporting"
> 
> * util/log.c
> 
>   - Control:
> 
>     · Some logging is always on
> 
>     · Some logging is off by default, enabled per "log item" with -d
> 
>     · Some can additionally be limited to address ranges with -dfilter
> 
>   - To the file given by -D (default stderr), or with -d tid to files
>     with names derived from the pattern given by -D (%d is replaced by
>     the thread ID)
> 
>   - Format:
>         [TIME ]MESSAGE
>     where the optional part is controlled by -msg timestamp (-msg
>     guest-name has no effect here)
> 
>   - Not covered by MAINTAINERS
> 
> * Tracing
> 
>   - Control: off by default, enabled with -trace per trace point (and
>     also -d trace: --- I find that duplication bizarre)
> 
>   - Run time control with HMP commands trace-event, trace-file, QMP
>     commands trace-event-get-state, trace-event-set-state
> 
>   - To whatever backends are compiled in:
> 
>     · "log" wraps around util/log.c's always-on logging
> 
>     · "simple" logs to a binary file given by -trace file=
> 
>     · "syslog" logs to POSIX syslog
> 
>     · "ftrace", "dtrace", "ust" integrate with Linux ftrace, DTrace /
>       SystemTap, and LTTng userspace tracing, respectively
> 
>   - Maintained: see MAINTAINERS "Traicing"
> 
> * Unstructured ad hoc printing to stdout or stderr
> 
> I think that's it.
> 
> Observations:
> 
> * Mixing logs with different formats in one destination makes them
>   needlessly hard to read and parse.
> 
>   Daniel's "util: sync error_report & qemu_log output more closely"
>   series makes util/error-report.c and util/log.c use a common message
>   prefix
> 
>       [TIME ][GUEST-NAME ]PROGNAME\(THREAD-NAME\):...
> 
>   where the optional parts are controlled by -msg.  Continues prior work
>   in that direction: commit 012842c0755 (log: make '-msg timestamp=on'
>   apply to all qemu_log usage).
> 
> * Spreading logs over multiple destinations can make the order hard to
>   determine.
> 
>   -D splits util/log.c from util/error-report.c.
> 
>   -d tid further splits per thread.
> 
>   Splitting per thread feels fairly redundant once the prefix includes
>   the thread name.  Thread names is easier to make sense of than numeric
>   thread IDs in the split filenames.

Also gives you a chronological record of the log across all threads
if we have it in one file avoiding cross-correlation needs.

> 
>   To keep the complete log in one place, avoid -D, and enable trace
>   backend "log".
> 
> * In my view, util/log.c consists of three layers.  Form bottom to top:
> 
>   * Logging messages: qemu_log()
> 
>   * Control of what to log ("log items"): qemu_log_mask()
> 
>   * Address filtering: qemu_log_in_addr_range()
> 
>   The bottom layer is also used by trace backend "log".
> 
> * Tracing vs. "log items"
> 
>   Tracing and "log items" both provide opt-in logging.
> 
>   Why do we have two?  Feels like an accident to me.
> 
>   When to use which?  I guess people pick whatever they're familiar
>   with.
> 
>   Would we be better off with just one?  I wish...
> 
>   Which one?  Clearly tracing, because tracing backends provide plenty
>   of useful functionality "log items" lack.
> 
>   "Log items" support per-thread log files.  With tracing, you could
>   instead split by thread names once Daniel's series is in.
> 
>   Address range filtering is only used with "log items".  It could just
>   as easily be used with tracing.

There is another trap door (or perhaps better described as back door).

qemu_log_trylock() returns the raw FILE * handle, which the callers
will directly write to. This is used instead of qemu_log() in a number
of places, and often has large data dumps written to it. This bypasses
any prefixes like timestamps, thread id, etc.  This direct FILE usage
would not map well over to tracing.

Also tracing wouldn't  allow qemu-user to provide its '-strace' CLI
arg, because we can't guarantee that QEMU is built with a trace
backend that will print to the console.

This makes it challenging (impossible) to entirely replace qemu_log
with tracing.


The other thing I find slightly wierd is 'info_report'. error vs
warning is clear - one is fatal, one is not, but the warning vs
info distinction is far from clearcut.

So warn_report vs info_report, also involves a choice of qemu_log(),
error_[v]printf(), fprintf(stderr, ...), g_printerr,  g_message,
g_critical, g_warning, g_info, and g_debug

... all of them are used somewhere in QEMU :-)

I feel like qemu_log ought to be obsoleted by glib's logging APIs,
but again we have the problem with the the raw FILE* usage for
large data dumps. Some glib APIs we use will already be using
glib's logging APIs, and we wire upa  custom backend for glib
to call into  info_report/warn_report/error_report, with glib's
DEBUG level squashed into info_report

With regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

Re: The different ways QEMU logs stuff

[Peter Maydell]

On Thu, 11 Sept 2025 at 13:10, Markus Armbruster <armbru@redhat.com> wrote:
>
> - Control: off by default, enabled with -trace per trace point (and
>    also -d trace: --- I find that duplication bizarre)

If you're a primarily-logging user it makes perfect sense:
I want to be able to control everything I log in one
place ("-d in_asm,exec,trace:gicv3*").

> * In my view, util/log.c consists of three layers.  Form bottom to top:
>
>   * Logging messages: qemu_log()
>
>   * Control of what to log ("log items"): qemu_log_mask()
>
>   * Address filtering: qemu_log_in_addr_range()
>
>   The bottom layer is also used by trace backend "log".
>
> * Tracing vs. "log items"
>
>   Tracing and "log items" both provide opt-in logging.
>
>   Why do we have two?  Feels like an accident to me.

Partly this is because tracing is newer but it doesn't do the things
the 'log' facility does. In particular, with logging you enable
the category of things you want to see (e.g. "tell me about
anything where the guest does something we didn't implement")
whereas trace events have no such categorization.

Log messages don't have the weird restrictions that trace
events have that some of the backends impose (e.g. "no
floating point values").

Logging is easier to read and write because the format string is
right there in the source file, rather than having to be
separated out into the trace-events file.

-d also always works and does the same thing regardless
of what tracing backend QEMU was configured with.

>   When to use which?  I guess people pick whatever they're familiar
>   with.

I use logging for "I want to get logs of what TCG is doing",
and for the "show me everything in this category" logging.
I use trace events for "I want to see what this device emulation
is doing".

>   Would we be better off with just one?  I wish...
>
>   Which one?  Clearly tracing, because tracing backends provide plenty
>   of useful functionality "log items" lack.

But the reverse is also true, which is why we still have both.

-- PMM

Re: The different ways QEMU logs stuff

[Paolo Bonzini]

On 9/11/25 14:10, Markus Armbruster wrote:
> * Tracing
> 
>    - Control: off by default, enabled with -trace per trace point (and
>      also -d trace: --- I find that duplication bizarre)

The series adding both "-trace enable=..." and "-d trace:" justifies it 
like this 
(https://lists.nongnu.org/archive/html/qemu-devel/2015-10/msg05808.html):

---
add a "-d trace:foo" option that is a synonym for "-trace foo";
this makes the new functionality more discoverable to people used
to "-d", makes it available for user-mode emulation (which does
not have -trace), and is somewhat nice if you want to enable both
tracepoints and some other "-d" flag (patch 9).  When globbing
it is also less susceptible to unwanted shell expansion.

For example, you can trace block device I/O and save the result
to a file just by adding "-trace bdrv_aio_*,file=trace.txt", or
correlate it to guest PCs with "-d exec,nochain,trace:bdrv_aio_*".
---

These days, user-mode emulation does have -trace (commit 6533dd6e111, 
"trace: [linux-user] Commandline arguments to control tracing").

Also, "-trace file=..." is a synonym of -D if the log backend is 
enabled, so it made sense to have a synonym also for "trace enable=" 
within "-d".

>      · "log" wraps around util/log.c's always-on logging

(FWIW this used to be "stderr" and it was not enabled by default; this 
ensured that tracing was used a lot less even by developers :)).

> * Spreading logs over multiple destinations can make the order hard to
>    determine.
> 
>    -D splits util/log.c from util/error-report.c.
> 
>    -d tid further splits per thread.
> 
>    Splitting per thread feels fairly redundant once the prefix includes
>    the thread name.  Thread names is easier to make sense of than numeric
>    thread IDs in the split filenames.

https://lore.kernel.org/all/20220417183019.755276-1-richard.henderson@linaro.org/ 
says "this can be extremely helpful in debugging user-only threads".

> * In my view, util/log.c consists of three layers.  Form bottom to top:
> 
>    * Logging messages: qemu_log()
> 
>    * Control of what to log ("log items"): qemu_log_mask()
> 
>    * Address filtering: qemu_log_in_addr_range()
> 
>    The bottom layer is also used by trace backend "log".

Makes sense.

> * Tracing vs. "log items"
> 
>    Tracing and "log items" both provide opt-in logging.
> 
>    Why do we have two?  Feels like an accident to me.

One is structured and the other is not.  Structure is both a curse and a 
blessing: a blessing because it allows plugging in external tools, a 
curse because it limits what you can write.

>    Address range filtering is only used with "log items".  It could just
>    as easily be used with tracing.

Agreed that address range filtering could be added to tracetool and 
supported by tracepoints (though probably it does not make sense for all 
of them, and maybe only makes sense for very few due to TCG's preference 
for log items).

Paolo

Re: The different ways QEMU logs stuff

[Richard Henderson]

On 9/11/25 14:49, Paolo Bonzini wrote:
>>    -d tid further splits per thread.
>>
>>    Splitting per thread feels fairly redundant once the prefix includes
>>    the thread name.  Thread names is easier to make sense of than numeric
>>    thread IDs in the split filenames.
> 
> https://lore.kernel.org/all/20220417183019.755276-1-richard.henderson@linaro.org/ says 
> "this can be extremely helpful in debugging user-only threads".

Compare strace -ff.


r~

Re: The different ways QEMU logs stuff

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1322 bytes --]

On Thu, Sep 11, 2025 at 02:10:15PM +0200, Markus Armbruster wrote:
> * Tracing vs. "log items"
> 
>   Tracing and "log items" both provide opt-in logging.
> 
>   Why do we have two?  Feels like an accident to me.
> 
>   When to use which?  I guess people pick whatever they're familiar
>   with.
> 
>   Would we be better off with just one?  I wish...
> 
>   Which one?  Clearly tracing, because tracing backends provide plenty
>   of useful functionality "log items" lack.
> 
>   "Log items" support per-thread log files.  With tracing, you could
>   instead split by thread names once Daniel's series is in.
> 
>   Address range filtering is only used with "log items".  It could just
>   as easily be used with tracing.

Paolo mentioned that tracing is structured (each event has typed
parameters) whereas logging consists of an arbitrary string. The reason
for this is that tracers are usually designed for low overhead and for
processing trace events. Tracing is used to instrument QEMU for detailed
analysis of control flow or performance investigation. It's a different
use case from logging although there is some overlap.

People like to use tools like perf(1), SystemTap, etc and tracing allows
QEMU to support them. It's not a use case where regular log files are
used.

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]