This is v2 of the histogram sorting error message patchset. The code is the same as v1 - this version only adds new Fixes:, Reviewed-by:, and Reported-by: tags. Text from original post: Hi, These patches add some improvements for histogram sorting, addressing some shortcomings pointed out by Masami. In order to address the specific problem pointed out by Masami, as well as add additional related error messages, the first patch does some simplification of assignment parsing. The second patch actually adds the new error messages. The fourth patch adds a new testcase for hist trigger parsing, similar to the same kind of tests for kprobes and uprobes. Additional tests covering all possible hist trigger errors should/will be added here in the future. The third patch just adds a missing hist: prefix to the error log so that the testcases work properly, and which should have been there anyway. Thanks, Tom The following changes since commit a124692b698b00026a58d89831ceda2331b2e1d0: ftrace: Enable trampoline when rec count returns back to one (2019-05-25 23:04:43 -0400) are available in the git repository at: git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace-hist-sort-err-msgs-v2 Tom Zanussi (4): tracing: Simplify assignment parsing for hist triggers tracing: Add hist trigger error messages for sort specification tracing: Add 'hist:' to hist trigger error log error string tracing: Add new testcases for hist trigger parsing errors kernel/trace/trace_events_hist.c | 94 +++++++++++----------- .../test.d/trigger/trigger-hist-syntax-errors.tc | 32 ++++++++ 2 files changed, 78 insertions(+), 48 deletions(-) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax-errors.tc -- 2.14.1
In the process of adding better error messages for sorting, I realized that strsep was being used incorrectly and some of the error paths I was expecting to be hit weren't and just fell through to the common invalid key error case. It also became obvious that for keyword assignments, it wasn't necessary to save the full assignment and reparse it later, and having a common empty-assignment check would also make more sense in terms of error processing. Change the code to fix these problems and simplify it for new error message changes in a subsequent patch. Fixes: e62347d24534 ("tracing: Add hist trigger support for user-defined sorting ('sort=' param)") Fixes: 7ef224d1d0e3 ("tracing: Add 'hist' event trigger command") Fixes: a4072fe85ba3 ("tracing: Add a clock attribute for hist triggers") Signed-off-by: Tom Zanussi <zanussi@kernel.org> Reported-by: Masami Hiramatsu <mhiramat@kernel.org> Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org> --- kernel/trace/trace_events_hist.c | 70 ++++++++++++++++------------------------ 1 file changed, 27 insertions(+), 43 deletions(-) diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c index ca6b0dff60c5..964d032f51c6 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -1985,12 +1985,6 @@ static int parse_map_size(char *str) unsigned long size, map_bits; int ret; - strsep(&str, "="); - if (!str) { - ret = -EINVAL; - goto out; - } - ret = kstrtoul(str, 0, &size); if (ret) goto out; @@ -2050,25 +2044,25 @@ static int parse_action(char *str, struct hist_trigger_attrs *attrs) static int parse_assignment(struct trace_array *tr, char *str, struct hist_trigger_attrs *attrs) { - int ret = 0; + int len, ret = 0; - if ((str_has_prefix(str, "key=")) || - (str_has_prefix(str, "keys="))) { - attrs->keys_str = kstrdup(str, GFP_KERNEL); + if ((len = str_has_prefix(str, "key=")) || + (len = str_has_prefix(str, "keys="))) { + attrs->keys_str = kstrdup(str + len, GFP_KERNEL); if (!attrs->keys_str) { ret = -ENOMEM; goto out; } - } else if ((str_has_prefix(str, "val=")) || - (str_has_prefix(str, "vals=")) || - (str_has_prefix(str, "values="))) { - attrs->vals_str = kstrdup(str, GFP_KERNEL); + } else if ((len = str_has_prefix(str, "val=")) || + (len = str_has_prefix(str, "vals=")) || + (len = str_has_prefix(str, "values="))) { + attrs->vals_str = kstrdup(str + len, GFP_KERNEL); if (!attrs->vals_str) { ret = -ENOMEM; goto out; } - } else if (str_has_prefix(str, "sort=")) { - attrs->sort_key_str = kstrdup(str, GFP_KERNEL); + } else if ((len = str_has_prefix(str, "sort="))) { + attrs->sort_key_str = kstrdup(str + len, GFP_KERNEL); if (!attrs->sort_key_str) { ret = -ENOMEM; goto out; @@ -2079,12 +2073,8 @@ static int parse_assignment(struct trace_array *tr, ret = -ENOMEM; goto out; } - } else if (str_has_prefix(str, "clock=")) { - strsep(&str, "="); - if (!str) { - ret = -EINVAL; - goto out; - } + } else if ((len = str_has_prefix(str, "clock="))) { + str += len; str = strstrip(str); attrs->clock = kstrdup(str, GFP_KERNEL); @@ -2092,8 +2082,8 @@ static int parse_assignment(struct trace_array *tr, ret = -ENOMEM; goto out; } - } else if (str_has_prefix(str, "size=")) { - int map_bits = parse_map_size(str); + } else if ((len = str_has_prefix(str, "size="))) { + int map_bits = parse_map_size(str + len); if (map_bits < 0) { ret = map_bits; @@ -2133,8 +2123,14 @@ parse_hist_trigger_attrs(struct trace_array *tr, char *trigger_str) while (trigger_str) { char *str = strsep(&trigger_str, ":"); + char *rhs; - if (strchr(str, '=')) { + rhs = strchr(str, '='); + if (rhs) { + if (!strlen(++rhs)) { + ret = -EINVAL; + goto free; + } ret = parse_assignment(tr, str, attrs); if (ret) goto free; @@ -4459,10 +4455,6 @@ static int create_val_fields(struct hist_trigger_data *hist_data, if (!fields_str) goto out; - strsep(&fields_str, "="); - if (!fields_str) - goto out; - for (i = 0, j = 1; i < TRACING_MAP_VALS_MAX && j < TRACING_MAP_VALS_MAX; i++) { field_str = strsep(&fields_str, ","); @@ -4557,10 +4549,6 @@ static int create_key_fields(struct hist_trigger_data *hist_data, if (!fields_str) goto out; - strsep(&fields_str, "="); - if (!fields_str) - goto out; - for (i = n_vals; i < n_vals + TRACING_MAP_KEYS_MAX; i++) { field_str = strsep(&fields_str, ","); if (!field_str) @@ -4718,12 +4706,6 @@ static int create_sort_keys(struct hist_trigger_data *hist_data) if (!fields_str) goto out; - strsep(&fields_str, "="); - if (!fields_str) { - ret = -EINVAL; - goto out; - } - for (i = 0; i < TRACING_MAP_SORT_KEYS_MAX; i++) { struct hist_field *hist_field; char *field_str, *field_name; @@ -4732,9 +4714,11 @@ static int create_sort_keys(struct hist_trigger_data *hist_data) sort_key = &hist_data->sort_keys[i]; field_str = strsep(&fields_str, ","); - if (!field_str) { - if (i == 0) - ret = -EINVAL; + if (!field_str) + break; + + if (!*field_str) { + ret = -EINVAL; break; } @@ -4744,7 +4728,7 @@ static int create_sort_keys(struct hist_trigger_data *hist_data) } field_name = strsep(&field_str, "."); - if (!field_name) { + if (!field_name || !*field_name) { ret = -EINVAL; break; } -- 2.14.1
Add error codes and messages for all the error paths leading to sort specification parsing errors. Signed-off-by: Tom Zanussi <zanussi@kernel.org> Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org> --- kernel/trace/trace_events_hist.c | 21 +++++++++++++++++---- 1 file changed, 17 insertions(+), 4 deletions(-) diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c index 964d032f51c6..d33c94a1cfa9 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -61,7 +61,12 @@ C(INVALID_SUBSYS_EVENT, "Invalid subsystem or event name"), \ C(INVALID_REF_KEY, "Using variable references in keys not supported"), \ C(VAR_NOT_FOUND, "Couldn't find variable"), \ - C(FIELD_NOT_FOUND, "Couldn't find field"), + C(FIELD_NOT_FOUND, "Couldn't find field"), \ + C(EMPTY_ASSIGNMENT, "Empty assignment"), \ + C(INVALID_SORT_MODIFIER,"Invalid sort modifier"), \ + C(EMPTY_SORT_FIELD, "Empty sort field"), \ + C(TOO_MANY_SORT_FIELDS, "Too many sort fields (Max = 2)"), \ + C(INVALID_SORT_FIELD, "Sort field must be a key or a val"), #undef C #define C(a, b) HIST_ERR_##a @@ -2129,6 +2134,7 @@ parse_hist_trigger_attrs(struct trace_array *tr, char *trigger_str) if (rhs) { if (!strlen(++rhs)) { ret = -EINVAL; + hist_err(tr, HIST_ERR_EMPTY_ASSIGNMENT, errpos(str)); goto free; } ret = parse_assignment(tr, str, attrs); @@ -4680,7 +4686,7 @@ static int create_hist_fields(struct hist_trigger_data *hist_data, return ret; } -static int is_descending(const char *str) +static int is_descending(struct trace_array *tr, const char *str) { if (!str) return 0; @@ -4691,11 +4697,14 @@ static int is_descending(const char *str) if (strcmp(str, "ascending") == 0) return 0; + hist_err(tr, HIST_ERR_INVALID_SORT_MODIFIER, errpos((char *)str)); + return -EINVAL; } static int create_sort_keys(struct hist_trigger_data *hist_data) { + struct trace_array *tr = hist_data->event_file->tr; char *fields_str = hist_data->attrs->sort_key_str; struct tracing_map_sort_key *sort_key; int descending, ret = 0; @@ -4719,10 +4728,12 @@ static int create_sort_keys(struct hist_trigger_data *hist_data) if (!*field_str) { ret = -EINVAL; + hist_err(tr, HIST_ERR_EMPTY_SORT_FIELD, errpos("sort=")); break; } if ((i == TRACING_MAP_SORT_KEYS_MAX - 1) && fields_str) { + hist_err(tr, HIST_ERR_TOO_MANY_SORT_FIELDS, errpos("sort=")); ret = -EINVAL; break; } @@ -4730,11 +4741,12 @@ static int create_sort_keys(struct hist_trigger_data *hist_data) field_name = strsep(&field_str, "."); if (!field_name || !*field_name) { ret = -EINVAL; + hist_err(tr, HIST_ERR_EMPTY_SORT_FIELD, errpos("sort=")); break; } if (strcmp(field_name, "hitcount") == 0) { - descending = is_descending(field_str); + descending = is_descending(tr, field_str); if (descending < 0) { ret = descending; break; @@ -4756,7 +4768,7 @@ static int create_sort_keys(struct hist_trigger_data *hist_data) if (strcmp(field_name, test_name) == 0) { sort_key->field_idx = idx; - descending = is_descending(field_str); + descending = is_descending(tr, field_str); if (descending < 0) { ret = descending; goto out; @@ -4767,6 +4779,7 @@ static int create_sort_keys(struct hist_trigger_data *hist_data) } if (j == hist_data->n_fields) { ret = -EINVAL; + hist_err(tr, HIST_ERR_INVALID_SORT_FIELD, errpos(field_name)); break; } } -- 2.14.1
The 'hist:' prefix gets stripped from the command text during command processing, but should be added back when displaying the command during error processing. Not only because it's what should be displayed but also because not having it means the test cases fail because the caret is miscalculated by the length of the prefix string. Signed-off-by: Tom Zanussi <zanussi@kernel.org> Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org> --- kernel/trace/trace_events_hist.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c index d33c94a1cfa9..79768f22d5c5 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -607,7 +607,8 @@ static void last_cmd_set(struct trace_event_file *file, char *str) if (!str) return; - strncpy(last_cmd, str, MAX_FILTER_STR_VAL - 1); + strcpy(last_cmd, "hist:"); + strncat(last_cmd, str, MAX_FILTER_STR_VAL - 1 - sizeof("hist:")); if (file) { call = file->event_call; -- 2.14.1
Add a testcase ensuring that the tracing error_log correctly displays hist trigger parsing errors. Signed-off-by: Tom Zanussi <zanussi@kernel.org> Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org> --- .../test.d/trigger/trigger-hist-syntax-errors.tc | 32 ++++++++++++++++++++++ 1 file changed, 32 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax-errors.tc diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax-errors.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax-errors.tc new file mode 100644 index 000000000000..d44087a2f3d1 --- /dev/null +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax-errors.tc @@ -0,0 +1,32 @@ +#!/bin/sh +# SPDX-License-Identifier: GPL-2.0 +# description: event trigger - test histogram parser errors + +if [ ! -f set_event -o ! -d events/kmem ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f events/kmem/kmalloc/trigger ]; then + echo "event trigger is not supported" + exit_unsupported +fi + +if [ ! -f events/kmem/kmalloc/hist ]; then + echo "hist trigger is not supported" + exit_unsupported +fi + +[ -f error_log ] || exit_unsupported + +check_error() { # command-with-error-pos-by-^ + ftrace_errlog_check 'hist:kmem:kmalloc' "$1" 'events/kmem/kmalloc/trigger' +} + +check_error 'hist:keys=common_pid:vals=bytes_req:sort=common_pid,^junk' # INVALID_SORT_FIELD +check_error 'hist:keys=common_pid:vals=bytes_req:^sort=' # EMPTY_ASSIGNMENT +check_error 'hist:keys=common_pid:vals=bytes_req:^sort=common_pid,' # EMPTY_SORT_FIELD +check_error 'hist:keys=common_pid:vals=bytes_req:sort=common_pid.^junk' # INVALID_SORT_MODIFIER +check_error 'hist:keys=common_pid:vals=bytes_req,bytes_alloc:^sort=common_pid,bytes_req,bytes_alloc' # TOO_MANY_SORT_FIELDS + +exit 0 -- 2.14.1
On Fri, 28 Jun 2019 12:40:23 -0500 Tom Zanussi <zanussi@kernel.org> wrote: > Add a testcase ensuring that the tracing error_log correctly displays > hist trigger parsing errors. Hi Tom, I noticed that I never applied these patches (just did), but I also notice that this test case fails. Can you have a look on my ftrace/core branch: git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git Thanks, -- Steve > > Signed-off-by: Tom Zanussi <zanussi@kernel.org> > Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org> > --- > .../test.d/trigger/trigger-hist-syntax-errors.tc | 32 ++++++++++++++++++++++ > 1 file changed, 32 insertions(+) > create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax-errors.tc > > diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax-errors.tc b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax-errors.tc > new file mode 100644 > index 000000000000..d44087a2f3d1 > --- /dev/null > +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax-errors.tc > @@ -0,0 +1,32 @@ > +#!/bin/sh > +# SPDX-License-Identifier: GPL-2.0 > +# description: event trigger - test histogram parser errors > + > +if [ ! -f set_event -o ! -d events/kmem ]; then > + echo "event tracing is not supported" > + exit_unsupported > +fi > + > +if [ ! -f events/kmem/kmalloc/trigger ]; then > + echo "event trigger is not supported" > + exit_unsupported > +fi > + > +if [ ! -f events/kmem/kmalloc/hist ]; then > + echo "hist trigger is not supported" > + exit_unsupported > +fi > + > +[ -f error_log ] || exit_unsupported > + > +check_error() { # command-with-error-pos-by-^ > + ftrace_errlog_check 'hist:kmem:kmalloc' "$1" 'events/kmem/kmalloc/trigger' > +} > + > +check_error 'hist:keys=common_pid:vals=bytes_req:sort=common_pid,^junk' # INVALID_SORT_FIELD > +check_error 'hist:keys=common_pid:vals=bytes_req:^sort=' # EMPTY_ASSIGNMENT > +check_error 'hist:keys=common_pid:vals=bytes_req:^sort=common_pid,' # EMPTY_SORT_FIELD > +check_error 'hist:keys=common_pid:vals=bytes_req:sort=common_pid.^junk' # INVALID_SORT_MODIFIER > +check_error 'hist:keys=common_pid:vals=bytes_req,bytes_alloc:^sort=common_pid,bytes_req,bytes_alloc' # TOO_MANY_SORT_FIELDS > + > +exit 0
Hi Steve, On Wed, 2020-01-29 at 09:22 -0500, Steven Rostedt wrote: > On Fri, 28 Jun 2019 12:40:23 -0500 > Tom Zanussi <zanussi@kernel.org> wrote: > > > Add a testcase ensuring that the tracing error_log correctly > > displays > > hist trigger parsing errors. > > Hi Tom, > > I noticed that I never applied these patches (just did), but I also > notice that this test case fails. > > Can you have a look on my ftrace/core branch: > > git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux- > trace.git > All the trigger testcases are passing for me, including this one: # ./ftracetest test.d/trigger/trigger-hist-syntax-errors.tc === Ftrace unit tests === [1] event trigger - test histogram parser errors [PASS] # of passed: 1 # of failed: 0 # of unresolved: 0 # of untested: 0 # of unsupported: 0 # of xfailed: 0 # of undefined(test bug): 0 Tom > Thanks, > > -- Steve > > > > > Signed-off-by: Tom Zanussi <zanussi@kernel.org> > > Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org> > > --- > > .../test.d/trigger/trigger-hist-syntax-errors.tc | 32 > > ++++++++++++++++++++++ > > 1 file changed, 32 insertions(+) > > create mode 100644 > > tools/testing/selftests/ftrace/test.d/trigger/trigger-hist-syntax- > > errors.tc > > > > diff --git a/tools/testing/selftests/ftrace/test.d/trigger/trigger- > > hist-syntax-errors.tc > > b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist- > > syntax-errors.tc > > new file mode 100644 > > index 000000000000..d44087a2f3d1 > > --- /dev/null > > +++ b/tools/testing/selftests/ftrace/test.d/trigger/trigger-hist- > > syntax-errors.tc > > @@ -0,0 +1,32 @@ > > +#!/bin/sh > > +# SPDX-License-Identifier: GPL-2.0 > > +# description: event trigger - test histogram parser errors > > + > > +if [ ! -f set_event -o ! -d events/kmem ]; then > > + echo "event tracing is not supported" > > + exit_unsupported > > +fi > > + > > +if [ ! -f events/kmem/kmalloc/trigger ]; then > > + echo "event trigger is not supported" > > + exit_unsupported > > +fi > > + > > +if [ ! -f events/kmem/kmalloc/hist ]; then > > + echo "hist trigger is not supported" > > + exit_unsupported > > +fi > > + > > +[ -f error_log ] || exit_unsupported > > + > > +check_error() { # command-with-error-pos-by-^ > > + ftrace_errlog_check 'hist:kmem:kmalloc' "$1" > > 'events/kmem/kmalloc/trigger' > > +} > > + > > +check_error > > 'hist:keys=common_pid:vals=bytes_req:sort=common_pid,^junk' > > # INVALID_SORT_FIELD > > +check_error 'hist:keys=common_pid:vals=bytes_req:^sort=' > > # EMPTY_ASSIGNMENT > > +check_error > > 'hist:keys=common_pid:vals=bytes_req:^sort=common_pid,' # > > EMPTY_SORT_FIELD > > +check_error > > 'hist:keys=common_pid:vals=bytes_req:sort=common_pid.^junk' > > # INVALID_SORT_MODIFIER > > +check_error > > 'hist:keys=common_pid:vals=bytes_req,bytes_alloc:^sort=common_pid,b > > ytes_req,bytes_alloc' # TOO_MANY_SORT_FIELDS > > + > > +exit 0 > >
[-- Attachment #1: Type: text/plain, Size: 513 bytes --] On Wed, 29 Jan 2020 08:44:27 -0600 Tom Zanussi <zanussi@kernel.org> wrote: > All the trigger testcases are passing for me, including this one: > > # ./ftracetest test.d/trigger/trigger-hist-syntax-errors.tc > === Ftrace unit tests === > [1] event trigger - test histogram parser errors [PASS] > > > # of passed: 1 > # of failed: 0 > # of unresolved: 0 > # of untested: 0 > # of unsupported: 0 > # of xfailed: 0 > # of undefined(test bug): 0 Strange, can you try with the attached config? -- Steve [-- Attachment #2: config.gz --] [-- Type: application/gzip, Size: 33636 bytes --]
On Wed, 29 Jan 2020 09:53:50 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:
> On Wed, 29 Jan 2020 08:44:27 -0600
> Tom Zanussi <zanussi@kernel.org> wrote:
>
> > All the trigger testcases are passing for me, including this one:
> >
> > # ./ftracetest test.d/trigger/trigger-hist-syntax-errors.tc
> > === Ftrace unit tests ===
> > [1] event trigger - test histogram parser errors [PASS]
> >
> >
> > # of passed: 1
> > # of failed: 0
> > # of unresolved: 0
> > # of untested: 0
> > # of unsupported: 0
> > # of xfailed: 0
> > # of undefined(test bug): 0
>
> Strange, can you try with the attached config?
>
Never mind. After checking out one branch and then back to this one, it
appears to work!
-- Steve