[Qemu-devel] [PATCH 0/2] improve tracing

[Qemu-devel] [PATCH 0/2] improve tracing

[Vladimir Sementsov-Ogievskiy]

Current trace system have a drawback: parameters of trace functions
are calculated even if corresponding tracepoint is disabled. Also, it
looks like trace function are not actually inlined by compiler (at
least for me).

Here is a fix proposal: move from function call to macros. Patch 02
is an example, of how to reduce extra calculations with help of
patch 01.

Vladimir Sementsov-Ogievskiy (2):
  trace: do not calculate arguments for disabled trace-points
  monitor: improve tracing in handle_qmp_command

 monitor.c                     |  6 +++---
 scripts/tracetool/format/h.py | 13 +++++++------
 2 files changed, 10 insertions(+), 9 deletions(-)

-- 
2.11.1

[Qemu-devel] [PATCH 1/2] trace: do not calculate arguments for disabled trace-points

[Vladimir Sementsov-Ogievskiy]

Do not calculate arguments if trace-point is disabled. For this:
 - move to macro do { ... } while (0) scheme
 - use additional macro-layer to handle calls of trace-points where
   a macro generates parameter list
   (like trace_e1000e_mac_set_permanent(MAC_ARG(macaddr)))

This is needed to allow some additional logic in trace-point parameter
calculation, which will not be executed if this trace-point is
disabled.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 scripts/tracetool/format/h.py | 13 +++++++------
 1 file changed, 7 insertions(+), 6 deletions(-)

diff --git a/scripts/tracetool/format/h.py b/scripts/tracetool/format/h.py
index aecf249d66..d0baccc453 100644
--- a/scripts/tracetool/format/h.py
+++ b/scripts/tracetool/format/h.py
@@ -73,12 +73,13 @@ def generate(events, backend, group):
             cond = "true"
 
         out('',
-            'static inline void %(api)s(%(args)s)',
-            '{',
-            '    if (%(cond)s) {',
-            '        %(api_nocheck)s(%(names)s);',
-            '    }',
-            '}',
+            '#define %(api)s(...)  _do_%(api)s(__VA_ARGS__)',
+            '#define _do_%(api)s(%(names)s) \\',
+            'do { \\',
+            '    if (%(cond)s) { \\',
+            '        %(api_nocheck)s(%(names)s); \\',
+            '    } \\',
+            '} while (0)',
             api=e.api(),
             api_nocheck=e.api(e.QEMU_TRACE_NOCHECK),
             args=e.args,
-- 
2.11.1

[Qemu-devel] [PATCH 2/2] monitor: improve tracing in handle_qmp_command

[Vladimir Sementsov-Ogievskiy]

Calculate req_json only if trace_handle_qmp_command enabled.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 monitor.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/monitor.c b/monitor.c
index 6d040e620f..3606a7928b 100644
--- a/monitor.c
+++ b/monitor.c
@@ -3823,7 +3823,7 @@ static void handle_qmp_command(JSONMessageParser *parser, GQueue *tokens)
     QDict *qdict = NULL;
     Monitor *mon = cur_mon;
     Error *err = NULL;
-    QString *req_json;
+    QString *req_json = NULL;
 
     req = json_parser_parse_err(tokens, NULL, &err);
     if (!req && !err) {
@@ -3841,8 +3841,8 @@ static void handle_qmp_command(JSONMessageParser *parser, GQueue *tokens)
         qdict_del(qdict, "id");
     } /* else will fail qmp_dispatch() */
 
-    req_json = qobject_to_json(req);
-    trace_handle_qmp_command(mon, qstring_get_str(req_json));
+    trace_handle_qmp_command(mon,
+                             qstring_get_str(req_json = qobject_to_json(req)));
     QDECREF(req_json);
 
     rsp = qmp_dispatch(cur_mon->qmp.commands, req);
-- 
2.11.1

Re: [Qemu-devel] [PATCH 2/2] monitor: improve tracing in handle_qmp_command

[Stefan Hajnoczi]

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

On Fri, Jul 21, 2017 at 05:31:49PM +0300, Vladimir Sementsov-Ogievskiy wrote:
> Calculate req_json only if trace_handle_qmp_command enabled.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>

Is there a real-world performance issue?

(I'm not against this change but it's important to understand the
rationale for performance optimizations.)

The monitor is a control channel.  Anything using it at high frequency
with low latency expectations will be disappointed.  We should look at
such cases and decide whether the monitor really is the appropriate
interface for them.

Stefan

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

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Lluís Vilanova]

