Unresolved reference for histogram variable

Unresolved reference for histogram variable

[Steven Rostedt]

Hi Tom,

I'm working on the SQL converter to the ftrace histogram interface, and
while testing the histogram code, I found something strange.

If I write the following:

 # 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:start2=$start,delta=common_timestamp-$start:onmatch(sched.sched_waking).trace(first,$start2,common_timestamp,next_pid,$delta)' > events/sched/sched_switch/trigger

 # cat events/sched/sched_switch/hist 
# event histogram
#
# trigger info: hist:keys=next_pid:vals=hitcount:start2=$start,delta=common_timestamp-$start:sort=hitcount:size=2048:clock=global:onmatch(sched.sched_waking).trace(first,$start2,common_timestamp,next_pid,$delta) [active]
#

{ next_pid:       1337 } hitcount:          1
{ next_pid:         35 } hitcount:          1
{ next_pid:        654 } hitcount:          1
{ next_pid:         20 } hitcount:          1
{ next_pid:       1392 } hitcount:          1
{ next_pid:       1336 } hitcount:          1
{ next_pid:         45 } hitcount:          1
{ next_pid:         15 } hitcount:          1
{ next_pid:        674 } hitcount:          1
{ next_pid:         40 } hitcount:          1
{ next_pid:          7 } hitcount:          1
{ next_pid:         25 } hitcount:          1
{ next_pid:         30 } hitcount:          1
{ next_pid:         12 } hitcount:          1
{ next_pid:       1693 } hitcount:          1
{ next_pid:        206 } hitcount:          1
{ next_pid:         27 } hitcount:          2
{ next_pid:        694 } hitcount:          2
{ next_pid:        438 } hitcount:          2
{ next_pid:       1016 } hitcount:          3
{ next_pid:         53 } hitcount:          4
{ next_pid:       1688 } hitcount:          4
{ next_pid:       1679 } hitcount:          4
{ next_pid:       1066 } hitcount:          6
{ next_pid:       1637 } hitcount:          6
{ next_pid:       1635 } hitcount:         11
{ next_pid:         11 } hitcount:         11
{ next_pid:        196 } hitcount:         12
{ next_pid:       1270 } hitcount:         15
{ next_pid:       1506 } hitcount:         18

Totals:
    Hits: 116
    Entries: 30
    Dropped: 0


All fine and dandy. But if I swap the two variables assignments...

 from: start2=$start,delta=common_timestamp-$start

 to: delta=common_timestamp-$start,start2=$start

Where I assign the delta before start2, I get this:

 # 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).trace(first,$start2,common_timestamp,next_pid,$delta) [active]
#


Totals:
    Hits: 0
    Entries: 0
    Dropped: 0


After spending a day placing trace_printk() and printk()s in the code,
I found the culprit, and it has to do with this line here:

in resolve_var_refs():

		if (self || !hist_field->read_once)
			var_val = tracing_map_read_var(var_elt, var_idx);
		else
			var_val = tracing_map_read_var_once(var_elt, var_idx);


It appears that:

  start2=$start

does not set the read_once() to the variable, which allows for the
delta calculation to work. But the delta calculation has:

in parse_expr():

	operand1->read_once = true;
	operand2->read_once = true;

Why is that?

This means that any variable used in an expression can not be use later
on.

Or should the variable be detected that it is used multiple times in
the expression, and have the parser detect this, and just reuse the
same variable multiple times?

-- Steve

Re: Unresolved reference for histogram variable

[Steven Rostedt]

On Thu, 16 Jan 2020 15:42:16 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> in parse_expr():
> 
> 	operand1->read_once = true;
> 	operand2->read_once = true;
> 
> Why is that?
> 
> This means that any variable used in an expression can not be use later
> on.
> 
> Or should the variable be detected that it is used multiple times in
> the expression, and have the parser detect this, and just reuse the
> same variable multiple times?

This patch seems to fix the problem, and lets us reuse the same
variable multiple times.

