On Thu, Sep 25, 2025 at 12:22:39PM +0200, Philippe Mathieu-Daudé wrote:
> Hi Daniel,
>
> On 25/9/25 11:44, Daniel P. Berrangé wrote:
> > This series is a tangent that came out of discussion in
> >
> > https://lists.nongnu.org/archive/html/qemu-devel/2025-08/msg00903.html
> >
> > In thinking about adding thread info to error_report, I
> > came to realize we should likely make qemu_log behave
> > consistently with error_report & friends. We already
> > honour '-msg timestamp=on', but don't honour 'guest-name=on'
> > and also don't include the binary name.
> >
> > As an example of the current state, consider mixing error and
> > log output today:
> >
> > - Default context:
> >
> > # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \
> > -d 'trace:qcrypto*'
> > qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55ac6d97f700 dir=fish
> > qcrypto_tls_creds_get_path TLS creds path creds=0x55ac6d97f700 filename=ca-cert.pem path=<none>
> > qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory
> >
> > - Full context:
> >
> > # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \
> > -d 'trace:qcrypto*' \
> > -msg guest-name=on,timestamp=on \
> > -name "fish food"
> > 2025-08-19T20:14:16.791413Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55e9a3458d10 dir=fish
> > 2025-08-19T20:14:16.791429Z qcrypto_tls_creds_get_path TLS creds path creds=0x55e9a3458d10 filename=ca-cert.pem path=<none>
> > 2025-08-19T20:14:16.791433Z fish food qemu-system-x86_64: Unable to access credentials fish/ca-cert.pem: No such file or directory
> >
> > And after this series is complete:
> >
> > - Default context:
> >
> > # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \
> > -d 'trace:qcrypto*'
> > qemu-system-x86_64(1184284:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55a24ad5cb30 dir=fish
> > qemu-system-x86_64(1184284:main): qcrypto_tls_creds_get_path TLS creds path creds=0x55a24ad5cb30 filename=ca-cert.pem path=<none>
> > qemu-system-x86_64(1184284:main): Unable to access credentials fish/ca-cert.pem: No such file or directory
> >
> > - Full context:
> >
> > # qemu-system-x86_64 -object tls-creds-x509,id=t0,dir=fish \
> > -d 'trace:qcrypto*' \
> > -msg guest-name=on,timestamp=on \
> > -name "fish food"
> > 2025-08-19T20:12:50.211823Z [fish food] qemu-system-x86_64(1168876:main): qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x5582183d8760 dir=fish
> > 2025-08-19T20:12:50.211842Z [fish food] qemu-system-x86_64(1168876:main): qcrypto_tls_creds_get_path TLS creds path creds=0x5582183d8760 filename=ca-cert.pem
> > +path=<none>
> > 2025-08-19T20:12:50.211846Z [fish food] qemu-system-x86_64(1168876:main): Unable to access credentials fish/ca-cert.pem: No such file or directory
> >
> > The main things to note:
> >
> > * error_report/warn_report/qemu_log share the same
> > output format and -msg applies to both
> >
> > * -msg debug-threads=on is now unconditionally enabled
> > and thus the param is deprecated & ignored
> >
> > * Thread ID and name are unconditionally enabled
> >
> > * Guest name is surrounded in [...] brackets
> >
> > * The default output lines are typically 15 chars
> > wider given that we always include the thread
> > ID + name now
> >
> > * This takes the liberty of assigning the new file
> > to the existing error-report.c maintainer (Markus)
> > Since splitting it off into message.c instead of
> > putting it all in error-report.c felt slightly
> > nicer.
> >
> > One thing I didn't tackle is making the location
> > info get reported for qemu_log. This is used to
> > give context for error messages when parsing some
> > CLI args, and could be interesting for log messages
> > associated with those same CLI args.
>
> Testing with this change on top ...:
>
> -- >8 --
> diff --git a/include/qemu/message.h b/include/qemu/message.h
> index 2cc092c993b..97fd2a94fbd 100644
> --- a/include/qemu/message.h
> +++ b/include/qemu/message.h
> @@ -10,2 +10,3 @@ enum QMessageFormatFlags {
> QMESSAGE_FORMAT_THREAD_INFO = (1 << 3),
> + QMESSAGE_FORMAT_VCPU_ID = (1 << 4),
> };
> diff --git a/system/vl.c b/system/vl.c
> index bf9f80491f2..2f43a075be9 100644
> --- a/system/vl.c
> +++ b/system/vl.c
> @@ -149,3 +149,4 @@
> (QMESSAGE_FORMAT_PROGRAM_NAME | \
> - QMESSAGE_FORMAT_THREAD_INFO)
> + QMESSAGE_FORMAT_THREAD_INFO | \
> + QMESSAGE_FORMAT_VCPU_ID)
>
> diff --git a/util/message.c b/util/message.c
> index 7d94b9d970d..19d1331403a 100644
> --- a/util/message.c
> +++ b/util/message.c
> @@ -6,2 +6,3 @@
> #include "monitor/monitor.h"
> +#include "hw/core/cpu.h"
>
> @@ -46,2 +47,8 @@ void qmessage_context_print(FILE *fp)
> }
> +
> + if (message_format & QMESSAGE_FORMAT_VCPU_ID) {
> + if (current_cpu) {
> + fprintf(fp, "(cpuid:%d): ", current_cpu->cpu_index);
> + }
> + }
> }
> ---
>
> ... on a branch where I test heavy vcpu context switching.
>
> When using tracing + stderr AND the stdio console, I sometimes get
> the trace events to disappear at some point. Not sure why (or if related
> to my branch) yet.
>
> When redirecting traces to a file ('-D foo.log'), all traces are
> collected (no hang).
>
> In both cases I notice a high performance slow down (when tracing is
> used).
>
> Suspicions:
> - flocking
The logging code (and thus tracing) already used flockfile in
qemu_log, so that should not be new. Only error_report gained
new flockfile calls in this series.
> - new formatting
Seems the more likely option. If practical, a git bisect across the
series should show which part introduced any slowdown.
Assuming you've not given any -msg option to QEMU though, the finger
probably points towards the thread name code, as the bit that is
new and enabled by default.
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 :|