Vladimir Sementsov-Ogievskiy writes:

> Current trace system have a drawback: parameters of trace functions
> are calculated even if corresponding tracepoint is disabled. Also, it
> looks like trace function are not actually inlined by compiler (at
> least for me).

> Here is a fix proposal: move from function call to macros. Patch 02
> is an example, of how to reduce extra calculations with help of
> patch 01.

The tracing functions *were* inlined last time I checked, although things
changed quite a lot since then. Not sure that will make a lot of difference in
terms of overall performance (needs measuring).

As for arguments, each trace event has a define TRACE_{NAME}_ENABLED that you
can use for that purpose. If this is not explained in tracing.txt, that is a
documentation bug.


Thanks,
  Lluis

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Vladimir Sementsov-Ogievskiy]

21.07.2017 20:04, Lluís Vilanova wrote:
> Vladimir Sementsov-Ogievskiy writes:
>
>> Current trace system have a drawback: parameters of trace functions
>> are calculated even if corresponding tracepoint is disabled. Also, it
>> looks like trace function are not actually inlined by compiler (at
>> least for me).
>> Here is a fix proposal: move from function call to macros. Patch 02
>> is an example, of how to reduce extra calculations with help of
>> patch 01.
> The tracing functions *were* inlined last time I checked, although things
> changed quite a lot since then. Not sure that will make a lot of difference in
> terms of overall performance (needs measuring).
>
> As for arguments, each trace event has a define TRACE_{NAME}_ENABLED that you
> can use for that purpose. If this is not explained in tracing.txt, that is a
> documentation bug.

These macroses are about enable/disable traces statically. I'm saying 
about dynamic disable/enable.

>
>
> Thanks,
>    Lluis


-- 
Best regards,
Vladimir

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Lluís Vilanova]

Vladimir Sementsov-Ogievskiy writes:

> 21.07.2017 20:04, Lluís Vilanova wrote:
>> Vladimir Sementsov-Ogievskiy writes:
>> 
>>> Current trace system have a drawback: parameters of trace functions
>>> are calculated even if corresponding tracepoint is disabled. Also, it
>>> looks like trace function are not actually inlined by compiler (at
>>> least for me).
>>> Here is a fix proposal: move from function call to macros. Patch 02
>>> is an example, of how to reduce extra calculations with help of
>>> patch 01.
>> The tracing functions *were* inlined last time I checked, although things
>> changed quite a lot since then. Not sure that will make a lot of difference in
>> terms of overall performance (needs measuring).
>> 
>> As for arguments, each trace event has a define TRACE_{NAME}_ENABLED that you
>> can use for that purpose. If this is not explained in tracing.txt, that is a
>> documentation bug.

> These macroses are about enable/disable traces statically. I'm saying about
> dynamic disable/enable.

Aha, I see. I think most events get passed already-calculated variables (usually
for other purposes), so I don't think it will have much of a performance
impact. Did you measure it?


Thanks,
  Lluis

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Denis V. Lunev]

On 07/24/2017 02:07 PM, Lluís Vilanova wrote:
> Vladimir Sementsov-Ogievskiy writes:
>
>> 21.07.2017 20:04, Lluís Vilanova wrote:
>>> Vladimir Sementsov-Ogievskiy writes:
>>>
>>>> Current trace system have a drawback: parameters of trace functions
>>>> are calculated even if corresponding tracepoint is disabled. Also, it
>>>> looks like trace function are not actually inlined by compiler (at
>>>> least for me).
>>>> Here is a fix proposal: move from function call to macros. Patch 02
>>>> is an example, of how to reduce extra calculations with help of
>>>> patch 01.
>>> The tracing functions *were* inlined last time I checked, although things
>>> changed quite a lot since then. Not sure that will make a lot of difference in
>>> terms of overall performance (needs measuring).
>>>
>>> As for arguments, each trace event has a define TRACE_{NAME}_ENABLED that you
>>> can use for that purpose. If this is not explained in tracing.txt, that is a
>>> documentation bug.
>> These macroses are about enable/disable traces statically. I'm saying about
>> dynamic disable/enable.
> Aha, I see. I think most events get passed already-calculated variables (usually
> for other purposes), so I don't think it will have much of a performance
> impact. Did you measure it?
>
>
> Thanks,
>   Lluis
The idea is that we can add more complex stuff after the patch.
QMP command log is a very good example of that.

