diff mbox series

libtracefs: Allow for the same event to be start and end in tracefs_sql()

Message ID 20220531172435.2a51eff3@rorschach.local.home (mailing list archive)
State Accepted
Commit deb54b1d20f6bae4fff7ce195540b81fedfb2bd0
Headers show
Series libtracefs: Allow for the same event to be start and end in tracefs_sql() | expand

Commit Message

Steven Rostedt May 31, 2022, 9:24 p.m. UTC
From: "Steven Rostedt (Google)" <rostedt@goodmis.org>

When creating a synthetic event that is based off of the same event with
two different fields, it should still work. But the assumption was that
every field that has a label will have the same label, which is not
true.

For example, to create an event that measures the time a task is
blocked, it needs to start and end on the same event (sched_switch), but
just use different fields.

  sqlhist -n blocked 'SELECT end.next_pid AS pid,end.next_comm AS comm,(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat
      FROM sched_switch AS start JOIN sched_switch AS end ON start.prev_pid = end.next_pid WHERE start.prev_state = 2'

But this gave the following error:

   Failed creating synthetic event!: Success
   SELECT end.next_pid AS pid,end.next_comm AS comm,(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat FROM sched_switch AS start JOIN sched_switch AS end ON start.prev_pid = end.next_pid WHERE start.prev_state = 2
       ^
   ERROR: 'end.next_pid'
   'start.prev_pid' and 'end.next_pid' must be a field for each event: 'sched_switch' and 'sched_switch'

Because the end sched_switch would already have the label "start" and it
would not create one for "end" making the "end" not resolve correctly.

Now it gives the correct answer:

  echo 's:blocked pid_t next_pid; char next_comm[16]; u64 lat;' >> /sys/kernel/tracing/dynamic_events
  echo 'hist:keys=prev_pid:__arg_21065_1=next_pid,__arg_21065_2=next_comm,__arg_21065_3=common_timestamp.usecs if prev_state == 2' >> /sys/kernel/tracing/events/sched/sched_switch/trigger
  echo 'hist:keys=next_pid:next_pid=$__arg_21065_1,next_comm=$__arg_21065_2,lat=common_timestamp.usecs-$__arg_21065_3:onmatch(sched.sched_switch).trace(blocked,$next_pid,$next_comm,$lat)' >> /sys/kernel/tracing/events/sched/sched_switch/trigger

Fixes: 25446407 ("libtracefs: Added new API tracefs_sql()")
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
 src/tracefs-sqlhist.c | 2 ++
 1 file changed, 2 insertions(+)

Comments

Harald Seiler May 31, 2022, 11:26 p.m. UTC | #1
On Tue, 2022-05-31 at 17:24 -0400, Steven Rostedt wrote:
> From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
> 
> When creating a synthetic event that is based off of the same event with
> two different fields, it should still work. But the assumption was that
> every field that has a label will have the same label, which is not
> true.
> 
> For example, to create an event that measures the time a task is
> blocked, it needs to start and end on the same event (sched_switch), but
> just use different fields.
> 
>   sqlhist -n blocked 'SELECT end.next_pid AS pid,end.next_comm AS comm,(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat
>       FROM sched_switch AS start JOIN sched_switch AS end ON start.prev_pid = end.next_pid WHERE start.prev_state = 2'
> 
> But this gave the following error:
> 
>    Failed creating synthetic event!: Success
>    SELECT end.next_pid AS pid,end.next_comm AS comm,(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat FROM sched_switch AS start JOIN sched_switch AS end ON start.prev_pid = end.next_pid WHERE
> start.prev_state = 2
>        ^
>    ERROR: 'end.next_pid'
>    'start.prev_pid' and 'end.next_pid' must be a field for each event: 'sched_switch' and 'sched_switch'
> 
> Because the end sched_switch would already have the label "start" and it
> would not create one for "end" making the "end" not resolve correctly.
> 
> Now it gives the correct answer:
> 
>   echo 's:blocked pid_t next_pid; char next_comm[16]; u64 lat;' >> /sys/kernel/tracing/dynamic_events
>   echo 'hist:keys=prev_pid:__arg_21065_1=next_pid,__arg_21065_2=next_comm,__arg_21065_3=common_timestamp.usecs if prev_state == 2' >> /sys/kernel/tracing/events/sched/sched_switch/trigger
>   echo 'hist:keys=next_pid:next_pid=$__arg_21065_1,next_comm=$__arg_21065_2,lat=common_timestamp.usecs-$__arg_21065_3:onmatch(sched.sched_switch).trace(blocked,$next_pid,$next_comm,$lat)' >>
> /sys/kernel/tracing/events/sched/sched_switch/trigger
> 
> Fixes: 25446407 ("libtracefs: Added new API tracefs_sql()")
> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>

Tested-by: Harald Seiler <hws@denx.de>

Just gave it a spin, this is great!

> ---
>  src/tracefs-sqlhist.c | 2 ++
>  1 file changed, 2 insertions(+)
> 
> diff --git a/src/tracefs-sqlhist.c b/src/tracefs-sqlhist.c
> index 9811362..cee037b 100644
> --- a/src/tracefs-sqlhist.c
> +++ b/src/tracefs-sqlhist.c
> @@ -285,6 +285,8 @@ static struct expr *find_field(struct sqlhist_bison *sb,
>                 if (!strcmp(field->raw, raw)) {
>                         if (label && !field->label)
>                                 field->label = label;
> +                       if (label && strcmp(label, field->label) != 0)
> +                               continue;
>                         return expr;
>                 }
>
diff mbox series

Patch

diff --git a/src/tracefs-sqlhist.c b/src/tracefs-sqlhist.c
index 9811362..cee037b 100644
--- a/src/tracefs-sqlhist.c
+++ b/src/tracefs-sqlhist.c
@@ -285,6 +285,8 @@  static struct expr *find_field(struct sqlhist_bison *sb,
 		if (!strcmp(field->raw, raw)) {
 			if (label && !field->label)
 				field->label = label;
+			if (label && strcmp(label, field->label) != 0)
+				continue;
 			return expr;
 		}