Bug 215513

Summary: libtracefs/Synthetic events: problem using tracefs_synth_add_compare_field()
Product: Tools Reporter: Yordan Karadzhov (ykaradzhov)
Component: Trace-cmd/KernelsharkAssignee: Default virtual assignee for Trace-cmd and kernelshark (tools_tracecmd_kernelshark)
Status: RESOLVED CODE_FIX    
Severity: normal CC: rostedt, zanussi
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 5.13.0-27 Subsystem:
Regression: No Bisected commit-id:
Attachments: libtracefs: Problem using tracefs_synth_add_compare_field()
fix expression is_signed state

Description Yordan Karadzhov 2022-01-21 12:24:38 UTC 
Created attachment 300295 [details]
libtracefs: Problem using tracefs_synth_add_compare_field()

I am not sure if this is a bug or I am doing something wrong when trying to use the API tracefs_synth_add_compare_field().

To demonstrate the problem, I made the following changes in the example code given in the documentation:

47a48,49
>       tracefs_synth_add_compare_field(synth, "prio", "prev_prio",
>                                       TRACEFS_SYNTH_DELTA_END, "delta_prio");
94c96,103
< 			tracefs_synth_create(synth);
---
>                       if (tracefs_synth_create(synth)) {
>                               show_event();
>                               char *err = tracefs_error_all(NULL);
>                               tracefs_error_clear(NULL);
>                               puts(err);
>                               free(err);
>                               exit(-1);
>                       }


The code is attached.
When I am trying to create the synthetic event I am getting the following:

echo 'swakeup_lat s32 pid; s32 prio; char comm[16]; s32 prev_prio; u64 delta; s32 delta_prio;' > /sys/kernel/tracing/dynamic_events
echo 'hist:keys=pid:__arg_10076_1=prio,__arg_10076_3=common_timestamp.usecs,__arg_10076_4=prio if prio < 100' > /sys/kernel/tracing/events/sched/sched_waking/trigger
echo 'hist:keys=next_pid:pid=next_pid,prio=$__arg_10076_1,comm=next_comm,__arg_10076_2=prev_prio,delta=common_timestamp.usecs-$__arg_10076_3,delta_prio=prev_prio-$__arg_10076_4:onmatch(sched.sched_waking).trace(wakeup_lat,$pid,$prio,$comm,$__arg_10076_2,$delta,$delta_prio) if next_prio < 50||!(prev_prio >= 100)' > /sys/kernel/tracing/events/sched/sched_switch/trigger
[ 2216.558275] hist:sched:sched_switch: error: Param type doesn't match synthetic event field type
  Command: hist:keys=next_pid:pid=next_pid,prio=$__arg_10076_1,comm=next_comm,__arg_10076_2=prev_prio,delta=common_timestamp.usecs-$__arg_10076_3,delta_prio=prev_prio-$__arg_10076_4:onmatch(sched.sched_waking).trace(wakeup_lat,$pid,$prio,$comm,$__arg_100


In the error message '^' points to 'prio=$__arg_10076_1'

Any ideas?

Thanks!
Yordan
Comment 1 Steven Rostedt 2022-01-23 02:37:21 UTC 
On Fri, 21 Jan 2022 12:24:38 +0000
bugzilla-daemon@bugzilla.kernel.org wrote:
> libtracefs: Problem using tracefs_synth_add_compare_field()
> 
> I am not sure if this is a bug or I am doing something wrong when trying to
> use
> the API tracefs_synth_add_compare_field().

May be a bug in the kernel.

> 
> The code is attached.
> When I am trying to create the synthetic event I am getting the following:
> 
> echo 'swakeup_lat s32 pid; s32 prio; char comm[16]; s32 prev_prio; u64 delta;
> s32 delta_prio;' > /sys/kernel/tracing/dynamic_events

Did you mean > synthetic_events or is the above "swakeup" suppose to be "s:wakeup_lat"?


> echo
> 'hist:keys=pid:__arg_10076_1=prio,__arg_10076_3=common_timestamp.usecs,__arg_10076_4=prio
> if prio < 100' > /sys/kernel/tracing/events/sched/sched_waking/trigger
> echo >
> 'hist:keys=next_pid:pid=next_pid,prio=$__arg_10076_1,comm=next_comm,__arg_10076_2=prev_prio,delta=common_timestamp.usecs-$__arg_10076_3,delta_prio=prev_prio-$__arg_10076_4:onmatch(sched.sched_waking).trace(wakeup_lat,$pid,$prio,$comm,$__arg_10076_2,$delta,$delta_prio)
> > if next_prio < 50||!(prev_prio >= 100)' >
> /sys/kernel/tracing/events/sched/sched_switch/trigger

> [ 2216.558275] hist:sched:sched_switch: error: Param type doesn't match
> synthetic event field type
>   Command:
>
> hist:keys=next_pid:pid=next_pid,prio=$__arg_10076_1,comm=next_comm,__arg_10076_2=prev_prio,delta=common_timestamp.usecs-$__arg_10076_3,delta_prio=prev_prio-$__arg_10076_4:onmatch(sched.sched_waking).trace(wakeup_lat,$pid,$prio,$comm,$__arg_100
> 
> 
> In the error message '^' points to 'prio=$__arg_10076_1'

Note, I see that it works if I switch "s32 prio" to "u32 prio". I
wonder if the variable passing is losing the sign?

And even after doing that, other things fail.

This looks more like a kernel bug than a library bug.

-- Steve
Comment 2 Tom Zanussi 2022-01-25 22:30:53 UTC 
Created attachment 300319 [details]
fix expression is_signed state
Comment 3 Tom Zanussi 2022-01-25 22:34:36 UTC 
Can you try the attached patch? The problem appears to be that the expression doesn't have the sign propagated to it, which this patch changes.

Also, it seems like the error text is cut off - I think your commands may be longer than 256 chars, which will also need a change in the kernel.  I can submit that as a second patch upstream if that's the cases.
Comment 4 Steven Rostedt 2022-02-21 22:11:51 UTC 
Fixed in the kernel with 097f1eefedea ("tracing: Propagate is_signed to expression")