Actually at our opinion macro will be safe but much better
from the point of side-effects - arguments will never be evaluated
until the trace happened.

Den

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Stefan Hajnoczi]

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

On Fri, Jul 21, 2017 at 08:04:17PM +0300, Lluís Vilanova wrote:
> Vladimir Sementsov-Ogievskiy writes:
> 
> > Current trace system have a drawback: parameters of trace functions
> > are calculated even if corresponding tracepoint is disabled. Also, it
> > looks like trace function are not actually inlined by compiler (at
> > least for me).
> 
> > Here is a fix proposal: move from function call to macros. Patch 02
> > is an example, of how to reduce extra calculations with help of
> > patch 01.
> 
> The tracing functions *were* inlined last time I checked, although things
> changed quite a lot since then. Not sure that will make a lot of difference in
> terms of overall performance (needs measuring).
> 
> As for arguments, each trace event has a define TRACE_{NAME}_ENABLED that you
> can use for that purpose. If this is not explained in tracing.txt, that is a
> documentation bug.

It is described in docs/devel/tracing.txt:

In addition, there might be cases where relatively complex computations must be
performed to generate values that are only used as arguments for a trace
function. In these cases you can use the macro 'TRACE_${EVENT_NAME}_ENABLED' to
guard such computations and avoid its compilation when the event is disabled:

    #include "trace.h"  /* needed for trace event prototype */
    
    void *qemu_vmalloc(size_t size)
    {
        void *ptr;
        size_t align = QEMU_VMALLOC_ALIGN;
    
        if (size < align) {
            align = getpagesize();
        }
        ptr = qemu_memalign(align, size);
        if (TRACE_QEMU_VMALLOC_ENABLED) { /* preprocessor macro */
            void *complex;
            /* some complex computations to produce the 'complex' value */
            trace_qemu_vmalloc(size, ptr, complex);
        }
        return ptr;
    }

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

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Stefan Hajnoczi]

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

On Fri, Jul 21, 2017 at 05:31:47PM +0300, Vladimir Sementsov-Ogievskiy wrote:
> Current trace system have a drawback: parameters of trace functions
> are calculated even if corresponding tracepoint is disabled. Also, it
> looks like trace function are not actually inlined by compiler (at
> least for me).
> 
> Here is a fix proposal: move from function call to macros. Patch 02
> is an example, of how to reduce extra calculations with help of
> patch 01.
> 
> Vladimir Sementsov-Ogievskiy (2):
>   trace: do not calculate arguments for disabled trace-points
>   monitor: improve tracing in handle_qmp_command

Please use the TRACE_FOO_ENABLED macro instead of putting computation
inside the trace event arguments.  This makes the code cleaner and
easier to read.

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

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Denis V. Lunev]

On 07/24/2017 02:34 PM, Stefan Hajnoczi wrote:
> On Fri, Jul 21, 2017 at 05:31:47PM +0300, Vladimir Sementsov-Ogievskiy wrote:
>> Current trace system have a drawback: parameters of trace functions
>> are calculated even if corresponding tracepoint is disabled. Also, it
>> looks like trace function are not actually inlined by compiler (at
>> least for me).
>>
>> Here is a fix proposal: move from function call to macros. Patch 02
>> is an example, of how to reduce extra calculations with help of
>> patch 01.
>>
>> Vladimir Sementsov-Ogievskiy (2):
>>   trace: do not calculate arguments for disabled trace-points
>>   monitor: improve tracing in handle_qmp_command
> Please use the TRACE_FOO_ENABLED macro instead of putting computation
> inside the trace event arguments.  This makes the code cleaner and
> easier to read.
At our opinion this ENABLED is compile time check while the option
could be tuned in runtime. Thus normally it would normally be
enabled while the trace is silent.

