[PATCH v5 8/8] trace: Add alternative synthetic event trace action syntax

From: Tom Zanussi
Date: Mon Oct 01 2018 - 12:18:51 EST


From: Tom Zanussi <tom.zanussi@xxxxxxxxxxxxxxx>

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.

Signed-off-by: Tom Zanussi <tom.zanussi@xxxxxxxxxxxxxxx>
---
Documentation/trace/histogram.rst | 20 +++++++++++
kernel/trace/trace_events_hist.c | 42 +++++++++++++++++++---
.../inter-event/trigger-onmatch-action-hist.tc | 13 +++++++
3 files changed, 71 insertions(+), 4 deletions(-)

diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histogram.rst
index e73a840a3598..98f960af0072 100644
--- a/Documentation/trace/histogram.rst
+++ b/Documentation/trace/histogram.rst
@@ -1849,6 +1849,10 @@ hist trigger specification.

- 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
@@ -1857,6 +1861,16 @@ hist trigger specification.
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
@@ -1896,6 +1910,12 @@ hist trigger specification.
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::
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 90f1a0cf34c0..05234538505e 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -352,6 +352,8 @@ struct action_data {

unsigned int var_ref_idx;
struct synth_event *synth_event;
+ bool use_trace_keyword;
+ char *synth_event_name;

union {
struct {
@@ -3584,6 +3586,8 @@ static void action_data_destroy(struct action_data *data)
if (data->synth_event)
data->synth_event->ref--;

+ kfree(data->synth_event_name);
+
kfree(data);

mutex_unlock(&synth_event_mutex);
@@ -3678,6 +3682,7 @@ static int track_data_create(struct hist_trigger_data *hist_data,
static int parse_action_params(char *params, struct action_data *data)
{
char *param, *saved_param;
+ bool first_param = true;
int ret = 0;

while (params) {
@@ -3706,6 +3711,13 @@ static int parse_action_params(char *params, struct action_data *data)
goto out;
}

+ if (first_param && data->use_trace_keyword) {
+ data->synth_event_name = saved_param;
+ first_param = false;
+ continue;
+ }
+ first_param = false;
+
data->params[data->n_params++] = saved_param;
}
out:
@@ -3789,6 +3801,9 @@ static int action_parse(char *str, struct action_data *data,
} else {
char *params = strsep(&str, ")");

+ if (strncmp(action_name, "trace", strlen("trace")) == 0)
+ data->use_trace_keyword = true;
+
if (params) {
ret = parse_action_params(params, data);
if (ret)
@@ -4007,13 +4022,19 @@ static int trace_action_create(struct hist_trigger_data *hist_data,
unsigned int i, var_ref_idx;
unsigned int field_pos = 0;
struct synth_event *event;
+ char *synth_event_name;
int ret = 0;

mutex_lock(&synth_event_mutex);

- event = find_synth_event(data->action_name);
+ if (data->use_trace_keyword)
+ synth_event_name = data->synth_event_name;
+ else
+ synth_event_name = data->action_name;
+
+ event = find_synth_event(synth_event_name);
if (!event) {
- hist_err("trace action: Couldn't find synthetic event: ", data->action_name);
+ hist_err("trace action: Couldn't find synthetic event: ", synth_event_name);
mutex_unlock(&synth_event_mutex);
return -EINVAL;
}
@@ -4781,8 +4802,10 @@ static void print_action_spec(struct seq_file *m,
seq_puts(m, ",");
}
} else if (data->action == ACTION_TRACE) {
+ if (data->use_trace_keyword)
+ seq_printf(m, "%s", data->synth_event_name);
for (i = 0; i < data->n_params; i++) {
- if (i)
+ if (i || data->use_trace_keyword)
seq_puts(m, ",");
seq_printf(m, "%s", data->params[i]);
}
@@ -4830,6 +4853,7 @@ static bool actions_match(struct hist_trigger_data *hist_data,
for (i = 0; i < hist_data->n_actions; i++) {
struct action_data *data = hist_data->actions[i];
struct action_data *data_test = hist_data_test->actions[i];
+ char *action_name, *action_name_test;

if (data->handler != data_test->handler)
return false;
@@ -4844,7 +4868,17 @@ static bool actions_match(struct hist_trigger_data *hist_data,
return false;
}

- if (strcmp(data->action_name, data_test->action_name) != 0)
+ if (data->use_trace_keyword)
+ action_name = data->synth_event_name;
+ else
+ action_name = data->action_name;
+
+ if (data_test->use_trace_keyword)
+ action_name_test = data_test->synth_event_name;
+ else
+ action_name_test = data_test->action_name;
+
+ if (strcmp(action_name, action_name_test) != 0)
return false;

if (data->handler == HANDLER_ONMATCH) {
diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc
index e84e7d048566..28beb83b61aa 100644
--- a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc
@@ -47,4 +47,17 @@ fi

do_reset

+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
+
+do_reset
+
exit 0
--
2.14.1