tracetool: Include thread id information in log backend

[Qemu-devel] [PATCH] tracetool: Include thread id information in log backend

Posted by Fabiano Rosas 5 years, 6 months ago

Currently the log backend prints the process id of QEMU at the start
of each output line, but since threads share the same PID there is no
clear distinction between their outputs.

Having the thread id present in the log makes it easier to see when
output comes from different threads. E.g.:

12423@1538597569.672527:qemu_mutex_lock waiting on mutex 0x1103ee60 (/root/qemu/util/main-loop.c:236)
...
12430@1538597569.503928:qemu_mutex_unlock released mutex 0x1103ee60 (/root/qemu/cpus.c:1238)
12431@1538597569.503937:qemu_mutex_locked taken mutex 0x1103ee60 (/root/qemu/cpus.c:1257)
^here

In the above, 12423 is the main process id and 12430 & 12431 are the
two vcpu threads.

 (qemu) info cpus
 * CPU #0: thread_id=12430
   CPU #1: thread_id=12431

Suggested-by: Murilo Opsfelder Araujo <muriloo@linux.ibm.com>
Signed-off-by: Fabiano Rosas <farosas@linux.ibm.com>
---
 scripts/tracetool/backend/log.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
index 6751f41bc5..33c95af8e9 100644
--- a/scripts/tracetool/backend/log.py
+++ b/scripts/tracetool/backend/log.py
@@ -39,7 +39,7 @@ def generate_h(event, group):
         '        struct timeval _now;',
         '        gettimeofday(&_now, NULL);',
         '        qemu_log("%%d@%%zu.%%06zu:%(name)s " %(fmt)s "\\n",',
-        '                 getpid(),',
+        '                 qemu_get_thread_id(),',
         '                 (size_t)_now.tv_sec, (size_t)_now.tv_usec',
         '                 %(argnames)s);',
         '    }',
-- 
2.17.1

Re: [Qemu-devel] [PATCH] tracetool: Include thread id information in log backend

Posted by Stefan Hajnoczi 5 years, 5 months ago

On Thu, Oct 04, 2018 at 11:30:09AM -0300, Fabiano Rosas wrote:
> Currently the log backend prints the process id of QEMU at the start
> of each output line, but since threads share the same PID there is no
> clear distinction between their outputs.
> 
> Having the thread id present in the log makes it easier to see when
> output comes from different threads. E.g.:
> 
> 12423@1538597569.672527:qemu_mutex_lock waiting on mutex 0x1103ee60 (/root/qemu/util/main-loop.c:236)
> ...
> 12430@1538597569.503928:qemu_mutex_unlock released mutex 0x1103ee60 (/root/qemu/cpus.c:1238)
> 12431@1538597569.503937:qemu_mutex_locked taken mutex 0x1103ee60 (/root/qemu/cpus.c:1257)
> ^here
> 
> In the above, 12423 is the main process id and 12430 & 12431 are the
> two vcpu threads.
> 
>  (qemu) info cpus
>  * CPU #0: thread_id=12430
>    CPU #1: thread_id=12431
> 
> Suggested-by: Murilo Opsfelder Araujo <muriloo@linux.ibm.com>
> Signed-off-by: Fabiano Rosas <farosas@linux.ibm.com>
> ---
>  scripts/tracetool/backend/log.py | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)

Thanks, applied to my tracing-next tree:
https://github.com/stefanha/qemu/commits/tracing-next

Stefan