So, under load, we will have extra allocation, copying the command buffer,
freeing memory without actual trace. In order to fix that we should
do something like

if (trace_event_get_state(TRACE_HANDLE_QMP_COMMAND)) {
   req_json = qobject_to_json(req);
   trace_handle_qmp_command(mon, req_json);
   QDECREF(req_json);
}

which is possible, but at our (me + Vova) opinion is ugly.
That is why we are proposing to switch to macro, which
will not require such tweaking.

Arguments will be only evaluated when necessary and we
will not have side-effects if the tracepoint is compile time
enabled and run-time disabled.

Though if the code above is acceptable, we can send the
patch with it. No problem.

Den

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Lluís Vilanova]

Denis V Lunev writes:

> On 07/24/2017 02:34 PM, Stefan Hajnoczi wrote:
>> On Fri, Jul 21, 2017 at 05:31:47PM +0300, Vladimir Sementsov-Ogievskiy wrote:
>>> Current trace system have a drawback: parameters of trace functions
>>> are calculated even if corresponding tracepoint is disabled. Also, it
>>> looks like trace function are not actually inlined by compiler (at
>>> least for me).
>>> 
>>> Here is a fix proposal: move from function call to macros. Patch 02
>>> is an example, of how to reduce extra calculations with help of
>>> patch 01.
>>> 
>>> Vladimir Sementsov-Ogievskiy (2):
>>> trace: do not calculate arguments for disabled trace-points
>>> monitor: improve tracing in handle_qmp_command
>> Please use the TRACE_FOO_ENABLED macro instead of putting computation
>> inside the trace event arguments.  This makes the code cleaner and
>> easier to read.
> At our opinion this ENABLED is compile time check while the option
> could be tuned in runtime. Thus normally it would normally be
> enabled while the trace is silent.

> So, under load, we will have extra allocation, copying the command buffer,
> freeing memory without actual trace. In order to fix that we should
> do something like

> if (trace_event_get_state(TRACE_HANDLE_QMP_COMMAND)) {
>    req_json = qobject_to_json(req);
>    trace_handle_qmp_command(mon, req_json);
>    QDECREF(req_json);
> }

> which is possible, but at our (me + Vova) opinion is ugly.
> That is why we are proposing to switch to macro, which
> will not require such tweaking.

> Arguments will be only evaluated when necessary and we
> will not have side-effects if the tracepoint is compile time
> enabled and run-time disabled.

> Though if the code above is acceptable, we can send the
> patch with it. No problem.

I completely get your point, but:

* I'm not sure it will have much of a performance impact.
* It is not obvious what's going to happen just by looking at the code of the
  calling site.

I prefer to minimize the use of macros, even if that makes a few trace event
calls to be a bit more verbose, as in your example above. Also, I quite dislike
the new style you propose:

  trace_handle_qmp_command(mon,
                           qstring_get_str(req_json = qobject_to_json(req)));
  QDECREF(req_json);


Cheers,
  Lluis

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Denis V. Lunev]

