Re: [PATCH 00/17] libtracefs: Introducing tracefs_sql() to create synthetice events with an SQL line

[Steven Rostedt <rostedt@goodmis.org>]

On Fri, 30 Jul 2021 18:18:07 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> FUNCTIONAL EXAMPLE:
> -------------------
> 
> After applying this patch, and installing it. If you compile the example from the man
> page (calling it sqlhist.c):
> 
>  >$ gcc -o sqlhist sqlhist.c `pkg-config --cflags --libs libtracefs`
>  >$ su
>  ># ./sqlhist -n syscall_wait -e 'select start.id, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat  
>     from sys_enter as start join sys_exit as end on start.common_pid = end.common_pid
>     where start.id != 23 && start.id != 7 && start.id != 61 && start.id != 230 &&
>           start.id != 232 && start.id != 270 && start.id != 271 && start.id != 202'
> 
> 
> (All the start.id filtering is hiding the syscalls that block for a long time)
> 
>  ># echo 'hist:keys=id.syscall,lat.buckets=10:sort=lat' > /sys/kernel/tracing/events/synthetic/syscall_wait/trigger  
> 
> <wait a while>
> 
>  ># cat /sys/kernel/tracing/events/synthetic/syscall_wait/hist  

And of course, I forgot to say what the above is doing :-p

I wanted to see how long syscalls block for. So I created a synthetic
event that connects with the starting of all system calls, with the
exit of the same system call, using the common_pid of the task as the
key to connect the two.

I record the id of the system call as well as the latency that is
recorded, and send that off to a synthetic event called "syscall_wait".

The '-e' option of the man page program sqlhist executes the command to
create the synthetic event.

Then I add a histogram to that event keying off the id (the ".syscall"
writes out the name of the system call along with the id), and the
latency "lat" grouping it in buckets of "5 microseconds", and sort it
by the latency.

I waited a while, and then reported the result.

When I first ran this, the system calls that block for a long time
filled up the histogram with useless data.  Those were the various
"poll" and "select" as well as (surprising) "futex" system call.

-- Steve