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