On 07/24/2017 05:43 PM, Lluís Vilanova wrote:
> Denis V Lunev writes:
>
>> On 07/24/2017 02:34 PM, Stefan Hajnoczi wrote:
>>> On Fri, Jul 21, 2017 at 05:31:47PM +0300, Vladimir Sementsov-Ogievskiy wrote:
>>>> Current trace system have a drawback: parameters of trace functions
>>>> are calculated even if corresponding tracepoint is disabled. Also, it
>>>> looks like trace function are not actually inlined by compiler (at
>>>> least for me).
>>>>
>>>> Here is a fix proposal: move from function call to macros. Patch 02
>>>> is an example, of how to reduce extra calculations with help of
>>>> patch 01.
>>>>
>>>> Vladimir Sementsov-Ogievskiy (2):
>>>> trace: do not calculate arguments for disabled trace-points
>>>> monitor: improve tracing in handle_qmp_command
>>> Please use the TRACE_FOO_ENABLED macro instead of putting computation
>>> inside the trace event arguments.  This makes the code cleaner and
>>> easier to read.
>> At our opinion this ENABLED is compile time check while the option
>> could be tuned in runtime. Thus normally it would normally be
>> enabled while the trace is silent.
>> So, under load, we will have extra allocation, copying the command buffer,
>> freeing memory without actual trace. In order to fix that we should
>> do something like
>> if (trace_event_get_state(TRACE_HANDLE_QMP_COMMAND)) {
>>    req_json = qobject_to_json(req);
>>    trace_handle_qmp_command(mon, req_json);
>>    QDECREF(req_json);
>> }
>> which is possible, but at our (me + Vova) opinion is ugly.
>> That is why we are proposing to switch to macro, which
>> will not require such tweaking.
>> Arguments will be only evaluated when necessary and we
>> will not have side-effects if the tracepoint is compile time
>> enabled and run-time disabled.
>> Though if the code above is acceptable, we can send the
>> patch with it. No problem.
> I completely get your point, but:
>
> * I'm not sure it will have much of a performance impact.
> * It is not obvious what's going to happen just by looking at the code of the
>   calling site.
>
> I prefer to minimize the use of macros, even if that makes a few trace event
> calls to be a bit more verbose, as in your example above. Also, I quite dislike
> the new style you propose:
>
>   trace_handle_qmp_command(mon,
>                            qstring_get_str(req_json = qobject_to_json(req)));
>   QDECREF(req_json);
>
>
> Cheers,
>   Lluis
This is a matter of overall performance. For example I can have 500 VMs.
In order to manage them, f.e. tweak balloon I have to collect statistics.
This happens 1 time/10 sec/VM. Libvirt issues the following

494665@1486641285.213042:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-balloon"
494665@1486641285.214181:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "qom-get"
494665@1486641285.214792:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-hotpluggable-cpus"
494665@1486641285.215283:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-cpus"
494665@1486641285.216153:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-blockstats"
494665@1486641285.216827:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-block"

We will have 300 commands in a second in all VMs. This is not that small
load. OK. I do think that I'll lost 2-3-5 percents of one host CPU due
to this allocation/free/copy. There are no measurements unfortunately.
At my opinion this matters.

Den

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Lluís Vilanova]

Denis V Lunev writes:

> On 07/24/2017 05:43 PM, Lluís Vilanova wrote:
>> Denis V Lunev writes:
>> 
>>> On 07/24/2017 02:34 PM, Stefan Hajnoczi wrote:
>>>> On Fri, Jul 21, 2017 at 05:31:47PM +0300, Vladimir Sementsov-Ogievskiy wrote:
>>>>> Current trace system have a drawback: parameters of trace functions
>>>>> are calculated even if corresponding tracepoint is disabled. Also, it
>>>>> looks like trace function are not actually inlined by compiler (at
>>>>> least for me).
>>>>> 
>>>>> Here is a fix proposal: move from function call to macros. Patch 02
>>>>> is an example, of how to reduce extra calculations with help of
>>>>> patch 01.
>>>>> 
>>>>> Vladimir Sementsov-Ogievskiy (2):
>>>>> trace: do not calculate arguments for disabled trace-points
>>>>> monitor: improve tracing in handle_qmp_command
>>>> Please use the TRACE_FOO_ENABLED macro instead of putting computation
>>>> inside the trace event arguments.  This makes the code cleaner and
>>>> easier to read.
>>> At our opinion this ENABLED is compile time check while the option
>>> could be tuned in runtime. Thus normally it would normally be
>>> enabled while the trace is silent.
>>> So, under load, we will have extra allocation, copying the command buffer,
>>> freeing memory without actual trace. In order to fix that we should
>>> do something like
>>> if (trace_event_get_state(TRACE_HANDLE_QMP_COMMAND)) {
>>> req_json = qobject_to_json(req);
>>> trace_handle_qmp_command(mon, req_json);
>>> QDECREF(req_json);
>>> }
>>> which is possible, but at our (me + Vova) opinion is ugly.
>>> That is why we are proposing to switch to macro, which
>>> will not require such tweaking.
>>> Arguments will be only evaluated when necessary and we
>>> will not have side-effects if the tracepoint is compile time
>>> enabled and run-time disabled.
>>> Though if the code above is acceptable, we can send the
>>> patch with it. No problem.
>> I completely get your point, but:
>> 
>> * I'm not sure it will have much of a performance impact.
>> * It is not obvious what's going to happen just by looking at the code of the
>> calling site.
>> 
>> I prefer to minimize the use of macros, even if that makes a few trace event
>> calls to be a bit more verbose, as in your example above. Also, I quite dislike
>> the new style you propose:
>> 
>> trace_handle_qmp_command(mon,
>> qstring_get_str(req_json = qobject_to_json(req)));
>> QDECREF(req_json);
>> 
>> 
>> Cheers,
>> Lluis
> This is a matter of overall performance. For example I can have 500 VMs.
> In order to manage them, f.e. tweak balloon I have to collect statistics.
> This happens 1 time/10 sec/VM. Libvirt issues the following

