FAILED: patch "[PATCH] tracing: Fix histogram code when expression has same var as" failed to apply to 4.19-stable tree

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 <[email protected]>.

thanks,

greg k-h

------------------ original commit in Linus's tree ------------------

From 8bcebc77e85f3d7536f96845a0fe94b1dddb6af0 Mon Sep 17 00:00:00 2001
From: "Steven Rostedt (VMware)" <[email protected]>
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/[email protected] open here

.home

Cc [email protected]

Fixes 067fe038e70f6 ("tracing: Add variable reference handling to

hist triggers")

Reviewed-by Tom Zanuss <[email protected]>

Tested-by Tom Zanussi <[email protected]>

Signed-off-by Steven Rostedt (VMware) <[email protected]>

kernel/trace/trace_events_hist.c +11 -0

index d33b046f985a..6ac35b9e195d 100644
@@ -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)

kernel/trace/trace_events_hist.c +11 -0

@@ -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 <[email protected]>
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 <[email protected]>
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.

Quoted 16 lines · On Mon, 27 Jan 2020 12:36:21 -0600 Tom Zanussi <[email protected]> wrote:

Hi Steve,

For 4.19, this patch applies if these patches are applied first:

commit 656fe2ba85e81d00e4447bf77b8da2be3c47acb2

Author: Tom Zanussi <[email protected]>
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 <[email protected]>
Date:   Tue Dec 18 14:33:23 2018 -0600

tracing: Remove open-coding of hist trigger var_ref management

Quoted 3 lines

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

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()

Quoted 3 lines · On Mon, 27 Jan 2020 13:19:28 -0600 Tom Zanussi <[email protected]> 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 :-(

Quoted 12 lines · On Mon, 27 Jan 2020 14:36:24 -0500 Steven Rostedt <[email protected]> wrote:

Quoted 3 lines · On Mon, 27 Jan 2020 13:19:28 -0600 Tom Zanussi <[email protected]> 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?