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

["Philippe Mathieu-Daudé" <philmd@linaro.org>]

On 25/9/25 12:31, Daniel P. Berrangé wrote:
> 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.


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

This is planned.

> Assuming you've not given any -msg option to QEMU though, the finger

Indeed.

> probably points towards the thread name code, as the bit that is
> new and enabled by default.

I thought about that then noticed the thread name is const (preformatted
once in each qemu_thread_get_name() implementation).

> 
> With regards,
> Daniel