> 494665@1486641285.213042:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-balloon"
> 494665@1486641285.214181:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "qom-get"
> 494665@1486641285.214792:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-hotpluggable-cpus"
> 494665@1486641285.215283:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-cpus"
> 494665@1486641285.216153:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-blockstats"
> 494665@1486641285.216827:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-block"

> We will have 300 commands in a second in all VMs. This is not that small
> load. OK. I do think that I'll lost 2-3-5 percents of one host CPU due
> to this allocation/free/copy. There are no measurements unfortunately.
> At my opinion this matters.

Sorry for beating the point, but I just want to make sure we're on the same
page. The example above (with the state check) and the one you propose in your
patch have exactly the same performance.

The change is then only in coding style, and I think the macros you propose make
the code harder to understand:

  trace_handle_qmp_command(mon,
                           qstring_get_str(req_json = qobject_to_json(req)));
  QDECREF(req_json);

If qobject_to_json() had any side-effect, it is not obvious why it would happen
only when tracing of that event is dynaically enabled. IMO that's a recipe for
errors.


Cheers,
  Lluis

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Stefan Hajnoczi]

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

On Mon, Jul 24, 2017 at 07:32:29PM +0300, Lluís Vilanova wrote:
> Denis V Lunev writes:
> 
> > On 07/24/2017 05:43 PM, Lluís Vilanova wrote:
> >> Denis V Lunev writes:
> >> 
> >>> On 07/24/2017 02:34 PM, Stefan Hajnoczi wrote:
> >>>> On Fri, Jul 21, 2017 at 05:31:47PM +0300, Vladimir Sementsov-Ogievskiy wrote:
> >>>>> Current trace system have a drawback: parameters of trace functions
> >>>>> are calculated even if corresponding tracepoint is disabled. Also, it
> >>>>> looks like trace function are not actually inlined by compiler (at
> >>>>> least for me).
> >>>>> 
> >>>>> Here is a fix proposal: move from function call to macros. Patch 02
> >>>>> is an example, of how to reduce extra calculations with help of
> >>>>> patch 01.
> >>>>> 
> >>>>> Vladimir Sementsov-Ogievskiy (2):
> >>>>> trace: do not calculate arguments for disabled trace-points
> >>>>> monitor: improve tracing in handle_qmp_command
> >>>> Please use the TRACE_FOO_ENABLED macro instead of putting computation
> >>>> inside the trace event arguments.  This makes the code cleaner and
> >>>> easier to read.
> >>> At our opinion this ENABLED is compile time check while the option
> >>> could be tuned in runtime. Thus normally it would normally be
> >>> enabled while the trace is silent.
> >>> So, under load, we will have extra allocation, copying the command buffer,
> >>> freeing memory without actual trace. In order to fix that we should
> >>> do something like
> >>> if (trace_event_get_state(TRACE_HANDLE_QMP_COMMAND)) {
> >>> req_json = qobject_to_json(req);
> >>> trace_handle_qmp_command(mon, req_json);
> >>> QDECREF(req_json);
> >>> }
> >>> which is possible, but at our (me + Vova) opinion is ugly.
> >>> That is why we are proposing to switch to macro, which
> >>> will not require such tweaking.
> >>> Arguments will be only evaluated when necessary and we
> >>> will not have side-effects if the tracepoint is compile time
> >>> enabled and run-time disabled.
> >>> Though if the code above is acceptable, we can send the
> >>> patch with it. No problem.
> >> I completely get your point, but:
> >> 
> >> * I'm not sure it will have much of a performance impact.
> >> * It is not obvious what's going to happen just by looking at the code of the
> >> calling site.
> >> 
> >> I prefer to minimize the use of macros, even if that makes a few trace event
> >> calls to be a bit more verbose, as in your example above. Also, I quite dislike
> >> the new style you propose:
> >> 
> >> trace_handle_qmp_command(mon,
> >> qstring_get_str(req_json = qobject_to_json(req)));
> >> QDECREF(req_json);
> >> 
> >> 
> >> Cheers,
> >> Lluis
> > This is a matter of overall performance. For example I can have 500 VMs.
> > In order to manage them, f.e. tweak balloon I have to collect statistics.
> > This happens 1 time/10 sec/VM. Libvirt issues the following
> 
> > 494665@1486641285.213042:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-balloon"
> > 494665@1486641285.214181:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "qom-get"
> > 494665@1486641285.214792:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-hotpluggable-cpus"
> > 494665@1486641285.215283:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-cpus"
> > 494665@1486641285.216153:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-blockstats"
> > 494665@1486641285.216827:handle_qmp_command mon 0x7f7fbce6bea0 cmd_name "query-block"
> 
> > We will have 300 commands in a second in all VMs. This is not that small
> > load. OK. I do think that I'll lost 2-3-5 percents of one host CPU due
> > to this allocation/free/copy. There are no measurements unfortunately.
> > At my opinion this matters.
> 
> Sorry for beating the point, but I just want to make sure we're on the same
> page. The example above (with the state check) and the one you propose in your
> patch have exactly the same performance.
> 
> The change is then only in coding style, and I think the macros you propose make
> the code harder to understand:
> 
>   trace_handle_qmp_command(mon,
>                            qstring_get_str(req_json = qobject_to_json(req)));
>   QDECREF(req_json);
> 
> If qobject_to_json() had any side-effect, it is not obvious why it would happen
> only when tracing of that event is dynaically enabled. IMO that's a recipe for
> errors.

