[PATCH 0/2] trace: make the 'log' backend timestamp configurable

[PATCH 0/2] trace: make the 'log' backend timestamp configurable

[Stefan Hajnoczi]

Zoltan reminded me that the 'log' backend prints tids/timestamps and this can
be unwanted in some cases. It's easier to look at trace output without them and
in some cases parsing is also more convenient with them.

Extend -msg timestamp=on|off to control the 'log' backend's tid/timestamp output.

Stefan Hajnoczi (2):
  error: rename error_with_timestamp to message_with_timestamp
  trace: make the 'log' backend timestamp configurable

 docs/devel/tracing.txt           |  3 +++
 include/qemu/error-report.h      |  2 +-
 softmmu/vl.c                     |  2 +-
 util/qemu-error.c                |  4 ++--
 scripts/tracetool/backend/log.py | 19 +++++++++++++------
 5 files changed, 20 insertions(+), 10 deletions(-)

-- 
2.29.2

[PATCH 1/2] error: rename error_with_timestamp to message_with_timestamp

[Stefan Hajnoczi]

The -msg timestamp=on|off option controls whether a timestamp is printed
with error_report() messages. The "-msg" name suggests that this option
has a wider effect than just error_report(). The next patch extends it
to the 'log' trace backend, so rename the variable from
error_with_timestamp to message_with_timestamp.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 include/qemu/error-report.h | 2 +-
 softmmu/vl.c                | 2 +-
 util/qemu-error.c           | 4 ++--
 3 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index a5ad95ff1b..9d197daca3 100644
--- a/include/qemu/error-report.h
+++ b/include/qemu/error-report.h
@@ -74,7 +74,7 @@ void error_init(const char *argv0);
 
 const char *error_get_progname(void);
 
-extern bool error_with_timestamp;
+extern bool message_with_timestamp;
 extern bool error_with_guestname;
 extern const char *error_guest_name;
 
diff --git a/softmmu/vl.c b/softmmu/vl.c
index a8876b8965..bd55468669 100644
--- a/softmmu/vl.c
+++ b/softmmu/vl.c
@@ -737,7 +737,7 @@ static void realtime_init(void)
 
 static void configure_msg(QemuOpts *opts)
 {
-    error_with_timestamp = qemu_opt_get_bool(opts, "timestamp", false);
+    message_with_timestamp = qemu_opt_get_bool(opts, "timestamp", false);
     error_with_guestname = qemu_opt_get_bool(opts, "guest-name", false);
 }
 
diff --git a/util/qemu-error.c b/util/qemu-error.c
index aa30f03564..52a9e013c4 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -25,7 +25,7 @@ typedef enum {
 } report_type;
 
 /* Prepend timestamp to messages */
-bool error_with_timestamp;
+bool message_with_timestamp;
 bool error_with_guestname;
 const char *error_guest_name;
 
@@ -208,7 +208,7 @@ static void vreport(report_type type, const char *fmt, va_list ap)
     GTimeVal tv;
     gchar *timestr;
 
