linux-kernel - Unresolved reference for histogram variable

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite for Android: free password hash cracker in your pocket

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Date:   Thu, 16 Jan 2020 15:42:16 -0500
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Tom Zanussi <zanussi@...nel.org>
Cc:     LKML <linux-kernel@...r.kernel.org>
Subject: Unresolved reference for histogram variable

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