[Qemu-devel] [PATCH 0/2] trace: fix trace_event_get_state() for SystemTap and LTTng UST

[Qemu-devel] [PATCH 0/2] trace: fix trace_event_get_state() for SystemTap and LTTng UST

[Stefan Hajnoczi]

Trace events that compute their arguments can affect performance.  The
following idom can be used to avoid computing arguments when the trace event is
disabled:

  if (trace_event_get_state(TRACE_MY_EVENT)) {
      char *str = g_strdup_printf("Expensive string ...", ...);
      trace_my_event(str);
      g_free(str);
  }

Unfortunately this breaks the trace event for SystemTap and LTTng UST since
those tracers manage their own enabled/disabled state.

These patches add per-backend dstate to trace_event_get_state() so that the
trace event fires as expected when enabled via SystemTap or LTTng UST.

Stefan Hajnoczi (2):
  trace: add TRACE_<event>_BACKEND_DSTATE()
  trace: check backend dstate in trace_event_get_state()

 trace/control.h                       | 20 ++++++++++++++++++--
 scripts/tracetool/__init__.py         |  1 +
 scripts/tracetool/backend/__init__.py |  3 +++
 scripts/tracetool/backend/dtrace.py   | 12 ++++++++++++
 scripts/tracetool/backend/ftrace.py   |  2 +-
 scripts/tracetool/backend/log.py      |  3 ++-
 scripts/tracetool/backend/simple.py   |  2 +-
 scripts/tracetool/backend/syslog.py   |  3 ++-
 scripts/tracetool/backend/ust.py      |  5 +++++
 scripts/tracetool/format/h.py         | 10 ++++++++++
 10 files changed, 55 insertions(+), 6 deletions(-)

-- 
2.13.3

[Qemu-devel] [PATCH 1/2] trace: add TRACE_<event>_BACKEND_DSTATE()

[Stefan Hajnoczi]

QEMU keeps track of trace event enabled/disabled state and provides
monitor commands to inspect and modify the "dstate".  SystemTap and
LTTng UST maintain independent enabled/disabled states for each trace
event.

Introduce a new per-event macro that combines backend-specific dstate
like this:

  #define TRACE_MY_EVENT_BACKEND_DSTATE() ( \
      QEMU_MY_EVENT_ENABLED() || /* SystemTap */ \
      tracepoint_enabled(qemu, my_event) /* LTTng UST */ || \
      false)

This will be used to extend trace_event_get_state() in the next patch.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/tracetool/__init__.py         |  1 +
 scripts/tracetool/backend/__init__.py |  3 +++
 scripts/tracetool/backend/dtrace.py   | 12 ++++++++++++
 scripts/tracetool/backend/ust.py      |  5 +++++
 scripts/tracetool/format/h.py         | 10 ++++++++++
 5 files changed, 31 insertions(+)

diff --git a/scripts/tracetool/__init__.py b/scripts/tracetool/__init__.py
index d4c204a472..0670ec17d5 100644
--- a/scripts/tracetool/__init__.py
+++ b/scripts/tracetool/__init__.py
@@ -271,6 +271,7 @@ class Event(object):
     QEMU_TRACE_NOCHECK       = "_nocheck__" + QEMU_TRACE
     QEMU_TRACE_TCG           = QEMU_TRACE + "_tcg"
     QEMU_DSTATE              = "_TRACE_%(NAME)s_DSTATE"
+    QEMU_BACKEND_DSTATE      = "TRACE_%(NAME)s_BACKEND_DSTATE"
     QEMU_EVENT               = "_TRACE_%(NAME)s_EVENT"
 
     def api(self, fmt=None):
diff --git a/scripts/tracetool/backend/__init__.py b/scripts/tracetool/backend/__init__.py
index f735a259c0..259c6a6531 100644
--- a/scripts/tracetool/backend/__init__.py
+++ b/scripts/tracetool/backend/__init__.py
@@ -119,5 +119,8 @@ class Wrapper:
     def generate(self, event, group):
         self._run_function("generate_%s", event, group)
 
+    def generate_backend_dstate(self, event, group):
+        self._run_function("generate_%s_backend_dstate", event, group)
+
     def generate_end(self, events, group):
         self._run_function("generate_%s_end", events, group)
