Re: Unresolved reference for histogram variable

[Tom Zanussi <zanussi@kernel.org>]

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