On Fri, 30 Jul 2021 18:18:07 -0400 Steven Rostedt <rostedt@xxxxxxxxxxx> 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
