The patch below does not apply to the 4.19-stable tree. If someone wants it applied there, or to any other stable or longterm tree, then please email the backport, including the original git commit id to stable@vger.kernel.org.
thanks,
greg k-h
------------------ original commit in Linus's tree ------------------
From 8bcebc77e85f3d7536f96845a0fe94b1dddb6af0 Mon Sep 17 00:00:00 2001
From: "Steven Rostedt (VMware)" rostedt@goodmis.org Date: Mon, 20 Jan 2020 13:07:31 -0500 Subject: [PATCH] tracing: Fix histogram code when expression has same var as value
While working on a tool to convert SQL syntex into the histogram language of the kernel, I discovered the following bug:
# echo 'first u64 start_time u64 end_time pid_t pid u64 delta' >> synthetic_events # echo 'hist:keys=pid:start=common_timestamp' > events/sched/sched_waking/trigger # echo 'hist:keys=next_pid:delta=common_timestamp-$start,start2=$start:onmatch(sched.sched_waking).trace(first,$start2,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger
Would not display any histograms in the sched_switch histogram side.
But if I were to swap the location of
"delta=common_timestamp-$start" with "start2=$start"
Such that the last line had:
# echo 'hist:keys=next_pid:start2=$start,delta=common_timestamp-$start:onmatch(sched.sched_waking).trace(first,$start2,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger
The histogram works as expected.
What I found out is that the expressions clear out the value once it is resolved. As the variables are resolved in the order listed, when processing:
delta=common_timestamp-$start
The $start is cleared. When it gets to "start2=$start", it errors out with "unresolved symbol" (which is silent as this happens at the location of the trace), and the histogram is dropped.
When processing the histogram for variable references, instead of adding a new reference for a variable used twice, use the same reference. That way, not only is it more efficient, but the order will no longer matter in processing of the variables.
From Tom Zanussi:
"Just to clarify some more about what the problem was is that without your patch, we would have two separate references to the same variable, and during resolve_var_refs(), they'd both want to be resolved separately, so in this case, since the first reference to start wasn't part of an expression, it wouldn't get the read-once flag set, so would be read normally, and then the second reference would do the read-once read and also be read but using read-once. So everything worked and you didn't see a problem:
from: start2=$start,delta=common_timestamp-$start
In the second case, when you switched them around, the first reference would be resolved by doing the read-once, and following that the second reference would try to resolve and see that the variable had already been read, so failed as unset, which caused it to short-circuit out and not do the trigger action to generate the synthetic event:
to: delta=common_timestamp-$start,start2=$start
With your patch, we only have the single resolution which happens correctly the one time it's resolved, so this can't happen."
Link: https://lore.kernel.org/r/20200116154216.58ca08eb@gandalf.local.home
Cc: stable@vger.kernel.org Fixes: 067fe038e70f6 ("tracing: Add variable reference handling to hist triggers") Reviewed-by: Tom Zanuss zanussi@kernel.org Tested-by: Tom Zanussi zanussi@kernel.org Signed-off-by: Steven Rostedt (VMware) rostedt@goodmis.org
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c index d33b046f985a..6ac35b9e195d 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -116,6 +116,7 @@ struct hist_field { struct ftrace_event_field *field; unsigned long flags; hist_field_fn_t fn; + unsigned int ref; unsigned int size; unsigned int offset; unsigned int is_signed; @@ -2427,8 +2428,16 @@ static int contains_operator(char *str) return field_op; }
+static void get_hist_field(struct hist_field *hist_field) +{ + hist_field->ref++; +} + static void __destroy_hist_field(struct hist_field *hist_field) { + if (--hist_field->ref > 1) + return; + kfree(hist_field->var.name); kfree(hist_field->name); kfree(hist_field->type); @@ -2470,6 +2479,8 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data, if (!hist_field) return NULL;
+ hist_field->ref = 1; + hist_field->hist_data = hist_data;
if (flags & HIST_FIELD_FL_EXPR || flags & HIST_FIELD_FL_ALIAS) @@ -2665,6 +2676,17 @@ static struct hist_field *create_var_ref(struct hist_trigger_data *hist_data, { unsigned long flags = HIST_FIELD_FL_VAR_REF; struct hist_field *ref_field; + int i; + + /* Check if the variable already exists */ + 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) { + get_hist_field(ref_field); + return ref_field; + } + }
ref_field = create_hist_field(var_field->hist_data, NULL, flags, NULL); if (ref_field) {
Hi Steve,
For 4.19, this patch applies if these patches are applied first:
commit 656fe2ba85e81d00e4447bf77b8da2be3c47acb2 Author: Tom Zanussi tom.zanussi@linux.intel.com Date: Tue Dec 18 14:33:24 2018 -0600
tracing: Use hist trigger's var_ref array to destroy var_refs
commit de40f033d4e84e843d6a12266e3869015ea9097c Author: Tom Zanussi tom.zanussi@linux.intel.com Date: Tue Dec 18 14:33:23 2018 -0600
tracing: Remove open-coding of hist trigger var_ref management
After applying all 3 to 4.19, I built and ran the ftrace/trigger selftests and didn't see any problems.
Tom
On Mon, 2020-01-27 at 16:37 +0100, gregkh@linuxfoundation.org wrote:
The patch below does not apply to the 4.19-stable tree. If someone wants it applied there, or to any other stable or longterm tree, then please email the backport, including the original git commit id to stable@vger.kernel.org.
thanks,
greg k-h
------------------ original commit in Linus's tree ------------------
From 8bcebc77e85f3d7536f96845a0fe94b1dddb6af0 Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (VMware)" rostedt@goodmis.org Date: Mon, 20 Jan 2020 13:07:31 -0500 Subject: [PATCH] tracing: Fix histogram code when expression has same var as value
While working on a tool to convert SQL syntex into the histogram language of the kernel, I discovered the following bug:
# echo 'first u64 start_time u64 end_time pid_t pid u64 delta' >> synthetic_events # echo 'hist:keys=pid:start=common_timestamp' > events/sched/sched_waking/trigger # echo 'hist:keys=next_pid:delta=common_timestamp- $start,start2=$start:onmatch(sched.sched_waking).trace(first,$start2, common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger
Would not display any histograms in the sched_switch histogram side.
But if I were to swap the location of
"delta=common_timestamp-$start" with "start2=$start"
Such that the last line had:
# echo 'hist:keys=next_pid:start2=$start,delta=common_timestamp- $start:onmatch(sched.sched_waking).trace(first,$start2,common_timesta mp,next_pid,$delta)' > events/sched/sched_switch/trigger
The histogram works as expected.
What I found out is that the expressions clear out the value once it is resolved. As the variables are resolved in the order listed, when processing:
delta=common_timestamp-$start
The $start is cleared. When it gets to "start2=$start", it errors out with "unresolved symbol" (which is silent as this happens at the location of the trace), and the histogram is dropped.
When processing the histogram for variable references, instead of adding a new reference for a variable used twice, use the same reference. That way, not only is it more efficient, but the order will no longer matter in processing of the variables.
From Tom Zanussi:
"Just to clarify some more about what the problem was is that without your patch, we would have two separate references to the same variable, and during resolve_var_refs(), they'd both want to be resolved separately, so in this case, since the first reference to start wasn't part of an expression, it wouldn't get the read-once flag set, so would be read normally, and then the second reference would do the read- once read and also be read but using read-once. So everything worked and you didn't see a problem:
from: start2=$start,delta=common_timestamp-$start
In the second case, when you switched them around, the first reference would be resolved by doing the read-once, and following that the second reference would try to resolve and see that the variable had already been read, so failed as unset, which caused it to short-circuit out and not do the trigger action to generate the synthetic event:
to: delta=common_timestamp-$start,start2=$start
With your patch, we only have the single resolution which happens correctly the one time it's resolved, so this can't happen."
Link: https://lore.kernel.org/r/20200116154216.58ca08eb@gandalf.local .home
Cc: stable@vger.kernel.org Fixes: 067fe038e70f6 ("tracing: Add variable reference handling to hist triggers") Reviewed-by: Tom Zanuss zanussi@kernel.org Tested-by: Tom Zanussi zanussi@kernel.org Signed-off-by: Steven Rostedt (VMware) rostedt@goodmis.org
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c index d33b046f985a..6ac35b9e195d 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -116,6 +116,7 @@ struct hist_field { struct ftrace_event_field *field; unsigned long flags; hist_field_fn_t fn;
- unsigned int ref; unsigned int size; unsigned int offset; unsigned int is_signed;
@@ -2427,8 +2428,16 @@ static int contains_operator(char *str) return field_op; } +static void get_hist_field(struct hist_field *hist_field) +{
- hist_field->ref++;
+}
static void __destroy_hist_field(struct hist_field *hist_field) {
- if (--hist_field->ref > 1)
return;
- kfree(hist_field->var.name); kfree(hist_field->name); kfree(hist_field->type);
@@ -2470,6 +2479,8 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data, if (!hist_field) return NULL;
- hist_field->ref = 1;
- hist_field->hist_data = hist_data;
if (flags & HIST_FIELD_FL_EXPR || flags & HIST_FIELD_FL_ALIAS) @@ -2665,6 +2676,17 @@ static struct hist_field *create_var_ref(struct hist_trigger_data *hist_data, { unsigned long flags = HIST_FIELD_FL_VAR_REF; struct hist_field *ref_field;
- int i;
- /* Check if the variable already exists */
- 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) {
get_hist_field(ref_field);
return ref_field;
}
- }
ref_field = create_hist_field(var_field->hist_data, NULL, flags, NULL); if (ref_field) {
On Mon, 27 Jan 2020 12:36:21 -0600 Tom Zanussi zanussi@kernel.org wrote:
Hi Steve,
For 4.19, this patch applies if these patches are applied first:
commit 656fe2ba85e81d00e4447bf77b8da2be3c47acb2 Author: Tom Zanussi tom.zanussi@linux.intel.com Date: Tue Dec 18 14:33:24 2018 -0600
tracing: Use hist trigger's var_ref array to destroy var_refs
commit de40f033d4e84e843d6a12266e3869015ea9097c Author: Tom Zanussi tom.zanussi@linux.intel.com Date: Tue Dec 18 14:33:23 2018 -0600
tracing: Remove open-coding of hist trigger var_ref management
After applying all 3 to 4.19, I built and ran the ftrace/trigger selftests and didn't see any problems.
Thanks, I was cherry-picking parts of those changes, but it wasn't fixing the issue itself. Let me just backport both of them in full and see if that works.
-- Steve
On Mon, 2020-01-27 at 13:51 -0500, Steven Rostedt wrote:
On Mon, 27 Jan 2020 12:36:21 -0600 Tom Zanussi zanussi@kernel.org wrote:
Hi Steve,
For 4.19, this patch applies if these patches are applied first:
commit 656fe2ba85e81d00e4447bf77b8da2be3c47acb2 Author: Tom Zanussi tom.zanussi@linux.intel.com Date: Tue Dec 18 14:33:24 2018 -0600
tracing: Use hist trigger's var_ref array to destroy var_refs
commit de40f033d4e84e843d6a12266e3869015ea9097c Author: Tom Zanussi tom.zanussi@linux.intel.com Date: Tue Dec 18 14:33:23 2018 -0600
tracing: Remove open-coding of hist trigger var_ref management
After applying all 3 to 4.19, I built and ran the ftrace/trigger selftests and didn't see any problems.
Thanks, I was cherry-picking parts of those changes, but it wasn't fixing the issue itself. Let me just backport both of them in full and see if that works.
It does fix the issue for me and passes the selftests. Remember that 4.19 doesn't have the .trace() hist action - you need to use the event name e.g. .first()
Tom
-- Steve
On Mon, 27 Jan 2020 13:19:28 -0600 Tom Zanussi zanussi@kernel.org wrote:
It does fix the issue for me and passes the selftests. Remember that 4.19 doesn't have the .trace() hist action - you need to use the event name e.g. .first()
Yeah I did that, but it was still clearing out the start variable when I tried. I'll test the full commits next, right after I fix my git repo that got corrupted because it had an alternative based on a repo that rebased :-(
-- Steve
On Mon, 27 Jan 2020 14:36:24 -0500 Steven Rostedt rostedt@goodmis.org wrote:
On Mon, 27 Jan 2020 13:19:28 -0600 Tom Zanussi zanussi@kernel.org wrote:
It does fix the issue for me and passes the selftests. Remember that 4.19 doesn't have the .trace() hist action - you need to use the event name e.g. .first()
Yeah I did that, but it was still clearing out the start variable when I tried. I'll test the full commits next, right after I fix my git repo that got corrupted because it had an alternative based on a repo that rebased :-(
Finally got my repo fixed. Yes, after applying the two commits, this failed patch applies fine, and it does fix the issue. The test I did:
# mount -t tracefs nodev /sys/kernel/tracing # cd /sys/kernel/tracing # echo 'first u64 start_time u64 end_time pid_t pid u64 delta' >> synthetic_events # echo 'hist:keys=pid:start=common_timestamp' > events/sched/sched_waking/trigger # echo 'hist:keys=next_pid:delta=common_timestamp-$start,start2=$start:onmatch(sched.sched_waking).first($start2,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger # cat events/sched/sched_switch/hist
And make sure there were events:
# cat events/sched/sched_switch/hist # event histogram # # trigger info: hist:keys=next_pid:vals=hitcount:delta=common_timestamp-$start,start2=$start:sort=hitcount:size=2048:clock=global:onmatch(sched.sched_waking).first($start2,common_timestamp,next_pid,$delta) [active] #
{ next_pid: 1246 } hitcount: 1 { next_pid: 153 } hitcount: 1 { next_pid: 21 } hitcount: 1 { next_pid: 26 } hitcount: 1 { next_pid: 1245 } hitcount: 1 { next_pid: 1613 } hitcount: 1 { next_pid: 1303 } hitcount: 1 { next_pid: 1375 } hitcount: 1 { next_pid: 67 } hitcount: 1 { next_pid: 41 } hitcount: 1 { next_pid: 12 } hitcount: 1 { next_pid: 31 } hitcount: 1 { next_pid: 46 } hitcount: 1 { next_pid: 36 } hitcount: 1 { next_pid: 16 } hitcount: 1 { next_pid: 606 } hitcount: 3 { next_pid: 102 } hitcount: 3 { next_pid: 936 } hitcount: 3 { next_pid: 13 } hitcount: 6 { next_pid: 10 } hitcount: 7 { next_pid: 1584 } hitcount: 13 { next_pid: 1579 } hitcount: 27 { next_pid: 145 } hitcount: 30 { next_pid: 1417 } hitcount: 33
Totals: Hits: 140 Entries: 24 Dropped: 0
Greg,
This patch is dependent on commits 656fe2ba85e81d00e4447bf77b8da2be3c47acb2 and de40f033d4e84e843d6a12266e3869015ea9097c
Can you backport them as well to 4.19 and then apply this fix?
Thanks!
-- Steve
On Mon, Jan 27, 2020 at 05:31:09PM -0500, Steven Rostedt wrote:
On Mon, 27 Jan 2020 14:36:24 -0500 Steven Rostedt rostedt@goodmis.org wrote:
On Mon, 27 Jan 2020 13:19:28 -0600 Tom Zanussi zanussi@kernel.org wrote:
It does fix the issue for me and passes the selftests. Remember that 4.19 doesn't have the .trace() hist action - you need to use the event name e.g. .first()
Yeah I did that, but it was still clearing out the start variable when I tried. I'll test the full commits next, right after I fix my git repo that got corrupted because it had an alternative based on a repo that rebased :-(
Finally got my repo fixed. Yes, after applying the two commits, this failed patch applies fine, and it does fix the issue. The test I did:
# mount -t tracefs nodev /sys/kernel/tracing # cd /sys/kernel/tracing # echo 'first u64 start_time u64 end_time pid_t pid u64 delta' >> synthetic_events # echo 'hist:keys=pid:start=common_timestamp' > events/sched/sched_waking/trigger # echo 'hist:keys=next_pid:delta=common_timestamp-$start,start2=$start:onmatch(sched.sched_waking).first($start2,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger # cat events/sched/sched_switch/hist
And make sure there were events:
# cat events/sched/sched_switch/hist # event histogram # # trigger info: hist:keys=next_pid:vals=hitcount:delta=common_timestamp-$start,start2=$start:sort=hitcount:size=2048:clock=global:onmatch(sched.sched_waking).first($start2,common_timestamp,next_pid,$delta) [active] #
{ next_pid: 1246 } hitcount: 1 { next_pid: 153 } hitcount: 1 { next_pid: 21 } hitcount: 1 { next_pid: 26 } hitcount: 1 { next_pid: 1245 } hitcount: 1 { next_pid: 1613 } hitcount: 1 { next_pid: 1303 } hitcount: 1 { next_pid: 1375 } hitcount: 1 { next_pid: 67 } hitcount: 1 { next_pid: 41 } hitcount: 1 { next_pid: 12 } hitcount: 1 { next_pid: 31 } hitcount: 1 { next_pid: 46 } hitcount: 1 { next_pid: 36 } hitcount: 1 { next_pid: 16 } hitcount: 1 { next_pid: 606 } hitcount: 3 { next_pid: 102 } hitcount: 3 { next_pid: 936 } hitcount: 3 { next_pid: 13 } hitcount: 6 { next_pid: 10 } hitcount: 7 { next_pid: 1584 } hitcount: 13 { next_pid: 1579 } hitcount: 27 { next_pid: 145 } hitcount: 30 { next_pid: 1417 } hitcount: 33
Totals: Hits: 140 Entries: 24 Dropped: 0
Greg,
This patch is dependent on commits 656fe2ba85e81d00e4447bf77b8da2be3c47acb2 and de40f033d4e84e843d6a12266e3869015ea9097c
Can you backport them as well to 4.19 and then apply this fix?
Will do, thanks!
greg k-h
linux-stable-mirror@lists.linaro.org