diff --git a/scripts/tracetool/backend/dtrace.py b/scripts/tracetool/backend/dtrace.py
index c6812b70a2..17f902cc62 100644
--- a/scripts/tracetool/backend/dtrace.py
+++ b/scripts/tracetool/backend/dtrace.py
@@ -44,8 +44,20 @@ def generate_h_begin(events, group):
     out('#include "%s"' % header,
         '')
 
+    # SystemTap defines <provider>_<name>_ENABLED() but other DTrace
+    # implementations might not.
+    for e in events:
+        out('#ifndef QEMU_%(uppername)s_ENABLED',
+            '#define QEMU_%(uppername)s_ENABLED() false',
+            '#endif',
+            uppername=e.name.upper())
 
 def generate_h(event, group):
     out('    QEMU_%(uppername)s(%(argnames)s);',
         uppername=event.name.upper(),
         argnames=", ".join(event.args.names()))
+
+
+def generate_h_backend_dstate(event, group):
+    out('    QEMU_%(uppername)s_ENABLED() || \\',
+        uppername=event.name.upper())
diff --git a/scripts/tracetool/backend/ust.py b/scripts/tracetool/backend/ust.py
index 2adaf548d5..412592b8e0 100644
--- a/scripts/tracetool/backend/ust.py
+++ b/scripts/tracetool/backend/ust.py
@@ -38,3 +38,8 @@ def generate_h(event, group):
     out('    tracepoint(qemu, %(name)s%(tp_args)s);',
         name=event.name,
         tp_args=argnames)
+
+
+def generate_h_backend_dstate(event, group):
+    out('    tracepoint_enabled(qemu, %(name)s) || \\',
+        name=event.name)
diff --git a/scripts/tracetool/format/h.py b/scripts/tracetool/format/h.py
index aecf249d66..e06f0f27c5 100644
--- a/scripts/tracetool/format/h.py
+++ b/scripts/tracetool/format/h.py
@@ -49,6 +49,16 @@ def generate(events, backend, group):
     backend.generate_begin(events, group)
 
     for e in events:
