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