| Message ID | 20170310031521.630-1-eblake@redhat.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
[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) { >
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.
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
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
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
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
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) {
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(-)