I agree and this is why I said "cleaner and easier to read".  Side
effects in macro/function arguments are prone to bugs.

Stefan

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

Re: [Qemu-devel] [PATCH 0/2] improve tracing

[Philippe Mathieu-Daudé]

On 07/24/2017 09:17 AM, Denis V. Lunev wrote:
> On 07/24/2017 02:34 PM, Stefan Hajnoczi wrote:
>> On Fri, Jul 21, 2017 at 05:31:47PM +0300, Vladimir Sementsov-Ogievskiy wrote:
>>> Current trace system have a drawback: parameters of trace functions
>>> are calculated even if corresponding tracepoint is disabled. Also, it
>>> looks like trace function are not actually inlined by compiler (at
>>> least for me).
>>>
>>> Here is a fix proposal: move from function call to macros. Patch 02
>>> is an example, of how to reduce extra calculations with help of
>>> patch 01.
>>>
>>> Vladimir Sementsov-Ogievskiy (2):
>>>    trace: do not calculate arguments for disabled trace-points
>>>    monitor: improve tracing in handle_qmp_command
>> Please use the TRACE_FOO_ENABLED macro instead of putting computation
>> inside the trace event arguments.  This makes the code cleaner and
>> easier to read.
> At our opinion this ENABLED is compile time check while the option
> could be tuned in runtime. Thus normally it would normally be
> enabled while the trace is silent.
> 
> So, under load, we will have extra allocation, copying the command buffer,
> freeing memory without actual trace. In order to fix that we should
> do something like
> 
> if (trace_event_get_state(TRACE_HANDLE_QMP_COMMAND)) {
>     req_json = qobject_to_json(req);
>     trace_handle_qmp_command(mon, req_json);
>     QDECREF(req_json);
> }
> 
> which is possible, but at our (me + Vova) opinion is ugly.

It seems to me much cleaner/easier to read than your patch, I really 
prefer this way. It is so nice/useful that it deserves to be starred as 
an example in docs/devel/tracing.txt :)

> That is why we are proposing to switch to macro, which
> will not require such tweaking.
> 
> Arguments will be only evaluated when necessary and we
> will not have side-effects if the tracepoint is compile time
> enabled and run-time disabled.
> 
> Though if the code above is acceptable, we can send the
> patch with it. No problem.
> 
> Den