* Using matched variables in trace actions
@ 2020-01-29 3:01 Steven Rostedt
2020-01-29 14:19 ` Tom Zanussi
2020-01-29 22:08 ` Tom Zanussi
0 siblings, 2 replies; 3+ messages in thread
From: Steven Rostedt @ 2020-01-29 3:01 UTC (permalink / raw)
To: Tom Zanussi; +Cc: LKML
Hi Tom,
I was debugging a histogram that wasn't working.
I had the following:
# cd /sys/kernel/tracing/
# echo 'first u64 start_time u64 end_time pid_t pid u64 delta' > synthetic_events
# echo 'hist:keys=pid:start_time=common_timestamp' > events/sched/sched_waking/trigger
# echo 'hist:keys=next_pid:delta=common_timestamp-$start_time:onmatch(sched.sched_waking).first($start_time,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger
Which produced:
# echo 1 > synthetic/enable
# cat trace
[..]
<idle>-0 [005] d..4 342.980379: first: start_time=342980373002 end_time=197 pid=43140 delta=18446744072217752717
<idle>-0 [000] d..4 342.980439: first: start_time=342980434369 end_time=1598 pid=44526 delta=18446744072239552512
<idle>-0 [005] d..4 342.980495: first: start_time=342980489992 end_time=197 pid=44739 delta=18446744072217752717
<idle>-0 [000] d..4 342.980528: first: start_time=342980525307 end_time=1598 pid=15317 delta=18446744072239552512
<idle>-0 [003] d..4 342.981176: first: start_time=342981170950 end_time=10 pid=42697 delta=18446744072217752717
<idle>-0 [003] d..4 342.985178: first: start_time=342985174789 end_time=10 pid=31097 delta=18446744072217752717
<idle>-0 [003] d..4 342.989172: first: start_time=342989168085 end_time=10 pid=30487 delta=18446744072217752717
<idle>-0 [001] d..4 343.044173: first: start_time=343044169712 end_time=593 pid=30677 delta=18446744072217752717
<idle>-0 [003] d..4 343.358828: first: start_time=343358824790 end_time=713 pid=24892 delta=18446744072217752717
<idle>-0 [003] d..4 343.533459: first: start_time=343533455001 end_time=1466 pid=24272 delta=18446744072217752717
Now, this is strange, because the end_time should not ever be 10!
I added debugging and found that everything is shifted off by one.
That is for
<idle>-0 [003] d..4 343.533459: first: start_time=343533455001 end_time=1466 pid=24272 delta=18446744072217752717
end_time is actually 343533455001
pid is actually 1466
and delta is 24272
Which also means that that delta that is printed is reading some random
variable, and if you look at it in hex it's ffffffffa714f48d which
looks to be some random pointer.
Playing with this, I found that the issue is that I have $start_time in
my parameter list for the synthetic event. But $start_time was a
variable defined by sched_waking and not sched_switch. Although the
references can read that variable, the synthetic parameters fail on
that, and basically ignore it.
That is, if I add start=$start_time and use $start as a parameter it
works fine.
# echo 'hist:keys=next_pid:start=$start_time,delta=common_timestamp-$start_time:onmatch(sched.sched_waking).first($start,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger
# cat trace
[...]
<idle>-0 [001] d..4 679.668272: first: start_time=679668221531 end_time=679668266756 pid=1598 delta=45225
<idle>-0 [006] d..4 679.668425: first: start_time=679668406777 end_time=679668420837 pid=10 delta=14060
<idle>-0 [006] d..4 679.672431: first: start_time=679672407062 end_time=679672426696 pid=10 delta=19634
<idle>-0 [006] d..4 679.676443: first: start_time=679676408260 end_time=679676438476 pid=10 delta=30216
<idle>-0 [003] d..4 679.715562: first: start_time=679715533636 end_time=679715558490 pid=713 delta=24854
<idle>-0 [003] d..4 679.865699: first: start_time=679865670612 end_time=679865695333 pid=1466 delta=24721
<idle>-0 [003] d..4 679.865775: first: start_time=679865764528 end_time=679865773007 pid=1466 delta=8479
<idle>-0 [003] d..4 679.865842: first: start_time=679865833406 end_time=679865840063 pid=1466 delta=6657
<idle>-0 [003] d..4 679.865906: first: start_time=679865898302 end_time=679865904792 pid=1466 delta=6490
<idle>-0 [003] d..4 679.865970: first: start_time=679865962239 end_time=679865968686 pid=1466 delta=6447
<idle>-0 [003] d..4 679.866034: first: start_time=679866026284 end_time=679866032651 pid=1466 delta=6367
<idle>-0 [003] d..4 679.866098: first: start_time=679866090264 end_time=679866096593 pid=1466 delta=6329
<idle>-0 [003] d..4 679.866162: first: start_time=679866154251 end_time=679866160656 pid=1466 delta=6405
<idle>-0 [003] d..4 679.866226: first: start_time=679866218281 end_time=679866224500 pid=1466 delta=6219
<idle>-0 [003] d..4 679.866290: first: start_time=679866282296 end_time=679866288558 pid=1466 delta=6262
But this is a bug. We either should fail the creation of the trigger,
or we should allow it and handle it properly.
-- Steve
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: Using matched variables in trace actions
2020-01-29 3:01 Using matched variables in trace actions Steven Rostedt
@ 2020-01-29 14:19 ` Tom Zanussi
2020-01-29 22:08 ` Tom Zanussi
1 sibling, 0 replies; 3+ messages in thread
From: Tom Zanussi @ 2020-01-29 14:19 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML
Hi Steve,
On Tue, 2020-01-28 at 22:01 -0500, Steven Rostedt wrote:
> Hi Tom,
>
> I was debugging a histogram that wasn't working.
>
> I had the following:
>
> # cd /sys/kernel/tracing/
> # echo 'first u64 start_time u64 end_time pid_t pid u64 delta' > synthetic_events
> # echo 'hist:keys=pid:start_time=common_timestamp' > events/sched/sched_waking/trigger
> # echo 'hist:keys=next_pid:delta=common_timestamp-$start_time:onmatch(sched.sched_waking).first($start_time,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger
>
> Which produced:
>
Yes, this is definitely strange, and a bug. I'll root-cause it and try
to come up with a fix today. Thanks for reporting it, as well as the
workaround.
Tom
> # echo 1 > synthetic/enable
> # cat trace
> [..]
> <idle>-0 [005] d..4 342.980379: first: start_time=342980373002 end_time=197 pid=43140 delta=18446744072217752717
> <idle>-0 [000] d..4 342.980439: first: start_time=342980434369 end_time=1598 pid=44526 delta=18446744072239552512
> <idle>-0 [005] d..4 342.980495: first: start_time=342980489992 end_time=197 pid=44739 delta=18446744072217752717
> <idle>-0 [000] d..4 342.980528: first: start_time=342980525307 end_time=1598 pid=15317 delta=18446744072239552512
> <idle>-0 [003] d..4 342.981176: first: start_time=342981170950 end_time=10 pid=42697 delta=18446744072217752717
> <idle>-0 [003] d..4 342.985178: first: start_time=342985174789 end_time=10 pid=31097 delta=18446744072217752717
> <idle>-0 [003] d..4 342.989172: first: start_time=342989168085 end_time=10 pid=30487 delta=18446744072217752717
> <idle>-0 [001] d..4 343.044173: first: start_time=343044169712 end_time=593 pid=30677 delta=18446744072217752717
> <idle>-0 [003] d..4 343.358828: first: start_time=343358824790 end_time=713 pid=24892 delta=18446744072217752717
> <idle>-0 [003] d..4 343.533459: first: start_time=343533455001 end_time=1466 pid=24272 delta=18446744072217752717
>
> Now, this is strange, because the end_time should not ever be 10!
>
> I added debugging and found that everything is shifted off by one.
>
> That is for
>
> <idle>-0 [003] d..4 343.533459: first: start_time=343533455001 end_time=1466 pid=24272 delta=18446744072217752717
>
>
> end_time is actually 343533455001
> pid is actually 1466
> and delta is 24272
>
> Which also means that that delta that is printed is reading some random
> variable, and if you look at it in hex it's ffffffffa714f48d which
> looks to be some random pointer.
>
> Playing with this, I found that the issue is that I have $start_time in
> my parameter list for the synthetic event. But $start_time was a
> variable defined by sched_waking and not sched_switch. Although the
> references can read that variable, the synthetic parameters fail on
> that, and basically ignore it.
>
> That is, if I add start=$start_time and use $start as a parameter it
> works fine.
>
> # echo 'hist:keys=next_pid:start=$start_time,delta=common_timestamp-$start_time:onmatch(sched.sched_waking).first($start,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger
>
>
> # cat trace
> [...]
> <idle>-0 [001] d..4 679.668272: first: start_time=679668221531 end_time=679668266756 pid=1598 delta=45225
> <idle>-0 [006] d..4 679.668425: first: start_time=679668406777 end_time=679668420837 pid=10 delta=14060
> <idle>-0 [006] d..4 679.672431: first: start_time=679672407062 end_time=679672426696 pid=10 delta=19634
> <idle>-0 [006] d..4 679.676443: first: start_time=679676408260 end_time=679676438476 pid=10 delta=30216
> <idle>-0 [003] d..4 679.715562: first: start_time=679715533636 end_time=679715558490 pid=713 delta=24854
> <idle>-0 [003] d..4 679.865699: first: start_time=679865670612 end_time=679865695333 pid=1466 delta=24721
> <idle>-0 [003] d..4 679.865775: first: start_time=679865764528 end_time=679865773007 pid=1466 delta=8479
> <idle>-0 [003] d..4 679.865842: first: start_time=679865833406 end_time=679865840063 pid=1466 delta=6657
> <idle>-0 [003] d..4 679.865906: first: start_time=679865898302 end_time=679865904792 pid=1466 delta=6490
> <idle>-0 [003] d..4 679.865970: first: start_time=679865962239 end_time=679865968686 pid=1466 delta=6447
> <idle>-0 [003] d..4 679.866034: first: start_time=679866026284 end_time=679866032651 pid=1466 delta=6367
> <idle>-0 [003] d..4 679.866098: first: start_time=679866090264 end_time=679866096593 pid=1466 delta=6329
> <idle>-0 [003] d..4 679.866162: first: start_time=679866154251 end_time=679866160656 pid=1466 delta=6405
> <idle>-0 [003] d..4 679.866226: first: start_time=679866218281 end_time=679866224500 pid=1466 delta=6219
> <idle>-0 [003] d..4 679.866290: first: start_time=679866282296 end_time=679866288558 pid=1466 delta=6262
>
> But this is a bug. We either should fail the creation of the trigger,
> or we should allow it and handle it properly.
>
> -- Steve
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: Using matched variables in trace actions
2020-01-29 3:01 Using matched variables in trace actions Steven Rostedt
2020-01-29 14:19 ` Tom Zanussi
@ 2020-01-29 22:08 ` Tom Zanussi
1 sibling, 0 replies; 3+ messages in thread
From: Tom Zanussi @ 2020-01-29 22:08 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML
Hi Steve,
On Tue, 2020-01-28 at 22:01 -0500, Steven Rostedt wrote:
> Hi Tom,
>
> I was debugging a histogram that wasn't working.
>
> I had the following:
>
> # cd /sys/kernel/tracing/
> # echo 'first u64 start_time u64 end_time pid_t pid u64 delta' > synthetic_events
> # echo 'hist:keys=pid:start_time=common_timestamp' > events/sched/sched_waking/trigger
> # echo 'hist:keys=next_pid:delta=common_timestamp-$start_time:onmatch(sched.sched_waking).first($start_time,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger
>
> Which produced:
>
> # echo 1 > synthetic/enable
> # cat trace
> [..]
> <idle>-0 [005] d..4 342.980379: first: start_time=342980373002 end_time=197 pid=43140 delta=18446744072217752717
> <idle>-0 [000] d..4 342.980439: first: start_time=342980434369 end_time=1598 pid=44526 delta=18446744072239552512
> <idle>-0 [005] d..4 342.980495: first: start_time=342980489992 end_time=197 pid=44739 delta=18446744072217752717
This problem is fallout of the 'tracing: Fix histogram code when
expression has same var as value' fix, which because now that the
var_ref_vals var ref positions are unique, breaks the assumption that
the trace action params are all in a row at the end. So in this case,
they're one off and so the values are skewed by one position.
The patch below fixes the problem for me and passes all the ftrace
tests.
Tom
[PATCH] tracing: Fix now invalid var_ref_vals assumption in trace action
The patch 'tracing: Fix histogram code when expression has same var as
value' added code to return an existing variable reference when
creating a new variable reference, which resulted in var_ref_vals
slots being reused instead of being duplicated.
The implementation of the trace action assumes that the end of the
var_ref_vals array starting at action_data.var_ref_idx corresponds to
the values that will be assigned to the trace params. The patch
mentioned above invalidates that assumption, which means that each
param needs to explicitly specify its index into var_ref_vals.
This fix changes action_data.var_ref_idx to an array of var ref
indexes to account for that.
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
kernel/trace/trace_events_hist.c | 53 ++++++++++++++++++++++++++++------------
1 file changed, 38 insertions(+), 15 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 95a2ba9ff495..cb52ae05f6fe 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -475,11 +475,12 @@ struct action_data {
* 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.
+ * var_ref_vals array. This var_ref_idx array is an array of
+ * indices into the var_ref_vals array, one for each synthetic
+ * event param, and is passed to the synthetic event
+ * invocation.
*/
- unsigned int var_ref_idx;
+ unsigned int var_ref_idx[TRACING_MAP_VARS_MAX];
struct synth_event *synth_event;
bool use_trace_keyword;
char *synth_event_name;
@@ -881,14 +882,14 @@ static struct trace_event_functions synth_event_funcs = {
static notrace void trace_event_raw_event_synth(void *__data,
u64 *var_ref_vals,
- unsigned int var_ref_idx)
+ unsigned int *var_ref_idx)
{
struct trace_event_file *trace_file = __data;
struct synth_trace_event *entry;
struct trace_event_buffer fbuffer;
struct trace_buffer *buffer;
struct synth_event *event;
- unsigned int i, n_u64;
+ unsigned int i, n_u64, val_idx;
int fields_size = 0;
event = trace_file->event_call->data;
@@ -911,15 +912,16 @@ static notrace void trace_event_raw_event_synth(void *__data,
goto out;
for (i = 0, n_u64 = 0; i < event->n_fields; i++) {
+ val_idx = var_ref_idx[i];
if (event->fields[i]->is_string) {
- char *str_val = (char *)(long)var_ref_vals[var_ref_idx + i];
+ char *str_val = (char *)(long)var_ref_vals[val_idx];
char *str_field = (char *)&entry->fields[n_u64];
strscpy(str_field, str_val, STR_VAR_LEN_MAX);
n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
} else {
struct synth_field *field = event->fields[i];
- u64 val = var_ref_vals[var_ref_idx + i];
+ u64 val = var_ref_vals[val_idx];
switch (field->size) {
case 1:
@@ -1119,10 +1121,10 @@ static struct tracepoint *alloc_synth_tracepoint(char *name)
}
typedef void (*synth_probe_func_t) (void *__data, u64 *var_ref_vals,
- unsigned int var_ref_idx);
+ unsigned int *var_ref_idx);
static inline void trace_synth(struct synth_event *event, u64 *var_ref_vals,
- unsigned int var_ref_idx)
+ unsigned int *var_ref_idx)
{
struct tracepoint *tp = event->tp;
@@ -2663,6 +2665,22 @@ static int init_var_ref(struct hist_field *ref_field,
goto out;
}
+static int find_var_ref_idx(struct hist_trigger_data *hist_data,
+ struct hist_field *var_field)
+{
+ struct hist_field *ref_field;
+ int i;
+
+ for (i = 0; i < hist_data->n_var_refs; i++) {
+ ref_field = hist_data->var_refs[i];
+ if (ref_field->var.idx == var_field->var.idx &&
+ ref_field->var.hist_data == var_field->hist_data)
+ return i;
+ }
+
+ return -ENOENT;
+}
+
/**
* create_var_ref - Create a variable reference and attach it to trigger
* @hist_data: The trigger that will be referencing the variable
@@ -4239,11 +4257,11 @@ static int trace_action_create(struct hist_trigger_data *hist_data,
struct trace_array *tr = hist_data->event_file->tr;
char *event_name, *param, *system = NULL;
struct hist_field *hist_field, *var_ref;
- unsigned int i, var_ref_idx;
+ unsigned int i;
unsigned int field_pos = 0;
struct synth_event *event;
char *synth_event_name;
- int ret = 0;
+ int var_ref_idx, ret = 0;
lockdep_assert_held(&event_mutex);
@@ -4260,8 +4278,6 @@ static int trace_action_create(struct hist_trigger_data *hist_data,
event->ref++;
- var_ref_idx = hist_data->n_var_refs;
-
for (i = 0; i < data->n_params; i++) {
char *p;
@@ -4310,6 +4326,14 @@ static int trace_action_create(struct hist_trigger_data *hist_data,
goto err;
}
+ var_ref_idx = find_var_ref_idx(hist_data, var_ref);
+ if (WARN_ON(var_ref_idx < 0)) {
+ ret = var_ref_idx;
+ goto err;
+ }
+
+ data->var_ref_idx[i] = var_ref_idx;
+
field_pos++;
kfree(p);
continue;
@@ -4328,7 +4352,6 @@ static int trace_action_create(struct hist_trigger_data *hist_data,
}
data->synth_event = event;
- data->var_ref_idx = var_ref_idx;
out:
return ret;
err:
--
2.14.1
^ permalink raw reply related [flat|nested] 3+ messages in thread
end of thread, other threads:[~2020-01-29 22:08 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-01-29 3:01 Using matched variables in trace actions Steven Rostedt
2020-01-29 14:19 ` Tom Zanussi
2020-01-29 22:08 ` Tom Zanussi
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).