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

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: Windows password security audit tool. GUI, reports in PDF.

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

Message-ID: <20210730183136.46eeb036@oasis.local.home>
Date:   Fri, 30 Jul 2021 18:31:36 -0400
From:   Steven Rostedt <rostedt@...dmis.org>
To:     linux-trace-devel@...r.kernel.org
Cc:     linux-kernel@...r.kernel.org, Tom Zanussi <zanussi@...nel.org>,
        Daniel Bristot de Oliveira <bristot@...hat.com>,
        Masami Hiramatsu <mhiramat@...nel.org>,
        Namhyung Kim <namhyung@...nel.org>,
        linux-rt-users <linux-rt-users@...r.kernel.org>,
        Clark Williams <williams@...hat.com>
Subject: Re: [PATCH 00/17] libtracefs: Introducing tracefs_sql() to create
 synthetice events with an SQL line

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