-- Steve

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 117a1202a6b9..b7f944735a4a 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;
@@ -2432,8 +2433,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);
@@ -2475,6 +2484,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)
@@ -2670,6 +2681,19 @@ 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;
+
+	for (i = 0; i < hist_data->n_var_refs; i++) {
+		ref_field = hist_data->var_refs[i];
+		/* Maybe this is overkill? */
+		if (ref_field->var.idx == var_field->var.idx &&
+		    ref_field->var.hist_data == var_field->hist_data &&
+		    ref_field->size == var_field->size &&
+		    ref_field->is_signed == var_field->is_signed) {
+			get_hist_field(ref_field);
+			return ref_field;
+		}
+	}
 
 	ref_field = create_hist_field(var_field->hist_data, NULL, flags, NULL);
 	if (ref_field) {

Re: Unresolved reference for histogram variable

[Tom Zanussi]

Hi Steve,

On Thu, 2020-01-16 at 16:56 -0500, Steven Rostedt wrote:
> On Thu, 16 Jan 2020 15:42:16 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > in parse_expr():
> > 
> > 	operand1->read_once = true;
> > 	operand2->read_once = true;
> > 
> > Why is that?
> > 
> > This means that any variable used in an expression can not be use
> > later
> > on.
> > 
> > Or should the variable be detected that it is used multiple times
> > in
> > the expression, and have the parser detect this, and just reuse the
> > same variable multiple times?
> 
> This patch seems to fix the problem, and lets us reuse the same
> variable multiple times.

It works for me too, and seems like it should be a good fix for the
problem.  The size and is_signed might be the overkill you're referring
to, but I'd like to spend time tomorrow verifying that and doing some
testing to make sure.

Thanks,

Tom

> 
> -- Steve
> 
> diff --git a/kernel/trace/trace_events_hist.c
> b/kernel/trace/trace_events_hist.c
> index 117a1202a6b9..b7f944735a4a 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;
> @@ -2432,8 +2433,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);
> @@ -2475,6 +2484,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)
> @@ -2670,6 +2681,19 @@ 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;
> +
> +	for (i = 0; i < hist_data->n_var_refs; i++) {
> +		ref_field = hist_data->var_refs[i];
> +		/* Maybe this is overkill? */
> +		if (ref_field->var.idx == var_field->var.idx &&
> +		    ref_field->var.hist_data == var_field->hist_data 
> &&
> +		    ref_field->size == var_field->size &&
> +		    ref_field->is_signed == var_field->is_signed) {
> +			get_hist_field(ref_field);
> +			return ref_field;
> +		}
> +	}
>  
>  	ref_field = create_hist_field(var_field->hist_data, NULL,
> flags, NULL);
>  	if (ref_field) {

Re: Unresolved reference for histogram variable

[Tom Zanussi]

Hi Steve,

On Thu, 2020-01-16 at 16:56 -0500, Steven Rostedt wrote:
> On Thu, 16 Jan 2020 15:42:16 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > in parse_expr():
> > 
> > 	operand1->read_once = true;
> > 	operand2->read_once = true;
> > 
> > Why is that?
> > 
> > This means that any variable used in an expression can not be use
> > later
> > on.
> > 
> > Or should the variable be detected that it is used multiple times
> > in
> > the expression, and have the parser detect this, and just reuse the
> > same variable multiple times?
> 
> This patch seems to fix the problem, and lets us reuse the same
> variable multiple times.
> 

I tested this patch after removing the checks for size and is_signed,
which aren't needed because just the var.idx and hist_data is enough to
know you're referencing the same variable.

So removing these lines: 

		    ref_field->size == var_field->size &&
		    ref_field->is_signed == var_field->is_signed) {

passed selftests and the specific failure you found.

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.

Anyway, here's my reviewed and tested-by:

Reviewed-by: Tom Zanuss <zanussi@kernel.org>
Tested-by: Tom Zanussi <zanussi@kernel.org>

Thanks,

Tom



> -- Steve
> 
> diff --git a/kernel/trace/trace_events_hist.c
> b/kernel/trace/trace_events_hist.c
> index 117a1202a6b9..b7f944735a4a 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;
> @@ -2432,8 +2433,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);
> @@ -2475,6 +2484,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)
> @@ -2670,6 +2681,19 @@ 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;
> +
> +	for (i = 0; i < hist_data->n_var_refs; i++) {
> +		ref_field = hist_data->var_refs[i];
> +		/* Maybe this is overkill? */
> +		if (ref_field->var.idx == var_field->var.idx &&
> +		    ref_field->var.hist_data == var_field->hist_data 
> &&
> +		    ref_field->size == var_field->size &&
> +		    ref_field->is_signed == var_field->is_signed) {
> +			get_hist_field(ref_field);
> +			return ref_field;
> +		}
> +	}
>  
>  	ref_field = create_hist_field(var_field->hist_data, NULL,
> flags, NULL);
>  	if (ref_field) {

Re: Unresolved reference for histogram variable

[Steven Rostedt]

On Fri, 17 Jan 2020 16:04:50 -0600
Tom Zanussi <zanussi@kernel.org> wrote:

> Reviewed-by: Tom Zanuss <zanussi@kernel.org>
> Tested-by: Tom Zanussi <zanussi@kernel.org>

Thanks! BTW, here's the final version of the patch that I'm starting
testing on:

-- Steve

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>
---
 kernel/trace/trace_events_hist.c | 22 ++++++++++++++++++++++
 1 file changed, 22 insertions(+)

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) {
-- 
2.20.1

Re: Unresolved reference for histogram variable

[Tom Zanussi]

Hi Steve,

On Thu, 2020-01-16 at 15:42 -0500, Steven Rostedt wrote:
> Hi Tom,
> 
> I'm working on the SQL converter to the ftrace histogram interface,
> and
> while testing the histogram code, I found something strange.
> 
> If I write the following:
> 
>  # 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:start2=$start,delta=common_timestamp-
> $start:onmatch(sched.sched_waking).trace(first,$start2,common_timesta
> mp,next_pid,$delta)' > events/sched/sched_switch/trigger
> 
>  # cat events/sched/sched_switch/hist 
> # event histogram
> #
> # trigger info:
> hist:keys=next_pid:vals=hitcount:start2=$start,delta=common_timestamp
> -$start:sort=hitcount:size=2048:clock=global:onmatch(sched.sched_waki
> ng).trace(first,$start2,common_timestamp,next_pid,$delta) [active]
> #
> 
> { next_pid:       1337 } hitcount:          1
> { next_pid:         35 } hitcount:          1
> { next_pid:        654 } hitcount:          1
> { next_pid:         20 } hitcount:          1
> { next_pid:       1392 } hitcount:          1
> { next_pid:       1336 } hitcount:          1
> { next_pid:         45 } hitcount:          1
> { next_pid:         15 } hitcount:          1
> { next_pid:        674 } hitcount:          1
> { next_pid:         40 } hitcount:          1
> { next_pid:          7 } hitcount:          1
> { next_pid:         25 } hitcount:          1
> { next_pid:         30 } hitcount:          1
> { next_pid:         12 } hitcount:          1
> { next_pid:       1693 } hitcount:          1
> { next_pid:        206 } hitcount:          1
> { next_pid:         27 } hitcount:          2
> { next_pid:        694 } hitcount:          2
> { next_pid:        438 } hitcount:          2
> { next_pid:       1016 } hitcount:          3
> { next_pid:         53 } hitcount:          4
> { next_pid:       1688 } hitcount:          4
> { next_pid:       1679 } hitcount:          4
> { next_pid:       1066 } hitcount:          6
> { next_pid:       1637 } hitcount:          6
> { next_pid:       1635 } hitcount:         11
> { next_pid:         11 } hitcount:         11
> { next_pid:        196 } hitcount:         12
> { next_pid:       1270 } hitcount:         15
> { next_pid:       1506 } hitcount:         18
> 
> Totals:
>     Hits: 116
>     Entries: 30
>     Dropped: 0
> 
> 
> All fine and dandy. But if I swap the two variables assignments...
> 
>  from: start2=$start,delta=common_timestamp-$start
> 
>  to: delta=common_timestamp-$start,start2=$start
> 
> Where I assign the delta before start2, I get this:

Yeah, what's happening is that after being used the $start variable
gets 'unset', and then start2 is assigned to that unset variable so is
also unset, and then the onmatch sees that $start2 is unset so results
in the trigger not firing because it sees start2 as unset.

In the first case, that doesn't happen, because start2 is assigned
first, and is still set when the onmatch happens.

I think you're right and it should just refer to the same variable
multiple times before it get unset.

> 
>  # 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(sch
> ed.sched_waking).trace(first,$start2,common_timestamp,next_pid,$delta
> ) [active]
> #
> 
> 
> Totals:
>     Hits: 0
>     Entries: 0
>     Dropped: 0
> 
> 
> After spending a day placing trace_printk() and printk()s in the
> code,
> I found the culprit, and it has to do with this line here:
> 
> in resolve_var_refs():
> 
> 		if (self || !hist_field->read_once)
> 			var_val = tracing_map_read_var(var_elt,
> var_idx);
> 		else
> 			var_val = tracing_map_read_var_once(var_elt,
> var_idx);
> 
> 
> It appears that:
> 
>   start2=$start
> 
> does not set the read_once() to the variable, which allows for the
> delta calculation to work. But the delta calculation has:

