[Qemu-devel] [PATCH for-2.9] mirror: Fix backwards mirror_yield parameters

[Qemu-devel] [PATCH for-2.9] mirror: Fix backwards mirror_yield parameters

[Eric Blake]

trace-events lists the parameters for mirror_yield consistently
with other events (cnt just after s, like in mirror_before_sleep;
in_flight last, like in mirror_yield_in_flight).  But the callers
were passing parameters in the wrong order, leading to poor trace
messages, including type truncation when there are more than 4G
dirty sectors involved.

Signed-off-by: Eric Blake <eblake@redhat.com>
---
 block/mirror.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/block/mirror.c b/block/mirror.c
index 4f3a5cb..1c403c5 100644
--- a/block/mirror.c
+++ b/block/mirror.c
@@ -633,7 +633,7 @@ static int coroutine_fn mirror_dirty_init(MirrorBlockJob *s)
             }

             if (s->in_flight >= MAX_IN_FLIGHT) {
-                trace_mirror_yield(s, s->in_flight, s->buf_free_count, -1);
+                trace_mirror_yield(s, -1, s->buf_free_count, s->in_flight);
                 mirror_wait_for_io(s);
                 continue;
             }
@@ -808,7 +808,7 @@ static void coroutine_fn mirror_run(void *opaque)
             s->common.iostatus == BLOCK_DEVICE_IO_STATUS_OK) {
             if (s->in_flight >= MAX_IN_FLIGHT || s->buf_free_count == 0 ||
                 (cnt == 0 && s->in_flight > 0)) {
-                trace_mirror_yield(s, s->in_flight, s->buf_free_count, cnt);
+                trace_mirror_yield(s, cnt, s->buf_free_count, s->in_flight);
                 mirror_wait_for_io(s);
                 continue;
             } else if (cnt != 0) {
-- 
2.9.3

Re: [Qemu-devel] [PATCH for-2.9] mirror: Fix backwards mirror_yield parameters

[Eric Blake]

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

[adding Stefan in cc, as trace maintainer]

On 03/09/2017 09:15 PM, Eric Blake wrote:

Perhaps I should update the subject to mention trace?

> trace-events lists the parameters for mirror_yield consistently
> with other events (cnt just after s, like in mirror_before_sleep;
> in_flight last, like in mirror_yield_in_flight).  But the callers
> were passing parameters in the wrong order, leading to poor trace
> messages, including type truncation when there are more than 4G
> dirty sectors involved.
> 
> Signed-off-by: Eric Blake <eblake@redhat.com>
> ---
>  block/mirror.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/block/mirror.c b/block/mirror.c
> index 4f3a5cb..1c403c5 100644
> --- a/block/mirror.c
> +++ b/block/mirror.c
> @@ -633,7 +633,7 @@ static int coroutine_fn mirror_dirty_init(MirrorBlockJob *s)
>              }
> 
>              if (s->in_flight >= MAX_IN_FLIGHT) {
> -                trace_mirror_yield(s, s->in_flight, s->buf_free_count, -1);
> +                trace_mirror_yield(s, -1, s->buf_free_count, s->in_flight);
>                  mirror_wait_for_io(s);
>                  continue;
>              }
> @@ -808,7 +808,7 @@ static void coroutine_fn mirror_run(void *opaque)
>              s->common.iostatus == BLOCK_DEVICE_IO_STATUS_OK) {
>              if (s->in_flight >= MAX_IN_FLIGHT || s->buf_free_count == 0 ||
>                  (cnt == 0 && s->in_flight > 0)) {
> -                trace_mirror_yield(s, s->in_flight, s->buf_free_count, cnt);
> +                trace_mirror_yield(s, cnt, s->buf_free_count, s->in_flight);
>                  mirror_wait_for_io(s);
>                  continue;
>              } else if (cnt != 0) {
> 

-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

Re: [Qemu-devel] [PATCH for-2.9] mirror: Fix backwards mirror_yield parameters

[Eric Blake]

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

On 03/09/2017 09:25 PM, Eric Blake wrote:
> [adding Stefan in cc, as trace maintainer]
> 
> On 03/09/2017 09:15 PM, Eric Blake wrote:
> 
> Perhaps I should update the subject to mention trace?
> 
>> trace-events lists the parameters for mirror_yield consistently
>> with other events (cnt just after s, like in mirror_before_sleep;
>> in_flight last, like in mirror_yield_in_flight).  But the callers
>> were passing parameters in the wrong order, leading to poor trace
>> messages, including type truncation when there are more than 4G
>> dirty sectors involved.

I traced it back to commit bd48bde. And I started auditing for more,
finding at least a bad caller to trace_megasas_iovec_underflow since
commit e8f943ce, so I'll be submitting a v2 that turns this into a
full-blown series.

My v2 will turn on -Wformat checking to catch any more instances of type
mismatch between callers and trace-events (I'm turning up LOTS of places
where the caller and trace-events disagree on types, leading to silent
truncation such as a caller's uint64_t passed to the trace's uint32_t),
so it's turning into rather a large series.  The obvious wrong
parameters and probably even the type mismatch cleanups are probably 2.9
material (although many of the things I'm fixing have been wrong in 2.8
or earlier, and are not necessarily 2.9 regressions), but the code to
actually enable -Wformat flagging may best be left for 2.10 material,
since there may be latent type mismatches in files that I'm not
compiling due to my configure/installed-library settings, but which
would break builds for others (we'll see what the buildbots say, at any
rate).  Stay tuned for v2...

Oh, how am I enabling -Wformat checking, you ask?  Our existing code
generates:

static inline void trace_foo(int param)
{
    if (cond) {
         do stuff, including with the log tracer...
         qemu_log_mask(LOG_TRACE, "%d@%zd.%06zd:mirror_start " "bs %p s
%p opaque %p" "\n", ..., param);
    }
}

and qemu-log_mask() already does -Wformat checking - but ONLY for the
types declared as the parameters to trace_foo.  It is NOT detecting type
mismatches at the caller, such as if I call trace_foo(my_long).

So my trick: I taught the generator to output the inline trace_foo() as
before, but now follow it up with:

#define trace_foo(...) \
  do { \
    if (0) { \
      printf(<format> "\n", ## __VA_ARGS__); \
    } \
    trace_foo(__VA_ARGS__); \
  } while (0)

which creates a dead-code printf for the desired compile-time type
validations, using the format from the trace-events file.

And here's where I'm stuck: the makefiles are broken.  Touching
scripts/tracetool/format/h.py does NOT cause tracetool to be re-run by a
mere 'make'; I've had to resort to 'make -B block/trace.h-timestamp' to
get things to rebuild.  And this is in spite of the fact that h.py
_should_ be getting listed in $(tracetool-y) by trace/Makefile.objs, and
$(tracetool-y) is listed as a dependency of %/trace.h-timestamp in the
top-level Makefile.  I would appreciate anyone with advice or an idea on
how to patch Makefile to get the dependency working without me having to
manually kick it.

-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 604 bytes --]

Re: [Qemu-devel] [PATCH for-2.9] mirror: Fix backwards mirror_yield parameters

[Stefan Hajnoczi]

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

On Fri, Mar 10, 2017 at 02:49:22PM -0600, Eric Blake wrote:
> On 03/09/2017 09:25 PM, Eric Blake wrote:
> > [adding Stefan in cc, as trace maintainer]
> > 
> > On 03/09/2017 09:15 PM, Eric Blake wrote:
> > 
> > Perhaps I should update the subject to mention trace?
> > 
> >> trace-events lists the parameters for mirror_yield consistently
> >> with other events (cnt just after s, like in mirror_before_sleep;
> >> in_flight last, like in mirror_yield_in_flight).  But the callers
> >> were passing parameters in the wrong order, leading to poor trace
> >> messages, including type truncation when there are more than 4G
> >> dirty sectors involved.
> 
> I traced it back to commit bd48bde. And I started auditing for more,
> finding at least a bad caller to trace_megasas_iovec_underflow since
> commit e8f943ce, so I'll be submitting a v2 that turns this into a
> full-blown series.
> 
> My v2 will turn on -Wformat checking to catch any more instances of type
> mismatch between callers and trace-events (I'm turning up LOTS of places
> where the caller and trace-events disagree on types, leading to silent
> truncation such as a caller's uint64_t passed to the trace's uint32_t),
> so it's turning into rather a large series.  The obvious wrong
> parameters and probably even the type mismatch cleanups are probably 2.9
> material (although many of the things I'm fixing have been wrong in 2.8
> or earlier, and are not necessarily 2.9 regressions), but the code to
> actually enable -Wformat flagging may best be left for 2.10 material,
> since there may be latent type mismatches in files that I'm not
> compiling due to my configure/installed-library settings, but which
> would break builds for others (we'll see what the buildbots say, at any
> rate).  Stay tuned for v2...
> 
> Oh, how am I enabling -Wformat checking, you ask?  Our existing code
> generates:
> 
> static inline void trace_foo(int param)
> {
>     if (cond) {
>          do stuff, including with the log tracer...
>          qemu_log_mask(LOG_TRACE, "%d@%zd.%06zd:mirror_start " "bs %p s
> %p opaque %p" "\n", ..., param);
>     }
> }
> 
> and qemu-log_mask() already does -Wformat checking - but ONLY for the
> types declared as the parameters to trace_foo.  It is NOT detecting type
> mismatches at the caller, such as if I call trace_foo(my_long).
> 
> So my trick: I taught the generator to output the inline trace_foo() as
> before, but now follow it up with:
> 
> #define trace_foo(...) \
>   do { \
>     if (0) { \
>       printf(<format> "\n", ## __VA_ARGS__); \
>     } \
>     trace_foo(__VA_ARGS__); \
>   } while (0)
> 
> which creates a dead-code printf for the desired compile-time type
> validations, using the format from the trace-events file.
> 
> And here's where I'm stuck: the makefiles are broken.  Touching
> scripts/tracetool/format/h.py does NOT cause tracetool to be re-run by a
> mere 'make'; I've had to resort to 'make -B block/trace.h-timestamp' to
> get things to rebuild.  And this is in spite of the fact that h.py
> _should_ be getting listed in $(tracetool-y) by trace/Makefile.objs, and
> $(tracetool-y) is listed as a dependency of %/trace.h-timestamp in the
> top-level Makefile.  I would appreciate anyone with advice or an idea on
> how to patch Makefile to get the dependency working without me having to
> manually kick it.

Also CCing Daniel Berrange.  He recently touched the tracing Makefiles
and may have ideas.

Stefan

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

Re: [Qemu-devel] [PATCH for-2.9] mirror: Fix backwards mirror_yield parameters

[Daniel P. Berrange]

On Wed, Mar 15, 2017 at 06:18:35PM +0800, Stefan Hajnoczi wrote:
> On Fri, Mar 10, 2017 at 02:49:22PM -0600, Eric Blake wrote:
> > And here's where I'm stuck: the makefiles are broken.  Touching
> > scripts/tracetool/format/h.py does NOT cause tracetool to be re-run by a
> > mere 'make'; I've had to resort to 'make -B block/trace.h-timestamp' to
> > get things to rebuild.  And this is in spite of the fact that h.py
> > _should_ be getting listed in $(tracetool-y) by trace/Makefile.objs, and
> > $(tracetool-y) is listed as a dependency of %/trace.h-timestamp in the
> > top-level Makefile.  I would appreciate anyone with advice or an idea on
> > how to patch Makefile to get the dependency working without me having to
> > manually kick it.
> 
> Also CCing Daniel Berrange.  He recently touched the tracing Makefiles
> and may have ideas.

I've been looking at this and I'm damned if I understand what's broken.
All the required dependancies look to be expressed in the Makefile

  %/trace.h: %/trace.h-timestamp
  %/trace.h-timestamp: $(SRC_PATH)/%/trace-events $(tracetool-y)

and $(tracetool-y) expands to the list of source files

  tracetool-y = $(SRC_PATH)/scripts/tracetool.py
  tracetool-y += $(shell find $(SRC_PATH)/scripts/tracetool -name "*.py")


If I do 'touch hw/net/trace-events', then hw/net/trace.h gets rebuilt,
but if do 'touch scripts/tracetool.py' it doesn't get built. So somehow
make seems to be dropping the $(tracetool-y) deps despite being listed
against the %/trace-h-timestamp file, and despite earlier deps on
trace-events being honoured

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://entangle-photo.org       -o-    http://search.cpan.org/~danberr/ :|

Re: [Qemu-devel] [PATCH for-2.9] mirror: Fix backwards mirror_yield parameters

[Daniel P. Berrange]

On Wed, Mar 15, 2017 at 10:26:44AM +0000, Daniel P. Berrange wrote:
> On Wed, Mar 15, 2017 at 06:18:35PM +0800, Stefan Hajnoczi wrote:
> > On Fri, Mar 10, 2017 at 02:49:22PM -0600, Eric Blake wrote:
> > > And here's where I'm stuck: the makefiles are broken.  Touching
> > > scripts/tracetool/format/h.py does NOT cause tracetool to be re-run by a
> > > mere 'make'; I've had to resort to 'make -B block/trace.h-timestamp' to
> > > get things to rebuild.  And this is in spite of the fact that h.py
> > > _should_ be getting listed in $(tracetool-y) by trace/Makefile.objs, and
> > > $(tracetool-y) is listed as a dependency of %/trace.h-timestamp in the
> > > top-level Makefile.  I would appreciate anyone with advice or an idea on
> > > how to patch Makefile to get the dependency working without me having to
> > > manually kick it.
> > 
> > Also CCing Daniel Berrange.  He recently touched the tracing Makefiles
> > and may have ideas.
> 
> I've been looking at this and I'm damned if I understand what's broken.
> All the required dependancies look to be expressed in the Makefile
> 
>   %/trace.h: %/trace.h-timestamp
>   %/trace.h-timestamp: $(SRC_PATH)/%/trace-events $(tracetool-y)
> 
> and $(tracetool-y) expands to the list of source files
> 
>   tracetool-y = $(SRC_PATH)/scripts/tracetool.py
>   tracetool-y += $(shell find $(SRC_PATH)/scripts/tracetool -name "*.py")
> 
> 
> If I do 'touch hw/net/trace-events', then hw/net/trace.h gets rebuilt,
> but if do 'touch scripts/tracetool.py' it doesn't get built. So somehow
> make seems to be dropping the $(tracetool-y) deps despite being listed
> against the %/trace-h-timestamp file, and despite earlier deps on
> trace-events being honoured

Oh this is a fun one.  While the $(tracetool-y) variable *is* defined at
the time the build rules execute, it is *not* defined at the time make
evaluates dependancies, so it expanded to be empty ! I copied you on
the easy fix

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://entangle-photo.org       -o-    http://search.cpan.org/~danberr/ :|

Re: [Qemu-devel] [PATCH for-2.9] mirror: Fix backwards mirror_yield parameters

[Stefan Hajnoczi]

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

On Wed, Mar 15, 2017 at 10:59:24AM +0000, Daniel P. Berrange wrote:
> On Wed, Mar 15, 2017 at 10:26:44AM +0000, Daniel P. Berrange wrote:
> > On Wed, Mar 15, 2017 at 06:18:35PM +0800, Stefan Hajnoczi wrote:
> > > On Fri, Mar 10, 2017 at 02:49:22PM -0600, Eric Blake wrote:
> > > > And here's where I'm stuck: the makefiles are broken.  Touching
> > > > scripts/tracetool/format/h.py does NOT cause tracetool to be re-run by a
> > > > mere 'make'; I've had to resort to 'make -B block/trace.h-timestamp' to
> > > > get things to rebuild.  And this is in spite of the fact that h.py
> > > > _should_ be getting listed in $(tracetool-y) by trace/Makefile.objs, and
> > > > $(tracetool-y) is listed as a dependency of %/trace.h-timestamp in the
> > > > top-level Makefile.  I would appreciate anyone with advice or an idea on
> > > > how to patch Makefile to get the dependency working without me having to
> > > > manually kick it.
> > > 
> > > Also CCing Daniel Berrange.  He recently touched the tracing Makefiles
> > > and may have ideas.
> > 
> > I've been looking at this and I'm damned if I understand what's broken.
> > All the required dependancies look to be expressed in the Makefile
> > 
> >   %/trace.h: %/trace.h-timestamp
> >   %/trace.h-timestamp: $(SRC_PATH)/%/trace-events $(tracetool-y)
> > 
> > and $(tracetool-y) expands to the list of source files
> > 
> >   tracetool-y = $(SRC_PATH)/scripts/tracetool.py
> >   tracetool-y += $(shell find $(SRC_PATH)/scripts/tracetool -name "*.py")
> > 
> > 
> > If I do 'touch hw/net/trace-events', then hw/net/trace.h gets rebuilt,
> > but if do 'touch scripts/tracetool.py' it doesn't get built. So somehow
> > make seems to be dropping the $(tracetool-y) deps despite being listed
> > against the %/trace-h-timestamp file, and despite earlier deps on
> > trace-events being honoured
> 
> Oh this is a fun one.  While the $(tracetool-y) variable *is* defined at
> the time the build rules execute, it is *not* defined at the time make
> evaluates dependancies, so it expanded to be empty ! I copied you on
> the easy fix

Nice find, thanks for the help!

Stefan

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