-    if (error_with_timestamp && !monitor_cur()) {
+    if (message_with_timestamp && !monitor_cur()) {
         g_get_current_time(&tv);
         timestr = g_time_val_to_iso8601(&tv);
         error_printf("%s ", timestr);
-- 
2.29.2

[PATCH 2/2] trace: make the 'log' backend timestamp configurable

[Stefan Hajnoczi]

Timestamps in tracing output can be distracting. Make it possible to
control tid/timestamp printing with -msg timestamp=on|off. The default
is no tid/timestamps. Previously they were always printed.

Suggested-by: BALATON Zoltan <balaton@eik.bme.hu>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 docs/devel/tracing.txt           |  3 +++
 scripts/tracetool/backend/log.py | 19 +++++++++++++------
 2 files changed, 16 insertions(+), 6 deletions(-)

diff --git a/docs/devel/tracing.txt b/docs/devel/tracing.txt
index dba43fc7a4..cd744c0429 100644
--- a/docs/devel/tracing.txt
+++ b/docs/devel/tracing.txt
@@ -211,6 +211,9 @@ effectively turns trace events into debug printfs.
 This is the simplest backend and can be used together with existing code that
 uses DPRINTF().
 
+The -msg timestamp=on|off command-line option controls whether or not to print
+the tid/timestamp prefix for each trace event.
+
 === Simpletrace ===
 
 The "simple" backend supports common use cases and comes as part of the QEMU
diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
index bc43dbb4f4..17ba1cd90e 100644
--- a/scripts/tracetool/backend/log.py
+++ b/scripts/tracetool/backend/log.py
@@ -20,6 +20,7 @@ PUBLIC = True
 
 def generate_h_begin(events, group):
     out('#include "qemu/log-for-trace.h"',
+        '#include "qemu/error-report.h"',
         '')
 
 
@@ -35,14 +36,20 @@ def generate_h(event, group):
         cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
 
     out('    if (%(cond)s && qemu_loglevel_mask(LOG_TRACE)) {',
-        '        struct timeval _now;',
-        '        gettimeofday(&_now, NULL);',
+        '        if (message_with_timestamp) {',
+        '            struct timeval _now;',
+        '            gettimeofday(&_now, NULL);',
         '#line %(event_lineno)d "%(event_filename)s"',
-        '        qemu_log("%%d@%%zu.%%06zu:%(name)s " %(fmt)s "\\n",',
-        '                 qemu_get_thread_id(),',
-        '                 (size_t)_now.tv_sec, (size_t)_now.tv_usec',
-        '                 %(argnames)s);',
+        '            qemu_log("%%d@%%zu.%%06zu:%(name)s " %(fmt)s "\\n",',
+        '                     qemu_get_thread_id(),',
+        '                     (size_t)_now.tv_sec, (size_t)_now.tv_usec',
+        '                     %(argnames)s);',
         '#line %(out_next_lineno)d "%(out_filename)s"',
+        '        } else {',
+        '#line %(event_lineno)d "%(event_filename)s"',
+        '            qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
+        '#line %(out_next_lineno)d "%(out_filename)s"',
+        '        }',
         '    }',
         cond=cond,
         event_lineno=event.lineno,
-- 
2.29.2

Re: [PATCH 0/2] trace: make the 'log' backend timestamp configurable

[Philippe Mathieu-Daudé]

Hi Stefan,

On 1/25/21 12:35 PM, Stefan Hajnoczi wrote:
> Zoltan reminded me that the 'log' backend prints tids/timestamps and this can
> be unwanted in some cases. It's easier to look at trace output without them and
> in some cases parsing is also more convenient with them.
> 
> Extend -msg timestamp=on|off to control the 'log' backend's tid/timestamp output.
> 
> Stefan Hajnoczi (2):
>   error: rename error_with_timestamp to message_with_timestamp
>   trace: make the 'log' backend timestamp configurable
> 
>  docs/devel/tracing.txt           |  3 +++
>  include/qemu/error-report.h      |  2 +-
>  softmmu/vl.c                     |  2 +-
>  util/qemu-error.c                |  4 ++--
>  scripts/tracetool/backend/log.py | 19 +++++++++++++------
>  5 files changed, 20 insertions(+), 10 deletions(-)

I applied your series, rebuilt, but nothing changed.

Apparently there is some buildsys rule missing, the
trace files weren't regenerated.

After full tree 'make clean' I could successfully test:
Tested-by: Philippe Mathieu-Daudé <philmd@redhat.com>

Ignoring the buildsys issue:
Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>

Regards,

Phil.

Re: [PATCH 0/2] trace: make the 'log' backend timestamp configurable

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1279 bytes --]

On Mon, Jan 25, 2021 at 03:06:30PM +0100, Philippe Mathieu-Daudé wrote:
> Hi Stefan,
> 
> On 1/25/21 12:35 PM, Stefan Hajnoczi wrote:
> > Zoltan reminded me that the 'log' backend prints tids/timestamps and this can
> > be unwanted in some cases. It's easier to look at trace output without them and
> > in some cases parsing is also more convenient with them.
> > 
> > Extend -msg timestamp=on|off to control the 'log' backend's tid/timestamp output.
> > 
> > Stefan Hajnoczi (2):
> >   error: rename error_with_timestamp to message_with_timestamp
> >   trace: make the 'log' backend timestamp configurable
> > 
> >  docs/devel/tracing.txt           |  3 +++
> >  include/qemu/error-report.h      |  2 +-
> >  softmmu/vl.c                     |  2 +-
> >  util/qemu-error.c                |  4 ++--
> >  scripts/tracetool/backend/log.py | 19 +++++++++++++------
> >  5 files changed, 20 insertions(+), 10 deletions(-)
> 
> I applied your series, rebuilt, but nothing changed.
> 
> Apparently there is some buildsys rule missing, the
> trace files weren't regenerated.

I sent a separate patch that adds tracetool dependencies to meson.build:
"[PATCH] trace: add meson custom_target() depend_files for tracetool"

That will fix the issue.

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH 0/2] trace: make the 'log' backend timestamp configurable

[BALATON Zoltan]

On Mon, 25 Jan 2021, Stefan Hajnoczi wrote:
> Zoltan reminded me that the 'log' backend prints tids/timestamps and this can
> be unwanted in some cases. It's easier to look at trace output without them and
> in some cases parsing is also more convenient with them.
>
> Extend -msg timestamp=on|off to control the 'log' backend's tid/timestamp output.

Thank you, this works for me

Tested-by: BALATON Zoltan <balaton@eik.bme.hu>

but I had to remove build dir and rerun configure to get it omit 
timestamps. Just running make (which reruns configure) or make distclean 
and running configure does not seem to be enough to pick up some changes 
since the meson conversion. (I had similar problem with gtk being detected 
and used despite having --disable-gtk on configure before the gtk test was 
moved to meson; so I think there's some problem detecting changes in 
configure options somewhere. That was also fixed by rerunning configure 
after starting from clean build dir but did not work when keeping old 
build dir or make distclean. This is probably not a problem for someone 
downloading the sources and compiling it once, only annoying for 
developers who build it all the time.)

Regards,
BALATON Zoltan

> Stefan Hajnoczi (2):
>  error: rename error_with_timestamp to message_with_timestamp
>  trace: make the 'log' backend timestamp configurable
>
> docs/devel/tracing.txt           |  3 +++
> include/qemu/error-report.h      |  2 +-
> softmmu/vl.c                     |  2 +-
> util/qemu-error.c                |  4 ++--
> scripts/tracetool/backend/log.py | 19 +++++++++++++------
> 5 files changed, 20 insertions(+), 10 deletions(-)

Re: [PATCH 0/2] trace: make the 'log' backend timestamp configurable

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1481 bytes --]

