Re: [PATCH v4 00/23] util: sync error_report & qemu_log output more closely

["Daniel P. Berrangé" <berrange@redhat.com>]

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