In this case, the start2=$start happens before the expression that
unsets it, so works, but when it happens afterwards, the read_once() in
the expression causes the value to be unset, so results in the start2
being unset.

> 
> in parse_expr():
> 
> 	operand1->read_once = true;
> 	operand2->read_once = true;
> 
> Why is that?
> 
> This means that any variable used in an expression can not be use
> later
> on.

The read_once is a a shortcut to prevent expressions from using
uninitialized variables, so if any are unset, they cause any actions
referring to unset variables to not be triggered, and after being read
once the variables are unset.  It's better described in
Documentation/histogram.rst:

"A variable's value is normally available to any subsequent event until
it is set to something else by a subsequent event.  The one exception
to that rule is that any variable used in an expression is essentially
'read-once' - once it's used by an expression in a subsequent event,
it's reset to its 'unset' state, which means it can't be used again
unless it's set again.  This ensures not only that an event doesn't
use an uninitialized variable in a calculation, but that that variable
is used only once and not for any unrelated subsequent match."

The assumption was that expressions would generally be used that way
e.g. like the common_timestamp-$ts0, where a bogus $ts0 would mean
disaster.

> 
> Or should the variable be detected that it is used multiple times in
> the expression, and have the parser detect this, and just reuse the
> same variable multiple times?

Yeah, I think that makes sense - I'll look at your patch and see if
that's the best way to do it.

Thanks,

Tom

> 
> -- Steve