+        # tracer-specific dstate
+        out('',
+            '#define %(api)s() ( \\',
+            api=e.api(e.QEMU_BACKEND_DSTATE))
+
+        if "disable" not in e.properties:
+            backend.generate_backend_dstate(e, group)
+
+        out('    false)')
+
         # tracer without checks
         out('',
             'static inline void %(api)s(%(args)s)',
-- 
2.13.3

[Qemu-devel] [PATCH 2/2] trace: check backend dstate in trace_event_get_state()

[Stefan Hajnoczi]

Code that checks dstate is unaware of SystemTap and LTTng UST dstate, so
the following trace event will not fire when solely enabled by SystemTap
or LTTng UST:

  if (trace_event_get_state(TRACE_MY_EVENT)) {
      str = g_strdup_printf("Expensive string to generate ...",
                            ...);
      trace_my_event(str);
      g_free(str);
  }

Most users of trace_event_get_state() want to know both QEMU and backend
dstate for the event.  Update the macro to include backend dstate.

Introduce trace_event_get_state_qemu() for those callers who really only
want QEMU dstate.  This includes the trace backends (like 'log') which
should only trigger when event are enabled via QEMU.

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 trace/control.h                     | 20 ++++++++++++++++++--
 scripts/tracetool/backend/ftrace.py |  2 +-
 scripts/tracetool/backend/log.py    |  3 ++-
 scripts/tracetool/backend/simple.py |  2 +-
 scripts/tracetool/backend/syslog.py |  3 ++-
 5 files changed, 24 insertions(+), 6 deletions(-)

diff --git a/trace/control.h b/trace/control.h
index b931824d60..b996c34c08 100644
--- a/trace/control.h
+++ b/trace/control.h
@@ -93,16 +93,32 @@ static bool trace_event_is_vcpu(TraceEvent *ev);
 static const char * trace_event_get_name(TraceEvent *ev);
 
 /**
+ * trace_event_get_state_qemu:
+ * @id: Event identifier name.
+ *
+ * Get the tracing state of an event, both static and the QEMU dynamic state.
+ * Note that some backends maintain their own dynamic state, use
+ * trace_event_get_state() instead if you wish to include it.
+ *
+ * If the event has the disabled property, the check will have no performance
+ * impact.
+ */
+#define trace_event_get_state_qemu(id)                       \
+    ((id ##_ENABLED) && trace_event_get_state_dynamic_by_id(id))
+
+/**
  * trace_event_get_state:
  * @id: Event identifier name.
  *
- * Get the tracing state of an event (both static and dynamic).
+ * Get the tracing state of an event (both static and dynamic).  Both QEMU and
+ * backend-specific dynamic state are included.
  *
  * If the event has the disabled property, the check will have no performance
  * impact.
  */
 #define trace_event_get_state(id)                       \
-    ((id ##_ENABLED) && trace_event_get_state_dynamic_by_id(id))
+    ((id ##_ENABLED) && (trace_event_get_state_dynamic_by_id(id) || \
+                         id ##_BACKEND_DSTATE()))
 
 /**
  * trace_event_get_vcpu_state:
diff --git a/scripts/tracetool/backend/ftrace.py b/scripts/tracetool/backend/ftrace.py
index dd0eda4441..fba637b376 100644
--- a/scripts/tracetool/backend/ftrace.py
+++ b/scripts/tracetool/backend/ftrace.py
@@ -33,7 +33,7 @@ def generate_h(event, group):
         '        char ftrace_buf[MAX_TRACE_STRLEN];',
         '        int unused __attribute__ ((unused));',
         '        int trlen;',
-        '        if (trace_event_get_state(%(event_id)s)) {',
+        '        if (trace_event_get_state_qemu(%(event_id)s)) {',
         '            trlen = snprintf(ftrace_buf, MAX_TRACE_STRLEN,',
         '                             "%(name)s " %(fmt)s "\\n" %(argnames)s);',
         '            trlen = MIN(trlen, MAX_TRACE_STRLEN - 1);',
diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
index 54f0a69886..4562b9d12d 100644
--- a/scripts/tracetool/backend/log.py
+++ b/scripts/tracetool/backend/log.py
@@ -33,7 +33,8 @@ def generate_h(event, group):
         # already checked on the generic format code
         cond = "true"
     else:
-        cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
+        cond = "trace_event_get_state_qemu(%s)" % \
+               ("TRACE_" + event.name.upper())
 
     out('    if (%(cond)s) {',
         '        struct timeval _now;',
diff --git a/scripts/tracetool/backend/simple.py b/scripts/tracetool/backend/simple.py
index f983670ee1..a39bbdc5c6 100644
--- a/scripts/tracetool/backend/simple.py
+++ b/scripts/tracetool/backend/simple.py
@@ -73,7 +73,7 @@ def generate_c(event, group):
         # already checked on the generic format code
         cond = "true"
     else:
-        cond = "trace_event_get_state(%s)" % event_id
+        cond = "trace_event_get_state_qemu(%s)" % event_id
 
     out('',
         '    if (!%(cond)s) {',
diff --git a/scripts/tracetool/backend/syslog.py b/scripts/tracetool/backend/syslog.py
index 1ce627f0fc..3ee07bf7fd 100644
--- a/scripts/tracetool/backend/syslog.py
+++ b/scripts/tracetool/backend/syslog.py
@@ -33,7 +33,8 @@ def generate_h(event, group):
         # already checked on the generic format code
         cond = "true"
     else:
-        cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
+        cond = "trace_event_get_state_qemu(%s)" % \
+               ("TRACE_" + event.name.upper())
 
     out('    if (%(cond)s) {',
         '        syslog(LOG_INFO, "%(name)s " %(fmt)s %(argnames)s);',
-- 
2.13.3

Re: [Qemu-devel] [PATCH 2/2] trace: check backend dstate in trace_event_get_state()

[Daniel P. Berrange]

On Fri, Jul 28, 2017 at 10:20:53AM +0100, Stefan Hajnoczi wrote:
> Code that checks dstate is unaware of SystemTap and LTTng UST dstate, so
> the following trace event will not fire when solely enabled by SystemTap
> or LTTng UST:
> 
>   if (trace_event_get_state(TRACE_MY_EVENT)) {
>       str = g_strdup_printf("Expensive string to generate ...",
>                             ...);
>       trace_my_event(str);
>       g_free(str);
>   }
> 
> Most users of trace_event_get_state() want to know both QEMU and backend
> dstate for the event.  Update the macro to include backend dstate.
> 
> Introduce trace_event_get_state_qemu() for those callers who really only
> want QEMU dstate.  This includes the trace backends (like 'log') which
> should only trigger when event are enabled via QEMU.

I'm not convinced this is quite right as is.

The QEMU state for an event is set via cli flags to -trace and that
is intended for use with with things like simpletrace or log which
have no other way to filter which events are turned on at runtime.
For these calling trace_event_get_state_dynamic_by_id() is right.

For DTrace / LTT-NG, and event is active if the kernel has turned
on the dynamic probe location.  Any command line args like -trace
should not influence this at all, so we should *not* involve QEMU
state at all - only the backend state. So for these we should only
be calling the backend specific test and ignoring
trace_event_get_state_dynamic_by_id() entirely. Your patch though
makes it consider both.



> Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
> ---
>  trace/control.h                     | 20 ++++++++++++++++++--
>  scripts/tracetool/backend/ftrace.py |  2 +-
>  scripts/tracetool/backend/log.py    |  3 ++-
>  scripts/tracetool/backend/simple.py |  2 +-
>  scripts/tracetool/backend/syslog.py |  3 ++-
>  5 files changed, 24 insertions(+), 6 deletions(-)
> 
> diff --git a/trace/control.h b/trace/control.h
> index b931824d60..b996c34c08 100644
> --- a/trace/control.h
> +++ b/trace/control.h
> @@ -93,16 +93,32 @@ static bool trace_event_is_vcpu(TraceEvent *ev);
>  static const char * trace_event_get_name(TraceEvent *ev);
>  
>  /**
> + * trace_event_get_state_qemu:
> + * @id: Event identifier name.
> + *
> + * Get the tracing state of an event, both static and the QEMU dynamic state.
> + * Note that some backends maintain their own dynamic state, use
> + * trace_event_get_state() instead if you wish to include it.
> + *
> + * If the event has the disabled property, the check will have no performance
> + * impact.
> + */
> +#define trace_event_get_state_qemu(id)                       \
> +    ((id ##_ENABLED) && trace_event_get_state_dynamic_by_id(id))
> +
> +/**
>   * trace_event_get_state:
>   * @id: Event identifier name.
>   *
> - * Get the tracing state of an event (both static and dynamic).
> + * Get the tracing state of an event (both static and dynamic).  Both QEMU and
> + * backend-specific dynamic state are included.
>   *
>   * If the event has the disabled property, the check will have no performance
>   * impact.
>   */
>  #define trace_event_get_state(id)                       \
> -    ((id ##_ENABLED) && trace_event_get_state_dynamic_by_id(id))
> +    ((id ##_ENABLED) && (trace_event_get_state_dynamic_by_id(id) || \
> +                         id ##_BACKEND_DSTATE()))
>  
>  /**
>   * trace_event_get_vcpu_state:
> diff --git a/scripts/tracetool/backend/ftrace.py b/scripts/tracetool/backend/ftrace.py
> index dd0eda4441..fba637b376 100644
> --- a/scripts/tracetool/backend/ftrace.py
> +++ b/scripts/tracetool/backend/ftrace.py
> @@ -33,7 +33,7 @@ def generate_h(event, group):
>          '        char ftrace_buf[MAX_TRACE_STRLEN];',
>          '        int unused __attribute__ ((unused));',
>          '        int trlen;',
> -        '        if (trace_event_get_state(%(event_id)s)) {',
> +        '        if (trace_event_get_state_qemu(%(event_id)s)) {',
>          '            trlen = snprintf(ftrace_buf, MAX_TRACE_STRLEN,',
>          '                             "%(name)s " %(fmt)s "\\n" %(argnames)s);',
>          '            trlen = MIN(trlen, MAX_TRACE_STRLEN - 1);',
> diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
> index 54f0a69886..4562b9d12d 100644
> --- a/scripts/tracetool/backend/log.py
> +++ b/scripts/tracetool/backend/log.py
> @@ -33,7 +33,8 @@ def generate_h(event, group):
>          # already checked on the generic format code
>          cond = "true"
>      else:
> -        cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
> +        cond = "trace_event_get_state_qemu(%s)" % \
> +               ("TRACE_" + event.name.upper())
>  
>      out('    if (%(cond)s) {',
>          '        struct timeval _now;',
> diff --git a/scripts/tracetool/backend/simple.py b/scripts/tracetool/backend/simple.py
> index f983670ee1..a39bbdc5c6 100644
> --- a/scripts/tracetool/backend/simple.py
> +++ b/scripts/tracetool/backend/simple.py
> @@ -73,7 +73,7 @@ def generate_c(event, group):
>          # already checked on the generic format code
>          cond = "true"
>      else:
> -        cond = "trace_event_get_state(%s)" % event_id
> +        cond = "trace_event_get_state_qemu(%s)" % event_id
>  
>      out('',
>          '    if (!%(cond)s) {',
> diff --git a/scripts/tracetool/backend/syslog.py b/scripts/tracetool/backend/syslog.py
> index 1ce627f0fc..3ee07bf7fd 100644
> --- a/scripts/tracetool/backend/syslog.py
> +++ b/scripts/tracetool/backend/syslog.py
> @@ -33,7 +33,8 @@ def generate_h(event, group):
>          # already checked on the generic format code
>          cond = "true"
>      else:
> -        cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
> +        cond = "trace_event_get_state_qemu(%s)" % \
> +               ("TRACE_" + event.name.upper())
>  
>      out('    if (%(cond)s) {',
>          '        syslog(LOG_INFO, "%(name)s " %(fmt)s %(argnames)s);',
> -- 
> 2.13.3
> 
> 

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

Re: [Qemu-devel] [PATCH 2/2] trace: check backend dstate in trace_event_get_state()

[Stefan Hajnoczi]

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

On Fri, Jul 28, 2017 at 12:05:44PM +0100, Daniel P. Berrange wrote:
> On Fri, Jul 28, 2017 at 10:20:53AM +0100, Stefan Hajnoczi wrote:
> > Code that checks dstate is unaware of SystemTap and LTTng UST dstate, so
> > the following trace event will not fire when solely enabled by SystemTap
> > or LTTng UST:
> > 
> >   if (trace_event_get_state(TRACE_MY_EVENT)) {
> >       str = g_strdup_printf("Expensive string to generate ...",
> >                             ...);
> >       trace_my_event(str);
> >       g_free(str);
> >   }
> > 
> > Most users of trace_event_get_state() want to know both QEMU and backend
> > dstate for the event.  Update the macro to include backend dstate.
> > 
> > Introduce trace_event_get_state_qemu() for those callers who really only
> > want QEMU dstate.  This includes the trace backends (like 'log') which
> > should only trigger when event are enabled via QEMU.
> 
> I'm not convinced this is quite right as is.
> 
> The QEMU state for an event is set via cli flags to -trace and that
> is intended for use with with things like simpletrace or log which
> have no other way to filter which events are turned on at runtime.
> For these calling trace_event_get_state_dynamic_by_id() is right.
> 
> For DTrace / LTT-NG, and event is active if the kernel has turned
> on the dynamic probe location.  Any command line args like -trace
> should not influence this at all, so we should *not* involve QEMU
> state at all - only the backend state. So for these we should only
> be calling the backend specific test and ignoring
> trace_event_get_state_dynamic_by_id() entirely. Your patch though
> makes it consider both.

I think you're referring to this:

  #define trace_event_get_state(id)                       \
      ((id ##_ENABLED) && (trace_event_get_state_dynamic_by_id(id) || \
                           id ##_BACKEND_DSTATE()))

We could change it to:

  #define trace_event_get_state(id)                       \
      ((id ##_ENABLED) && id ##_BACKEND_DSTATE())

and modify the log, syslog, ftrace, etc backends to emit
trace_event_get_state_dynamic_by_id(id) as their backend dstate.

However, in the multi-backend case with ./configure
--enable-trace-backends=log,syslog this expands to:

  ((id ##_ENABLED) && (trace_event_get_state_dynamic_by_id(id) || \
                       trace_event_get_state_dynamic_by_id(id) || \
		       false))

I couldn't bring myself to have multiple calls to
trace_event_get_state_dynamic_by_id() :).

What do you think?

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

Re: [Qemu-devel] [PATCH 2/2] trace: check backend dstate in trace_event_get_state()

[Daniel P. Berrange]

On Fri, Jul 28, 2017 at 04:56:49PM +0100, Stefan Hajnoczi wrote:
> On Fri, Jul 28, 2017 at 12:05:44PM +0100, Daniel P. Berrange wrote:
> > On Fri, Jul 28, 2017 at 10:20:53AM +0100, Stefan Hajnoczi wrote:
> > > Code that checks dstate is unaware of SystemTap and LTTng UST dstate, so
> > > the following trace event will not fire when solely enabled by SystemTap
> > > or LTTng UST:
> > > 
> > >   if (trace_event_get_state(TRACE_MY_EVENT)) {
> > >       str = g_strdup_printf("Expensive string to generate ...",
> > >                             ...);
> > >       trace_my_event(str);
> > >       g_free(str);
> > >   }
> > > 
> > > Most users of trace_event_get_state() want to know both QEMU and backend
> > > dstate for the event.  Update the macro to include backend dstate.
> > > 
> > > Introduce trace_event_get_state_qemu() for those callers who really only
> > > want QEMU dstate.  This includes the trace backends (like 'log') which
> > > should only trigger when event are enabled via QEMU.
> > 
> > I'm not convinced this is quite right as is.
> > 
> > The QEMU state for an event is set via cli flags to -trace and that
> > is intended for use with with things like simpletrace or log which
> > have no other way to filter which events are turned on at runtime.
> > For these calling trace_event_get_state_dynamic_by_id() is right.
> > 
> > For DTrace / LTT-NG, and event is active if the kernel has turned
> > on the dynamic probe location.  Any command line args like -trace
> > should not influence this at all, so we should *not* involve QEMU
> > state at all - only the backend state. So for these we should only
> > be calling the backend specific test and ignoring
> > trace_event_get_state_dynamic_by_id() entirely. Your patch though
> > makes it consider both.
> 
> I think you're referring to this:
> 
>   #define trace_event_get_state(id)                       \
>       ((id ##_ENABLED) && (trace_event_get_state_dynamic_by_id(id) || \
>                            id ##_BACKEND_DSTATE()))
> 
> We could change it to:
> 
>   #define trace_event_get_state(id)                       \
>       ((id ##_ENABLED) && id ##_BACKEND_DSTATE())
> 
> and modify the log, syslog, ftrace, etc backends to emit
> trace_event_get_state_dynamic_by_id(id) as their backend dstate.

Yeah that's exactly what I imagined.

> 
> However, in the multi-backend case with ./configure
> --enable-trace-backends=log,syslog this expands to:
> 
>   ((id ##_ENABLED) && (trace_event_get_state_dynamic_by_id(id) || \
>                        trace_event_get_state_dynamic_by_id(id) || \
> 		       false))
> 
> I couldn't bring myself to have multiple calls to
> trace_event_get_state_dynamic_by_id() :).

I don't think that's worth worrying about.

trace_event_get_state_dynamic_by_id() is optimized to a simple inline
condition check. IOW, if you have 3 backends enable concurrently which
each use trace_event_get_state_dynamic_by_id(), this is no worse than
if you have 3 other backends enabled concurrently that each perform
some backend specific check.

Since trace_event_get_state_dynamic_by_id() is inline check, the
compiler might even optimize away the redundant check of the same
variable, or the processor might have optimized it too.

Enabling many backends at once is not particularly common anyway,
but in the absolute worst case, you could make tracetool intelligent
enough to notice the duplicate calls to trace_event_get_state_dynamic_by_id
and merge them into one in the generated code.


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

Re: [Qemu-devel] [PATCH 2/2] trace: check backend dstate in trace_event_get_state()

[Lluís Vilanova]

Daniel P Berrange writes:

> On Fri, Jul 28, 2017 at 10:20:53AM +0100, Stefan Hajnoczi wrote:
>> Code that checks dstate is unaware of SystemTap and LTTng UST dstate, so
>> the following trace event will not fire when solely enabled by SystemTap
>> or LTTng UST:
>> 
>> if (trace_event_get_state(TRACE_MY_EVENT)) {
>> str = g_strdup_printf("Expensive string to generate ...",
>> ...);
>> trace_my_event(str);
>> g_free(str);
>> }
>> 
>> Most users of trace_event_get_state() want to know both QEMU and backend
>> dstate for the event.  Update the macro to include backend dstate.
>> 
>> Introduce trace_event_get_state_qemu() for those callers who really only
>> want QEMU dstate.  This includes the trace backends (like 'log') which
>> should only trigger when event are enabled via QEMU.

> I'm not convinced this is quite right as is.

> The QEMU state for an event is set via cli flags to -trace and that
> is intended for use with with things like simpletrace or log which
> have no other way to filter which events are turned on at runtime.
> For these calling trace_event_get_state_dynamic_by_id() is right.

> For DTrace / LTT-NG, and event is active if the kernel has turned
> on the dynamic probe location.  Any command line args like -trace
> should not influence this at all, so we should *not* involve QEMU
> state at all - only the backend state. So for these we should only
> be calling the backend specific test and ignoring
> trace_event_get_state_dynamic_by_id() entirely. Your patch though
> makes it consider both.

I think this is because Stefan's proposal is to have code written into QEMU's
code that needs to know if *any+ backend has that event enabled, in order to
know if the expensive argument must be generated. Remember, that's regular QEMU
code, not auto-generated.

I would also try to minimise changes and name this new functionality as
trace_event_get_state_all, _any, _backends or something on those
lines. Otherwise we'll break the consistency of the API with other functions
(e.g., trace_event_get_vcpu_state only checks QEMU's state, and will always do
so because external backends do not support that feature).


Thanks,
  Lluis



>> Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
>> ---
>> trace/control.h                     | 20 ++++++++++++++++++--
>> scripts/tracetool/backend/ftrace.py |  2 +-
>> scripts/tracetool/backend/log.py    |  3 ++-
>> scripts/tracetool/backend/simple.py |  2 +-
>> scripts/tracetool/backend/syslog.py |  3 ++-
>> 5 files changed, 24 insertions(+), 6 deletions(-)
>> 
>> diff --git a/trace/control.h b/trace/control.h
>> index b931824d60..b996c34c08 100644
>> --- a/trace/control.h
>> +++ b/trace/control.h
>> @@ -93,16 +93,32 @@ static bool trace_event_is_vcpu(TraceEvent *ev);
>> static const char * trace_event_get_name(TraceEvent *ev);
>> 
>> /**
>> + * trace_event_get_state_qemu:
>> + * @id: Event identifier name.
>> + *
>> + * Get the tracing state of an event, both static and the QEMU dynamic state.
>> + * Note that some backends maintain their own dynamic state, use
>> + * trace_event_get_state() instead if you wish to include it.
>> + *
>> + * If the event has the disabled property, the check will have no performance
>> + * impact.
>> + */
>> +#define trace_event_get_state_qemu(id)                       \
>> +    ((id ##_ENABLED) && trace_event_get_state_dynamic_by_id(id))
>> +
>> +/**
>> * trace_event_get_state:
>> * @id: Event identifier name.
>> *
>> - * Get the tracing state of an event (both static and dynamic).
>> + * Get the tracing state of an event (both static and dynamic).  Both QEMU and
>> + * backend-specific dynamic state are included.
>> *
>> * If the event has the disabled property, the check will have no performance
>> * impact.
>> */
>> #define trace_event_get_state(id)                       \
>> -    ((id ##_ENABLED) && trace_event_get_state_dynamic_by_id(id))
>> +    ((id ##_ENABLED) && (trace_event_get_state_dynamic_by_id(id) || \
>> +                         id ##_BACKEND_DSTATE()))
>> 
>> /**
>> * trace_event_get_vcpu_state:
>> diff --git a/scripts/tracetool/backend/ftrace.py b/scripts/tracetool/backend/ftrace.py
>> index dd0eda4441..fba637b376 100644
>> --- a/scripts/tracetool/backend/ftrace.py
>> +++ b/scripts/tracetool/backend/ftrace.py
>> @@ -33,7 +33,7 @@ def generate_h(event, group):
>> '        char ftrace_buf[MAX_TRACE_STRLEN];',
>> '        int unused __attribute__ ((unused));',
>> '        int trlen;',
>> -        '        if (trace_event_get_state(%(event_id)s)) {',
>> +        '        if (trace_event_get_state_qemu(%(event_id)s)) {',
>> '            trlen = snprintf(ftrace_buf, MAX_TRACE_STRLEN,',
>> '                             "%(name)s " %(fmt)s "\\n" %(argnames)s);',
>> '            trlen = MIN(trlen, MAX_TRACE_STRLEN - 1);',
>> diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
>> index 54f0a69886..4562b9d12d 100644
>> --- a/scripts/tracetool/backend/log.py
>> +++ b/scripts/tracetool/backend/log.py
>> @@ -33,7 +33,8 @@ def generate_h(event, group):
>> # already checked on the generic format code
>> cond = "true"
>> else:
>> -        cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
>> +        cond = "trace_event_get_state_qemu(%s)" % \
>> +               ("TRACE_" + event.name.upper())
>> 
>> out('    if (%(cond)s) {',
>> '        struct timeval _now;',
>> diff --git a/scripts/tracetool/backend/simple.py b/scripts/tracetool/backend/simple.py
>> index f983670ee1..a39bbdc5c6 100644
>> --- a/scripts/tracetool/backend/simple.py
>> +++ b/scripts/tracetool/backend/simple.py
>> @@ -73,7 +73,7 @@ def generate_c(event, group):
>> # already checked on the generic format code
>> cond = "true"
>> else:
>> -        cond = "trace_event_get_state(%s)" % event_id
>> +        cond = "trace_event_get_state_qemu(%s)" % event_id
>> 
>> out('',
>> '    if (!%(cond)s) {',
>> diff --git a/scripts/tracetool/backend/syslog.py b/scripts/tracetool/backend/syslog.py
>> index 1ce627f0fc..3ee07bf7fd 100644
>> --- a/scripts/tracetool/backend/syslog.py
>> +++ b/scripts/tracetool/backend/syslog.py
>> @@ -33,7 +33,8 @@ def generate_h(event, group):
>> # already checked on the generic format code
>> cond = "true"
>> else:
>> -        cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
>> +        cond = "trace_event_get_state_qemu(%s)" % \
>> +               ("TRACE_" + event.name.upper())
>> 
>> out('    if (%(cond)s) {',
>> '        syslog(LOG_INFO, "%(name)s " %(fmt)s %(argnames)s);',
>> -- 
>> 2.13.3
>> 
>> 

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

Re: [Qemu-devel] [PATCH 0/2] trace: fix trace_event_get_state() for SystemTap and LTTng UST

[Denis V. Lunev]

On 07/28/2017 12:20 PM, Stefan Hajnoczi wrote:
> Trace events that compute their arguments can affect performance.  The
> following idom can be used to avoid computing arguments when the trace event is
> disabled:
>
>   if (trace_event_get_state(TRACE_MY_EVENT)) {
>       char *str = g_strdup_printf("Expensive string ...", ...);
>       trace_my_event(str);
>       g_free(str);
>   }
>
> Unfortunately this breaks the trace event for SystemTap and LTTng UST since
> those tracers manage their own enabled/disabled state.
>
> These patches add per-backend dstate to trace_event_get_state() so that the
> trace event fires as expected when enabled via SystemTap or LTTng UST.
>
> Stefan Hajnoczi (2):
>   trace: add TRACE_<event>_BACKEND_DSTATE()
>   trace: check backend dstate in trace_event_get_state()
>
>  trace/control.h                       | 20 ++++++++++++++++++--
>  scripts/tracetool/__init__.py         |  1 +
>  scripts/tracetool/backend/__init__.py |  3 +++
>  scripts/tracetool/backend/dtrace.py   | 12 ++++++++++++
>  scripts/tracetool/backend/ftrace.py   |  2 +-
>  scripts/tracetool/backend/log.py      |  3 ++-
>  scripts/tracetool/backend/simple.py   |  2 +-
>  scripts/tracetool/backend/syslog.py   |  3 ++-
>  scripts/tracetool/backend/ust.py      |  5 +++++
>  scripts/tracetool/format/h.py         | 10 ++++++++++
>  10 files changed, 55 insertions(+), 6 deletions(-)
>
looks good to me!

This also fixes the same issue not only in my code, but in

static void ohci_td_pkt(const char *msg, const uint8_t *buf, size_t len)
and in colo code.

Reviewed-by: Denis V. Lunev <den@openvz.org>