tracing: Hist trigger snapshot and onchange additions
Subsystems (4)
v7 cover tracing: Hist trigger snapshot and onchange additions
From: Tom Zanussi <[email protected]>
Hi,
This is v7 of the hist trigger snapshot and onchange additions patchset. It does a bit of refactoring to address the suggestions made by Masami in v6.
It also adds an additional patch to update the trigger/inter-event testcases with SPDX license blurbs.
BTW, I noticed that with the recent kselftest changes, I now get mangled output when running the selftests, though I can still see well enough that the tests passed as expected. This happens with any of the ftrace selftests and not just the trigger selftests. In my case, this is using the stock Terminal in Ubuntu 17.10, in case that helps. Example output:
# ./ftracetest test.d/trigger/
-e === Ftrace unit tests ===
-e -n [1] event trigger - test inter-event histogram trigger expected fail actions
-e [\e[31mXFAIL\e[0m]
-e -n [2] event trigger - test extended error support
-e [\e[32mPASS\e[0m]
-e -n [3] event trigger - test field variable support
-e [\e[32mPASS\e[0m]
-e -n [4] event trigger - test inter-event combined histogram trigger
-e [\e[32mPASS\e[0m]
-e -n [5] event trigger - test multiple actions on hist trigger
-e [\e[32mPASS\e[0m]
.
.
.
-e
-e # of passed: 31
-e # of failed: 0
-e # of unresolved: 0
-e # of untested: 0
-e # of unsupported: 0
-e # of xfailed: 1
-e # of undefined(test bug): 0
v6->v7 changes:
- Removed unnecessary HANDLER_ONMAX checks from onmax_print()/create()
- Moved handler assignment to acion_parse()
- Changed goto in ATION_TRACE case in action_create() to return
- Changed EINVAL to EEXIST in action_create() ACTION_SAVE case
- Made the return logic in create_actions() more consistent
- Merged 'tracing: Move hist trigger key printing into a separate function' into 'tracing: Add hist trigger snapshot() action'
- Updated the new snapshot, onchange, and trace test cases to match 4.20 kselftest changes.
- Added new xfail test case that make sure certain unsupported handler/action combinations fail as expected.
- While updating the test cases, realized that the other testcases in the inter-event subdir needed SPDX license updates, so added them.
v5->v6 changes:
- Added new Documentation patch explaining handler.action
- Added new README patch explaining handler.action
- Added separate snapshot() Documentation
- Added new snapshot() test case
- Updated README with snapshote()
- Added separate onchange() Documentation
- Added separate onchange() test case
- Updated README with onchange()
- Added separate trace() test case
- Updated README with trace() and <synthetic_event>() syntax
v4->v5 changes:
- added 'trace' keyword test case
- added 'onchange' handler test case
v3->v4 changes:
- added 'trace' keyword for generating synthetic events
- fix elt_data leak
- changed cond_update to cond_update_fn_t
v2->v3 changes:
- fixed problem where trace actions were only being allowed for onmatch handlers - now trace actions can be used with any handler.
- fixed problem where no action was being assigned to onmatch handlers if save or snapshot actions were specified.
v1->v2 changes:
- added missing tracing_cond_snapshot_data() definition for when CONFIG_TRACER_SNAPSHOT not defined
- removed an unnecessary WARN_ON() in track_data_snapshot_print()
Original text:
This patchset adds some useful new functions to the hist trigger code: a snapshot action and an onchange handler.
In order to make it easier to add these and in the process make the code more generic, I separated the code into explicit 'handlers' and 'actions', handlers being things like 'onmax' and 'onchange', and 'actions' being things like 'take a snapshot' or 'save some fields'.
The first few patches do that basic refactoring, which make it easier to add the subsequent changes that arbitrarily combine actions and handlers.
The fourth patch adds a 'conditional snapshot' capability that via a new tracing_snaphot_cond() function extends the existing snapshot code. It allows the caller to associate some user data with the snapshot that can be checked and saved in an update() callback whose return value determines whether the snapshot should be taken or not.
The remaining patches finally add the new snapshot action and onchange handler functionality - please see those patches for details and some examples.
Thanks,
Tom
The following changes since commit ee474b81fe5aa5dc0faae920bf66240fbf55f891:
tracing/kprobes: Fix strpbrk() argument order (2018-11-05 09:47:14 -0500)
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/hist-snapshot-onchange-v7
Tom Zanussi (16):
tracing: Refactor hist trigger action code
tracing: Make hist trigger Documentation better reflect
actions/handlers
tracing: Add hist trigger handler.action documentation to README
tracing: Split up onmatch action data
tracing: Generalize hist trigger onmax and save action
tracing: Add conditional snapshot
tracing: Add hist trigger snapshot() action
tracing: Add hist trigger snapshot() action Documentation
tracing: Add hist trigger snapshot() action test case
tracing: Add hist trigger onchange() handler
tracing: Add hist trigger onchange() handler Documentation
tracing: Add hist trigger onchange() handler test case
tracing: Add alternative synthetic event trace action syntax
tracing: Add alternative synthetic event trace action test case
tracing: Add hist trigger action 'expected fail' test case
tracing: Add SPDX license GPL-2.0 license identifier to inter-event
testcases
Documentation/trace/histogram.rst | 285 +++++- kernel/trace/trace.c | 177 +++- kernel/trace/trace.h | 56 +- kernel/trace/trace_events_hist.c | 1062 +++++++++++++++----- kernel/trace/trace_events_trigger.c | 2 +- kernel/trace/trace_sched_wakeup.c | 2 +- .../inter-event/trigger-action-hist-xfail.tc | 30 + .../inter-event/trigger-extended-error-support.tc | 1 + .../inter-event/trigger-field-variable-support.tc | 1 + .../trigger-inter-event-combined-hist.tc | 1 + .../inter-event/trigger-multi-actions-accept.tc | 1 + .../inter-event/trigger-onchange-action-hist.tc | 28 + .../inter-event/trigger-onmatch-action-hist.tc | 1 + .../trigger-onmatch-onmax-action-hist.tc | 1 + .../inter-event/trigger-onmax-action-hist.tc | 1 + .../inter-event/trigger-snapshot-action-hist.tc | 43 + .../trigger-synthetic-event-createremove.tc | 1 + .../inter-event/trigger-trace-action-hist.tc | 42 + 18 files changed, 1433 insertions(+), 302 deletions(-) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-action-hist-xfail.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onchange-action-hist.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-trace-action-hist.tc
Signature · 1 line
2.14.1
PATCH v7 1/16 tracing: Refactor hist trigger action code
From: Tom Zanussi <[email protected]>
The hist trigger action code currently implements two essentially hard-coded pairs of 'actions' - onmax(), which tracks a variable and saves some event fields when a max is hit, and onmatch(), which is hard-coded to generate a synthetic event.
These hardcoded pairs (track max/save fields and detect match/generate synthetic event) should really be decoupled into separate components that can then be arbitrarily combined. The first component of each pair (track max/detect match) is called a 'handler' in the new code, while the second component (save fields/generate synthetic event) is called an 'action' in this scheme.
This change refactors the action code to reflect this split by adding two handlers, HANDLER_ONMATCH and HANDLER_ONMAX, along with two actions, ACTION_SAVE and ACTION_TRACE.
The new code combines them to produce the existing ONMATCH/TRACE and ONMAX/SAVE functionality, but doesn't implement the other combinations now possible. Future patches will expand these to further useful cases, such as ONMAX/TRACE, as well as add additional handlers and actions such as ONCHANGE and SNAPSHOT.
--- kernel/trace/trace_events_hist.c | 395 +++++++++++++++++++++++---------------- 1 file changed, 232 insertions(+), 163 deletions(-)
kernel/trace/trace_events_hist.c +232 -163
@@ -287,9 +287,9 @@ struct hist_trigger_data {struct field_var_hist *field_var_hists[SYNTH_FIELDS_MAX ];unsigned int n_field_var_hists; -struct field_var *max_vars[SYNTH_FIELDS_MAX ]; -unsigned int n_max_vars; -unsigned int n_max_var_str; +struct field_var *save_vars[SYNTH_FIELDS_MAX ]; +unsigned int n_save_vars; +unsigned int n_save_var_str; };struct synth_field {
@@ -319,8 +319,22 @@ typedef void (*action_fn_t) (struct hist_trigger_data *hist_data,struct ring_buffer_event *rbe, struct action_data *data, u64 *var_ref_vals); +enum handler_id { +HANDLER_ONMATCH =1 , +HANDLER_ONMAX , +}; + +enum action_id { +ACTION_SAVE =1 , +ACTION_TRACE , +}; +struct action_data { +enum handler_id handler; +enum action_id action; +char *action_name;action_fn_t fn; +unsigned int n_params;char *params[SYNTH_FIELDS_MAX ];
@@ -329,13 +343,11 @@ struct action_data {unsigned int var_ref_idx;char *match_event;char *match_event_system; -char *synth_event_name;struct synth_event *synth_event; } onmatch;struct {char *var_str; -char *fn_name;unsigned int max_var_ref_idx;struct hist_field *max_var;struct hist_field *var;
@@ -1571,7 +1583,7 @@ find_match_var(struct hist_trigger_data *hist_data, char *var_name)for (i =0 ; i < hist_data->n_actions; i++) {struct action_data *data = hist_data->actions[i]; -if (data->fn == action_trace) { +if (data->handler ==HANDLER_ONMATCH ) {char *system = data->onmatch.match_event_system;char *event_name = data->onmatch.match_event;
@@ -2003,7 +2015,7 @@ static int hist_trigger_elt_data_alloc(struct tracing_map_elt *elt) } } - n_str = hist_data->n_field_var_str + hist_data->n_max_var_str; + n_str = hist_data->n_field_var_str + hist_data->n_save_var_str; size =STR_VAR_LEN_MAX ;
@@ -2945,7 +2957,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,int ret;if (target_hist_data->n_field_var_hists >=SYNTH_FIELDS_MAX ) { -hist_err_event ("onmatch: Too many field variables defined: " , +hist_err_event ("trace action: Too many field variables defined: " , subsys_name, event_name, field_name);return ERR_PTR (-EINVAL ); }
@@ -2953,7 +2965,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data, file =event_file (tr, subsys_name, event_name);if (IS_ERR (file)) { -hist_err_event ("onmatch: Event file not found: " , +hist_err_event ("trace action: Event file not found: " , subsys_name, event_name, field_name); ret =PTR_ERR (file);return ERR_PTR (ret);
@@ -2967,7 +2979,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,*/ hist_data =find_compatible_hist (target_hist_data, file);if (!hist_data) { -hist_err_event ("onmatch: Matching event histogram not found: " , +hist_err_event ("trace action: Matching event histogram not found: " , subsys_name, event_name, field_name);return ERR_PTR (-EINVAL ); }
@@ -3029,7 +3041,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,kfree (cmd);kfree (var_hist->cmd);kfree (var_hist); -hist_err_event ("onmatch: Couldn't create histogram for field: " , +hist_err_event ("trace action: Couldn't create histogram for field: " , subsys_name, event_name, field_name);return ERR_PTR (ret); }
@@ -3042,7 +3054,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,if (IS_ERR_OR_NULL (event_var)) {kfree (var_hist->cmd);kfree (var_hist); -hist_err_event ("onmatch: Couldn't find synthetic variable: " , +hist_err_event ("trace action: Couldn't find synthetic variable: " , subsys_name, event_name, field_name);return ERR_PTR (-EINVAL ); }
@@ -3125,8 +3137,8 @@ static void update_max_vars(struct hist_trigger_data *hist_data,struct ring_buffer_event *rbe, void *rec) { - __update_field_vars(elt, rbe, rec, hist_data->max_vars, - hist_data->n_max_vars, hist_data->n_field_var_str); + __update_field_vars(elt, rbe, rec, hist_data->save_vars, + hist_data->n_save_vars, hist_data->n_field_var_str); } static struct hist_field *create_var(struct hist_trigger_data *hist_data,
@@ -3270,9 +3282,9 @@ static void onmax_print(struct seq_file *m,seq_printf (m,"\n\tmax: %10llu" ,tracing_map_read_var (elt, max_idx)); -for (i =0 ; i < hist_data->n_max_vars; i++) { -struct hist_field *save_val = hist_data->max_vars[i]->val; -struct hist_field *save_var = hist_data->max_vars[i]->var; +for (i =0 ; i < hist_data->n_save_vars; i++) { +struct hist_field *save_val = hist_data->save_vars[i]->val; +struct hist_field *save_var = hist_data->save_vars[i]->var;u64 val; save_var_idx = save_var->var.idx;
@@ -3316,7 +3328,7 @@ static void onmax_destroy(struct action_data *data)destroy_hist_field (data->onmax.var,0 );kfree (data->onmax.var_str); -kfree (data->onmax.fn_name); +kfree (data->action_name);for (i =0 ; i < data->n_params; i++)kfree (data->params[i]);
@@ -3324,16 +3336,17 @@ static void onmax_destroy(struct action_data *data)kfree (data); } +static int action_create (struct hist_trigger_data *hist_data, +struct action_data *data); +static int onmax_create (struct hist_trigger_data *hist_data,struct action_data *data) { +struct hist_field *var_field, *ref_field, *max_var =NULL ;struct trace_event_file *file = hist_data->event_file; -struct hist_field *var_field, *ref_field, *max_var;unsigned int var_ref_idx = hist_data->n_var_refs; -struct field_var *field_var; -char *onmax_var_str, *param; +char *onmax_var_str;unsigned long flags; -unsigned int i;int ret =0 ; onmax_var_str = data->onmax.var_str;
@@ -3363,8 +3376,8 @@ static int onmax_create(struct hist_trigger_data *hist_data, ref_field->var_ref_idx = hist_data->n_var_refs++; data->onmax.var = ref_field; - data->fn = onmax_save; data->onmax.max_var_ref_idx = var_ref_idx; + max_var =create_var (hist_data, file,"max" ,sizeof (u64),"u64" );if (IS_ERR (max_var)) {hist_err ("onmax: Couldn't create onmax variable: " ,"max" );
@@ -3373,27 +3386,7 @@ static int onmax_create(struct hist_trigger_data *hist_data, } data->onmax.max_var = max_var; -for (i =0 ; i < data->n_params; i++) { - param =kstrdup (data->params[i],GFP_KERNEL ); -if (!param) { - ret = -ENOMEM ; - goto out; - } - - field_var =create_target_field_var (hist_data,NULL ,NULL , param); -if (IS_ERR (field_var)) { -hist_err ("onmax: Couldn't create field variable: " , param); - ret =PTR_ERR (field_var); -kfree (param); - goto out; - } - - hist_data->max_vars[hist_data->n_max_vars++] = field_var; -if (field_var->val->flags &HIST_FIELD_FL_STRING ) - hist_data->n_max_var_str++; - -kfree (param); - } + ret =action_create (hist_data, data); out:return ret; }
@@ -3404,11 +3397,14 @@ static int parse_action_params(char *params, struct action_data *data)int ret =0 ;while (params) { -if (data->n_params >=SYNTH_FIELDS_MAX ) +if (data->n_params >=SYNTH_FIELDS_MAX ) { +hist_err ("Too many action params" ,"" ); goto out; + } param =strsep (¶ms,"," );if (!param) { +hist_err ("No action param found" ,"" ); ret = -EINVAL ; goto out; }
@@ -3432,10 +3428,71 @@ static int parse_action_params(char *params, struct action_data *data)return ret; } -static struct action_data *onmax_parse (char *str) +static int action_parse (char *str,struct action_data *data, +enum handler_id handler) +{ +char *action_name; +int ret =0 ; + +strsep (&str,"." ); +if (!str) { +hist_err ("action parsing: No action found" ,"" ); + ret = -EINVAL ; + goto out; + } + + action_name =strsep (&str,"(" ); +if (!action_name || !str) { +hist_err ("action parsing: No action found" ,"" ); + ret = -EINVAL ; + goto out; + } + +if (strncmp (action_name,"save" ,strlen ("save" )) ==0 ) { +char *params =strsep (&str,")" ); + +if (!params) { +hist_err ("action parsing: No params found for %s" ,"save" ); + ret = -EINVAL ; + goto out; + } + + ret =parse_action_params (params, data); +if (ret) + goto out; + +if (handler ==HANDLER_ONMAX ) + data->fn = onmax_save; + + data->action =ACTION_SAVE ; + }else { +char *params =strsep (&str,")" ); + +if (params) { + ret =parse_action_params (params, data); +if (ret) + goto out; + } + + data->fn = action_trace; + data->action =ACTION_TRACE ; + } + + data->action_name =kstrdup (action_name,GFP_KERNEL ); +if (!data->action_name) { + ret = -ENOMEM ; + goto out; + } + + data->handler = handler; + out: +return ret; +} + +static struct action_data *onmax_parse (char *str,enum handler_id handler) { -char *onmax_fn_name, *onmax_var_str;struct action_data *data; +char *onmax_var_str;int ret = -EINVAL ; data =kzalloc (sizeof (*data),GFP_KERNEL );
@@ -3454,33 +3511,9 @@ static struct action_data *onmax_parse(char *str) goto free; } -strsep (&str,"." ); -if (!str) - goto free; - - onmax_fn_name =strsep (&str,"(" ); -if (!onmax_fn_name || !str) - goto free; - -if (strncmp (onmax_fn_name,"save" ,strlen ("save" )) ==0 ) { -char *params =strsep (&str,")" ); - -if (!params) { - ret = -EINVAL ; - goto free; - } - - ret =parse_action_params (params, data); -if (ret) - goto free; - }else - goto free; - - data->onmax.fn_name =kstrdup (onmax_fn_name,GFP_KERNEL ); -if (!data->onmax.fn_name) { - ret = -ENOMEM ; + ret =action_parse (str, data, handler); +if (ret) goto free; - } out:return data; free:
@@ -3497,7 +3530,7 @@ static void onmatch_destroy(struct action_data *data)kfree (data->onmatch.match_event);kfree (data->onmatch.match_event_system); -kfree (data->onmatch.synth_event_name); +kfree (data->action_name);for (i =0 ; i < data->n_params; i++)kfree (data->params[i]);
@@ -3574,8 +3607,9 @@ static int check_synth_field(struct synth_event *event, }static struct hist_field * -onmatch_find_var (struct hist_trigger_data *hist_data,struct action_data *data, -char *system,char *event,char *var) +trace_action_find_var (struct hist_trigger_data *hist_data, +struct action_data *data, +char *system,char *event,char *var) {struct hist_field *hist_field;
@@ -3583,7 +3617,7 @@ onmatch_find_var(struct hist_trigger_data *hist_data, struct action_data *data, hist_field =find_target_event_var (hist_data, system, event, var);if (!hist_field) { -if (!system) { +if (!system && data->handler ==HANDLER_ONMATCH ) { system = data->onmatch.match_event_system; event = data->onmatch.match_event; }
@@ -3592,15 +3626,15 @@ onmatch_find_var(struct hist_trigger_data *hist_data, struct action_data *data, }if (!hist_field) -hist_err_event ("onmatch: Couldn't find onmatch param: $" , system, event, var); +hist_err_event ("trace action: Couldn't find param: $" , system, event, var);return hist_field; }static struct hist_field * -onmatch_create_field_var (struct hist_trigger_data *hist_data, -struct action_data *data,char *system, -char *event,char *var) +trace_action_create_field_var (struct hist_trigger_data *hist_data, +struct action_data *data,char *system, +char *event,char *var) {struct hist_field *hist_field =NULL ;struct field_var *field_var;
@@ -3623,7 +3657,7 @@ onmatch_create_field_var(struct hist_trigger_data *hist_data,* looking for fields on the onmatch(system.event.xxx) * event. */ -if (!system) { +if (!system && data->handler ==HANDLER_ONMATCH ) { system = data->onmatch.match_event_system; event = data->onmatch.match_event; }
@@ -3647,9 +3681,8 @@ onmatch_create_field_var(struct hist_trigger_data *hist_data, goto out; } -static int onmatch_create (struct hist_trigger_data *hist_data, -struct trace_event_file *file, -struct action_data *data) +static int trace_action_create (struct hist_trigger_data *hist_data, +struct action_data *data) {char *event_name, *param, *system =NULL ;struct hist_field *hist_field, *var_ref;
@@ -3659,12 +3692,14 @@ static int onmatch_create(struct hist_trigger_data *hist_data,int ret =0 ;mutex_lock (&synth_event_mutex); - event =find_synth_event (data->onmatch.synth_event_name); + + event =find_synth_event (data->action_name);if (!event) { -hist_err ("onmatch: Couldn't find synthetic event: " , data->onmatch.synth_event_name); +hist_err ("trace action: Couldn't find synthetic event: " , data->action_name);mutex_unlock (&synth_event_mutex);return -EINVAL ; } + event->ref++;mutex_unlock (&synth_event_mutex);
@@ -3693,13 +3728,15 @@ static int onmatch_create(struct hist_trigger_data *hist_data, }if (param[0 ] =='$' ) - hist_field =onmatch_find_var (hist_data, data, system, - event_name, param); + hist_field =trace_action_find_var (hist_data, data, + system, event_name, + param);else - hist_field =onmatch_create_field_var (hist_data, data, - system, - event_name, - param); + hist_field =trace_action_create_field_var (hist_data, + data, + system, + event_name, + param);if (!hist_field) {kfree (p);
@@ -3721,7 +3758,7 @@ static int onmatch_create(struct hist_trigger_data *hist_data,continue ; } -hist_err_event ("onmatch: Param type doesn't match synthetic event field type: " , +hist_err_event ("trace action: Param type doesn't match synthetic event field type: " , system, event_name, param);kfree (p); ret = -EINVAL ;
@@ -3729,12 +3766,11 @@ static int onmatch_create(struct hist_trigger_data *hist_data, }if (field_pos != event->n_fields) { -hist_err ("onmatch: Param count doesn't match synthetic event field count: " , event->name); +hist_err ("trace action: Param count doesn't match synthetic event field count: " , event->name); ret = -EINVAL ; goto err; } - data->fn = action_trace; data->onmatch.synth_event = event; data->onmatch.var_ref_idx = var_ref_idx; out:
@@ -3747,10 +3783,58 @@ static int onmatch_create(struct hist_trigger_data *hist_data, goto out; } +static int action_create (struct hist_trigger_data *hist_data, +struct action_data *data) +{ +struct field_var *field_var; +unsigned int i; +char *param; +int ret =0 ; + +if (data->action ==ACTION_TRACE ) +return trace_action_create (hist_data, data); + +if (data->action ==ACTION_SAVE ) { +if (hist_data->n_save_vars) { + ret = -EEXIST ; +hist_err ("save action: Can't have more than one save() action per hist" ,"" ); + goto out; + } + +for (i =0 ; i < data->n_params; i++) { + param =kstrdup (data->params[i],GFP_KERNEL ); +if (!param) { + ret = -ENOMEM ; + goto out; + } + + field_var =create_target_field_var (hist_data,NULL ,NULL , param); +if (IS_ERR (field_var)) { +hist_err ("save action: Couldn't create field variable: " , param); + ret =PTR_ERR (field_var); +kfree (param); + goto out; + } + + hist_data->save_vars[hist_data->n_save_vars++] = field_var; +if (field_var->val->flags &HIST_FIELD_FL_STRING ) + hist_data->n_save_var_str++; +kfree (param); + } + } + out: +return ret; +} + +static int onmatch_create (struct hist_trigger_data *hist_data, +struct action_data *data) +{ +return action_create (hist_data, data); +} +static struct action_data *onmatch_parse (struct trace_array *tr,char *str) {char *match_event, *match_event_system; -char *synth_event_name, *params;struct action_data *data;int ret = -EINVAL ;
@@ -3788,31 +3872,7 @@ static struct action_data *onmatch_parse(struct trace_array *tr, char *str) goto free; } -strsep (&str,"." ); -if (!str) { -hist_err ("onmatch: Missing . after onmatch(): " , str); - goto free; - } - - synth_event_name =strsep (&str,"(" ); -if (!synth_event_name || !str) { -hist_err ("onmatch: Missing opening paramlist paren: " , synth_event_name); - goto free; - } - - data->onmatch.synth_event_name =kstrdup (synth_event_name,GFP_KERNEL ); -if (!data->onmatch.synth_event_name) { - ret = -ENOMEM ; - goto free; - } - - params =strsep (&str,")" ); -if (!params || !str || (str &&strlen (str))) { -hist_err ("onmatch: Missing closing paramlist paren: " , params); - goto free; - } - - ret =parse_action_params (params, data); + ret =action_parse (str, data,HANDLER_ONMATCH );if (ret) goto free; out:
@@ -4252,9 +4312,9 @@ static void destroy_actions(struct hist_trigger_data *hist_data)for (i =0 ; i < hist_data->n_actions; i++) {struct action_data *data = hist_data->actions[i]; -if (data->fn == action_trace) +if (data->handler ==HANDLER_ONMATCH )onmatch_destroy (data); -else if (data->fn == onmax_save) +else if (data->handler ==HANDLER_ONMAX )onmax_destroy (data);else kfree (data);
@@ -4280,16 +4340,14 @@ static int parse_actions(struct hist_trigger_data *hist_data) ret =PTR_ERR (data);break ; } - data->fn = action_trace; }else if (strncmp (str,"onmax(" ,strlen ("onmax(" )) ==0 ) {char *action_str = str +strlen ("onmax(" ); - data =onmax_parse (action_str); + data =onmax_parse (action_str,HANDLER_ONMAX );if (IS_ERR (data)) { ret =PTR_ERR (data);break ; } - data->fn = onmax_save; }else { ret = -EINVAL ;break ;
@@ -4301,8 +4359,7 @@ static int parse_actions(struct hist_trigger_data *hist_data)return ret; } -static int create_actions (struct hist_trigger_data *hist_data, -struct trace_event_file *file) +static int create_actions (struct hist_trigger_data *hist_data) {struct action_data *data;unsigned int i;
@@ -4311,14 +4368,17 @@ static int create_actions(struct hist_trigger_data *hist_data,for (i =0 ; i < hist_data->attrs->n_actions; i++) { data = hist_data->actions[i]; -if (data->fn == action_trace) { - ret =onmatch_create (hist_data, file, data); +if (data->handler ==HANDLER_ONMATCH ) { + ret =onmatch_create (hist_data, data);if (ret) -return ret; - }else if (data->fn == onmax_save) { +break ; + }else if (data->handler ==HANDLER_ONMAX ) { ret =onmax_create (hist_data, data);if (ret) -return ret; +break ; + }else { + ret = -EINVAL ; +break ; } }
@@ -4334,26 +4394,42 @@ static void print_actions(struct seq_file *m,for (i =0 ; i < hist_data->n_actions; i++) {struct action_data *data = hist_data->actions[i]; -if (data->fn == onmax_save) +if (data->handler ==HANDLER_ONMAX )onmax_print (m, hist_data, elt, data); } } +static void print_action_spec (struct seq_file *m, +struct hist_trigger_data *hist_data, +struct action_data *data) +{ +unsigned int i; + +if (data->action ==ACTION_SAVE ) { +for (i =0 ; i < hist_data->n_save_vars; i++) { +seq_printf (m,"%s" , hist_data->save_vars[i]->var->var.name); +if (i < hist_data->n_save_vars -1 ) +seq_puts (m,"," ); + } + }else if (data->action ==ACTION_TRACE ) { +for (i =0 ; i < data->n_params; i++) { +if (i) +seq_puts (m,"," ); +seq_printf (m,"%s" , data->params[i]); + } + } +} +static void print_onmax_spec (struct seq_file *m,struct hist_trigger_data *hist_data,struct action_data *data) { -unsigned int i; -seq_puts (m,":onmax(" );seq_printf (m,"%s" , data->onmax.var_str); -seq_printf (m,").%s(" , data->onmax.fn_name); +seq_printf (m,").%s(" , data->action_name); + +print_action_spec (m, hist_data, data); -for (i =0 ; i < hist_data->n_max_vars; i++) { -seq_printf (m,"%s" , hist_data->max_vars[i]->var->var.name); -if (i < hist_data->n_max_vars -1 ) -seq_puts (m,"," ); - }seq_puts (m,")" ); }
@@ -4361,18 +4437,12 @@ static void print_onmatch_spec(struct seq_file *m, struct hist_trigger_data *hist_data, struct action_data *data) { - unsigned int i; - seq_printf(m, ":onmatch(%s.%s).", data->onmatch.match_event_system, data->onmatch.match_event); -seq_printf (m,"%s(" , data->onmatch.synth_event->name); +seq_printf (m,"%s(" , data->action_name); -for (i =0 ; i < data->n_params; i++) { -if (i) -seq_puts (m,"," ); -seq_printf (m,"%s" , data->params[i]); - } +print_action_spec (m, hist_data, data);seq_puts (m,")" ); }
@@ -4389,7 +4459,9 @@ static bool actions_match(struct hist_trigger_data *hist_data,struct action_data *data = hist_data->actions[i];struct action_data *data_test = hist_data_test->actions[i]; -if (data->fn != data_test->fn) +if (data->handler != data_test->handler) +return false; +if (data->action != data_test->action)return false;if (data->n_params != data_test->n_params)
@@ -4400,23 +4472,20 @@ static bool actions_match(struct hist_trigger_data *hist_data,return false; } -if (data->fn == action_trace) { -if (strcmp (data->onmatch.synth_event_name, - data_test->onmatch.synth_event_name) !=0 ) -return false; +if (strcmp (data->action_name, data_test->action_name) !=0 ) +return false; + +if (data->handler ==HANDLER_ONMATCH ) {if (strcmp (data->onmatch.match_event_system, data_test->onmatch.match_event_system) !=0 )return false;if (strcmp (data->onmatch.match_event, data_test->onmatch.match_event) !=0 )return false; - }else if (data->fn == onmax_save) { + }else if (data->handler ==HANDLER_ONMAX ) {if (strcmp (data->onmax.var_str, data_test->onmax.var_str) !=0 )return false; -if (strcmp (data->onmax.fn_name, - data_test->onmax.fn_name) !=0 ) -return false; } }
@@ -4432,9 +4501,9 @@ static void print_actions_spec(struct seq_file *m,for (i =0 ; i < hist_data->n_actions; i++) {struct action_data *data = hist_data->actions[i]; -if (data->fn == action_trace) +if (data->handler ==HANDLER_ONMATCH )print_onmatch_spec (m, hist_data, data); -else if (data->fn == onmax_save) +else if (data->handler ==HANDLER_ONMAX )print_onmax_spec (m, hist_data, data); } }
@@ -5611,7 +5680,7 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,if (has_hist_vars (hist_data))save_hist_vars (hist_data); - ret =create_actions (hist_data, file); + ret =create_actions (hist_data);if (ret) goto out_unreg;
Signature · 1 line
2.14.1
PATCH v7 2/16 tracing: Make hist trigger Documentation better reflect actions/handlers
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
The action/handler code refactoring didn't change the action/handler syntax, but did generalize it - the Documentation should reflect that.
--- Documentation/trace/histogram.rst | 56 ++++++++++++++++++++++++++++++--------- 1 file changed, 43 insertions(+), 13 deletions(-)
Documentation/trace/histogram.rst +43 -13
@@ -25,7 +25,7 @@ Documentation written by Tom Zanussi hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>] [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue] - [:clear][:name=histname1] [if <filter>] + [:clear][:name=histname1][:<handler>.<action>] [if <filter>] When a matching event is hit, an entry is added to a hash table using the key(s) and value(s) named. Keys and values correspond to
@@ -1831,21 +1831,51 @@ and looks and behaves just like any other event:: Like any other event, once a histogram is enabled for the event, the output can be displayed by reading the event's 'hist' file. -2.2.3 Hist trigger 'actions' ----------------------------- +2.2.3 Hist trigger 'handlers' and 'actions' +------------------------------------------- -A hist trigger 'action' is a function that's executed whenever a -histogram entry is added or updated. +A hist trigger 'action' is a function that's executed (in most cases +conditionally) whenever a histogram entry is added or updated. -The default 'action' if no special function is explicitly specified is -as it always has been, to simply update the set of values associated -with an entry. Some applications, however, may want to perform -additional actions at that point, such as generate another event, or -compare and save a maximum. +When a histogram entry is added or updated, a hist trigger 'handler' +is what decides whether the corresponding action is actually invoked +or not. -The following additional actions are available. To specify an action -for a given event, simply specify the action between colons in the -hist trigger specification. +Hist trigger handlers and actions are paired together in the general +form: + + <handler>.<action> + +To specify a handler.action pair for a given event, simply specify +that handler.action pair between colons in the hist trigger +specification. + +In theory, any handler can be combined with any action, but in +practice, not every handler.action combination is currently supported; +if a given handler.action combination isn't supported, the hist +trigger will fail with -EINVAL; + +The default 'handler.action' if none is explicity specified is as it +always has been, to simply update the set of values associated with an +entry. Some applications, however, may want to perform additional +actions at that point, such as generate another event, or compare and +save a maximum. + +The supported handlers and actions are listed below, and each is +described in more detail in the following paragraphs, in the context +of descriptions of some common and useful handler.action combinations. + +The available handlers are: + + - onmatch(matching.event) - invoke action on any addition or update + - onmax(var) - invoke action if var exceeds current max + +The available actions are: + + - <synthetic_event_name>(param list) - generate synthetic event + - save(field,...) - save current event fields + +The following commonly-used handler.action pairs are available: - onmatch(matching.event).<synthetic_event_name>(param list)
Signature · 1 line
2.14.1
PATCH v7 3/16 tracing: Add hist trigger handler.action documentation to README
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add abbreviated documentation for handlers and actions to README.
--- kernel/trace/trace.c | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-)
kernel/trace/trace.c +11 -1
@@ -4686,6 +4686,7 @@ static const char readme_msg[] ="\t [:size=#entries]\n" "\t [:pause][:continue][:clear]\n" "\t [:name=histname1]\n" +"\t [:<handler>.<action>]\n" "\t [if <filter>]\n\n" "\t When a matching event is hit, an entry is added to a hash\n" "\t table using the key(s) and value(s) named, and the value of a\n"
@@ -4727,7 +4728,16 @@ static const char readme_msg[] ="\t The enable_hist and disable_hist triggers can be used to\n" "\t have one event conditionally start and stop another event's\n" "\t already-attached hist trigger. The syntax is analagous to\n" - "\t the enable_event and disable_event triggers.\n" +"\t the enable_event and disable_event triggers.\n\n" +"\t Hist trigger handlers and actions are executed whenever a\n" +"\t a histogram entry is added or updated. They take the form:\n\n" +"\t <handler>.<action>\n\n" +"\t The available handlers are:\n\n" +"\t onmatch(matching.event) - invoke on addition or update\n" +"\t onmax(var) - invoke if var exceeds current max\n\n" +"\t The available actions are:\n\n" +"\t <synthetic_event>(param list) - generate synthetic event\n" + "\t save(field,...) - save current event fields\n"#endif ;
Signature · 1 line
2.14.1
PATCH v7 4/16 tracing: Split up onmatch action data
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Currently, the onmatch action data binds the onmatch action to data related to synthetic event generation. Since we want to allow the onmatch handler to potentially invoke a different action, and because we expect other handlers to generate synthetic events, we need to separate the data related to these two functions.
Also rename the onmatch data to something more descriptive, and create and use common action data destroy function.
--- kernel/trace/trace_events_hist.c | 91 ++++++++++++++++++++-------------------- 1 file changed, 46 insertions(+), 45 deletions(-)
kernel/trace/trace_events_hist.c +46 -45
@@ -338,13 +338,14 @@ struct action_data {unsigned int n_params;char *params[SYNTH_FIELDS_MAX ]; +unsigned int var_ref_idx; +struct synth_event *synth_event; +union {struct { -unsigned int var_ref_idx; -char *match_event; -char *match_event_system; -struct synth_event *synth_event; - } onmatch; +char *event; +char *event_system; + } match_data;struct {char *var_str;
@@ -1010,9 +1011,9 @@ static void action_trace(struct hist_trigger_data *hist_data,struct ring_buffer_event *rbe, struct action_data *data, u64 *var_ref_vals) { - struct synth_event *event = data->onmatch.synth_event; + struct synth_event *event = data->synth_event; -trace_synth (event, var_ref_vals, data->onmatch.var_ref_idx); +trace_synth (event, var_ref_vals, data->var_ref_idx); } struct hist_var_data {
@@ -1584,8 +1585,8 @@ find_match_var(struct hist_trigger_data *hist_data, char *var_name)struct action_data *data = hist_data->actions[i];if (data->handler ==HANDLER_ONMATCH ) { -char *system = data->onmatch.match_event_system; -char *event_name = data->onmatch.match_event; +char *system = data->match_data.event_system; +char *event_name = data->match_data.event; file =find_var_file (tr, system, event_name, var_name);if (!file)
@@ -3320,20 +3321,33 @@ static void onmax_save(struct hist_trigger_data *hist_data,update_max_vars (hist_data, elt, rbe, rec); } -static void onmax_destroy (struct action_data *data) +static void action_data_destroy (struct action_data *data) {unsigned int i; -destroy_hist_field (data->onmax.max_var,0 ); -destroy_hist_field (data->onmax.var,0 ); +mutex_lock (&synth_event_mutex); -kfree (data->onmax.var_str);kfree (data->action_name);for (i =0 ; i < data->n_params; i++)kfree (data->params[i]); +if (data->synth_event) + data->synth_event->ref--; +kfree (data); + +mutex_unlock (&synth_event_mutex); +} + +static void onmax_destroy (struct action_data *data) +{ +destroy_hist_field (data->onmax.max_var,0 ); +destroy_hist_field (data->onmax.var,0 ); + +kfree (data->onmax.var_str); + +action_data_destroy (data); } static int action_create(struct hist_trigger_data *hist_data,
@@ -3524,23 +3538,10 @@ static struct action_data *onmax_parse(char *str, enum handler_id handler)static void onmatch_destroy (struct action_data *data) { -unsigned int i; - -mutex_lock (&synth_event_mutex); - -kfree (data->onmatch.match_event); -kfree (data->onmatch.match_event_system); -kfree (data->action_name); +kfree (data->match_data.event); +kfree (data->match_data.event_system); -for (i =0 ; i < data->n_params; i++) -kfree (data->params[i]); - -if (data->onmatch.synth_event) - data->onmatch.synth_event->ref--; - -kfree (data); - -mutex_unlock (&synth_event_mutex); +action_data_destroy (data); }static void destroy_field_var (struct field_var *field_var)
@@ -3618,8 +3619,8 @@ trace_action_find_var(struct hist_trigger_data *hist_data, hist_field =find_target_event_var (hist_data, system, event, var);if (!hist_field) {if (!system && data->handler ==HANDLER_ONMATCH ) { - system = data->onmatch.match_event_system; - event = data->onmatch.match_event; + system = data->match_data.event_system; + event = data->match_data.event; } hist_field =find_event_var (hist_data, system, event, var);
@@ -3658,8 +3659,8 @@ trace_action_create_field_var(struct hist_trigger_data *hist_data,* event. */ if (!system && data->handler ==HANDLER_ONMATCH ) { - system = data->onmatch.match_event_system; - event = data->onmatch.match_event; + system = data->match_data.event_system; + event = data->match_data.event; }/*
@@ -3771,8 +3772,8 @@ static int trace_action_create(struct hist_trigger_data *hist_data, goto err; } - data->onmatch.synth_event = event; - data->onmatch.var_ref_idx = var_ref_idx; + data->synth_event = event; + data->var_ref_idx = var_ref_idx; out:return ret; err:
@@ -3860,14 +3861,14 @@ static struct action_data *onmatch_parse(struct trace_array *tr, char *str) goto free; } - data->onmatch.match_event =kstrdup (match_event,GFP_KERNEL ); -if (!data->onmatch.match_event) { + data->match_data.event =kstrdup (match_event,GFP_KERNEL ); +if (!data->match_data.event) { ret = -ENOMEM ; goto free; } - data->onmatch.match_event_system =kstrdup (match_event_system,GFP_KERNEL ); -if (!data->onmatch.match_event_system) { + data->match_data.event_system =kstrdup (match_event_system,GFP_KERNEL ); +if (!data->match_data.event_system) { ret = -ENOMEM ; goto free; }
@@ -4437,8 +4438,8 @@ static void print_onmatch_spec(struct seq_file *m, struct hist_trigger_data *hist_data, struct action_data *data) { - seq_printf(m, ":onmatch(%s.%s).", data->onmatch.match_event_system, - data->onmatch.match_event); + seq_printf(m, ":onmatch(%s.%s).", data->match_data.event_system, + data->match_data.event);seq_printf (m,"%s(" , data->action_name);
@@ -4476,11 +4477,11 @@ static bool actions_match(struct hist_trigger_data *hist_data,return false;if (data->handler ==HANDLER_ONMATCH ) { -if (strcmp (data->onmatch.match_event_system, - data_test->onmatch.match_event_system) !=0 ) +if (strcmp (data->match_data.event_system, + data_test->match_data.event_system) !=0 )return false; -if (strcmp (data->onmatch.match_event, - data_test->onmatch.match_event) !=0 ) +if (strcmp (data->match_data.event, + data_test->match_data.event) !=0 )return false; }else if (data->handler ==HANDLER_ONMAX ) { if (strcmp(data->onmax.var_str,
Signature · 1 line
2.14.1
PATCH v7 5/16 tracing: Generalize hist trigger onmax and save action
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
The action refactor code allowed actions and handlers to be separated, but the existing onmax handler and save action code is still not flexible enough to handle arbitrary coupling. This change generalizes them and in the process makes additional handlers and actions easier to implement.
The onmax action can be broken up and thought of as two separate components - a variable to be tracked (the parameter given to the onmax($var_to_track) function) and an invisible variable created to save the ongoing result of doing something with that variable, such as saving the max value of that variable so far seen.
Separating it out like this and renaming it appropriately allows us to use the same code for similar tracking functions such as onchange($var_to_track), which would just track the last value seen rather than the max seen so far, which is useful in some situations.
Additionally, because different handlers and actions may want to save and access data differently e.g. save and retrieve tracking values as local variables vs something more global, save_val() and get_val() interface functions are introduced and max-specific implementations are used instead.
The same goes for the code that checks whether a maximum has been hit
- a generic check_val() interface and max-checking implementation is used instead, which allows future patches to make use of he same code using their own implemetations of similar functionality.
--- kernel/trace/trace_events_hist.c | 225 ++++++++++++++++++++++++++------------- 1 file changed, 151 insertions(+), 74 deletions(-)
kernel/trace/trace_events_hist.c +151 -74
@@ -319,6 +319,15 @@ typedef void (*action_fn_t) (struct hist_trigger_data *hist_data,struct ring_buffer_event *rbe, struct action_data *data, u64 *var_ref_vals); +typedef bool (*check_track_val_fn_t ) (u64 track_val,u64 var_val); +typedef bool (*save_track_val_fn_t ) (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data, +unsigned int track_var_idx,u64 var_val); +typedef u64 (*get_track_val_fn_t ) (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data); +enum handler_id {HANDLER_ONMATCH =1 ,HANDLER_ONMAX ,
@@ -349,14 +358,18 @@ struct action_data {struct {char *var_str; -unsigned int max_var_ref_idx; -struct hist_field *max_var; -struct hist_field *var; - } onmax; +struct hist_field *var_ref; +unsigned int var_ref_idx; + +struct hist_field *track_var; + +check_track_val_fn_t check_val; +save_track_val_fn_t save_val; +get_track_val_fn_t get_val; + } track_data; }; }; -static char last_hist_cmd[MAX_FILTER_STR_VAL ];static char hist_err_str[MAX_FILTER_STR_VAL ];
@@ -3133,10 +3146,10 @@ static void update_field_vars(struct hist_trigger_data *hist_data, hist_data->n_field_vars, 0); } -static void update_max_vars (struct hist_trigger_data *hist_data, -struct tracing_map_elt *elt, -struct ring_buffer_event *rbe, -void *rec) +static void update_save_vars (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct ring_buffer_event *rbe, +void *rec) {__update_field_vars (elt, rbe, rec, hist_data->save_vars, hist_data->n_save_vars, hist_data->n_field_var_str);
@@ -3274,14 +3287,68 @@ create_target_field_var(struct hist_trigger_data *target_hist_data,return create_field_var (target_hist_data, file, var_name); } -static void onmax_print (struct seq_file *m, -struct hist_trigger_data *hist_data, -struct tracing_map_elt *elt, -struct action_data *data) +static bool check_track_val_max (u64 track_val,u64 var_val) { -unsigned int i, save_var_idx, max_idx = data->onmax.max_var->var.idx; +if (var_val <= track_val) +return false; + +return true; +} -seq_printf (m,"\n\tmax: %10llu" ,tracing_map_read_var (elt, max_idx)); +static u64 get_track_val_local (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data) +{ +unsigned int track_var_idx = data->track_data.track_var->var.idx; +u64 track_val; + + track_val =tracing_map_read_var (elt, track_var_idx); + +return track_val; +} + +static bool save_track_val_local (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data, +unsigned int track_var_idx,u64 var_val) +{ +bool ret = false; +u64 track_val; + + track_val =tracing_map_read_var (elt, track_var_idx); + +if (data->track_data.check_val (track_val, var_val)) { +tracing_map_set_var (elt, track_var_idx, var_val); + ret = true; + } + +return ret; +} + +static bool update_track_val (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data,u64 *var_ref_vals) +{ +unsigned int track_var_idx = data->track_data.track_var->var.idx; +unsigned int track_var_ref_idx = data->track_data.var_ref_idx; +u64 var_val; + + var_val = var_ref_vals[track_var_ref_idx]; + +return data->track_data.save_val (hist_data, elt, data, + track_var_idx, var_val); +} + +static void track_data_print (struct seq_file *m, +struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data) +{ +u64 track_val = data->track_data.get_val (hist_data, elt, data); +unsigned int i, save_var_idx; + +if (data->handler ==HANDLER_ONMAX ) +seq_printf (m,"\n\tmax: %10llu" , track_val);for (i =0 ; i < hist_data->n_save_vars; i++) {struct hist_field *save_val = hist_data->save_vars[i]->val;
@@ -3300,25 +3367,13 @@ static void onmax_print(struct seq_file *m, } } -static void onmax_save (struct hist_trigger_data *hist_data, -struct tracing_map_elt *elt,void *rec, -struct ring_buffer_event *rbe, -struct action_data *data,u64 *var_ref_vals) +static void ontrack_save (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt,void *rec, +struct ring_buffer_event *rbe, +struct action_data *data,u64 *var_ref_vals) { -unsigned int max_idx = data->onmax.max_var->var.idx; -unsigned int max_var_ref_idx = data->onmax.max_var_ref_idx; - -u64 var_val, max_val; - - var_val = var_ref_vals[max_var_ref_idx]; - max_val =tracing_map_read_var (elt, max_idx); - -if (var_val <= max_val) -return ; - -tracing_map_set_var (elt, max_idx, var_val); - -update_max_vars (hist_data, elt, rbe, rec); +if (update_track_val (hist_data, elt, data, var_ref_vals)) +update_save_vars (hist_data, elt, rbe, rec); }static void action_data_destroy (struct action_data *data)
@@ -3340,12 +3395,13 @@ static void action_data_destroy(struct action_data *data)mutex_unlock (&synth_event_mutex); } -static void onmax_destroy (struct action_data *data) +static void track_data_destroy (struct hist_trigger_data *hist_data, +struct action_data *data) { -destroy_hist_field (data->onmax.max_var,0 ); -destroy_hist_field (data->onmax.var,0 ); +destroy_hist_field (data->track_data.track_var,0 ); +destroy_hist_field (data->track_data.var_ref,0 ); -kfree (data->onmax.var_str); +kfree (data->track_data.var_str);action_data_destroy (data); }
@@ -3353,26 +3409,26 @@ static void onmax_destroy(struct action_data *data)static int action_create (struct hist_trigger_data *hist_data,struct action_data *data); -static int onmax_create (struct hist_trigger_data *hist_data, -struct action_data *data) +static int track_data_create (struct hist_trigger_data *hist_data, +struct action_data *data) { -struct hist_field *var_field, *ref_field, *max_var =NULL ; +struct hist_field *var_field, *ref_field, *track_var =NULL ;struct trace_event_file *file = hist_data->event_file;unsigned int var_ref_idx = hist_data->n_var_refs; -char *onmax_var_str; +char *track_data_var_str;unsigned long flags;int ret =0 ; - onmax_var_str = data->onmax.var_str; -if (onmax_var_str[0 ] !='$' ) { -hist_err ("onmax: For onmax(x), x must be a variable: " , onmax_var_str); + track_data_var_str = data->track_data.var_str; +if (track_data_var_str[0 ] !='$' ) { +hist_err ("For onmax(x), x must be a variable: " , track_data_var_str);return -EINVAL ; } - onmax_var_str++; + track_data_var_str++; - var_field =find_target_event_var (hist_data,NULL ,NULL , onmax_var_str); + var_field =find_target_event_var (hist_data,NULL ,NULL , track_data_var_str);if (!var_field) { -hist_err ("onmax: Couldn't find onmax variable: " , onmax_var_str); +hist_err ("Couldn't find onmax variable: " , track_data_var_str);return -EINVAL ; }
@@ -3388,17 +3444,18 @@ static int onmax_create(struct hist_trigger_data *hist_data, } hist_data->var_refs[hist_data->n_var_refs] = ref_field; ref_field->var_ref_idx = hist_data->n_var_refs++; - data->onmax.var = ref_field; + data->track_data.var_ref = ref_field; - data->onmax.max_var_ref_idx = var_ref_idx; + data->track_data.var_ref_idx = var_ref_idx; - max_var =create_var (hist_data, file,"max" ,sizeof (u64),"u64" ); -if (IS_ERR (max_var)) { -hist_err ("onmax: Couldn't create onmax variable: " ,"max" ); - ret =PTR_ERR (max_var); +if (data->handler ==HANDLER_ONMAX ) + track_var =create_var (hist_data, file,"__max" ,sizeof (u64),"u64" ); +if (IS_ERR (track_var)) { +hist_err ("Couldn't create onmax variable: " ,"__max" ); + ret =PTR_ERR (track_var); goto out; } - data->onmax.max_var = max_var; + data->track_data.track_var = track_var; ret =action_create (hist_data, data); out:
@@ -3476,7 +3533,17 @@ static int action_parse(char *str, struct action_data *data, goto out;if (handler ==HANDLER_ONMAX ) - data->fn = onmax_save; + data->track_data.check_val = check_track_val_max; +else { +hist_err ("action parsing: Handler doesn't support action: " , action_name); + ret = -EINVAL ; + goto out; + } + + data->track_data.save_val = save_track_val_local; + data->track_data.get_val = get_track_val_local; + + data->fn = ontrack_save; data->action =ACTION_SAVE ; }else {
@@ -3488,7 +3555,14 @@ static int action_parse(char *str, struct action_data *data, goto out; } +if (handler ==HANDLER_ONMAX ) + data->track_data.check_val = check_track_val_max; + + data->track_data.save_val = save_track_val_local; + data->track_data.get_val = get_track_val_local; + data->fn = action_trace; + data->action =ACTION_TRACE ; }
@@ -3503,24 +3577,25 @@ static int action_parse(char *str, struct action_data *data,return ret; } -static struct action_data *onmax_parse (char *str,enum handler_id handler) +static struct action_data *track_data_parse (struct hist_trigger_data *hist_data, +char *str,enum handler_id handler) {struct action_data *data; -char *onmax_var_str;int ret = -EINVAL ; +char *var_str; data =kzalloc (sizeof (*data),GFP_KERNEL );if (!data)return ERR_PTR (-ENOMEM ); - onmax_var_str =strsep (&str,")" ); -if (!onmax_var_str || !str) { + var_str =strsep (&str,")" ); +if (!var_str || !str) { ret = -EINVAL ; goto free; } - data->onmax.var_str =kstrdup (onmax_var_str,GFP_KERNEL ); -if (!data->onmax.var_str) { + data->track_data.var_str =kstrdup (var_str,GFP_KERNEL ); +if (!data->track_data.var_str) { ret = -ENOMEM ; goto free; }
@@ -3531,7 +3606,7 @@ static struct action_data *onmax_parse(char *str, enum handler_id handler) out:return data; free: -onmax_destroy (data); +track_data_destroy (hist_data, data); data =ERR_PTR (ret); goto out; }
@@ -4316,7 +4391,7 @@ static void destroy_actions(struct hist_trigger_data *hist_data)if (data->handler ==HANDLER_ONMATCH )onmatch_destroy (data);else if (data->handler ==HANDLER_ONMAX ) -onmax_destroy (data); +track_data_destroy (hist_data, data);else kfree (data); }
@@ -4344,7 +4419,8 @@ static int parse_actions(struct hist_trigger_data *hist_data) }else if (strncmp (str,"onmax(" ,strlen ("onmax(" )) ==0 ) {char *action_str = str +strlen ("onmax(" ); - data =onmax_parse (action_str,HANDLER_ONMAX ); + data =track_data_parse (hist_data, action_str, +HANDLER_ONMAX );if (IS_ERR (data)) { ret =PTR_ERR (data);break ;
@@ -4374,7 +4450,7 @@ static int create_actions(struct hist_trigger_data *hist_data)if (ret)break ; }else if (data->handler ==HANDLER_ONMAX ) { - ret =onmax_create (hist_data, data); + ret =track_data_create (hist_data, data);if (ret)break ; }else {
@@ -4396,7 +4472,7 @@ static void print_actions(struct seq_file *m,struct action_data *data = hist_data->actions[i];if (data->handler ==HANDLER_ONMAX ) -onmax_print (m, hist_data, elt, data); +track_data_print (m, hist_data, elt, data); } }
@@ -4421,12 +4497,13 @@ static void print_action_spec(struct seq_file *m, } } -static void print_onmax_spec (struct seq_file *m, -struct hist_trigger_data *hist_data, -struct action_data *data) +static void print_track_data_spec (struct seq_file *m, +struct hist_trigger_data *hist_data, +struct action_data *data) { -seq_puts (m,":onmax(" ); -seq_printf (m,"%s" , data->onmax.var_str); +if (data->handler ==HANDLER_ONMAX ) +seq_puts (m,":onmax(" ); +seq_printf (m,"%s" , data->track_data.var_str);seq_printf (m,").%s(" , data->action_name);print_action_spec (m, hist_data, data);
@@ -4484,8 +4561,8 @@ static bool actions_match(struct hist_trigger_data *hist_data, data_test->match_data.event) != 0)return false; }else if (data->handler ==HANDLER_ONMAX ) { -if (strcmp (data->onmax.var_str, - data_test->onmax.var_str) !=0 ) +if (strcmp (data->track_data.var_str, + data_test->track_data.var_str) !=0 )return false; } }
@@ -4505,7 +4582,7 @@ static void print_actions_spec(struct seq_file *m,if (data->handler ==HANDLER_ONMATCH )print_onmatch_spec (m, hist_data, data);else if (data->handler ==HANDLER_ONMAX ) -print_onmax_spec (m, hist_data, data); +print_track_data_spec (m, hist_data, data); } }
Signature · 1 line
2.14.1
Re: [PATCH v7 05/16] tracing: Generalize hist trigger onmax and save action
Hi Tom,
Quoted 56 lines · Tom Zanussi
From: Tom Zanussi <[email protected]>
The action refactor code allowed actions and handlers to be separated, but the existing onmax handler and save action code is still not flexible enough to handle arbitrary coupling. This change generalizes them and in the process makes additional handlers and actions easier to implement.
The onmax action can be broken up and thought of as two separate components - a variable to be tracked (the parameter given to the
onmax($var_to_track)function) and an invisible variable created to save the ongoing result of doing something with that variable, such as saving the max value of that variable so far seen.Separating it out like this and renaming it appropriately allows us to use the same code for similar tracking functions such as
onchange($var_to_track), which would just track the last value seen rather than the max seen so far, which is useful in some situations.Additionally, because different handlers and actions may want to save and access data differently e.g. save and retrieve tracking values as local variables vs something more global,
save_val()andget_val()interface functions are introduced and max-specific implementations are used instead.The same goes for the code that checks whether a maximum has been hit
- a genericcheck_val()interface and max-checking implementation is used instead, which allows future patches to make use of he same code using their own implemetations of similar functionality.Signed-off-by Tom Zanussi <[email protected]>--- kernel/trace/trace_events_hist.c | 225 ++++++++++++++++++++++++++------------- 1 file changed, 151 insertions(+), 74 deletions(-)kernel/trace/trace_events_hist.c +9
-0@@ -319,6 +319,15 @@ typedef void (*action_fn_t) (struct hist_trigger_data *hist_data,struct ring_buffer_event *rbe, struct action_data *data, u64 *var_ref_vals); +typedef bool (*check_track_val_fn_t ) (u64 track_val,u64 var_val); +typedef bool (*save_track_val_fn_t ) (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data, +unsigned int track_var_idx,u64 var_val); +typedef u64 (*get_track_val_fn_t ) (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data); +enum handler_id {HANDLER_ONMATCH =1 ,HANDLER_ONMAX ,
kernel/trace/trace_events_hist.c struct action_data { · line 362
Quoted 9 lines
kernel/trace/trace_events_hist.c +2
-4@@ -349,14 +358,18 @@ struct action_data {struct {char *var_str; -unsigned int max_var_ref_idx; -struct hist_field *max_var; -struct hist_field *var; - } onmax; +struct hist_field *var_ref; +unsigned int var_ref_idx;
I have a question. It's confusing for me there are many indexes for a variable (ref). The hist_field already has var.idx, var_idx and var_ref_idx in it. But you also added an external var_ref_idx along with the var_ref. Also I see another var_ref_idx in the action data. Is all that really needed? Could you please add some comment then?
Thanks,
Namhyung
Quoted 9 lines
kernel/trace/trace_events_hist.c +7
-0+ +struct hist_field *track_var; + +check_track_val_fn_t check_val; +save_track_val_fn_t save_val; +get_track_val_fn_t get_val; + } track_data; }; };
Re: [PATCH v7 05/16] tracing: Generalize hist trigger onmax and save action
Hi Namhyung,
Quoted 5 lines · Namhyung Kim
Hi Tom,
Quoted 2 lines · Tom Zanussi
From: Tom Zanussi <[email protected]>
[snip]
Quoted 1 line
Quoted 1 line
enum handler_id {
Quoted 4 lines
Quoted 4 lines
(quoted diff) +0
-0HANDLER_ONMATCH = 1, HANDLER_ONMAX,@@ -349,14 +358,18 @@ struct action_data {
Quoted 17 lines
Review struct action_data { · line 363
Quoted 9 lines
(quoted diff) +2
-4struct { char *var_str; - unsigned int max_var_ref_id x; - struct hist_field *max_var; - struct hist_field *var; - } onmax; + struct hist_field *var_ref; + unsigned int var_ref_idx;I have a question. It's confusing for me there are many indexes for a
variable (ref). Thehist_fieldalready has var.idx,var_idxandvar_ref_idxin it. But you also added an externalvar_ref_idxalong with thevar_ref. Also I see anothervar_ref_idxin the action data. Is all that really needed? Could you please add some comment then?
Below is a patch with some comments I'll merge into the next version that I hope will help make things more clear. Basically, the hist_field.var_idx isn't used so I've removed it and therefore that source of confusion, while var.idx is the variable's unique 'handle' in the tracing_map, used when getting and setting the variable. And then there are the several versions of var_ref_idx used for different purposes depending on the context, but all of them are indices into the array of variable values collected when a trigger is hit. For example, the var_ref_idx defined inside track_data is the index that points to the tracked var value, which the action can use directly, and the var_ref_idx alongside the synth fields in action_data is the index of the first param used when generating a synthetic event, and so on.
Tom
kernel/trace/trace_events_hist.c +46 -1
@@ -39,6 +39,16 @@ enum field_op_id { FIELD_OP_UNARY_MINUS, }; +/* +* A hist_var (histogram variable) contains variable information for +* hist_fields having the HIST_FIELD_FL_VAR or HIST_FIELD_FL_VAR_REF +* flag set. A hist_var has a variable name e.g. ts0, and is +* associated with a given histogram trigger, as specified by +* hist_data. The hist_var idx is the unique index assigned to the +* variable by the hist trigger's tracing_map. The idx is what is +* used to set a variable's value and, by a variable reference, to +* retrieve it. +*/ struct hist_var {char *name;struct hist_trigger_data *hist_data;
@@ -60,7 +70,15 @@ struct hist_field {char *system;char *event_name;char *name; -unsigned int var_idx; + +/* +* When a histogram trigger is hit, if it has any references +* to variables, the values of those variables are collected +* into a var_ref_vals array by resolve_var_refs(). The +* current value of each variable is read from the tracing_map +* using the hist field's hist_var.idx and entered into the +* var_ref_idx entry i.e. var_ref_vals[var_ref_idx]. +*/ unsigned int var_ref_idx;bool read_once; };
@@ -350,6 +368,14 @@ struct action_data {unsigned int n_params;char *params[SYNTH_FIELDS_MAX ]; +/* +* When a histogram trigger is hit, the values of any +* references to variables, including variables being passed +* as parameters to synthetic events, are collected into a +* var_ref_vals array. This var_ref_idx is the index of the +* first param in the array to be passed to the synthetic +* event invocation. +*/ unsigned int var_ref_idx;struct synth_event *synth_event;bool use_trace_keyword;
@@ -362,10 +388,29 @@ struct action_data { } match_data;struct { +/* +* var_str and var_ref refer to the variable +* being tracked e.g onmax($var). +*/ char *var_str;struct hist_field *var_ref; + +/* +* When a histogram trigger is hit, the values +* of any references to variables, including +* variables being tracked e.g. onmax($var), +* are collected into a var_ref_vals array. +* This var_ref_idx is the index of the +* tracked var value in var_ref_vals, which +* the action can make use of directly. +*/ unsigned int var_ref_idx; +/* +* This track_var contains the 'invisible' +* tracking variable created to keep the +* current e.g. max value. +*/ struct hist_field *track_var;check_track_val_fn_t check_val;
Re: [PATCH v7 05/16] tracing: Generalize hist trigger onmax and save action
Quoted 34 lines · Tom Zanussi
Hi Namhyung,
Quoted 5 lines · Namhyung Kim
Hi Tom,
Quoted 2 lines · Tom Zanussi
From: Tom Zanussi <[email protected]>
[snip]
Quoted 1 line
Quoted 1 line
enum
handler_id{Quoted 4 lines
Quoted 4 lines
(quoted diff) +0
-0HANDLER_ONMATCH = 1, HANDLER_ONMAX,@@ -349,14 +358,18 @@ struct action_data {Quoted 16 lines
Review struct action_data { · line 362
Quoted 8 lines
(quoted diff) +2
-4struct { char *var_str; - unsigned int max_var_ref_idx; - struct hist_field *max_var; - struct hist_field *var; - } onmax; + struct hist_field *var_ref; + unsigned int var_ref_idx;I have a question. It's confusing for me there are many indexes for a
variable (ref). Thehist_fieldalready has var.idx,var_idxandvar_ref_idxin it. But you also added an externalvar_ref_idxalong with thevar_ref. Also I see anothervar_ref_idxin the action data. Is all that really needed? Could you please add some comment then?
Quoted 3 lines
Below is a patch with some comments I'll merge into the next version that I hope will help make things more clear. Basically, the hist_field.var_idx isn't used so I've removed it and therefore that
Thanks!
Quoted 5 lines
source of confusion, while var.idx is the variable's unique 'handle' in the
tracing_map, used when getting and setting the variable. And then there are the several versions ofvar_ref_idxused for different purposes depending on the context, but all of them are indices into the array of variable values collected when a trigger is hit. For example,
So IIUC field->var_ref_idx is an index to the val_ref_vals array, right? Then if we keep the all hist_fields we don't need to have a separate var_ref_idx IMHO.
Quoted 2 lines
the
var_ref_idxdefined insidetrack_datais the index that points to the tracked var value, which the action can use directly, and the
I guess the track_data.var_ref_idx is always same as the track_data.track_var.var_ref_idx, no? If so we can get rid of it.
Quoted 2 lines
var_ref_idxalongside the synth fields inaction_datais the index of the first param used when generating a synthetic event, and so on.
For synth event, we have hist_data->synth_var_refs[] but it's not passed to trace_synth() so no way to know original var_ref_idx and I'm ok with having action_data.var_ref_idx.
But I don't see where hist_data->synth_var_refs is used other than find_var_ref(). And for that purpose, I guess it's more efficient to use hist_data->var_refs[] so that we can remove synth_var_refs.
Quoted 57 lines
Tom
kernel/trace/trace_events_hist.c +27
-1@@ -39,6 +39,16 @@ enum field_op_id { FIELD_OP_UNARY_MINUS, }; +/* +* A hist_var (histogram variable) contains variable information for +* hist_fields having the HIST_FIELD_FL_VAR or HIST_FIELD_FL_VAR_REF +* flag set. A hist_var has a variable name e.g. ts0, and is +* associated with a given histogram trigger, as specified by +* hist_data. The hist_var idx is the unique index assigned to the +* variable by the hist trigger's tracing_map. The idx is what is +* used to set a variable's value and, by a variable reference, to +* retrieve it. +*/ struct hist_var {char *name;struct hist_trigger_data *hist_data;@@ -60,7 +70,15 @@ struct hist_field {char *system;char *event_name;char *name; -unsigned int var_idx; + +/* +* When a histogram trigger is hit, if it has any references +* to variables, the values of those variables are collected +* into a var_ref_vals array by resolve_var_refs(). The +* current value of each variable is read from the tracing_map +* using the hist field's hist_var.idx and entered into the +* var_ref_idx entry i.e. var_ref_vals[var_ref_idx]. +*/ unsigned int var_ref_idx;bool read_once; };@@ -350,6 +368,14 @@ struct action_data {unsigned int n_params;char *params[SYNTH_FIELDS_MAX ]; +/* +* When a histogram trigger is hit, the values of any +* references to variables, including variables being passed +* as parameters to synthetic events, are collected into a +* var_ref_vals array. This var_ref_idx is the index of the +* first param in the array to be passed to the synthetic +* event invocation. +*/ unsigned int var_ref_idx;struct synth_event *synth_event;bool use_trace_keyword;
kernel/trace/trace_events_hist.c struct action_data { · line 395
Quoted 8 lines
kernel/trace/trace_events_hist.c +4
-0@@ -362,10 +388,29 @@ struct action_data { } match_data;struct { +/* +* var_str and var_ref refer to the variable +* being tracked e.g onmax($var). +*/ char *var_str;
Can it be different from var_ref->var.name?
Thanks,
Namhyung
Quoted 21 lines
kernel/trace/trace_events_hist.c +15
-0struct hist_field *var_ref; + +/* +* When a histogram trigger is hit, the values +* of any references to variables, including +* variables being tracked e.g. onmax($var), +* are collected into a var_ref_vals array. +* This var_ref_idx is the index of the +* tracked var value in var_ref_vals, which +* the action can make use of directly. +*/ unsigned int var_ref_idx; +/* +* This track_var contains the 'invisible' +* tracking variable created to keep the +* current e.g. max value. +*/ struct hist_field *track_var;check_track_val_fn_t check_val;
Re: [PATCH v7 05/16] tracing: Generalize hist trigger onmax and save action
Hi Namhyung,
Quoted 60 lines · Namhyung Kim
Quoted 41 lines · Tom Zanussi
Hi Namhyung,
Quoted 5 lines · Namhyung Kim
Hi Tom,
Quoted 2 lines · Tom Zanussi
From: Tom Zanussi <[email protected]>
[snip]
Quoted 1 line
Quoted 1 line
enum
handler_id{Quoted 17 lines
Quoted 4 lines
(quoted diff) +0
-0HANDLER_ONMATCH = 1, HANDLER_ONMAX,@@ -349,14 +358,18 @@ struct action_data {Review struct action_data { · line 364
Quoted 10 lines
(quoted diff) +2
-4struct { char *var_str; - unsigned int max_var_re f_idx; - struct hist_field *max_var; - struct hist_field *var; - } onmax; + struct hist_field *var_ref; + unsigned int var_ref_id x;I have a question. It's confusing for me there are many indexes for
Quoted 9 lines
a
variable (ref). Thehist_fieldalready has var.idx,var_idxandvar_ref_idxin it. But you also added an externalvar_ref_idxalong
with thevar_ref. Also I see anothervar_ref_idxin the action data.
Is all that really needed? Could you please add some comment then?Quoted 4 lines
Below is a patch with some comments I'll merge into the next version
that I hope will help make things more clear. Basically, the hist_field.var_idx isn't used so I've removed it and therefore thatThanks!
Quoted 9 lines
source of confusion, while var.idx is the variable's unique 'handle' in
thetracing_map, used when getting and setting the variable. And then
there are the several versions ofvar_ref_idxused for different purposes depending on the context, but all of them are indices into the
array of variable values collected when a trigger is hit. For example,
Quoted 4 lines
So IIUC
field->var_ref_idxis an index to theval_ref_valsarray, right? Then if we keep the allhist_fieldswe don't need to have a separatevar_ref_idxIMHO.
hist_field_var_ref() needs to be be able to retrieve var_ref_idx given the field alone, so I'm not sure this can be removed.
Quoted 8 lines
Quoted 4 lines
the
var_ref_idxdefined insidetrack_datais the index that points to
the tracked var value, which the action can use directly, and theI guess the track_data.var_ref_idx is always same as the track_data.track_var.var_ref_idx, no? If so we can get rid of it.
Yes, you're right, that seems to be redundant in the code, will remove it.
Quoted 5 lines
Quoted 4 lines
var_ref_idxalongside the synth fields inaction_datais the index of
the first param used when generating a synthetic event, and so on.
Quoted 9 lines
For synth event, we have hist_data->synth_var_refs[] but it's not passed to
trace_synth()so no way to know originalvar_ref_idxand I'm
ok with having action_data.var_ref_idx.But I don't see where
hist_data->synth_var_refsis used other thanfind_var_ref(). And for that purpose, I guess it's more efficient to use hist_data->var_refs[] so that we can removesynth_var_refs.
It's also used to destroy hist_fields in destroy_synth_var_refs(), but this points out something that should be cleaned up too - because of the way the code developed over time, we now have separate sets of fields like this that should be unified - I'll add some patches to do that. And that will get rid of the separate synth_var_refs and use hist_data->var_refs, which as you correctly point out will be more efficient.
Quoted 70 lines
Quoted 70 lines
Tom
kernel/trace/trace_events_hist.c +2
-0@@ -39,6 +39,16 @@ enum field_op_id { FIELD_OP_UNARY_MINUS, }; +/* +* A hist_var (histogram variable) contains variable information for
+ *hist_fieldshaving theHIST_FIELD_FL_VARorHIST_FIELD_FL_VAR_REF
+ * flag set. Ahist_varhas a variable name e.g. ts0, and is
+ * associated with a given histogram trigger, as specified by
+ *hist_data. Thehist_varidx is the unique index assigned to the
+ * variable by the hist trigger'stracing_map. The idx is what is
+ * used to set a variable's value and, by a variable reference, to
+ * retrieve it.
+ */
structhist_var{kernel/trace/trace_events_hist.c +3
-1char *name;struct hist_trigger_data *hist_data;@@ -60,7 +70,15 @@ struct hist_field {char *system;char *event_name;char *name; -unsigned int var_idx; + +/* +* When a histogram trigger is hit, if it has any references
kernel/trace/trace_events_hist.c +1
-0+* to variables, the values of those variables are collected
kernel/trace/trace_events_hist.c +2
-0+* into a var_ref_vals array by resolve_var_refs(). The +* current value of each variable is read from the
tracing_mapkernel/trace/trace_events_hist.c +1
-0+* using the hist field's hist_var.idx and entered into the
kernel/trace/trace_events_hist.c +5
-0+* var_ref_idx entry i.e. var_ref_vals[var_ref_idx]. +*/ unsigned int var_ref_idx;bool read_once; };@@ -350,6 +368,14 @@ struct action_data {unsigned int n_params;char *params[SYNTH_FIELDS_MAX ]; +/* +* When a histogram trigger is hit, the values of any +* references to variables, including variables being passed
kernel/trace/trace_events_hist.c +2
-0+* as parameters to synthetic events, are collected into a +* var_ref_vals array. This var_ref_idx is the index of the
kernel/trace/trace_events_hist.c +3
-0+* first param in the array to be passed to the synthetic +* event invocation. +*/ unsigned int var_ref_idx;struct synth_event *synth_event;bool use_trace_keyword;@@ -362,10 +388,29 @@ struct action_data { } match_data;
Quoted 10 lines
kernel/trace/trace_events_hist.c struct action_data { · line 395
Quoted 7 lines
kernel/trace/trace_events_hist.c +2
-0struct { +/* +* var_str and var_ref refer to the variable
kernel/trace/trace_events_hist.c +2
-0+* being tracked e.g onmax($var). +*/ char *var_str;Can it be different from
var_ref->var.name?
Well, it's slightly different in that it still has the '$' prefix - it's used for printing the action, but there's no reason not to get rid of it and use var_ref instead.
Thanks for the useful comments,
Tom
Re: [PATCH v7 05/16] tracing: Generalize hist trigger onmax and save action
In reply to Tom ZanussiQuoted 145 lines · Tom Zanussi
From: Tom Zanussi <[email protected]>
The action refactor code allowed actions and handlers to be separated, but the existing onmax handler and save action code is still not flexible enough to handle arbitrary coupling. This change generalizes them and in the process makes additional handlers and actions easier to implement.
The onmax action can be broken up and thought of as two separate components - a variable to be tracked (the parameter given to the
onmax($var_to_track)function) and an invisible variable created to save the ongoing result of doing something with that variable, such as saving the max value of that variable so far seen.Separating it out like this and renaming it appropriately allows us to use the same code for similar tracking functions such as
onchange($var_to_track), which would just track the last value seen rather than the max seen so far, which is useful in some situations.Additionally, because different handlers and actions may want to save and access data differently e.g. save and retrieve tracking values as local variables vs something more global,
save_val()andget_val()interface functions are introduced and max-specific implementations are used instead.The same goes for the code that checks whether a maximum has been hit
- a genericcheck_val()interface and max-checking implementation is used instead, which allows future patches to make use of he same code using their own implemetations of similar functionality.Signed-off-by Tom Zanussi <[email protected]>--- kernel/trace/trace_events_hist.c | 225 ++++++++++++++++++++++++++------------- 1 file changed, 151 insertions(+), 74 deletions(-)kernel/trace/trace_events_hist.c +61
-15@@ -319,6 +319,15 @@ typedef void (*action_fn_t) (struct hist_trigger_data *hist_data,struct ring_buffer_event *rbe, struct action_data *data, u64 *var_ref_vals); +typedef bool (*check_track_val_fn_t ) (u64 track_val,u64 var_val); +typedef bool (*save_track_val_fn_t ) (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data, +unsigned int track_var_idx,u64 var_val); +typedef u64 (*get_track_val_fn_t ) (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data); +enum handler_id {HANDLER_ONMATCH =1 ,HANDLER_ONMAX ,@@ -349,14 +358,18 @@ struct action_data {struct {char *var_str; -unsigned int max_var_ref_idx; -struct hist_field *max_var; -struct hist_field *var; - } onmax; +struct hist_field *var_ref; +unsigned int var_ref_idx; + +struct hist_field *track_var; + +check_track_val_fn_t check_val; +save_track_val_fn_t save_val; +get_track_val_fn_t get_val; + } track_data; }; }; -static char last_hist_cmd[MAX_FILTER_STR_VAL ];static char hist_err_str[MAX_FILTER_STR_VAL ];@@ -3133,10 +3146,10 @@ static void update_field_vars(struct hist_trigger_data *hist_data, hist_data->n_field_vars, 0); } -static void update_max_vars (struct hist_trigger_data *hist_data, -struct tracing_map_elt *elt, -struct ring_buffer_event *rbe, -void *rec) +static void update_save_vars (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct ring_buffer_event *rbe, +void *rec) {__update_field_vars (elt, rbe, rec, hist_data->save_vars, hist_data->n_save_vars, hist_data->n_field_var_str);@@ -3274,14 +3287,68 @@ create_target_field_var(struct hist_trigger_data *target_hist_data,return create_field_var (target_hist_data, file, var_name); } -static void onmax_print (struct seq_file *m, -struct hist_trigger_data *hist_data, -struct tracing_map_elt *elt, -struct action_data *data) +static bool check_track_val_max (u64 track_val,u64 var_val) { -unsigned int i, save_var_idx, max_idx = data->onmax.max_var->var.idx; +if (var_val <= track_val) +return false; + +return true; +} -seq_printf (m,"\n\tmax: %10llu" ,tracing_map_read_var (elt, max_idx)); +static u64 get_track_val_local (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data) +{ +unsigned int track_var_idx = data->track_data.track_var->var.idx; +u64 track_val; + + track_val =tracing_map_read_var (elt, track_var_idx); + +return track_val; +} + +static bool save_track_val_local (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data, +unsigned int track_var_idx,u64 var_val) +{ +bool ret = false; +u64 track_val; + + track_val =tracing_map_read_var (elt, track_var_idx); + +if (data->track_data.check_val (track_val, var_val)) { +tracing_map_set_var (elt, track_var_idx, var_val); + ret = true; + } + +return ret; +} + +static bool update_track_val (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data,u64 *var_ref_vals)
kernel/trace/trace_events_hist.c create_target_field_var(struct hist_trigger_data *target_hist_data, · line 3340
Quoted 10 lines
kernel/trace/trace_events_hist.c +10
-0+{ +unsigned int track_var_idx = data->track_data.track_var->var.idx; +unsigned int track_var_ref_idx = data->track_data.var_ref_idx; +u64 var_val; + + var_val = var_ref_vals[track_var_ref_idx]; + +return data->track_data.save_val (hist_data, elt, data, + track_var_idx, var_val); +}
It's bit confusing for me update_track_val() calls ->save_val() and it in turn calls ->check_val(). Why not having wrappers corresponding to their callback name? - get_track_val(), check_track_val() and save_trace_val()...
Quoted 33 lines
kernel/trace/trace_events_hist.c +15
-10+ +static void track_data_print (struct seq_file *m, +struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt, +struct action_data *data) +{ +u64 track_val = data->track_data.get_val (hist_data, elt, data); +unsigned int i, save_var_idx; + +if (data->handler ==HANDLER_ONMAX ) +seq_printf (m,"\n\tmax: %10llu" , track_val);for (i =0 ; i < hist_data->n_save_vars; i++) {struct hist_field *save_val = hist_data->save_vars[i]->val;@@ -3300,25 +3367,13 @@ static void onmax_print(struct seq_file *m, } } -static void onmax_save (struct hist_trigger_data *hist_data, -struct tracing_map_elt *elt,void *rec, -struct ring_buffer_event *rbe, -struct action_data *data,u64 *var_ref_vals) +static void ontrack_save (struct hist_trigger_data *hist_data, +struct tracing_map_elt *elt,void *rec, +struct ring_buffer_event *rbe, +struct action_data *data,u64 *var_ref_vals) { -unsigned int max_idx = data->onmax.max_var->var.idx; -unsigned int max_var_ref_idx = data->onmax.max_var_ref_idx; - -u64 var_val, max_val; - - var_val = var_ref_vals[max_var_ref_idx];
kernel/trace/trace_events_hist.c static void onmax_print(struct seq_file *m, · line 3376
Quoted 10 lines
kernel/trace/trace_events_hist.c +2
-8- max_val =tracing_map_read_var (elt, max_idx); - -if (var_val <= max_val) -return ; - -tracing_map_set_var (elt, max_idx, var_val); - -update_max_vars (hist_data, elt, rbe, rec); +if (update_track_val (hist_data, elt, data, var_ref_vals)) +update_save_vars (hist_data, elt, rbe, rec);
... and then it should look like:
if (check_track_val()) {
save_track_val();
update_save_vars();
}I also think update_save_vars() also needs to be renamed something like save_track_vars() or save_trace_data().
Thanks,
Namhyung
Quoted 1 line
kernel/trace/trace_events_hist.c +0
-0}
Re: [PATCH v7 05/16] tracing: Generalize hist trigger onmax and save action
Hi Namhyung,
Quoted 4 lines · Namhyung Kim
Quoted 3 lines · Tom Zanussi
From: Tom Zanussi <[email protected]>
[snip]
Quoted 7 lines
kernel/trace/trace_events_hist.c static void onmax_print(struct seq_file *m, · line 3376
Quoted 4 lines
kernel/trace/trace_events_hist.c +2
-2- -update_max_vars (hist_data, elt, rbe, rec); +if (update_track_val (hist_data, elt, data, var_ref_vals)) +update_save_vars (hist_data, elt, rbe, rec);... and then it should look like:
Quoted 8 lines
if (check_track_val()) { save_track_val(); update_save_vars(); }I also think
update_save_vars()also needs to be renamed something likesave_track_vars()orsave_trace_data().
Yes, this is much nicer - I've made these changes and more for v8. Thanks for the input.
Tom
PATCH v7 6/16 tracing: Add conditional snapshot
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Currently, tracing snapshots are context-free - they capture the ring buffer contents at the time the tracing_snapshot() function was invoked, and nothing else. Additionally, they're always taken unconditionally - the calling code can decide whether or not to take a snapshot, but the data used to make that decision is kept separately from the snapshot itself.
This change adds the ability to associate with each trace instance some user data, along with an 'update' function that can use that data to determine whether or not to actually take a snapshot. The update function can then update that data along with any other state (as part of the data presumably), if warranted.
Because snapshots are 'global' per-instance, only one user can enable and use a conditional snapshot for any given trace instance. To enable a conditional snapshot (see details in the function and data structure comments), the user calls tracing_snapshot_cond_enable(). Similarly, to disable a conditional snapshot and free it up for other users, tracing_snapshot_cond_disable() should be called.
To actually initiate a conditional snapshot, tracing_snapshot_cond() should be called. tracing_snapshot_cond() will invoke the update() callback, allowing the user to decide whether or not to actually take the snapshot and update the user-defined data associated with the snapshot. If the callback returns 'true', tracing_snapshot_cond() will then actually take the snapshot and return.
This scheme allows for flexibility in snapshot implementations - for example, by implementing slightly different update() callbacks, snapshots can be taken in situations where the user is only interested in taking a snapshot when a new maximum in hit versus when a value changes in any way at all. Future patches will demonstrate both cases.
--- kernel/trace/trace.c | 162 ++++++++++++++++++++++++++++++++++-- kernel/trace/trace.h | 56 ++++++++++++- kernel/trace/trace_events_trigger.c | 2 +- kernel/trace/trace_sched_wakeup.c | 2 +- 4 files changed, 211 insertions(+), 11 deletions(-)
kernel/trace/trace.c +155 -7
@@ -894,7 +894,7 @@ int __trace_bputs(unsigned long ip, const char *str)EXPORT_SYMBOL_GPL (__trace_bputs);#ifdef CONFIG_TRACER_SNAPSHOT -void tracing_snapshot_instance (struct trace_array *tr) +void tracing_snapshot_instance (struct trace_array *tr,void *cond_data) {struct tracer *tracer = tr->current_trace;unsigned long flags;
@@ -920,7 +920,7 @@ void tracing_snapshot_instance(struct trace_array *tr) }local_irq_save (flags); -update_max_tr (tr, current,smp_processor_id ()); +update_max_tr (tr, current,smp_processor_id (), cond_data);local_irq_restore (flags); }
@@ -942,10 +942,58 @@ void tracing_snapshot(void) {struct trace_array *tr = &global_trace; -tracing_snapshot_instance (tr); +tracing_snapshot_instance (tr,NULL ); }EXPORT_SYMBOL_GPL (tracing_snapshot); +/** +* tracing_snapshot_cond - conditionally take a snapshot of the current buffer. +* @tr: The tracing instance to snapshot +* @cond_data: The data to be tested conditionally, and possibly saved +* +* This is the same as tracing_snapshot() except that the snapshot is +* conditional - the snapshot will only happen if the +* cond_snapshot.update() implementation receiving the cond_data +* returns true, which means that the trace array's cond_snapshot +* update() operation used the cond_data to determine whether the +* snapshot should be taken, and if it was, presumably saved it along +* with the snapshot. +*/ +void tracing_snapshot_cond (struct trace_array *tr,void *cond_data) +{ +tracing_snapshot_instance (tr, cond_data); +} +EXPORT_SYMBOL_GPL (tracing_snapshot_cond); + +/** +* tracing_snapshot_cond_data - get the user data associated with a snapshot +* @tr: The tracing instance +* +* When the user enables a conditional snapshot using +* tracing_snapshot_cond_enable(), the user-defined cond_data is saved +* with the snapshot. This accessor is used to retrieve it. +* +* Should not be called from cond_snapshot.update(), since it takes +* the tr->max_lock lock, which the code calling +* cond_snapshot.update() has already done. +* +* Returns the cond_data associated with the trace array's snapshot. +*/ +void *tracing_cond_snapshot_data (struct trace_array *tr) +{ +void *cond_data =NULL ; + +arch_spin_lock (&tr->max_lock); + +if (tr->cond_snapshot) + cond_data = tr->cond_snapshot->cond_data; + +arch_spin_unlock (&tr->max_lock); + +return cond_data; +} +EXPORT_SYMBOL_GPL (tracing_cond_snapshot_data); +static int resize_buffer_duplicate_size (struct trace_buffer *trace_buf,struct trace_buffer *size_buf,int cpu_id);static void set_buffer_entries (struct trace_buffer *buf,unsigned long val);
@@ -1025,12 +1073,85 @@ void tracing_snapshot_alloc(void)tracing_snapshot (); }EXPORT_SYMBOL_GPL (tracing_snapshot_alloc); + +/** +* tracing_snapshot_cond_enable - enable conditional snapshot for an instance +* @tr: The tracing instance +* @cond_data: User data to associate with the snapshot +* @update: Implementation of the cond_snapshot update function +* +* Check whether the conditional snapshot for the given instance has +* already been enabled; if so, return -EBUSY, else create a +* cond_snapshot and save the cond_data and update function inside. +* +* Returns 0 if successful, error otherwise. +*/ +int tracing_snapshot_cond_enable (struct trace_array *tr,void *cond_data, +cond_update_fn_t update) +{ +struct cond_snapshot *cond_snapshot; +int ret =0 ; + + cond_snapshot =kzalloc (sizeof (*cond_snapshot),GFP_KERNEL ); +if (!cond_snapshot) +return -ENOMEM ; + + cond_snapshot->cond_data = cond_data; + cond_snapshot->update = update; + +arch_spin_lock (&tr->max_lock); + +if (tr->cond_snapshot) { +kfree (cond_snapshot); + ret = -EBUSY ; + }else + tr->cond_snapshot = cond_snapshot; + +arch_spin_unlock (&tr->max_lock); + +return ret; +} +EXPORT_SYMBOL_GPL (tracing_snapshot_cond_enable); + +/** +* tracing_snapshot_cond_disable - disable conditional snapshot for an instance +* @tr: The tracing instance +* +* Check whether the conditional snapshot for the given instance is +* enabled; if so, free the cond_snapshot associated with it, +* otherwise return -EINVAL. +* +* Returns 0 if successful, error otherwise. +*/ +int tracing_snapshot_cond_disable (struct trace_array *tr) +{ +int ret =0 ; + +arch_spin_lock (&tr->max_lock); + +if (!tr->cond_snapshot) + ret = -EINVAL ; +else { +kfree (tr->cond_snapshot); + tr->cond_snapshot =NULL ; + } + +arch_spin_unlock (&tr->max_lock); + +return ret; +} +EXPORT_SYMBOL_GPL (tracing_snapshot_cond_disable);#else void tracing_snapshot (void ) {WARN_ONCE (1 ,"Snapshot feature not enabled, but internal snapshot used" ); }EXPORT_SYMBOL_GPL (tracing_snapshot); +void tracing_snapshot_cond (struct trace_array *tr,void *cond_data) +{ +WARN_ONCE (1 ,"Snapshot feature not enabled, but internal conditional snapshot used" ); +} +EXPORT_SYMBOL_GPL (tracing_snapshot_cond);int tracing_alloc_snapshot (void ) {WARN_ONCE (1 ,"Snapshot feature not enabled, but snapshot allocation used" );
@@ -1043,6 +1164,27 @@ void tracing_snapshot_alloc(void) tracing_snapshot(); }EXPORT_SYMBOL_GPL (tracing_snapshot_alloc); +void *tracing_cond_snapshot_data (struct trace_array *tr) +{ +WARN_ONCE (1 ,"Snapshot feature not enabled, but tried to get internal conditional snapshot data" ); + +return NULL ; +} +EXPORT_SYMBOL_GPL (tracing_cond_snapshot_data); +int tracing_snapshot_cond_enable (struct trace_array *tr,void *cond_data,cond_update_fn_t update) +{ +WARN_ONCE (1 ,"Snapshot feature not enabled, but tried to enable internal conditional snapshot" ); + +return false; +} +EXPORT_SYMBOL_GPL (tracing_snapshot_cond_enable); +int tracing_snapshot_cond_disable (struct trace_array *tr) +{ +WARN_ONCE (1 ,"Snapshot feature not enabled, but tried to disable internal conditional snapshot" ); + +return false; +} +EXPORT_SYMBOL_GPL (tracing_snapshot_cond_disable);#endif /* CONFIG_TRACER_SNAPSHOT */ void tracer_tracing_off (struct trace_array *tr)
@@ -1359,7 +1501,8 @@ __update_max_tr(struct trace_array *tr, struct task_struct *tsk, int cpu)* about which task was the cause of this latency. */ void -update_max_tr (struct trace_array *tr,struct task_struct *tsk,int cpu) +update_max_tr (struct trace_array *tr,struct task_struct *tsk,int cpu, +void *cond_data) {if (tr->stop_count)return ;
@@ -1380,6 +1523,11 @@ update_max_tr(struct trace_array *tr, struct task_struct *tsk, int cpu)else ring_buffer_record_off (tr->max_buffer.buffer); +if (tr->cond_snapshot && !tr->cond_snapshot->update (tr, cond_data)) { +arch_spin_unlock (&tr->max_lock); +return ; + } +swap (tr->trace_buffer.buffer, tr->max_buffer.buffer);__update_max_tr (tr, tsk, cpu);
@@ -6489,7 +6637,7 @@ tracing_snapshot_write(struct file *filp, const char __user *ubuf, size_t cnt,local_irq_disable ();/* Now, we're going to swap */ if (iter->cpu_file ==RING_BUFFER_ALL_CPUS ) -update_max_tr (tr, current,smp_processor_id ()); +update_max_tr (tr, current,smp_processor_id (),NULL );else update_max_tr_single (tr, current, iter->cpu_file);local_irq_enable ();
@@ -7081,7 +7229,7 @@ ftrace_snapshot(unsigned long ip, unsigned long parent_ip, struct trace_array *tr, struct ftrace_probe_ops *ops, void *data) { -tracing_snapshot_instance (tr ); +tracing_snapshot_instance (tr ,NULL ); } static void
@@ -7103,7 +7251,7 @@ ftrace_count_snapshot(unsigned long ip, unsigned long parent_ip, (*count)--; } -tracing_snapshot_instance (tr); +tracing_snapshot_instance (tr,NULL ); } static int
kernel/trace/trace.h +54 -2
86 lines not on this page · raw message
kernel/trace/trace_events_trigger.c +1 -1
@@ -1049,7 +1049,7 @@ snapshot_trigger(struct event_trigger_data *data, void *rec,struct trace_event_file *file = data->private_data;if (file) -tracing_snapshot_instance (file->tr); +tracing_snapshot_instance (file->tr,NULL );else tracing_snapshot (); }
kernel/trace/trace_sched_wakeup.c +1 -1
@@ -494,7 +494,7 @@ probe_wakeup_sched_switch(void *ignore, bool preempt,if (likely (!is_tracing_stopped ())) { wakeup_trace->max_latency = delta; -update_max_tr (wakeup_trace, wakeup_task, wakeup_cpu); +update_max_tr (wakeup_trace, wakeup_task, wakeup_cpu,NULL ); } out_unlock:
Signature · 1 line
2.14.1
PATCH v7 7/16 tracing: Add hist trigger snapshot() action
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add support for hist:handlerXXX($var).snapshot(), which will take a snapshot of the current trace buffer whenever handlerXXX is hit.
As a first user, this also adds snapshot() action support for the onmax() handler i.e. hist:onmax($var).snapshot().
Also, the hist trigger key printing is moved into a separate function so the snapshot() action can print a histogram key outside the histogram display - add and use hist_trigger_print_key() for that purpose.
--- kernel/trace/trace.c | 1 + kernel/trace/trace_events_hist.c | 309 +++++++++++++++++++++++++++++++++++++-- 2 files changed, 298 insertions(+), 12 deletions(-)
kernel/trace/trace.c +1 -0
@@ -4886,6 +4886,7 @@ static const char readme_msg[] ="\t The available actions are:\n\n" "\t <synthetic_event>(param list) - generate synthetic event\n" "\t save(field,...) - save current event fields\n" + "\t snapshot() - snapshot the trace buffer\n"#endif ;
kernel/trace/trace_events_hist.c +297 -12
429 lines not on this page · raw message
Signature · 1 line
2.14.1
PATCH v7 8/16 tracing: Add hist trigger snapshot() action Documentation
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add Documentation for the hist:handlerXXX($var).snapshot() action.
--- Documentation/trace/histogram.rst | 110 ++++++++++++++++++++++++++++++++++++++ 1 file changed, 110 insertions(+)
Documentation/trace/histogram.rst +110 -0
@@ -1874,6 +1874,7 @@ The available actions are: - <synthetic_event_name>(param list) - generate synthetic event - save(field,...) - save current event fields + - snapshot() - snapshot the trace buffer The following commonly-used handler.action pairs are available:
@@ -2030,6 +2031,115 @@ The following commonly-used handler.action pairs are available: Entries: 2 Dropped: 0 + - onmax(var).snapshot() + + The 'onmax(var).snapshot()' hist trigger action is invoked + whenever the value of 'var' associated with a histogram entry + exceeds the current maximum contained in that variable. + + The end result is that a global snapshot of the trace buffer will + be saved in the tracing/snapshot file if 'var' exceeds the current + maximum for any hist trigger entry. + + Note that in this case the maximum is a global maximum for the + current trace instance, which is the maximum across all buckets of + the histogram. The key of the specific trace event that caused + the global maximum and the global maximum itself are displayed, + along with a message stating that a snapshot has been taken and + where to find it. The user can use the key information displayed + to locate the corresponding bucket in the histogram for even more + detail. + + As an example the below defines a couple of hist triggers, one for + sched_waking and another for sched_switch, keyed on pid. Whenever + a sched_waking event occurs, the timestamp is saved in the entry + corresponding to the current pid, and when the scheduler switches + back to that pid, the timestamp difference is calculated. If the + resulting latency, stored in wakeup_lat, exceeds the current + maximum latency, a snapshot is taken. As part of the setup, all + the scheduler events are also enabled, which are the events that + will show up in the snapshot when it is taken at some point: + + # echo 1 > /sys/kernel/debug/tracing/events/sched/enable + + # echo 'hist:keys=pid:ts0=common_timestamp.usecs \ + if comm=="cyclictest"' >> \ + /sys/kernel/debug/tracing/events/sched/sched_waking/trigger + + # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \ + onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio, \ + prev_comm):onmax($wakeup_lat).snapshot() \ + if next_comm=="cyclictest"' >> \ + /sys/kernel/debug/tracing/events/sched/sched_switch/trigger + + When the histogram is displayed, for each bucket the max value + and the saved values corresponding to the max are displayed + following the rest of the fields. + + If a snaphot was taken, there is also a message indicating that, + along with the value and event that triggered the global maximum: + + # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist + { next_pid: 2101 } hitcount: 200 + max: 52 next_prio: 120 next_comm: cyclictest \ + prev_pid: 0 prev_prio: 120 prev_comm: swapper/6 + + { next_pid: 2103 } hitcount: 1326 + max: 572 next_prio: 19 next_comm: cyclictest \ + prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 + + { next_pid: 2102 } hitcount: 1982 \ + max: 74 next_prio: 19 next_comm: cyclictest \ + prev_pid: 0 prev_prio: 120 prev_comm: swapper/5 + + Snapshot taken (see tracing/snapshot). Details: + triggering value { onmax($wakeup_lat) }: 572 \ + triggered by event with key: { next_pid: 2103 } + + Totals: + Hits: 3508 + Entries: 3 + Dropped: 0 + + In the above case, the event that triggered the global maximum has + the key with next_pid == 2103. If you look at the bucket that has + 2103 as the key, you'll find the additional values save()'d along + with the local maximum for that bucket, which should be the same + as the global maximum (since that was the same value that + triggered the global snapshot). + + And finally, looking at the snapshot data should show at or near + the end the event that triggered the snapshot (in this case you + can verify the timestamps between the sched_waking and + sched_switch events, which should match the time displayed in the + global maximum): + + # cat /sys/kernel/debug/tracing/snapshot + + <...>-2103 [005] d..3 309.873125: sched_switch: prev_comm=cyclictest prev_pid=2103 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 + <idle>-0 [005] d.h3 309.873611: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005 + <idle>-0 [005] dNh4 309.873613: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005 + <idle>-0 [005] d..3 309.873616: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 + <...>-2102 [005] d..3 309.873625: sched_switch: prev_comm=cyclictest prev_pid=2102 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 + <idle>-0 [005] d.h3 309.874624: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005 + <idle>-0 [005] dNh4 309.874626: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005 + <idle>-0 [005] dNh3 309.874628: sched_waking: comm=cyclictest pid=2103 prio=19 target_cpu=005 + <idle>-0 [005] dNh4 309.874630: sched_wakeup: comm=cyclictest pid=2103 prio=19 target_cpu=005 + <idle>-0 [005] d..3 309.874633: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 + <idle>-0 [004] d.h3 309.874757: sched_waking: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 + <idle>-0 [004] dNh4 309.874762: sched_wakeup: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 + <idle>-0 [004] d..3 309.874766: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=gnome-terminal- next_pid=1699 next_prio=120 + gnome-terminal--1699 [004] d.h2 309.874941: sched_stat_runtime: comm=gnome-terminal- pid=1699 runtime=180706 [ns] vruntime=1126870572 [ns] + <idle>-0 [003] d.s4 309.874956: sched_waking: comm=rcu_sched pid=9 prio=120 target_cpu=007 + <idle>-0 [003] d.s5 309.874960: sched_wake_idle_without_ipi: cpu=7 + <idle>-0 [003] d.s5 309.874961: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=007 + <idle>-0 [007] d..3 309.874963: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_sched next_pid=9 next_prio=120 + rcu_sched-9 [007] d..3 309.874973: sched_stat_runtime: comm=rcu_sched pid=9 runtime=13646 [ns] vruntime=22531430286 [ns] + rcu_sched-9 [007] d..3 309.874978: sched_switch: prev_comm=rcu_sched prev_pid=9 prev_prio=120 prev_state=R+ ==> next_comm=swapper/7 next_pid=0 next_prio=120 + <...>-2102 [005] d..4 309.874994: sched_migrate_task: comm=cyclictest pid=2103 prio=19 orig_cpu=5 dest_cpu=1 + <...>-2102 [005] d..4 309.875185: sched_wake_idle_without_ipi: cpu=1 + <idle>-0 [001] d..3 309.875200: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2103 next_prio=19 + 3. User space creating a trigger --------------------------------
Signature · 1 line
2.14.1
PATCH v7 9/16 tracing: Add hist trigger snapshot() action test case
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add a test case verifying the basic functionality of the hist:snapshot() action.
--- .../inter-event/trigger-snapshot-action-hist.tc | 43 ++++++++++++++++++++++ 1 file changed, 43 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc new file +43 -0
@@ -0,0 +1,43 @@ +#!/bin/sh +# SPDX-License-Identifier: GPL-2.0 +# description: event trigger - test inter-event histogram trigger snapshot action + +fail() { #msg + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f snapshot ]; then + echo "snapshot is not supported" + exit_unsupported +fi + +grep -q "onchange(var)" README > /dev/null || exit_unsupported # version issue + +grep -q "snapshot()" README > /dev/null || exit_unsupported # version issue + +echo "Test snapshot action" + +echo 1 > /sys/kernel/debug/tracing/events/sched/enable + +echo 'hist:keys=comm:newprio=prio:onchange($newprio).save(comm,prio):onchange($newprio).snapshot() if comm=="ping"' >> /sys/kernel/debug/tracing/events/sched/sched_waking/trigger + +ping $LOCALHOST -c 3 +nice -n 1 ping $LOCALHOST -c 3 + +echo 0 > /sys/kernel/debug/tracing/events/sched/enable + +if ! grep -q "changed:" events/sched/sched_waking/hist; then + fail "Failed to create onchange action inter-event histogram" +fi + +if ! grep -q "comm=ping" snapshot; then + fail "Failed to create snapshot action inter-event histogram" +fi + +exit 0
Signature · 1 line
2.14.1
Masami Hiramatsu
maintainerRe: [PATCH v7 09/16] tracing: Add hist trigger snapshot() action test case
Quoted 29 lines · On Wed, 14 Nov 2018 14:18:06 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Add a test case verifying the basic functionality of the hist:snapshot() action.
Signed-off-by Tom Zanussi <[email protected]>--- .../inter-event/trigger-snapshot-action-hist.tc | 43 ++++++++++++++++++++++ 1 file changed, 43 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tctools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc new file +12
-0@@ -0,0 +1,43 @@ +#!/bin/sh +# SPDX-License-Identifier: GPL-2.0 +# description: event trigger - test inter-event histogram trigger snapshot action + +fail() { #msg + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc line 22
Quoted 10 lines
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc new file +10
-0+fi + +if [ ! -f snapshot ]; then + echo "snapshot is not supported" + exit_unsupported +fi + +grep -q "onchange(var)" README > /dev/null || exit_unsupported # version issue + +grep -q "snapshot()" README > /dev/null || exit_unsupported # version issue
"grep -q ... > /dev/null" is redundant, since -q doesn't show anything. please drop "> /dev/null" redirection.
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc line 28
Quoted 6 lines
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc new file +6
-0+ +echo "Test snapshot action" + +echo 1 > /sys/kernel/debug/tracing/events/sched/enable + +echo 'hist:keys=comm:newprio=prio:onchange($newprio).save(comm,prio):onchange($newprio).snapshot() if comm=="ping"' >> /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
This tests onchange().snapshot(), but document change only describes onmax().snapshot(). Maybe we should improve document too.
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc line 33
Quoted 5 lines
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc new file +5
-0+ +ping $LOCALHOST -c 3 +nice -n 1 ping $LOCALHOST -c 3 + +echo 0 > /sys/kernel/debug/tracing/events/sched/enable
Shouldn't we stop tracing instead of disabling the event?
Thank you,
Quoted 13 lines
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc new file +10
-0+ +if ! grep -q "changed:" events/sched/sched_waking/hist; then + fail "Failed to create onchange action inter-event histogram" +fi + +if ! grep -q "comm=ping" snapshot; then + fail "Failed to create snapshot action inter-event histogram" +fi + +exit 0Signature · 1 line
2.14.1
Signature · 1 line
Masami Hiramatsu <[email protected]>
Re: [PATCH v7 09/16] tracing: Add hist trigger snapshot() action test case
Hi Masami,
Quoted 57 lines · Masami Hiramatsu
Quoted 48 lines · On Wed, 14 Nov 2018 14:18:06 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Add a test case verifying the basic functionality of the hist:snapshot() action.
Signed-off-by Tom Zanussi <[email protected]>--- .../inter-event/trigger-snapshot-action-hist.tc | 43 ++++++++++++++++++++++ 1 file changed, 43 insertions(+) create mode 100644
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc(quoted diff) +0
-0event/trigger-snapshot-action-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter- event/trigger-snapshot-action-hist.tc
new file mode 100644
index 000000000000..a0a51e6a6a0ctools/testing/selftests/ftrace/test.d/trigger/inter- new file +0
-0event/trigger-snapshot-action-hist.tc
tools/testing/selftests/ftrace/test.d/trigger/inter- new file +3
-0@@ -0,0 +1,43 @@ +#!/bin/sh +# SPDX-License-Identifier: GPL-2.0 +# description: event trigger - test inter-event histogram triggersnapshot action
tools/testing/selftests/ftrace/test.d/trigger/inter- new file +17
-0+ +fail() { #msg + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f snapshot ]; then + echo "snapshot is not supported" + exit_unsupported +fi + +grep -q "onchange(var)" README > /dev/null || exit_unsupported #version issue
tools/testing/selftests/ftrace/test.d/trigger/inter- new file +2
-0+ +grep -q "snapshot()" README > /dev/null || exit_unsupported #Quoted 1 line
version issue
"grep -q ... >
/dev/null" is redundant, since -q doesn't show anything.
please drop ">/dev/null" redirection.
Quoted 14 lines
Quoted 9 lines
tools/testing/selftests/ftrace/test.d/trigger/inter- new file +6
-0+ +echo "Test snapshot action" + +echo 1 > /sys/kernel/debug/tracing/events/sched/enable + +echo'hist:keys=comm:newprio=prio:onchange($newprio).save(comm,prio):onc hange($newprio).snapshot() if comm=="ping"' >>
/sys/kernel/debug/tracing/events/sched/sched_waking/triggerThis tests onchange().snapshot(), but document change only describes onmax().snapshot().
Maybe we should improve document too.
Yes, good point, will do.
Quoted 8 lines
tools/testing/selftests/ftrace/test.d/trigger/inter-
Quoted 5 lines
tools/testing/selftests/ftrace/test.d/trigger/inter- new file +5
-0+ +ping $LOCALHOST -c 3 +nice -n 1 ping $LOCALHOST -c 3 + +echo 0 > /sys/kernel/debug/tracing/events/sched/enableShouldn't we stop tracing instead of disabling the event?
This is just reversing the enable, so should be fine, but I can stop tracing instead if you prefer.
Thanks,
Tom
Masami Hiramatsu
maintainerRe: [PATCH v7 09/16] tracing: Add hist trigger snapshot() action test case
Hi Tom,
Quoted 10 lines · On Tue, 27 Nov 2018 16:53:45 -0600 Tom Zanussi <[email protected]> wrote:
Quoted 7 lines
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc line 33
Quoted 4 lines
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc new file +4
-0+ping $LOCALHOST -c 3 +nice -n 1 ping $LOCALHOST -c 3 + +echo 0 > /sys/kernel/debug/tracing/events/sched/enableShouldn't we stop tracing instead of disabling the event?
This is just reversing the enable, so should be fine, but I can stop tracing instead if you prefer.
Oops, maybe we have to check the difference between event enabling and trace enabling.
echo 0 > tracing_on will stop writing ring buffer, but event may continue to be called. Does this mean hist will be updated? (and I guess preferrable behavior is to stop hist too, isn't it?)
Thank you,
Signature · 1 line
Masami Hiramatsu <[email protected]>
Re: [PATCH v7 09/16] tracing: Add hist trigger snapshot() action test case
Hi Masami,
Quoted 17 lines · Masami Hiramatsu
Hi Tom,
Quoted 11 lines · On Tue, 27 Nov 2018 16:53:45 -0600 Tom Zanussi <[email protected]> wrote:
Quoted 7 lines
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc line 33
Quoted 4 lines
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc new file +4
-0+ping $LOCALHOST -c 3 +nice -n 1 ping $LOCALHOST -c 3 + +echo 0 > /sys/kernel/debug/tracing/events/sched/enableShouldn't we stop tracing instead of disabling the event?
This is just reversing the enable, so should be fine, but I can stop
tracing instead if you prefer.
Quoted 9 lines
Oops, maybe we have to check the difference between event enabling and
trace enabling.
echo 0 >tracing_onwill stop writing ring buffer, but event may continue
to be called. Does this mean hist will be updated? (and I guess preferrable
behavior is to stop hist too, isn't it?)
For this test case, we're only enabling the sched events so we have something in the snapshot buffer to verify that the snapshot worked, so either should work for this purpose.
The triggers are supposed to work even if nothing is being logged to the ring buffer, so the hist triggers updating when tracing to the buffers is disabled is consistent with that...
Tom
Quoted 3 lines
Thank you,
Re: [PATCH v7 09/16] tracing: Add hist trigger snapshot() action test case
In reply to Masami HiramatsuHi Masami,
Quoted 57 lines · Masami Hiramatsu
Quoted 48 lines · On Wed, 14 Nov 2018 14:18:06 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Add a test case verifying the basic functionality of the hist:snapshot() action.
Signed-off-by Tom Zanussi <[email protected]>--- .../inter-event/trigger-snapshot-action-hist.tc | 43 ++++++++++++++++++++++ 1 file changed, 43 insertions(+) create mode 100644
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc(quoted diff) +0
-0event/trigger-snapshot-action-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter- event/trigger-snapshot-action-hist.tc
new file mode 100644
index 000000000000..a0a51e6a6a0ctools/testing/selftests/ftrace/test.d/trigger/inter- new file +0
-0event/trigger-snapshot-action-hist.tc
tools/testing/selftests/ftrace/test.d/trigger/inter- new file +3
-0@@ -0,0 +1,43 @@ +#!/bin/sh +# SPDX-License-Identifier: GPL-2.0 +# description: event trigger - test inter-event histogram triggersnapshot action
tools/testing/selftests/ftrace/test.d/trigger/inter- new file +17
-0+ +fail() { #msg + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f snapshot ]; then + echo "snapshot is not supported" + exit_unsupported +fi + +grep -q "onchange(var)" README > /dev/null || exit_unsupported #version issue
tools/testing/selftests/ftrace/test.d/trigger/inter- new file +2
-0+ +grep -q "snapshot()" README > /dev/null || exit_unsupported #Quoted 1 line
version issue
"grep -q ... >
/dev/null" is redundant, since -q doesn't show anything.
please drop ">/dev/null" redirection.
Quoted 14 lines
Quoted 9 lines
tools/testing/selftests/ftrace/test.d/trigger/inter- new file +6
-0+ +echo "Test snapshot action" + +echo 1 > /sys/kernel/debug/tracing/events/sched/enable + +echo'hist:keys=comm:newprio=prio:onchange($newprio).save(comm,prio):onc hange($newprio).snapshot() if comm=="ping"' >>
/sys/kernel/debug/tracing/events/sched/sched_waking/triggerThis tests onchange().snapshot(), but document change only describes onmax().snapshot().
Maybe we should improve document too.
Actually, onchange().snapshot() is documented in '[PATCH v7 11/16]
tracing: Add hist trigger onchange() handler Documentation'. I can change the order of the patches if it matters.
Thanks,
Tom
PATCH v7 10/16 tracing: Add hist trigger onchange() handler
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add support for a hist:onchange($var) handler, similar to the onmax() handler but triggering whenever there's any change in $var, not just a max.
--- kernel/trace/trace.c | 3 +- kernel/trace/trace_events_hist.c | 68 ++++++++++++++++++++++++++++++++-------- 2 files changed, 57 insertions(+), 14 deletions(-)
kernel/trace/trace.c +2 -1
@@ -4882,7 +4882,8 @@ static const char readme_msg[] ="\t <handler>.<action>\n\n" "\t The available handlers are:\n\n" "\t onmatch(matching.event) - invoke on addition or update\n" -"\t onmax(var) - invoke if var exceeds current max\n\n" +"\t onmax(var) - invoke if var exceeds current max\n" +"\t onchange(var) - invoke action if var changes\n\n" "\t The available actions are:\n\n" "\t <synthetic_event>(param list) - generate synthetic event\n" "\t save(field,...) - save current event fields\n"
kernel/trace/trace_events_hist.c +55 -13
182 lines not on this page · raw message
Signature · 1 line
2.14.1
PATCH v7 11/16 tracing: Add hist trigger onchange() handler Documentation
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add Documentation for the hist:onchange($var) handler.
--- Documentation/trace/histogram.rst | 98 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 98 insertions(+)
Documentation/trace/histogram.rst +98 -0
@@ -1869,6 +1869,7 @@ The available handlers are: - onmatch(matching.event) - invoke action on any addition or update - onmax(var) - invoke action if var exceeds current max + - onchange(var) - invoke action if var changes The available actions are:
@@ -2140,6 +2141,103 @@ The following commonly-used handler.action pairs are available: <...>-2102 [005] d..4 309.875185: sched_wake_idle_without_ipi: cpu=1 <idle>-0 [001] d..3 309.875200: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2103 next_prio=19 + - onchange(var).save(field,.. .) + + The 'onchange(var).save(field,...)' hist trigger action is invoked + whenever the value of 'var' associated with a histogram entry + changes. + + The end result is that the trace event fields specified as the + onchange.save() params will be saved if 'var' changes for that + hist trigger entry. This allows context from the event that + changed the value to be saved for later reference. When the + histogram is displayed, additional fields displaying the saved + values will be printed. + + - onchange(var).snapshot() + + The 'onchange(var).snapshot()' hist trigger action is invoked + whenever the value of 'var' associated with a histogram entry + changes. + + The end result is that a global snapshot of the trace buffer will + be saved in the tracing/snapshot file if 'var' changes for any + hist trigger entry. + + Note that in this case the changed value is a global variable + associated withe current trace instance. The key of the specific + trace event that caused the value to change and the global value + itself are displayed, along with a message stating that a snapshot + has been taken and where to find it. The user can use the key + information displayed to locate the corresponding bucket in the + histogram for even more detail. + + As an example the below defines a hist trigger on the tcp_probe + event, keyed on dport. Whenever a tcp_probe event occurs, the + cwnd field is checked against the current value stored in the + $cwnd variable. If the value has changed, a snapshot is taken. + As part of the setup, all the scheduler and tcp events are also + enabled, which are the events that will show up in the snapshot + when it is taken at some point: + + # echo 1 > /sys/kernel/debug/tracing/events/sched/enable + # echo 1 > /sys/kernel/debug/tracing/events/tcp/enable + + # echo 'hist:keys=dport:cwnd=snd_cwnd: \ + onchange($cwnd).save(snd_wnd,srtt,rcv_wnd): \ + onchange($cwnd).snapshot()' >> \ + /sys/kernel/debug/tracing/events/tcp/tcp_probe/trigger + + When the histogram is displayed, for each bucket the tracked value + and the saved values corresponding to that value are displayed + following the rest of the fields. + + If a snaphot was taken, there is also a message indicating that, + along with the value and event that triggered the snapshot: + + # cat /sys/kernel/debug/tracing/events/tcp/tcp_probe/hist + { dport: 1521 } hitcount: 8 + changed: 10 snd_wnd: 35456 srtt: 154262 rcv_wnd: 42112 + + { dport: 80 } hitcount: 23 + changed: 10 snd_wnd: 28960 srtt: 19604 rcv_wnd: 29312 + + { dport: 9001 } hitcount: 172 + changed: 10 snd_wnd: 48384 srtt: 260444 rcv_wnd: 55168 + + { dport: 443 } hitcount: 211 + changed: 10 snd_wnd: 26960 srtt: 17379 rcv_wnd: 28800 + + Snapshot taken (see tracing/snapshot). Details: + triggering value { onchange($cwnd) }: 10 + triggered by event with key: { dport: 80 } + + Totals: + Hits: 414 + Entries: 4 + Dropped: 0 + + In the above case, the event that triggered the snapshot has the + key with dport == 80. If you look at the bucket that has 80 as + the key, you'll find the additional values save()'d along with the + changed value for that bucket, which should be the same as the + global changed value (since that was the same value that triggered + the global snapshot). + + And finally, looking at the snapshot data should show at or near + the end the event that triggered the snapshot: + + # cat /sys/kernel/debug/tracing/snapshot + + gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=49347 [ns] vruntime=1835730389 [ns] + kworker/u16:4-773 [003] d..3 49.823114: sched_switch: prev_comm=kworker/u16:4 prev_pid=773 prev_prio=120 prev_state=R+ ==> next_comm=kworker/3:2 next_pid=135 next_prio=120 + gnome-shell-1261 [006] d..3 49.823114: sched_switch: prev_comm=gnome-shell prev_pid=1261 prev_prio=120 prev_state=R+ ==> next_comm=kworker/6:2 next_pid=387 next_prio=120 + kworker/3:2-135 [003] d..3 49.823118: sched_stat_runtime: comm=kworker/3:2 pid=135 runtime=5339 [ns] vruntime=17815800388 [ns] + kworker/6:2-387 [006] d..3 49.823120: sched_stat_runtime: comm=kworker/6:2 pid=387 runtime=9594 [ns] vruntime=14589605367 [ns] + kworker/6:2-387 [006] d..3 49.823122: sched_switch: prev_comm=kworker/6:2 prev_pid=387 prev_prio=120 prev_state=R+ ==> next_comm=gnome-shell next_pid=1261 next_prio=120 + kworker/3:2-135 [003] d..3 49.823123: sched_switch: prev_comm=kworker/3:2 prev_pid=135 prev_prio=120 prev_state=T ==> next_comm=swapper/3 next_pid=0 next_prio=120 + <idle>-0 [004] ..s7 49.823798: tcp_probe: src=10.0.0.10:54326 dest=23.215.104.193:80 mark=0x0 length=32 snd_nxt=0xe3ae2ff5 snd_una=0xe3ae2ecd snd_cwnd=10 ssthresh=2147483647 snd_wnd=28960 srtt=19604 rcv_wnd=29312 + 3. User space creating a trigger --------------------------------
Signature · 1 line
2.14.1
PATCH v7 12/16 tracing: Add hist trigger onchange() handler test case
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add a test case verifying the basic functionality of the hist:onchange($var) handler.
--- .../inter-event/trigger-onchange-action-hist.tc | 28 ++++++++++++++++++++++ 1 file changed, 28 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onchange-action-hist.tc
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onchange-action-hist.tc new file +28 -0
@@ -0,0 +1,28 @@ +#!/bin/sh +# SPDX-License-Identifier: GPL-2.0 +# description: event trigger - test inter-event histogram trigger onchange action + +fail() { #msg + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +grep -q "onchange(var)" README > /dev/null || exit_unsupported # version issue + +echo "Test onchange action" + +echo 'hist:keys=comm:newprio=prio:onchange($newprio).save(comm,prio) if comm=="ping"' >> /sys/kernel/debug/tracing/events/sched/sched_waking/trigger + +ping $LOCALHOST -c 3 +nice -n 1 ping $LOCALHOST -c 3 + +if ! grep -q "changed:" events/sched/sched_waking/hist; then + fail "Failed to create onchange action inter-event histogram" +fi + +exit 0
Signature · 1 line
2.14.1
PATCH v7 13/16 tracing: Add alternative synthetic event trace action syntax
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add a 'trace(synthetic_event_name, params)' alternative to synthetic_event_name(params).
Currently, the syntax used for generating synthetic events is to invoke synthetic_event_name(params) i.e. use the synthetic event name as a function call.
Users requested a new form that more explicitly shows that the synthetic event is in effect being traced. In this version, a new 'trace()' keyword is used, and the synthetic event name is passed in as the first argument.
--- Documentation/trace/histogram.rst | 21 ++++++++++++++++++++ kernel/trace/trace.c | 1 + kernel/trace/trace_events_hist.c | 42 +++++++++++++++++++++++++++++++++++---- 3 files changed, 60 insertions(+), 4 deletions(-)
Documentation/trace/histogram.rst +21 -0
@@ -1874,6 +1874,7 @@ The available handlers are: The available actions are: - <synthetic_event_name>(param list) - generate synthetic event + - trace(<synthetic_event_name>,(param list)) - generate synthetic event - save(field,...) - save current event fields - snapshot() - snapshot the trace buffer
@@ -1881,6 +1882,10 @@ The following commonly-used handler.action pairs are available: - onmatch(matching.event).<synthetic_event_name>(param list) + or + + - onmatch(matching.event).trace(<synthetic_event_name>,(param list)) + The 'onmatch(matching.event).<synthetic_event_name>(params)' hist trigger action is invoked whenever an event matches and the histogram entry would be added or updated. It causes the named
@@ -1889,6 +1894,16 @@ The following commonly-used handler.action pairs are available: that consists of the values contained in those variables at the time the invoking event was hit. + There are two equivalent forms available for generating synthetic + events. In the first form, the synthetic event name is used as if + it were a function name. For example, if the synthetic event name + is 'wakeup_latency', the wakeup_latency event would be generated + by invoking it as if it were a function call, with the event field + values passed in as arguments: wakeup_latency(arg1,arg2). The + second form simply uses the 'trace' keyword as the function name + and passes in the synthetic event name as the first argument, + followed by the field values: trace(wakeup_latency,arg1,arg2). + The 'param list' consists of one or more parameters which may be either variables or fields defined on either the 'matching.event' or the target event. The variables or fields specified in the
@@ -1928,6 +1943,12 @@ The following commonly-used handler.action pairs are available: wakeup_new_test($testpid) if comm=="cyclictest"' >> \ /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger + Or, equivalently, using the 'trace' keyword syntax: + + # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ + trace(wakeup_new_test,$testpid) if comm=="cyclictest"' >> \ + /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger + Creating and displaying a histogram based on those events is now just a matter of using the fields and new synthetic event in the tracing/events/synthetic directory, as usual::
kernel/trace/trace.c +1 -0
@@ -4886,6 +4886,7 @@ static const char readme_msg[] ="\t onchange(var) - invoke action if var changes\n\n" "\t The available actions are:\n\n" "\t <synthetic_event>(param list) - generate synthetic event\n" +"\t trace(<synthetic_event>,(param list))- generate synthetic event\n" "\t save(field,...) - save current event fields\n" "\t snapshot() - snapshot the trace buffer\n"#endif
kernel/trace/trace_events_hist.c +38 -4
102 lines not on this page · raw message
Signature · 1 line
2.14.1
PATCH v7 14/16 tracing: Add alternative synthetic event trace action test case
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add a test case for the alternative trace(<synthetic_event, params) synthetic event generation syntax.
--- .../inter-event/trigger-trace-action-hist.tc | 42 ++++++++++++++++++++++ 1 file changed, 42 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-trace-action-hist.tc
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-trace-action-hist.tc new file +42 -0
@@ -0,0 +1,42 @@ +#!/bin/sh +# SPDX-License-Identifier: GPL-2.0 +# description: event trigger - test inter-event histogram trigger trace action + +fail() { #msg + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f synthetic_events ]; then + echo "synthetic event is not supported" + exit_unsupported +fi + +grep -q "trace(<synthetic_event>" README > /dev/null || exit_unsupported # version issue + +echo "Test create synthetic event" + +echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events +if [ ! -d events/synthetic/wakeup_latency ]; then + fail "Failed to create wakeup_latency synthetic event" +fi + +echo "Test create histogram for synthetic event using trace action" +echo "Test histogram variables,simple expression support and trace action" + +echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger +echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_wakeup).trace(wakeup_latency,$wakeup_lat,next_pid,next_comm) if next_comm=="ping"' > events/sched/sched_switch/trigger +echo 'hist:keys=comm,pid,lat:wakeup_lat=lat:sort=lat' > events/synthetic/wakeup_latency/trigger + +ping $LOCALHOST -c 5 + +if ! grep -q "ping" events/synthetic/wakeup_latency/hist; then + fail "Failed to create trace action inter-event histogram" +fi + +exit 0
Signature · 1 line
2.14.1
PATCH v7 15/16 tracing: Add hist trigger action 'expected fail' test case
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Add a test case verifying that basic action combinations fail as expected.
--- .../inter-event/trigger-action-hist-xfail.tc | 30 ++++++++++++++++++++++ 1 file changed, 30 insertions(+) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-action-hist-xfail.tc
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-action-hist-xfail.tc new file +30 -0
@@ -0,0 +1,30 @@ +#!/bin/sh +# SPDX-License-Identifier: GPL-2.0 +# description: event trigger - test inter-event histogram trigger expected fail actions + +fail() { #msg + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f snapshot ]; then + echo "snapshot is not supported" + exit_unsupported +fi + +grep -q "snapshot()" README > /dev/null || exit_unsupported # version issue + +echo "Test expected snapshot action failure" + +echo 'hist:keys=comm:onmatch(sched.sched_wakeup).snapshot()' >> /sys/kernel/debug/tracing/events/sched/sched_waking/trigger && exit_fail + +echo "Test expected save action failure" + +echo 'hist:keys=comm:onmatch(sched.sched_wakeup).save(comm,prio)' >> /sys/kernel/debug/tracing/events/sched/sched_waking/trigger && exit_fail + +exit_xfail
Signature · 1 line
2.14.1
PATCH v7 16/16 tracing: Add SPDX license GPL-2.0 license identifier to inter-event testcases
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Apparently this directory was missed in the license cleanup process - add the missing identifiers to the trigger/inter-event test cases.
--- .../ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc | 1 + .../ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc | 1 + .../test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc | 1 + .../ftrace/test.d/trigger/inter-event/trigger-multi-actions-accept.tc | 1 + .../ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc | 1 + .../test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc | 1 + .../ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc | 1 + .../test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc | 1 + 8 files changed, 8 insertions(+)
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc +1 -0
@@ -1,4 +1,5 @@ #!/bin/sh +# SPDX-License-Identifier: GPL-2.0 # description: event trigger - test extended error support
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc +1 -0
@@ -1,4 +1,5 @@ #!/bin/sh +# SPDX-License-Identifier: GPL-2.0 # description: event trigger - test field variable support fail() { #msg
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc +1 -0
@@ -1,4 +1,5 @@ #!/bin/sh +# SPDX-License-Identifier: GPL-2.0 # description: event trigger - test inter-event combined histogram trigger fail() { #msg
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-multi-actions-accept.tc +1 -0
@@ -1,4 +1,5 @@ #!/bin/sh +# SPDX-License-Identifier: GPL-2.0 # description: event trigger - test multiple actions on hist trigger fail() { #msg
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc +1 -0
@@ -1,4 +1,5 @@ #!/bin/sh +# SPDX-License-Identifier: GPL-2.0 # description: event trigger - test inter-event histogram trigger onmatch action fail() { #msg
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc +1 -0
@@ -1,4 +1,5 @@ #!/bin/sh +# SPDX-License-Identifier: GPL-2.0 # description: event trigger - test inter-event histogram trigger onmatch-onmax action fail() { #msg
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc +1 -0
@@ -1,4 +1,5 @@ #!/bin/sh +# SPDX-License-Identifier: GPL-2.0 # description: event trigger - test inter-event histogram trigger onmax action fail() { #msg
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc +1 -0
@@ -1,4 +1,5 @@ #!/bin/sh +# SPDX-License-Identifier: GPL-2.0 # description: event trigger - test synthetic event create remove fail() { #msg
Signature · 1 line
2.14.1
Masami Hiramatsu
maintainerHi Tom,
Quoted 7 lines · On Wed, 14 Nov 2018 14:17:57 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Hi,
This is v7 of the hist trigger snapshot and onchange additions patchset. It does a bit of refactoring to address the suggestions made by Masami in v6.
Thank you for fixing it.
Quoted 9 lines
It also adds an additional patch to update the trigger/inter-event testcases with SPDX license blurbs.
BTW, I noticed that with the recent kselftest changes, I now get mangled output when running the selftests, though I can still see well enough that the tests passed as expected. This happens with any of the ftrace selftests and not just the trigger selftests. In my case, this is using the stock Terminal in Ubuntu 17.10, in case that helps.
Hmm, it should be fixed by8096fbcf55c0 ("selftests/ftrace: Use colored output when available")
Could you check your kernel has this commit?
BTW, what terminal and environment (especially echo command) did you run your tests on? (It seems echo command didn't accept -e option)
Thank you,
Quoted 166 lines
Example output:
# ./ftracetest test.d/trigger/(quoted diff) +0
-11-e === Ftrace unit tests === -e -n [1] event trigger - test inter-event histogram trigger expected fail actions -e [\e[31mXFAIL\e[0m] -e -n [2] event trigger - test extended error support -e [\e[32mPASS\e[0m] -e -n [3] event trigger - test field variable support -e [\e[32mPASS\e[0m] -e -n [4] event trigger - test inter-event combined histogram trigger -e [\e[32mPASS\e[0m] -e -n [5] event trigger - test multiple actions on hist trigger -e [\e[32mPASS\e[0m].
.
.(quoted diff) +0
-8-e -e # of passed: 31 -e # of failed: 0 -e # of unresolved: 0 -e # of untested: 0 -e # of unsupported: 0 -e # of xfailed: 1 -e # of undefined(test bug): 0
v6->v7changes:- Removed unnecessary
HANDLER_ONMAXchecks from onmax_print()/create()
- Moved handler assignment toacion_parse()
- Changed goto inATION_TRACEcase inaction_create()to return
- Changed EINVAL to EEXIST inaction_create()ACTION_SAVEcase
- Made the return logic increate_actions()more consistent
- Merged 'tracing: Move hist trigger key printing into a separate function' into 'tracing: Add hist triggersnapshot()action'
- Updated the new snapshot, onchange, and trace test cases to match 4.20 kselftest changes.
- Added new xfail test case that make sure certain unsupported handler/action combinations fail as expected.
- While updating the test cases, realized that the other testcases in the inter-event subdir needed SPDX license updates, so added them.
v5->v6changes:- Added new Documentation patch explaining handler.action
- Added new README patch explaining handler.action
- Added separatesnapshot()Documentation
- Added newsnapshot()test case
- Updated README withsnapshote()
- Added separateonchange()Documentation
- Added separateonchange()test case
- Updated README withonchange()
- Added separatetrace()test case
- Updated README withtrace()and <synthetic_event>() syntax
v4->v5changes:- added 'trace' keyword test case
- added 'onchange' handler test case
v3->v4changes:- added 'trace' keyword for generating synthetic events
- fixelt_dataleak
- changedcond_updatetocond_update_fn_t
v2->v3changes:- fixed problem where trace actions were only being allowed for onmatch handlers - now trace actions can be used with any handler.
- fixed problem where no action was being assigned to onmatch handlers if save or snapshot actions were specified.
v1->v2changes:- added missing
tracing_cond_snapshot_data()definition for whenCONFIG_TRACER_SNAPSHOTnot defined
- removed an unnecessaryWARN_ON()intrack_data_snapshot_print()Original text:
This patchset adds some useful new functions to the hist trigger code: a snapshot action and an onchange handler.
In order to make it easier to add these and in the process make the code more generic, I separated the code into explicit 'handlers' and 'actions', handlers being things like 'onmax' and 'onchange', and 'actions' being things like 'take a snapshot' or 'save some fields'.
The first few patches do that basic refactoring, which make it easier to add the subsequent changes that arbitrarily combine actions and handlers.
The fourth patch adds a 'conditional snapshot' capability that via a new
tracing_snaphot_cond()function extends the existing snapshot code. It allows the caller to associate some user data with the snapshot that can be checked and saved in anupdate()callback whose return value determines whether the snapshot should be taken or not.The remaining patches finally add the new snapshot action and onchange handler functionality - please see those patches for details and some examples.
Thanks,
Tom
The following changes since commit
ee474b81fe5aa5dc0faae920bf66240fbf55f891:tracing/kprobes: Fix
strpbrk()argument order (2018-11-05 09:47:14 -0500)are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.gitftrace/hist-snapshot-onchange-v7Tom Zanussi (16):
tracing: Refactor hist trigger action code
tracing: Make hist trigger Documentation better reflect
actions/handlers
tracing: Add hist trigger handler.action documentation to README
tracing: Split up onmatch action data
tracing: Generalize hist trigger onmax and save action
tracing: Add conditional snapshot
tracing: Add hist triggersnapshot()action
tracing: Add hist triggersnapshot()action Documentation
tracing: Add hist triggersnapshot()action test case
tracing: Add hist triggeronchange()handler
tracing: Add hist triggeronchange()handler Documentation
tracing: Add hist triggeronchange()handler test case
tracing: Add alternative synthetic event trace action syntax
tracing: Add alternative synthetic event trace action test case
tracing: Add hist trigger action 'expected fail' test case
tracing: Add SPDX license GPL-2.0 license identifier to inter-event
testcasesDocumentation/trace/histogram.rst | 285 +++++- kernel/trace/trace.c | 177 +++- kernel/trace/trace.h | 56 +- kernel/trace/trace_events_hist.c | 1062 +++++++++++++++----- kernel/trace/trace_events_trigger.c | 2 +- kernel/trace/trace_sched_wakeup.c | 2 +- .../inter-event/trigger-action-hist-xfail.tc | 30 + .../inter-event/trigger-extended-error-support.tc | 1 + .../inter-event/trigger-field-variable-support.tc | 1 + .../trigger-inter-event-combined-hist.tc | 1 + .../inter-event/trigger-multi-actions-accept.tc | 1 + .../inter-event/trigger-onchange-action-hist.tc | 28 + .../inter-event/trigger-onmatch-action-hist.tc | 1 + .../trigger-onmatch-onmax-action-hist.tc | 1 + .../inter-event/trigger-onmax-action-hist.tc | 1 + .../inter-event/trigger-snapshot-action-hist.tc | 43 + .../trigger-synthetic-event-createremove.tc | 1 + .../inter-event/trigger-trace-action-hist.tc | 42 + 18 files changed, 1433 insertions(+), 302 deletions(-) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-action-hist-xfail.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onchange-action-hist.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-snapshot-action-hist.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-trace-action-hist.tcSignature · 1 line
2.14.1
Signature · 1 line
Masami Hiramatsu <[email protected]>
Hi Masami,
Quoted 28 lines · Masami Hiramatsu
Hi Tom,
Quoted 7 lines · On Wed, 14 Nov 2018 14:17:57 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Hi,
This is v7 of the hist trigger snapshot and onchange additions patchset. It does a bit of refactoring to address the suggestions made by Masami in v6.
Thank you for fixing it.
Quoted 4 lines
It also adds an additional patch to update the trigger/inter-event testcases with SPDX license blurbs.
Quoted 8 lines
BTW, I noticed that with the recent kselftest changes, I now get mangled output when running the selftests, though I can still see well
enough that the tests passed as expected. This happens with any of the ftrace selftests and not just the trigger selftests. In my case,
this is using the stock Terminal in Ubuntu 17.10, in case that helps.
Quoted 5 lines
Hmm, it should be fixed by
8096fbcf55c0("selftests/ftrace: Use colored output when available")Could you check your kernel has this commit?
Yes, it does have this commit.
Quoted 4 lines
BTW, what terminal and environment (especially echo command) did you run your tests on? (It seems echo command didn't accept -e option)
For that system, I'm using Gnome terminal 3.24.2 and GNU bash, version 4.4.12(1)-release (x86_64-pc-linux-gnu) (Ubuntu 17.10).
If I change 'echo' to '/bin/echo' in e.g. prlog() it works fine, so it must be the inbuilt bash echo that's not doing the right thing. I thought it might be the xpg_echo option, but 'shopt -s xpg_echo' doesn't have any effect.
I also tried on a Fedora 28 system (GNOME terminal 3.28.2, GNU bash, version 4.4.23(1)-release (x86_64-redhat-linux-gnu), and it worked fine.
Also, tried a Ubuntu 18.04.1 system (GNOME Terminal 3.28.1, GNU bash, version 4.4.19(1)-release (x86_64-pc-linux-gnu) and in that case the colors worked fine, but still got the '-e -n' and newlines in the output:
-e -n [28] (instance) event trigger - test histogram modifiers
-e [PASS]
-e -n [29] (instance) event trigger - test histogram trigger
-e [PASS]
Again, substituting '/bin/echo' in prlog() fixed things in this case
too. I guess the builtin bash 'echo' can't be relied on..
Tom
Quoted 197 lines
Thank you,
Quoted 193 lines
Example output:
# ./ftracetest test.d/trigger/(quoted diff) +0
-2-e === Ftrace unit tests === -e -n [1] event trigger - test inter-event histogram triggerexpected fail actions
(quoted diff) +0
-6-e [\e[31mXFAIL\e[0m] -e -n [2] event trigger - test extended error support -e [\e[32mPASS\e[0m] -e -n [3] event trigger - test field variable support -e [\e[32mPASS\e[0m] -e -n [4] event trigger - test inter-event combined histogramtrigger
(quoted diff) +0
-3-e [\e[32mPASS\e[0m] -e -n [5] event trigger - test multiple actions on hist trigger -e [\e[32mPASS\e[0m].
.
.(quoted diff) +0
-8-e -e # of passed: 31 -e # of failed: 0 -e # of unresolved: 0 -e # of untested: 0 -e # of unsupported: 0 -e # of xfailed: 1 -e # of undefined(test bug): 0
v6->v7changes:- Removed unnecessary
HANDLER_ONMAXchecks from
onmax_print()/create()
- Moved handler assignment toacion_parse()
- Changed goto inATION_TRACEcase inaction_create()to return
- Changed EINVAL to EEXIST inaction_create()ACTION_SAVEcase
- Made the return logic increate_actions()more consistent
- Merged 'tracing: Move hist trigger key printing into a separate function' into 'tracing: Add hist triggersnapshot()action'
- Updated the new snapshot, onchange, and trace test cases to
match
4.20 kselftest changes.
- Added new xfail test case that make sure certain unsupported handler/action combinations fail as expected.
- While updating the test cases, realized that the other
testcases
in the inter-event subdir needed SPDX license updates, so added them.
v5->v6changes:- Added new Documentation patch explaining handler.action
- Added new README patch explaining handler.action
- Added separatesnapshot()Documentation
- Added newsnapshot()test case
- Updated README withsnapshote()
- Added separateonchange()Documentation
- Added separateonchange()test case
- Updated README withonchange()
- Added separatetrace()test case
- Updated README withtrace()and <synthetic_event>() syntax
v4->v5changes:- added 'trace' keyword test case
- added 'onchange' handler test case
v3->v4changes:- added 'trace' keyword for generating synthetic events
- fixelt_dataleak
- changedcond_updatetocond_update_fn_t
v2->v3changes:- fixed problem where trace actions were only being allowed for onmatch handlers - now trace actions can be used with any
handler.
- fixed problem where no action was being assigned to onmatch handlers if save or snapshot actions were specified.
v1->v2changes:- added missing
tracing_cond_snapshot_data()definition for whenCONFIG_TRACER_SNAPSHOTnot defined
- removed an unnecessaryWARN_ON()intrack_data_snapshot_print()Original text:
This patchset adds some useful new functions to the hist trigger code: a snapshot action and an onchange handler.
In order to make it easier to add these and in the process make the code more generic, I separated the code into explicit 'handlers' and
'actions', handlers being things like 'onmax' and 'onchange', and 'actions' being things like 'take a snapshot' or 'save some fields'.The first few patches do that basic refactoring, which make it easier
to add the subsequent changes that arbitrarily combine actions and handlers.The fourth patch adds a 'conditional snapshot' capability that via a
newtracing_snaphot_cond()function extends the existing snapshot code. It allows the caller to associate some user data with the snapshot that can be checked and saved in anupdate()callback whose
return value determines whether the snapshot should be taken or not.The remaining patches finally add the new snapshot action and onchange
handler functionality - please see those patches for details and some
examples.Thanks,
Tom
The following changes since commit
ee474b81fe5aa5dc0faae920bf66240fbf55f891:tracing/kprobes: Fix
strpbrk()argument order (2018-11-05
09:47:14 -0500)are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-
trace.git ftrace/hist-snapshot-onchange-v7Tom Zanussi (16):
tracing: Refactor hist trigger action code
tracing: Make hist trigger Documentation better reflect
actions/handlers
tracing: Add hist trigger handler.action documentation to README
tracing: Split up onmatch action data
tracing: Generalize hist trigger onmax and save action
tracing: Add conditional snapshot
tracing: Add hist triggersnapshot()action
tracing: Add hist triggersnapshot()action Documentation
tracing: Add hist triggersnapshot()action test case
tracing: Add hist triggeronchange()handler
tracing: Add hist triggeronchange()handler Documentation
tracing: Add hist triggeronchange()handler test case
tracing: Add alternative synthetic event trace action syntax
tracing: Add alternative synthetic event trace action test case
tracing: Add hist trigger action 'expected fail' test case
tracing: Add SPDX license GPL-2.0 license identifier to inter-
event
testcasesDocumentation/trace/histogram.rst | 285 +++++- kernel/trace/trace.c | 177 +++- kernel/trace/trace.h | 56 +- kernel/trace/trace_events_hist.c | 1062 +++++++++++++++----- kernel/trace/trace_events_trigger.c | 2 +- kernel/trace/trace_sched_wakeup.c | 2 +- .../inter-event/trigger-action-hist-xfail.tc | 30 + .../inter-event/trigger-extended-error-support.tc | 1 + .../inter-event/trigger-field-variable-support.tc | 1 + .../trigger-inter-event-combined-hist.tc | 1 + .../inter-event/trigger-multi-actions-accept.tc | 1 + .../inter-event/trigger-onchange-action-hist.tc | 28 + .../inter-event/trigger-onmatch-action-hist.tc | 1 + .../trigger-onmatch-onmax-action-hist.tc | 1 + .../inter-event/trigger-onmax-action-hist.tc | 1 + .../inter-event/trigger-snapshot-action-hist.tc | 43 + .../trigger-synthetic-event-createremove.tc | 1 + .../inter-event/trigger-trace-action-hist.tc | 42 + 18 files changed, 1433 insertions(+), 302 deletions(-) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger- action-hist-xfail.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger- onchange-action-hist.tc create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger- snapshot-action-hist.tc create mode 100644
tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-trace-action-hist.tcSignature · 1 line
2.14.1
Masami Hiramatsu
maintainerQuoted 66 lines · On Mon, 26 Nov 2018 15:21:28 -0600 Tom Zanussi <[email protected]> wrote:
Hi Masami,
Quoted 28 lines · Masami Hiramatsu
Hi Tom,
Quoted 7 lines · On Wed, 14 Nov 2018 14:17:57 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Hi,
This is v7 of the hist trigger snapshot and onchange additions patchset. It does a bit of refactoring to address the suggestions made by Masami in v6.
Thank you for fixing it.
Quoted 4 lines
It also adds an additional patch to update the trigger/inter-event testcases with SPDX license blurbs.
Quoted 8 lines
BTW, I noticed that with the recent kselftest changes, I now get mangled output when running the selftests, though I can still see well
enough that the tests passed as expected. This happens with any of the ftrace selftests and not just the trigger selftests. In my case,
this is using the stock Terminal in Ubuntu 17.10, in case that helps.Quoted 5 lines
Hmm, it should be fixed by
8096fbcf55c0("selftests/ftrace: Use colored output when available")Could you check your kernel has this commit?
Yes, it does have this commit.
Quoted 4 lines
BTW, what terminal and environment (especially echo command) did you run your tests on? (It seems echo command didn't accept -e option)
For that system, I'm using Gnome terminal 3.24.2 and GNU bash, version 4.4.12(1)-release (x86_64-pc-linux-gnu) (Ubuntu 17.10).
If I change 'echo' to '
/bin/echo' in e.g.prlog()it works fine, so it must be the inbuilt bash echo that's not doing the right thing. I thought it might be thexpg_echooption, but 'shopt -sxpg_echo' doesn't have any effect.I also tried on a Fedora 28 system (GNOME terminal 3.28.2, GNU bash, version 4.4.23(1)-release (x86_64-redhat-linux-gnu), and it worked fine.
Also, tried a Ubuntu 18.04.1 system (GNOME Terminal 3.28.1, GNU bash, version 4.4.19(1)-release (x86_64-pc-linux-gnu) and in that case the colors worked fine, but still got the '-e -n' and newlines in the output:
(quoted diff) +0
-4-e -n [28] (instance) event trigger - test histogram modifiers -e [PASS] -e -n [29] (instance) event trigger - test histogram trigger -e [PASS]
Quoted 2 lines
Again, substituting '
/bin/echo' inprlog()fixed things in this case
too. I guess the builtin bash 'echo' can't be relied on..
OK, then we should use /bin/echo for avoiding this issue.
Thank you!
Signature · 1 line
Masami Hiramatsu <[email protected]>
Masami Hiramatsu
maintainerQuoted 22 lines · On Thu, 29 Nov 2018 22:52:25 +0900 Masami Hiramatsu <[email protected]> wrote:
Quoted 22 lines
For that system, I'm using Gnome terminal 3.24.2 and GNU bash, version 4.4.12(1)-release (x86_64-pc-linux-gnu) (Ubuntu 17.10).
If I change 'echo' to '
/bin/echo' in e.g.prlog()it works fine, so it must be the inbuilt bash echo that's not doing the right thing. I thought it might be thexpg_echooption, but 'shopt -sxpg_echo' doesn't have any effect.I also tried on a Fedora 28 system (GNOME terminal 3.28.2, GNU bash, version 4.4.23(1)-release (x86_64-redhat-linux-gnu), and it worked fine.
Also, tried a Ubuntu 18.04.1 system (GNOME Terminal 3.28.1, GNU bash, version 4.4.19(1)-release (x86_64-pc-linux-gnu) and in that case the colors worked fine, but still got the '-e -n' and newlines in the output:
(quoted diff) +0
-4-e -n [28] (instance) event trigger - test histogram modifiers -e [PASS] -e -n [29] (instance) event trigger - test histogram trigger -e [PASS]
Quoted 4 lines
Quoted 2 lines
Again, substituting '
/bin/echo' inprlog()fixed things in this case
too. I guess the builtin bash 'echo' can't be relied on..OK, then we should use
/bin/echofor avoiding this issue.
Ah, I found that usually ubuntu system use "dash" instead of "bash" for the alias of "sh", and its builtin echo command doesn't accept "-e". So if the first option is "-e", it treats all arguments are output string, including -e.
Anyway, still using /bin/echo is the best solution.
Thank you,
Signature · 1 line
Masami Hiramatsu <[email protected]>
Masami Hiramatsu
maintainerPATCH 1/1 sefltests/ftrace: Use /bin/echo for output with options
Use /bin/echo for console output with options like non newline (-n) and/or backslash escape (-e).
Tom Zanussi reported that when he tested ftracetest, it shows "-e" and "-n" options on the console, since a system which uses dash as the alias of /bin/sh, uses dash built-in echo command which doesn't accept "-e".
To avoid this issue, use /bin/echo instead of echo for the output with options.
--- tools/testing/selftests/ftrace/ftracetest | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)
tools/testing/selftests/ftrace/ftracetest +2 -2
@@ -173,8 +173,8 @@ strip_esc() { } prlog() { # messages - echo -e "$@" - [ "$LOG_FILE" ] && echo -e "$@" | strip_esc >> $LOG_FILE + /bin/echo -e "$@" + [ "$LOG_FILE" ] && /bin/echo -e "$@" | strip_esc >> $LOG_FILE } catlog() { #file cat $1
Re: [PATCH] sefltests/ftrace: Use /bin/echo for output with options
Quoted 25 lines · On Fri, 30 Nov 2018 00:07:43 +0900 Masami Hiramatsu <mhiramat at kernel.org>…
Use
/bin/echofor console output with options like non newline (-n) and/or backslash escape (-e).Tom Zanussi reported that when he tested ftracetest, it shows "-e" and "-n" options on the console, since a system which uses dash as the alias of
/bin/sh, uses dash built-in echo command which doesn't accept "-e".To avoid this issue, use
/bin/echoinstead of echo for the output with options.Fixes 8f381ac4d321 ("selftests/ftrace: Add color to the PASS / FAIL results")Link http://lkml.kernel.org/r/cover.1542221862.git.tom.zanussi at linux.intel.comReported-by Tom Zanussi <zanussi at kernel.org>Suggested-by Tom Zanussi <zanussi at kernel.org>Signed-off-by Masami Hiramatsu <mhiramat at kernel.org>--- tools/testing/selftests/ftrace/ftracetest | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)tools/testing/selftests/ftrace/ftracetest +0
-0
tools/testing/selftests/ftrace/ftracetest strip_esc() { · line 180
Quoted 10 lines
tools/testing/selftests/ftrace/ftracetest +2
-2@@ -173,8 +173,8 @@ strip_esc() { } prlog() { # messages - echo -e "$@" - [ "$LOG_FILE" ] && echo -e "$@" | strip_esc >> $LOG_FILE + /bin/echo -e "$@" + [ "$LOG_FILE" ] && /bin/echo -e "$@" | strip_esc >> $LOG_FILE } catlog() { #file cat $1
I'm fine with this change but I wonder if we should have a $ECHO that is defined to something that can be overwritten if need be.
-- Steve
Re: [PATCH] sefltests/ftrace: Use /bin/echo for output with options
In reply to Masami HiramatsuHi Masami,
Quoted 29 lines · Masami Hiramatsu
Use
/bin/echofor console output with options like non newline (-n) and/or backslash escape (-e).Tom Zanussi reported that when he tested ftracetest, it shows "-e" and "-n" options on the console, since a system which uses dash as the alias of
/bin/sh, uses dash built-in echo command which doesn't accept "-e".To avoid this issue, use
/bin/echoinstead of echo for the output with options.Fixes 8f381ac4d321 ("selftests/ftrace: Add color to the PASS / FAILresults")
.intel.com
Reported-by: Tom Zanussi <zanussi at kernel.org>
Suggested-by: Tom Zanussi <zanussi at kernel.org>
Signed-off-by: Masami Hiramatsu <mhiramat at kernel.org>--- tools/testing/selftests/ftrace/ftracetest | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-)tools/testing/selftests/ftrace/ftracetest +0
-0
tools/testing/selftests/ftrace/ftracetest strip_esc() { · line 180
Quoted 10 lines
tools/testing/selftests/ftrace/ftracetest +2
-2@@ -173,8 +173,8 @@ strip_esc() { } prlog() { # messages - echo -e "$@" - [ "$LOG_FILE" ] && echo -e "$@" | strip_esc >> $LOG_FILE + /bin/echo -e "$@" + [ "$LOG_FILE" ] && /bin/echo -e "$@" | strip_esc >> $LOG_FILE } catlog() { #file cat $1
I tried this on the three systems mentioned before, and it worked fine on all of them.
Steven Rostedt
maintainerRe: [PATCH] sefltests/ftrace: Use /bin/echo for output with options
Quoted 4 lines · On Thu, 29 Nov 2018 10:43:13 -0600 Tom Zanussi <[email protected]> wrote:
I tried this on the three systems mentioned before, and it worked fine on all of them.
Tested-by Tom Zanussi <tom.zanussi at linux.intel.com>
Shuah,
Can you take this in your tree. I already acked it.
Thanks!
-- Steve
Re: [PATCH] sefltests/ftrace: Use /bin/echo for output with options
Quoted 7 lines · Steven Rostedt
Quoted 4 lines · On Thu, 29 Nov 2018 10:43:13 -0600 Tom Zanussi <[email protected]> wrote:
I tried this on the three systems mentioned before, and it worked fine
on all of them.
Quoted 7 lines
Quoted 1 line
Tested-by Tom Zanussi <tom.zanussi at linux.intel.com>Shuah,
Can you take this in your tree. I already acked it.
Ping...
Quoted 3 lines
Thanks!
-- Steve