On Mon, Jan 25, 2021 at 08:50:23PM +0100, BALATON Zoltan wrote:
> On Mon, 25 Jan 2021, Stefan Hajnoczi wrote:
> > Zoltan reminded me that the 'log' backend prints tids/timestamps and this can
> > be unwanted in some cases. It's easier to look at trace output without them and
> > in some cases parsing is also more convenient with them.
> > 
> > Extend -msg timestamp=on|off to control the 'log' backend's tid/timestamp output.
> 
> Thank you, this works for me
> 
> Tested-by: BALATON Zoltan <balaton@eik.bme.hu>
> 
> but I had to remove build dir and rerun configure to get it omit timestamps.
> Just running make (which reruns configure) or make distclean and running
> configure does not seem to be enough to pick up some changes since the meson
> conversion. (I had similar problem with gtk being detected and used despite
> having --disable-gtk on configure before the gtk test was moved to meson; so
> I think there's some problem detecting changes in configure options
> somewhere. That was also fixed by rerunning configure after starting from
> clean build dir but did not work when keeping old build dir or make
> distclean. This is probably not a problem for someone downloading the
> sources and compiling it once, only annoying for developers who build it all
> the time.)

Thanks! The following meson.build fix in the tracing queue:

  [PATCH] trace: add meson custom_target() depend_files for tracetool

It solves this issue.

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH 0/2] trace: make the 'log' backend timestamp configurable

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 957 bytes --]

On Mon, Jan 25, 2021 at 11:35:05AM +0000, Stefan Hajnoczi wrote:
> Zoltan reminded me that the 'log' backend prints tids/timestamps and this can
> be unwanted in some cases. It's easier to look at trace output without them and
> in some cases parsing is also more convenient with them.
> 
> Extend -msg timestamp=on|off to control the 'log' backend's tid/timestamp output.
> 
> Stefan Hajnoczi (2):
>   error: rename error_with_timestamp to message_with_timestamp
>   trace: make the 'log' backend timestamp configurable
> 
>  docs/devel/tracing.txt           |  3 +++
>  include/qemu/error-report.h      |  2 +-
>  softmmu/vl.c                     |  2 +-
>  util/qemu-error.c                |  4 ++--
>  scripts/tracetool/backend/log.py | 19 +++++++++++++------
>  5 files changed, 20 insertions(+), 10 deletions(-)
> 
> -- 
> 2.29.2
> 

Thanks, applied to my master tree:
https://gitlab.com/stefanha/qemu/commits/master

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]