From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:26:40
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
I forgot to mention my special thanks:
Lukas Bulwahn for first introducing the idea at RT Summit on the Summit
Spring of 2019.
Daniel Black for sorting out the syntax of mapping the synthetic
event creations into SQL statements at Linux Plumbers, Fall of 2019.
This patch set depends on:
https://patchwork.kernel.org/project/linux-trace-devel/list/?series=525353
Below is from the man page, which has a fully functional parser as its
example (in man page, not here. But the usage of that parser is described in
the FUNCTIONAL EXAMPLE section below).
struct tracefs_synth *tracefs_sql(struct tep_handle *tep, const char *name,
const char *sql_buffer, char **err);
Major update since v1:
It was brought to my attention that the man page did not state that the
SQL syntax required JOIN .. ON in the statement. That is, they were not
optional. I decided to fix that. But not by updating the man page, but by
actually making JOIN .. ON optional. If you leave that out, the synthetic
event will not be completely created, but it will have enough to create
a histogram. See the bottom (HISTOGRAMS) for more info!
struct tracefs_synth *tracefs_sql(struct tep_handle *tep, const char *name,
const char *sql_buffer, char **err);
Synthetic events are dynamically created events that attach two existing
events together via one or more matching fields between the two events. It
can be used to find the latency between the events, or to simply pass fields
of the first event on to the second event to display as one event.
The Linux kernel interface to create synthetic events is complex, and there
needs to be a better way to create synthetic events that is easy and can be
understood via existing technology.
If you think of each event as a table, where the fields are the column of
the table and each instance of the event as a row, you can understand how
SQL can be used to attach two events together and for another event (table).
Utilizing the SQL SELECT FROM JOIN ON [ WHERE ] syntax, a synthetic event
can easily be created from two different events.
For simple SQL queries to make a histogram instead of a synthetic event, see
HISTOGRAMS below.
tracefs_sql() takes in a tep handler (See tep_local_events(3)) that is used
to verify the events within the sql_buffer expression. The name is the name
of the synthetic event to create. If err points to an address of a string,
it will be filled with a detailed message on any type of parsing error,
including fields that do not belong to an event, or if the events or fields
are not properly compared.
The example program below is a fully functional parser where it will create
a synthetic event from a SQL syntax passed in via the command line or a
file.
The SQL format is as follows:
SELECT <fields> FROM <start-event> JOIN <end-event> ON <matching-fields> WHERE <filter>
Note, although the examples show the SQL commands in uppercase, they are not
required to be so. That is, you can use "SELECT" or "select" or "sElEct".
For example:
SELECT syscalls.sys_enter_read.fd, syscalls.sys_exit_read.ret FROM syscalls.sys_enter_read
JOIN syscalls.sys_exit_read
ON syscalls.sys_enter_read.common_pid = syscalls.sys_exit_write.common_pid
Will create a synthetic event that with the fields:
u64 fd; s64 ret;
Because the function takes a tep handle, and usually all event names are
unique, you can leave off the system (group) name of the event, and
tracefs_sql() will discover the system for you.
That is, the above statement would work with:
SELECT sys_enter_read.fd, sys_exit_read.ret FROM sys_enter_read JOIN sys_exit_read
ON sys_enter_read.common_pid = sys_exit_write.common_pid
The AS keyword can be used to name the fields as well as to give an alias to
the events, such that the above can be simplified even more as;
SELECT start.fd, end.ret FROM sys_enter_read AS start JOIN sys_exit_read AS end ON start.common_pid = end.common_pid
The above aliases sys_enter_read as start and sys_exit_read as end and uses
those aliases to reference the event throughout the statement.
Using the AS keyword in the selection portion of the SQL statement will
define what those fields will be called in the synthetic event.
SELECT start.fd AS filed, end.ret AS return FROM sys_enter_read AS start JOIN sys_exit_read AS end
ON start.common_pid = end.common_pid
The above labels the fd of start as filed and the ret of end as return where
the synthetic event that is created will now have the fields:
u64 filed; s64 return;
The fields can also be calculated with results passed to the synthetic event:
select start.truesize, end.len, (start.truesize - end.len) as diff from napi_gro_receive_entry as start
JOIN netif_receive_skb as end ON start.skbaddr = end.skbaddr
Which would show the truesize" of the napi_gro_receive_entry event, the
actual len of the content, shown by the netif_receive_skb, and alse the
delta between the two and expressed by the field *diff.
The code also supports recording the timestamps at either event, and
performing calculations on them. For wakeup latency, you have:
select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start
JOIN sched_switch as end ON start.pid = end.next_pid
The above will create a synthetic event that records the pid of the task
being woken up, and the time difference between the sched_waking event and
the sched_switch event. The TIMESTAMP_USECS will truncate the time down to
microseconds as the timestamp usually recorded in the tracing buffer has
nanosecond resolution. If you do not want that truncation, use TIMESTAMP
instead of TIMESTAMP_USECS.
Finally, the WHERE clause can be added, that will let you add filters on
either or both events.
select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start
JOIN sched_switch as end ON start.pid = end.next_pid
WHERE start.prio < 100 && (!(end.prev_pid < 1 || end.prev_prio > 100) || end.prev_pid == 0)
NOTE
Although both events can be used together in the WHERE clause, they must not
be mixed outside the top most "&&" statements. You can not OR (||) the
events together, where a filter of one event is OR’d to a filter of the
other event. This does not make sense, as the synthetic event requires both
events to take place to be recorded. If one is filtered out, then the
synthetic event does not execute.
select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start
JOIN sched_switch as end ON start.pid = end.next_pid
WHERE start.prio < 100 && end.prev_prio < 100
The above is valid.
Where as the below is not.
select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start
JOIN sched_switch as end ON start.pid = end.next_pid
WHERE start.prio < 100 || end.prev_prio < 100
KEYWORDS AS EVENT FIELDS
In some cases, an event may have a keyword. For example,
regcache_drop_region has "from" as a field and the following will not work
select from from regcache_drop_region
In such cases, add a backslash to the conflicting field, and this will tell
the parser that the "from" is a field and not a keyword:
select \from from regcache_drop_region
HISTOGRAMS
Simple SQL statements without the JOIN ON may also be used, which will
create a histogram instead. When doing this, the struct tracefs_hist
descriptor can be retrieved from the returned synthetic event descriptor via
the tracefs_synth_get_start_hist(3).
In order to utilize the histogram types (see xxx) the CAST command of SQL
can be used.
That is:
select CAST(common_pid AS comm), CAST(id AS syscall) FROM sys_enter
Which produces:
# echo 'hist:keys=common_pid.execname,id.syscall' > events/raw_syscalls/sys_enter/trigger
# cat events/raw_syscalls/sys_enter/hist
{ common_pid: bash [ 18248], id: sys_setpgid [109] } hitcount: 1
{ common_pid: sendmail [ 1812], id: sys_read [ 0] } hitcount: 1
{ common_pid: bash [ 18247], id: sys_getpid [ 39] } hitcount: 1
{ common_pid: bash [ 18247], id: sys_dup2 [ 33] } hitcount: 1
{ common_pid: gmain [ 13684], id: sys_inotify_add_watch [254] } hitcount: 1
{ common_pid: cat [ 18247], id: sys_access [ 21] } hitcount: 1
{ common_pid: bash [ 18248], id: sys_getpid [ 39] } hitcount: 1
{ common_pid: cat [ 18247], id: sys_fadvise64 [221] } hitcount: 1
{ common_pid: sendmail [ 1812], id: sys_openat [257] } hitcount: 1
{ common_pid: less [ 18248], id: sys_munmap [ 11] } hitcount: 1
{ common_pid: sendmail [ 1812], id: sys_close [ 3] } hitcount: 1
{ common_pid: gmain [ 1534], id: sys_poll [ 7] } hitcount: 1
{ common_pid: bash [ 18247], id: sys_execve [ 59] } hitcount: 1
Note, string fields may not be cast.
The possible types to cast to are:
HEX - convert the value to use hex and not decimal
SYM - convert a pointer to symbolic (kallsyms values)
SYM-OFFSET - convert a pointer to symbolic and include the offset.
SYSCALL - convert the number to the mapped system call name
EXECNAME or COMM - can only be used with the common_pid field. Will show the
task name of the process.
LOG or LOG2 - bucket the key values in a log 2 values (1, 2, 3-4, 5-8, 9-16, 17-32, ...)
The above fields are not case sensitive, and "LOG2" works as good as "log".
A special CAST to COUNTER or COUNTER will make the field a value and not a
key. For example:
SELECT common_pid, CAST(bytes_req AS _COUNTER_) FROM kmalloc
Which will create
echo 'hist:keys=common_pid:vals=bytes_req' > events/kmem/kmalloc/trigger
cat events/kmem/kmalloc/hist
{ common_pid: 1812 } hitcount: 1 bytes_req: 32
{ common_pid: 9111 } hitcount: 2 bytes_req: 272
{ common_pid: 1768 } hitcount: 3 bytes_req: 1112
{ common_pid: 0 } hitcount: 4 bytes_req: 512
{ common_pid: 18297 } hitcount: 11 bytes_req: 2004
RETURN VALUE
Returns 0 on success and -1 on failure. On failure, if err is defined, it
will be allocated to hold a detailed description of what went wrong if it
the error was caused by a parsing error, or that an event, field does not
exist or is not compatible with what it was combined with.
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
# event histogram
#
# trigger info: hist:keys=id.syscall,lat.buckets=10:vals=hitcount:sort=lat.buckets=10:size=2048 [active]
#
{ id: sys_fadvise64 [221], lat: ~ 0-9 } hitcount: 1
{ id: sys_fcntl [ 72], lat: ~ 0-9 } hitcount: 5
{ id: sys_read [ 0], lat: ~ 0-9 } hitcount: 51
{ id: sys_dup2 [ 33], lat: ~ 0-9 } hitcount: 1
{ id: sys_newfstat [ 5], lat: ~ 0-9 } hitcount: 7
{ id: sys_getpid [ 39], lat: ~ 0-9 } hitcount: 18
{ id: sys_openat [257], lat: ~ 0-9 } hitcount: 3
{ id: sys_newstat [ 4], lat: ~ 0-9 } hitcount: 22
{ id: sys_newlstat [ 6], lat: ~ 0-9 } hitcount: 44
{ id: sys_write [ 1], lat: ~ 0-9 } hitcount: 23
{ id: sys_brk [ 12], lat: ~ 0-9 } hitcount: 4
{ id: sys_readlink [ 89], lat: ~ 0-9 } hitcount: 11
{ id: sys_close [ 3], lat: ~ 0-9 } hitcount: 21
{ id: sys_mprotect [ 10], lat: ~ 0-9 } hitcount: 4
{ id: sys_arch_prctl [158], lat: ~ 0-9 } hitcount: 2
{ id: sys_getuid [102], lat: ~ 0-9 } hitcount: 12
{ id: sys_rt_sigaction [ 13], lat: ~ 0-9 } hitcount: 105
{ id: sys_statfs [137], lat: ~ 0-9 } hitcount: 8
{ id: sys_rt_sigprocmask [ 14], lat: ~ 0-9 } hitcount: 121
{ id: sys_inotify_add_watch [254], lat: ~ 0-9 } hitcount: 7
{ id: sys_mmap [ 9], lat: ~ 0-9 } hitcount: 10
{ id: sys_ioctl [ 16], lat: ~ 0-9 } hitcount: 32
{ id: sys_pread64 [ 17], lat: ~ 0-9 } hitcount: 4
{ id: sys_setpgid [109], lat: ~ 0-9 } hitcount: 2
{ id: sys_lseek [ 8], lat: ~ 0-9 } hitcount: 11
{ id: sys_access [ 21], lat: ~ 0-9 } hitcount: 1
{ id: sys_rt_sigprocmask [ 14], lat: ~ 10-19 } hitcount: 9
{ id: sys_munmap [ 11], lat: ~ 10-19 } hitcount: 1
{ id: sys_newstat [ 4], lat: ~ 10-19 } hitcount: 1
{ id: sys_rt_sigaction [ 13], lat: ~ 10-19 } hitcount: 1
{ id: sys_read [ 0], lat: ~ 10-19 } hitcount: 11
{ id: sys_openat [257], lat: ~ 10-19 } hitcount: 13
{ id: sys_getpid [ 39], lat: ~ 10-19 } hitcount: 1
{ id: sys_inotify_add_watch [254], lat: ~ 10-19 } hitcount: 2
{ id: sys_write [ 1], lat: ~ 10-19 } hitcount: 10
{ id: sys_read [ 0], lat: ~ 20-29 } hitcount: 4
{ id: sys_pipe [ 22], lat: ~ 20-29 } hitcount: 1
{ id: sys_write [ 1], lat: ~ 20-29 } hitcount: 11
{ id: sys_write [ 1], lat: ~ 30-39 } hitcount: 2
{ id: sys_inotify_add_watch [254], lat: ~ 30-39 } hitcount: 1
{ id: sys_write [ 1], lat: ~ 40-49 } hitcount: 1
{ id: sys_inotify_add_watch [254], lat: ~ 40-49 } hitcount: 1
{ id: sys_openat [257], lat: ~ 40-49 } hitcount: 1
{ id: sys_read [ 0], lat: ~ 70-79 } hitcount: 8
{ id: sys_read [ 0], lat: ~ 80-89 } hitcount: 1
{ id: sys_read [ 0], lat: ~ 110-119 } hitcount: 2
{ id: sys_clone [ 56], lat: ~ 240-249 } hitcount: 1
{ id: sys_execve [ 59], lat: ~ 350-359 } hitcount: 1
{ id: sys_write [ 1], lat: ~ 1960-1969 } hitcount: 1
Totals:
Hits: 615
Entries: 49
Dropped: 0
Steven Rostedt (VMware) (21):
libtracefs: Added new API tracefs_sql()
tracefs: Add unit tests for tracefs_sql()
libtracefs: Add comparing start and end fields in tracefs_sql()
libtracefs: Add unit test to test tracefs_sql() compare
libtracefs: Add filtering for start and end events in tracefs_sql()
libtracefs: Add unit test to test tracefs_sql() where clause
libtracefs: Make sqlhist parser reentrant
libtracefs: Make parser unique to libtracefs
libtracefs: Add line number and index to expr structure
libtracefs: Add error message when match fields are not FROM and JOIN
events
libtracefs: Add error message when match or init fails from bad events
libtracefs; Add error message for bad selections to SQL sequence
libtracefs: Add error message when compare fields fail
libtracefs: Add error message for grouping events in SQL filter
libtracefs: Add error message for bad filters in SQL statement
libtracefs: Add error message when calculation has no label
libtracefs: Add man page for tracefs_sql()
libtracefs: Allow for simple SQL statements to create a histogram
libtracefs: Allow trace_sql() to take keywords for fields with
backslash
libtracefs: Add CAST() syntax to SQL parsing for histogram types
libtracefs: Add CAST(x AS _COUNTER_) syntax to create values in
histograms
Documentation/libtracefs-sql.txt | 504 ++++++++++
include/tracefs-local.h | 9 +
include/tracefs.h | 6 +
src/Makefile | 13 +
src/sqlhist-parse.h | 76 ++
src/sqlhist.l | 98 ++
src/sqlhist.y | 250 +++++
src/tracefs-hist.c | 166 +++-
src/tracefs-sqlhist.c | 1569 ++++++++++++++++++++++++++++++
utest/tracefs-utest.c | 78 ++
10 files changed, 2729 insertions(+), 40 deletions(-)
create mode 100644 Documentation/libtracefs-sql.txt
create mode 100644 src/sqlhist-parse.h
create mode 100644 src/sqlhist.l
create mode 100644 src/sqlhist.y
create mode 100644 src/tracefs-sqlhist.c
--
2.30.2
@@ -44,6 +44,12 @@#define KRETPROBE_ADDR "do_sys_openat2"#define KRETPROBE_FMT "ret=$retval"+#define SQL_1_EVENT "wakeup_1"+#define SQL_1_SQL "select sched_switch.next_pid as woke_pid, sched_waking.common_pid as waking_pid from sched_waking join sched_switch on sched_switch.next_pid = sched_waking.pid"++#define SQL_2_EVENT "wakeup_2"+#define SQL_2_SQL "select woke.next_pid as woke_pid, wake.common_pid as waking_pid from sched_waking as wake join sched_switch as woke on woke.next_pid = wake.pid"+staticstructtracefs_instance*test_instance;staticstructtep_handle*test_tep;structtest_sample{
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:24:23
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Add comparing a field and showing the differences between start and end
for tracefs_sql().
For example:
SELECT (end.common_timestamp.usecs - start.common_timestamp.usecs) AS
lat FROM sched_waking AS start JOIN sched_switch AS end ON
start.pid = stop.next_pid
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/sqlhist-parse.h | 1 +
src/sqlhist.y | 16 ++++++++
src/tracefs-sqlhist.c | 85 ++++++++++++++++++++++++++++++++++++++++++-
3 files changed, 101 insertions(+), 1 deletion(-)
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:24:28
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Add a test to test passing time from sched_waking to sched_switch to
show wake up latency.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
utest/tracefs-utest.c | 10 ++++++++++
1 file changed, 10 insertions(+)
@@ -50,6 +50,9 @@#define SQL_2_EVENT "wakeup_2"#define SQL_2_SQL "select woke.next_pid as woke_pid, wake.common_pid as waking_pid from sched_waking as wake join sched_switch as woke on woke.next_pid = wake.pid"+#define SQL_3_EVENT "wakeup_lat"+#define SQL_3_SQL "select start.pid, end.next_prio as prio, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start join sched_switch as end on start.pid = end.next_pid"+staticstructtracefs_instance*test_instance;staticstructtep_handle*test_tep;structtest_sample{
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:24:43
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Add %define api.prefix and defines to have the parser global variables use
tracefs_* instead of yy*, as without this, if a tool that links to this
library, and tries to use the synth sql parsing, it may end up using its
own yyparse() and friends functions.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/sqlhist.y | 10 ++++++++++
src/tracefs-sqlhist.c | 2 +-
2 files changed, 11 insertions(+), 1 deletion(-)
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:24:46
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
It is required that the "match" content (the ON portion of the SQL
sequence) has a field from the FROM event and a field from the JOIN event.
If they do not, then give a better message about what went wrong.
To simplify addition of future errors, also add a parse_error() that calls into
sql_parse_error() with the appropriate "ap" argument. That is, parse_error()
takes a normal printf() form and then translates it to the vprintf from of
sql_parse_error.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/tracefs-sqlhist.c | 43 +++++++++++++++++++++++++++++++++++++++++--
1 file changed, 41 insertions(+), 2 deletions(-)
@@ -582,6 +593,34 @@ static int update_vars(struct sql_table *table, struct field *event)return0;}+staticintmatch_error(structsqlhist_bison*sb,structmatch*match,+structfield*lmatch,structfield*rmatch)+{+structfield*lval=&match->lval->field;+structfield*rval=&match->rval->field;+structfield*field;+structexpr*expr;++if(lval->system!=lmatch->system||+lval->event!=lmatch->event){+expr=match->lval;+field=lval;+}else{+expr=match->rval;+field=rval;+}++sb->line_no=expr->line;+sb->line_idx=expr->idx;++parse_error(sb,field->raw,+"'%s' and '%s' must be a field for each event: '%s' and '%s'\n",+lval->raw,rval->raw,sb->table->to->field.raw,+sb->table->from->field.raw);++return-1;+}+staticinttest_match(structsql_table*table,structmatch*match){structfield*lval,*rval;
@@ -613,13 +652,13 @@ static int test_match(struct sql_table *table, struct match *match)(rval->event!=to->event)||(lval->system!=from->system)||(lval->event!=from->event))-return-1;+returnmatch_error(table->sb,match,from,to);}else{if((rval->system!=from->system)||(rval->event!=from->event)||(lval->system!=to->system)||(lval->event!=to->event))-return-1;+returnmatch_error(table->sb,match,to,from);}return0;}
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:24:56
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Add a test to test filtering of events via the WHERE clause.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
utest/tracefs-utest.c | 25 +++++++++++++++++++++++++
1 file changed, 25 insertions(+)
@@ -53,6 +53,13 @@#define SQL_3_EVENT "wakeup_lat"#define SQL_3_SQL "select start.pid, end.next_prio as prio, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start join sched_switch as end on start.pid = end.next_pid"+#define SQL_4_EVENT "wakeup_lat_2"+#define SQL_4_SQL "select start.pid, end.next_prio as prio, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start join sched_switch as end on start.pid = end.next_pid where (start.prio >= 1 && start.prio < 100) || !(start.pid >= 0 && start.pid <= 1) && end.prev_pid != 0"++#define SQL_5_EVENT "irq_lat"+#define SQL_5_SQL "select end.common_pid as pid, (end.common_timestamp.usecs - start.common_timestamp.usecs) as irq_lat from irq_disable as start join irq_enable as end on start.common_pid = end.common_pid, start.parent_offs == end.parent_offs where start.common_pid != 0"+#define SQL_5_START "irq_disable"+staticstructtracefs_instance*test_instance;staticstructtep_handle*test_tep;structtest_sample{
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:25:05
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
In order to have better error messages, record the line number and index
when an expr structure is created. Then this can be used to show where in
the SQL sequence a problem was found if the building of the synth event
has issues.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/tracefs-sqlhist.c | 4 ++++
1 file changed, 4 insertions(+)
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:25:10
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
If the building of the synthetic event fails on creating the selection,
report it properly.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/tracefs-sqlhist.c | 14 +++++++++++++-
1 file changed, 13 insertions(+), 1 deletion(-)
@@ -971,6 +971,16 @@ static void *synth_init_error(struct tep_handle *tep, struct sql_table *table)returnfield_match_error(tep,sb,match);}+staticvoidselection_error(structtep_handle*tep,+structsqlhist_bison*sb,structexpr*expr)+{+/* We just care about event not existing */+if(errno!=ENODEV)+return;++test_field_exists(tep,sb,expr);+}+staticstructtracefs_synth*build_synth(structtep_handle*tep,constchar*name,structsql_table*table)
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:25:13
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
If the tracefs_synth_init() or the matching fails due to events that do
not exist, or if the match fields are not compatible with each other. Add
an error message that reports this and where the problem is.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/tracefs-sqlhist.c | 101 +++++++++++++++++++++++++++++++++++++++++-
1 file changed, 99 insertions(+), 2 deletions(-)
@@ -876,6 +876,101 @@ static int build_filter(struct tracefs_synth *synth,returnret;}+staticinttest_event_exists(structtep_handle*tep,structsqlhist_bison*sb,+structexpr*expr,structtep_event**pevent)+{+constchar*system=expr->field.system;+constchar*event_name=expr->field.event;+structtep_event*event;++event=tep_find_event_by_name(tep,system,event_name);+if(pevent)+*pevent=event;+if(event)+return0;++sb->line_no=expr->line;+sb->line_idx=expr->idx;++parse_error(sb,expr->field.raw,"event not found\n");+return-1;+}++staticinttest_field_exists(structtep_handle*tep,structsqlhist_bison*sb,+structexpr*expr)+{+structtep_event*event;++if(test_event_exists(tep,sb,expr,&event))+return-1;++if(trace_verify_event_field(event,expr->field.field,NULL))+return0;++sb->line_no=expr->line;+sb->line_idx=expr->idx;++parse_error(sb,expr->field.raw,"Field '%s' not part of event %s\n",+expr->field.field,expr->field.event);+return-1;+}++staticvoid*field_match_error(structtep_handle*tep,structsqlhist_bison*sb,+structmatch*match)+{+switch(errno){+caseENODEV:+caseEBADE:+break;+default:+/* System error */+returnNULL;+}++/* ENODEV means that an event or field does not exist */+if(errno==ENODEV){+if(test_field_exists(tep,sb,match->lval))+returnNULL;+if(test_field_exists(tep,sb,match->rval))+returnNULL;+returnNULL;+}++/* fields exist, but values are not compatible */+sb->line_no=match->lval->line;+sb->line_idx=match->lval->idx;++parse_error(sb,match->lval->field.raw,+"Field '%s' is not compatible to match field '%s'\n",+match->lval->field.raw,match->rval->field.raw);+returnNULL;+}++staticvoid*synth_init_error(structtep_handle*tep,structsql_table*table)+{+structsqlhist_bison*sb=table->sb;+structmatch*match=table->matches;++switch(errno){+caseENODEV:+caseEBADE:+break;+default:+/* System error */+returnNULL;+}++/* ENODEV could mean that start or end events do not exist */+if(errno==ENODEV){+if(test_event_exists(tep,sb,table->from,NULL))+returnNULL;+if(test_event_exists(tep,sb,table->to,NULL))+returnNULL;+}++returnfield_match_error(tep,sb,match);+}+staticstructtracefs_synth*build_synth(structtep_handle*tep,constchar*name,structsql_table*table)
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:25:23
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
One requirement for the SQL filter in tracefs_sql() is that the WHERE
clause (filter) can only filter the FROM and JOIN events with "&&".
That is, you can not have:
sched_switch.next_pid == 0 || sched_waking.pid == 0
As the filtering one event stops the synthetic event, having an ||
conjunction makes no sense.
Add an error message that explains this when it is found.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/tracefs-sqlhist.c | 35 +++++++++++++++++++++++++----------
1 file changed, 25 insertions(+), 10 deletions(-)
@@ -715,21 +715,36 @@ static int build_compare(struct tracefs_synth *synth,returnret;}-staticintdo_verify_filter(structfilter*filter,+staticintverify_filter_error(structsqlhist_bison*sb,structexpr*expr,+constchar*event)+{+structfield*field=&expr->field;++sb->line_no=expr->line;+sb->line_idx=expr->idx;++parse_error(sb,field->raw,+"event '%s' can not be grouped or '||' together with '%s'\n"+"All filters between '&&' must be for the same event\n",+field->event,event);+return-1;+}++staticintdo_verify_filter(structsqlhist_bison*sb,structfilter*filter,constchar**system,constchar**event){intret;if(filter->type==FILTER_OR||filter->type==FILTER_AND){-ret=do_verify_filter(&filter->lval->filter,system,event);+ret=do_verify_filter(sb,&filter->lval->filter,system,event);if(ret)returnret;-returndo_verify_filter(&filter->rval->filter,system,event);+returndo_verify_filter(sb,&filter->rval->filter,system,event);}if(filter->type==FILTER_GROUP||filter->type==FILTER_NOT_GROUP){-returndo_verify_filter(&filter->lval->filter,system,event);+returndo_verify_filter(sb,&filter->lval->filter,system,event);}/*
@@ -744,12 +759,12 @@ static int do_verify_filter(struct filter *filter,if(filter->lval->field.system!=*system||filter->lval->field.event!=*event)-return-1;+returnverify_filter_error(sb,filter->lval,*event);return0;}-staticintverify_filter(structfilter*filter,+staticintverify_filter(structsqlhist_bison*sb,structfilter*filter,constchar**system,constchar**event){intret;
@@ -761,17 +776,17 @@ static int verify_filter(struct filter *filter,caseFILTER_NOT_GROUP:break;default:-returndo_verify_filter(filter,system,event);+returndo_verify_filter(sb,filter,system,event);}-ret=do_verify_filter(&filter->lval->filter,system,event);+ret=do_verify_filter(sb,&filter->lval->filter,system,event);if(ret)returnret;switch(filter->type){caseFILTER_OR:caseFILTER_AND:-returndo_verify_filter(&filter->rval->filter,system,event);+returndo_verify_filter(sb,&filter->rval->filter,system,event);default:return0;}
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:25:31
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Some events have fields with keywords, and the parsing will not let it
work. For example, you can have:
select from from regcache_drop_region
And that will produce a syntax error, as the from will confuse the parser.
Allow fields to start with a backslash, which will allow the parser to see
"from" as a field and not as a keyword. That is:
select \from from regcache_drop_region
will work as expected. Note, any field can start with a backslash, and the
starting backslash will be ignored.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
Documentation/libtracefs-sql.txt | 20 ++++++++++++++++++++
src/sqlhist.l | 6 ++++--
2 files changed, 24 insertions(+), 2 deletions(-)
@@ -162,6 +162,26 @@ select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sche WHERE start.prio < 100 || end.prev_prio < 100 --++KEYWORDS AS EVENT FIELDS+------------------------++In some cases, an event may have a keyword. For example, regcache_drop_region has "from"+as a field and the following will not work++[source,c]+--+ select from from regcache_drop_region+--++In such cases, add a backslash to the conflicting field, and this will tell the parser+that the "from" is a field and not a keyword:++[source,c]+--+ select \from from regcache_drop_region+--+ HISTOGRAMS ----------
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:25:36
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Use the CAST() command of SQL to define which items in the select should
be cast as values and not keys. By casting the field as the special value
_COUNTER_, it will turn the selection item into a value.
For example:
SELECT common_pid, CAST(bytes_req AS _COUNTER_) FROM kmalloc
Will create:
echo 'hist:keys=common_pid:vals=bytes_req' > events/kmem/kmalloc/trigger
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
Documentation/libtracefs-sql.txt | 24 ++++++++++++++++++++++++
include/tracefs-local.h | 2 ++
include/tracefs.h | 3 +++
src/tracefs-hist.c | 28 ++++++++++++++++++++++++++--
src/tracefs-sqlhist.c | 23 +++++++++++++++++++++++
5 files changed, 78 insertions(+), 2 deletions(-)
@@ -238,6 +238,30 @@ name of the process. *LOG* or *LOG2* - bucket the key values in a log 2 values (1, 2, 3-4, 5-8, 9-16, 17-32, ...)+The above fields are not case sensitive, and "LOG2" works as good as "log".++A special CAST to _COUNTER_ or __COUNTER__ will make the field a value and not+a key. For example:++[source,c]+--+ SELECT common_pid, CAST(bytes_req AS _COUNTER_) FROM kmalloc+--++Which will create++[source,c]+--+ echo 'hist:keys=common_pid:vals=bytes_req' > events/kmem/kmalloc/trigger++ cat events/kmem/kmalloc/hist++{ common_pid: 1812 } hitcount: 1 bytes_req: 32+{ common_pid: 9111 } hitcount: 2 bytes_req: 272+{ common_pid: 1768 } hitcount: 3 bytes_req: 1112+{ common_pid: 0 } hitcount: 4 bytes_req: 512+{ common_pid: 18297 } hitcount: 11 bytes_req: 2004+-- RETURN VALUE ------------
@@ -1253,6 +1253,17 @@ static int verify_field_type(struct tep_handle *tep,if(!type)return-1;+if(!strcmp(type,TRACEFS_HIST_COUNTER)||+!strcmp(type,"_COUNTER_")){+ret=HIST_COUNTER_TYPE;+if(tfield->flags&(TEP_FIELD_IS_STRING|TEP_FIELD_IS_ARRAY)){+parse_error(sb,field->raw,+"'%s' is a string, and counters may only be used with numbers\n");+ret=-1;+}+gotoout;+}+for(i=0;type[i];i++)type[i]=tolower(type[i]);
@@ -1292,6 +1303,7 @@ static int verify_field_type(struct tep_handle *tep,field->raw,type);ret=-1;}+out:free(type);returnret;fail_type:
@@ -1426,6 +1441,14 @@ static struct tracefs_synth *build_synth(struct tep_handle *tep,}}+if(!non_val&&!table->to){+table->sb->line_no=0;+table->sb->line_idx=10;+parse_error(table->sb,"CAST",+"Not all SELECT items can be of type _COUNTER_\n");+gotofree;+}+for(expr=table->where;expr;expr=expr->next){constchar*filter_system=NULL;constchar*filter_event=NULL;
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:25:39
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Add a man page for tracefs_sql(). Included in that man page is a full
working sql parser example program that can allow you to create synthetic
events from writing SQL on the command line.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
Documentation/libtracefs-sql.txt | 389 +++++++++++++++++++++++++++++++
1 file changed, 389 insertions(+)
create mode 100644 Documentation/libtracefs-sql.txt
@@ -0,0 +1,389 @@+libtracefs(3)+=============++NAME+----+tracefs_sql - Create a synthetitc event via an SQL statement++SYNOPSIS+--------+[verse]+--+*#include <tracefs.h>*++struct tracefs_synth *tracefs_sql(struct tep_handle pass:[*]tep, const char pass:[*]name,+ const char pass:[*]sql_buffer, char pass:[**]err);+--++DESCRIPTION+-----------+Synthetic events are dynamically created events that attach two existing events+together via one or more matching fields between the two events. It can be used+to find the latency between the events, or to simply pass fields of the first event+on to the second event to display as one event.++The Linux kernel interface to create synthetic events is complex, and there needs+to be a better way to create synthetic events that is easy and can be understood+via existing technology.++If you think of each event as a table, where the fields are the column of the table+and each instance of the event as a row, you can understand how SQL can be used+to attach two events together and form another event (table). Utilizing the+SQL *SELECT* *FROM* *JOIN* *ON* [ *WHERE* ] syntax, a synthetic event can easily+be created from two different events.+++*tracefs_sql*() takes in a *tep* handler (See _tep_local_events_(3)) that is used to+verify the events within the _sql_buffer_ expression. The _name_ is the name of the+synthetic event to create. If _err_ points to an address of a string, it will be filled+with a detailed message on any type of parsing error, including fields that do not belong+to an event, or if the events or fields are not properly compared.++The example program below is a fully functional parser where it will create a synthetic+event from a SQL syntax passed in via the command line or a file. ++The SQL format is as follows:++*SELECT* <fields> *FROM* <start-event> *JOIN* <end-event> *ON* <matching-fields> *WHERE* <filter>++Note, although the examples show the SQL commands in uppercase, they are not required to+be so. That is, you can use "SELECT" or "select" or "sElEct".++For example:+[source,c]+--+SELECT syscalls.sys_enter_read.fd, syscalls.sys_exit_read.ret FROM syscalls.sys_enter_read+ JOIN syscalls.sys_exit_read+ ON syscalls.sys_enter_read.common_pid = syscalls.sys_exit_write.common_pid+--++Will create a synthetic event that with the fields:++ u64 fd; s64 ret;++Because the function takes a _tep_ handle, and usually all event names are unique, you can+leave off the system (group) name of the event, and *tracefs_sql*() will discover the+system for you.++That is, the above statement would work with:++[source,c]+--+SELECT sys_enter_read.fd, sys_exit_read.ret FROM sys_enter_read JOIN sys_exit_read+ ON sys_enter_read.common_pid = sys_exit_write.common_pid+--++The *AS* keyword can be used to name the fields as well as to give an alias to the+events, such that the above can be simplified even more as:++[source,c]+--+SELECT start.fd, end.ret FROM sys_enter_read AS start JOIN sys_exit_read AS end ON start.common_pid = end.common_pid+--++The above aliases _sys_enter_read_ as *start* and _sys_exit_read_ as *end* and uses+those aliases to reference the event throughout the statement.++Using the *AS* keyword in the selection portion of the SQL statement will define what+those fields will be called in the synthetic event.++[source,c]+--+SELECT start.fd AS filed, end.ret AS return FROM sys_enter_read AS start JOIN sys_exit_read AS end+ ON start.common_pid = end.common_pid+--++The above labels the _fd_ of _start_ as *filed* and the _ret_ of _end_ as *return* where+the synthetic event that is created will now have the fields:++ u64 filed; s64 return;++The fields can also be calculated with results passed to the synthetic event:++[source,c]+--+select start.truesize, end.len, (start.truesize - end.len) as diff from napi_gro_receive_entry as start+ JOIN netif_receive_skb as end ON start.skbaddr = end.skbaddr+--++Which would show the *truesize* of the _napi_gro_receive_entry_ event, the actual+_len_ of the content, shown by the _netif_receive_skb_, and the delta between+the two and expressed by the field *diff*.++The code also supports recording the timestamps at either event, and performing calculations+on them. For wakeup latency, you have:++[source,c]+--+select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start+ JOIN sched_switch as end ON start.pid = end.next_pid+--++The above will create a synthetic event that records the _pid_ of the task being woken up,+and the time difference between the _sched_waking_ event and the _sched_switch_ event.+The *TIMESTAMP_USECS* will truncate the time down to microseconds as the timestamp usually+recorded in the tracing buffer has nanosecond resolution. If you do not want that+truncation, use *TIMESTAMP* instead of *TIMESTAMP_USECS*.++Finally, the *WHERE* clause can be added, that will let you add filters on either or both events.++[source,c]+--+select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start+ JOIN sched_switch as end ON start.pid = end.next_pid+ WHERE start.prio < 100 && (!(end.prev_pid < 1 || end.prev_prio > 100) || end.prev_pid == 0)+--++*NOTE*++Although both events can be used together in the *WHERE* clause, they must not be mixed outside+the top most "&&" statements. You can not OR (||) the events together, where a filter of one+event is OR'd to a filter of the other event. This does not make sense, as the synthetic event+requires both events to take place to be recorded. If one is filtered out, then the synthetic+event does not execute.++[source,c]+--+select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start+ JOIN sched_switch as end ON start.pid = end.next_pid+ WHERE start.prio < 100 && end.prev_prio < 100+--++The above is valid.++Where as the below is not.++[source,c]+--+select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start+ JOIN sched_switch as end ON start.pid = end.next_pid+ WHERE start.prio < 100 || end.prev_prio < 100+--+++RETURN VALUE+------------+Returns 0 on success and -1 on failure. On failure, if _err_ is defined, it will be+allocated to hold a detailed description of what went wrong if it the error was caused+by a parsing error, or that an event, field does not exist or is not compatible with+what it was combined with.++CREATE A TOOL+-------------++The below example is a functional program that can be used to parse SQL commands into+synthetic events.++[source, c]+--+ man tracefs_sql | sed -ne '/^EXAMPLE/,/FILES/ { /EXAMPLE/d ; /FILES/d ; p}' > sqlhist.c+ gcc -o sqlhist sqlhist.c `pkg-config --cflags --libs libtracefs`+--++Then you can run the above examples:++[source, c]+--+ sudo ./sqlhist 'select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sched_waking as start+ JOIN sched_switch as end ON start.pid = end.next_pid+ WHERE start.prio < 100 || end.prev_prio < 100'+--++EXAMPLE+-------+[source,c]+--+#include <stdio.h>+#include <stdlib.h>+#include <stdarg.h>+#include <string.h>+#include <errno.h>+#include <unistd.h>+#include <tracefs.h>++static void usage(char **argv)+{+ fprintf(stderr, "usage: %s [-ed][-n name][-t dir][-f file | sql-command-line]\n"+ " -n name - name of synthetic event 'Anonymous' if left off\n"+ " -t dir - use dir instead of /sys/kernel/tracing\n"+ " -e - execute the commands to create the synthetic event\n"+ " -d - delete the synthetic event that would be created\n"+ " -f file - read sql lines from file otherwise from the command line\n"+ " if file is '-' then read from standard input.\n",+ argv[0]);+ exit(-1);+}++static int do_sql(const char *buffer, const char *name,+ const char *trace_dir, bool execute)+{+ struct tracefs_synth *synth;+ struct tep_handle *tep;+ struct trace_seq seq;+ char *err;++ if (!name)+ name = "Anonymous";++ trace_seq_init(&seq);+ tep = tracefs_local_events(trace_dir);+ if (!tep) {+ if (!trace_dir)+ trace_dir = "tracefs directory";+ perror(trace_dir);+ exit(-1);+ }++ synth = tracefs_sql(tep, name, buffer, &err);+ if (!synth) {+ perror("Failed creating synthetic event!");+ if (err)+ fprintf(stderr, "%s", err);+ free(err);+ exit(-1);+ }++ tracefs_synth_show(&seq, NULL, synth);+ if (execute)+ tracefs_synth_create(NULL, synth);+ tracefs_synth_free(synth);++ trace_seq_do_printf(&seq);+ trace_seq_destroy(&seq);+ return 0;+}++int main (int argc, char **argv)+{+ char *trace_dir = NULL;+ char *buffer = NULL;+ char buf[BUFSIZ];+ int buffer_size = 0;+ const char *file = NULL;+ bool execute = false;+ const char *name;+ FILE *fp;+ size_t r;+ int c;+ int i;++ for (;;) {+ c = getopt(argc, argv, "ht:f:edn:");+ if (c == -1)+ break;++ switch(c) {+ case 'h':+ usage(argv);+ case 't':+ trace_dir = optarg;+ break;+ case 'f':+ file = optarg;+ break;+ case 'e':+ execute = true;+ break;+ case 'n':+ name = optarg;+ break;+ }+ }++ if (file) {+ if (!strcmp(file, "-"))+ fp = stdin;+ else+ fp = fopen(file, "r");+ if (!fp) {+ perror(file);+ exit(-1);+ }+ while ((r = fread(buf, 1, BUFSIZ, fp)) > 0) {+ buffer = realloc(buffer, buffer_size + r + 1);+ strncpy(buffer + buffer_size, buf, r);+ buffer_size += r;+ }+ fclose(fp);+ if (buffer_size)+ buffer[buffer_size] = '\0';+ } else if (argc == optind) {+ usage(argv);+ } else {+ for (i = optind; i < argc; i++) {+ r = strlen(argv[i]);+ buffer = realloc(buffer, buffer_size + r + 2);+ if (i != optind)+ buffer[buffer_size++] = ' ';+ strcpy(buffer + buffer_size, argv[i]);+ buffer_size += r;+ }+ }++ do_sql(buffer, name, trace_dir, execute);+ free(buffer);++ return 0;+}+--++FILES+-----+[verse]+--+*tracefs.h*+ Header file to include in order to have access to the library APIs.+*-ltracefs*+ Linker switch to add when building a program that uses the library.+--++SEE ALSO+--------+_libtracefs(3)_,+_libtraceevent(3)_,+_trace-cmd(1)_,+_tracefs_synth_init(3)_,+_tracefs_synth_add_match_field(3)_,+_tracefs_synth_add_compare_field(3)_,+_tracefs_synth_add_start_field(3)_,+_tracefs_synth_add_end_field(3)_,+_tracefs_synth_append_start_filter(3)_,+_tracefs_synth_append_end_filter(3)_,+_tracefs_synth_create(3)_,+_tracefs_synth_destroy(3)_,+_tracefs_synth_free(3)_,+_tracefs_synth_show(3)_,+_tracefs_hist_alloc(3)_,+_tracefs_hist_free(3)_,+_tracefs_hist_add_key(3)_,+_tracefs_hist_add_value(3)_,+_tracefs_hist_add_name(3)_,+_tracefs_hist_start(3)_,+_tracefs_hist_destory(3)_,+_tracefs_hist_add_sort_key(3)_,+_tracefs_hist_sort_key_direction(3)_++AUTHOR+------+[verse]+--+*Steven Rostedt* <rostedt@goodmis.org>+*Tzvetomir Stoyanov* <tz.stoyanov@gmail.com>+*sameeruddin shaik* <sameeruddin.shaik8@gmail.com>+--+REPORTING BUGS+--------------+Report bugs to <linux-trace-devel@vger.kernel.org>++LICENSE+-------+libtracefs is Free Software licensed under the GNU LGPL 2.1++RESOURCES+---------+https://git.kernel.org/pub/scm/libs/libtrace/libtracefs.git/++COPYING+-------+Copyright \(C) 2020 VMware, Inc. Free use of this software is granted under+the terms of the GNU Public License (GPL).
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:25:52
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
This adds the API tracefs_sql() that takes a tep_handle handler, a name,
and a SQL string and parses it to produce a tracefs_synth synthetic event
handler.
Currently it only supports simple SQL of the type:
SELECT start.common_pid AS pid, end.common_timestamp.usecs AS usecs
FROM sched_waking AS start JOIN sched_switch AS end
ON start.pid = end.next_pid
Special thanks to:
Lukas Bulwahn for first introducing the idea at RT Summit on the Summit
Spring of 2019.
Daniel Black for sorting out the syntax of mapping the synthetic
event creations into SQL statements at Linux Plumbers, Fall of 2019.
Cc: Lukas Bulwahn <lukas.bulwahn@gmail.com>
Cc: Daniel Black <redacted>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
include/tracefs.h | 3 +
src/Makefile | 13 +
src/sqlhist-parse.h | 69 +++++
src/sqlhist.l | 88 ++++++
src/sqlhist.y | 143 +++++++++
src/tracefs-sqlhist.c | 691 ++++++++++++++++++++++++++++++++++++++++++
6 files changed, 1007 insertions(+)
create mode 100644 src/sqlhist-parse.h
create mode 100644 src/sqlhist.l
create mode 100644 src/sqlhist.y
create mode 100644 src/tracefs-sqlhist.c
@@ -12,6 +12,11 @@ OBJS += tracefs-kprobes.oOBJS+=tracefs-hist.oOBJS+=tracefs-filter.o+# Order matters for the the three below+OBJS+=sqlhist-lex.o+OBJS+=sqlhist.tab.o+OBJS+=tracefs-sqlhist.o+OBJS:=$(OBJS:%.o=$(bdir)/%.o)DEPS:=$(OBJS:$(bdir)/%.o=$(bdir)/.%.d)
@@ -32,6 +37,14 @@ $(LIBTRACEFS_SHARED_SO): $(LIBTRACEFS_SHARED_VERSION)libtracefs.so:$(LIBTRACEFS_SHARED_SO)+# bison will create both sqlhist.tab.c and sqlhist.tab.h+sqlhist.tab.h:+sqlhist.tab.c:sqlhist.ysqlhist.tab.h+bison--debug-v--report-file=bison.report-d-o$@$<++sqlhist-lex.c:sqlhist.lsqlhist.tab.c+flex-o$@$<+$(bdir)/%.o:%.c$(Q)$(calldo_fpic_compile)
@@ -0,0 +1,691 @@+// SPDX-License-Identifier: LGPL-2.1+/*+*Copyright(C)2021VMwareInc,StevenRostedt<rostedt@goodmis.org>+*+*Updates:+*Copyright(C)2021,VMware,TzvetomirStoyanov<tz.stoyanov@gmail.com>+*+*/+#include<trace-seq.h>+#include<stdlib.h>+#include<errno.h>++#include"tracefs.h"+#include"tracefs-local.h"+#include"sqlhist-parse.h"++structsqlhist_bison*sb;++externintyylex_init(void*ptr_yy_globals);+externintyylex_init_extra(structsqlhist_bison*sb,void*ptr_yy_globals);+externintyylex_destroy(void*yyscanner);++structstr_hash{+structstr_hash*next;+char*str;+};++enumalias_type{+ALIAS_EVENT,+ALIAS_FIELD,+};++#define for_each_field(expr, field, table) \+for(expr=(table)->fields;expr;expr=(field)->next)++structfield{+structexpr*next;/* private link list */+constchar*system;+constchar*event;+constchar*raw;+constchar*label;+constchar*field;+};++structmatch{+structmatch*next;+structexpr*lval;+structexpr*rval;+};++enumexpr_type+{+EXPR_NUMBER,+EXPR_STRING,+EXPR_FIELD,+};++structexpr{+structexpr*free_list;+structexpr*next;+enumexpr_typetype;+union{+structfieldfield;+constchar*string;+longnumber;+};+};++structsql_table{+structsqlhist_bison*sb;+constchar*name;+structexpr*exprs;+structexpr*fields;+structexpr*from;+structexpr*to;+structmatch*matches;+structmatch**next_match;+structexpr*selections;+structexpr**next_selection;+};++__hiddenintmy_yyinput(char*buf,intmax)+{+if(!sb||!sb->buffer)+return-1;++if(sb->buffer_idx+max>sb->buffer_size)+max=sb->buffer_size-sb->buffer_idx;++if(max)+memcpy(buf,sb->buffer+sb->buffer_idx,max);++sb->buffer_idx+=max;++returnmax;+}++__hiddenvoidsql_parse_error(structsqlhist_bison*sb,constchar*text,+constchar*fmt,va_listap)+{+constchar*buffer=sb->buffer;+structtrace_seqs;+intline=sb->line_no;+intidx=sb->line_idx-strlen(text);+inti;++if(!buffer)+return;++trace_seq_init(&s);+if(!s.buffer){+fprintf(stderr,"Error allocating internal buffer\n");+return;+}++for(i=0;line&&buffer[i];i++){+if(buffer[i]=='\n')+line--;+}+for(;buffer[i]&&buffer[i]!='\n';i++)+trace_seq_putc(&s,buffer[i]);+trace_seq_putc(&s,'\n');+for(i=idx;i>0;i--)+trace_seq_putc(&s,' ');+trace_seq_puts(&s,"^\n");+trace_seq_printf(&s,"ERROR: '%s'\n",text);+trace_seq_vprintf(&s,fmt,ap);++trace_seq_terminate(&s);++sb->parse_error_str=strdup(s.buffer);+trace_seq_destroy(&s);+}++staticinlineunsignedintquick_hash(constchar*str)+{+unsignedintval=0;+intlen=strlen(str);++for(;len>=4;str+=4,len-=4){+val+=str[0];+val+=str[1]<<8;+val+=str[2]<<16;+val+=str[3]<<24;+}+for(;len>0;str++,len--)+val+=str[0]<<(len*8);++val*=2654435761;++returnval&((1<<HASH_BITS)-1);+}+++staticstructstr_hash*find_string(structsqlhist_bison*sb,constchar*str)+{+unsignedintkey=quick_hash(str);+structstr_hash*hash=sb->str_hash[key];++for(;hash;hash=hash->next){+if(!strcmp(hash->str,str))+returnhash;+}+returnNULL;+}++/*+*If@strisfound,thenreturnthehashstring.+*Thisletsstore_str()knowtofreestr.+*/+staticchar**add_hash(structsqlhist_bison*sb,constchar*str)+{+structstr_hash*hash;+unsignedintkey;++if((hash=find_string(sb,str))){+return&hash->str;+}++hash=malloc(sizeof(*hash));+if(!hash)+returnNULL;+key=quick_hash(str);+hash->next=sb->str_hash[key];+sb->str_hash[key]=hash;+hash->str=NULL;+return&hash->str;+}++__hiddenchar*store_str(structsqlhist_bison*sb,constchar*str)+{+char**pstr=add_hash(sb,str);++if(!pstr)+returnNULL;++if(!(*pstr))+*pstr=strdup(str);++return*pstr;+}++__hiddenintadd_selection(structsqlhist_bison*sb,void*select,+constchar*name)+{+structsql_table*table=sb->table;+structexpr*expr=select;++switch(expr->type){+caseEXPR_FIELD:+break;+caseEXPR_NUMBER:+caseEXPR_STRING:+default:+return-1;+}++if(expr->next)+return-1;++*table->next_selection=expr;+table->next_selection=&expr->next;++return0;+}++staticstructexpr*find_field(structsqlhist_bison*sb,+constchar*raw,constchar*label)+{+structfield*field;+structexpr*expr;++for_each_field(expr,field,sb->table){+field=&expr->field;++if(!strcmp(field->raw,raw)){+if(label&&!field->label)+field->label=label;+returnexpr;+}++if(label&&!strcmp(field->raw,label)){+if(!field->label){+field->label=label;+field->raw=raw;+}+returnexpr;+}++if(!field->label)+continue;++if(!strcmp(field->label,raw))+returnexpr;++if(label&&!strcmp(field->label,label))+returnexpr;+}+returnNULL;+}++staticvoid*create_expr(enumexpr_typetype,structexpr**expr_p)+{+structexpr*expr;++expr=calloc(1,sizeof(*expr));+if(!expr)+returnNULL;++if(expr_p)+*expr_p=expr;++expr->free_list=sb->table->exprs;+sb->table->exprs=expr;++expr->type=type;++switch(type){+caseEXPR_FIELD:return&expr->field;+caseEXPR_NUMBER:return&expr->number;+caseEXPR_STRING:return&expr->string;+}++returnNULL;+}++#define __create_expr(var, type, ENUM, expr) \+do{\+var=(type*)create_expr(EXPR_##ENUM,expr);\+}while(0)++#define create_field(var, expr) \+__create_expr(var,structfield,FIELD,expr)++__hiddenvoid*add_field(structsqlhist_bison*sb,+constchar*field_name,constchar*label)+{+structsql_table*table=sb->table;+structexpr*expr;+structfield*field;++expr=find_field(sb,field_name,label);+if(expr)+returnexpr;++create_field(field,&expr);++field->next=table->fields;+table->fields=expr;++field->raw=field_name;+field->label=label;++returnexpr;+}++__hiddenintadd_match(structsqlhist_bison*sb,void*A,void*B)+{+structsql_table*table=sb->table;+structmatch*match;++match=calloc(1,sizeof(*match));+if(!match)+return-1;++match->lval=A;+match->rval=B;++*table->next_match=match;+table->next_match=&match->next;++return0;+}++__hiddenintadd_from(structsqlhist_bison*sb,void*item)+{+structexpr*expr=item;++if(expr->type!=EXPR_FIELD)+return-1;++sb->table->from=expr;++return0;+}++__hiddenintadd_to(structsqlhist_bison*sb,void*item)+{+structexpr*expr=item;++if(expr->type!=EXPR_FIELD)+return-1;++sb->table->to=expr;++return0;+}++__hiddeninttable_start(structsqlhist_bison*sb)+{+structsql_table*table;++table=calloc(1,sizeof(*table));+if(!table)+return-ENOMEM;++table->sb=sb;+sb->table=table;++table->next_match=&table->matches;+table->next_selection=&table->selections;++return0;+}++staticintupdate_vars(structsql_table*table,structfield*event)+{+structsqlhist_bison*sb=table->sb;+structexpr*expr;+structfield*field;+constchar*label;+constchar*p,*r;+char*system;+intlen;++p=strchr(event->raw,'.');+if(p){+system=strndup(event->raw,p-event->raw);+if(!system)+return-1;+event->system=store_str(sb,system);+free(system);+if(!event->system)+return-1;+p++;+}else{+p=event->raw;+}++event->event=store_str(sb,p);+if(!event->event)+return-1;++if(!event->label)+event->label=event->event;++label=event->label;+len=strlen(label);++for_each_field(expr,field,table){+field=&expr->field;++if(field->event)+continue;++p=strchr(field->raw,'.');+if(p){+/* Does this field have a system */+r=strchr(p+1,'.');+if(r){+/* This has a system, and is not a alias */+system=strndup(field->raw,p-field->raw);+if(!system)+return-1;+field->system=store_str(sb,system);+free(system);+if(!field->system)+return-1;++/* save the event as well */+p++;+system=strndup(p,r-p);+if(!system)+return-1;+field->event=store_str(sb,system);+free(system);+if(!field->event)+return-1;+r++;+field->field=store_str(sb,r);+gotocheck_timestamps;+}+}++if(strncmp(field->raw,label,len))+continue;++if(field->raw[len]!='.')+continue;++field->system=event->system;+field->event=event->event;+field->field=field->raw+len+1;+check_timestamps:+if(!strcmp(field->field,"TIMESTAMP"))+field->field=store_str(sb,TRACEFS_TIMESTAMP);+elseif(!strcmp(field->field,"TIMESTAMP_USECS"))+field->field=store_str(sb,TRACEFS_TIMESTAMP_USECS);+}++return0;+}++staticinttest_match(structsql_table*table,structmatch*match)+{+structfield*lval,*rval;+structfield*to,*from;++if(!match->lval||!match->rval)+return-1;++if(match->lval->type!=EXPR_FIELD||match->rval->type!=EXPR_FIELD)+return-1;++to=&table->to->field;+from=&table->from->field;++lval=&match->lval->field;+rval=&match->rval->field;++/*+*Note,stringsarestoredinthestringstore,soall+*duplicatestringsarethesamevalue,andwecanuse+*normal"=="and"!="insteadofstrcmp().+*+*Eitherlval==toandrval==from+*orlval==fromandrval==to.+*/+if((lval->system!=to->system)||+(lval->event!=to->event)){+if((rval->system!=to->system)||+(rval->event!=to->event)||+(lval->system!=from->system)||+(lval->event!=from->event))+return-1;+}else{+if((rval->system!=from->system)||+(rval->event!=from->event)||+(lval->system!=to->system)||+(lval->event!=to->event))+return-1;+}+return0;+}++staticvoidassign_match(constchar*system,constchar*event,+structmatch*match,+constchar**start_match,constchar**end_match)+{+structfield*lval,*rval;++lval=&match->lval->field;+rval=&match->rval->field;++if(lval->system==system&&+lval->event==event){+*start_match=lval->field;+*end_match=rval->field;+}else{+*start_match=rval->field;+*end_match=lval->field;+}+}++staticstructtracefs_synth*build_synth(structtep_handle*tep,+constchar*name,+structsql_table*table)+{+structtracefs_synth*synth;+structfield*field;+structmatch*match;+structexpr*expr;+constchar*start_system;+constchar*start_event;+constchar*end_system;+constchar*end_event;+constchar*start_match;+constchar*end_match;+intret;++if(!table->to||!table->from)+returnNULL;++ret=update_vars(table,&table->to->field);+if(ret<0)+returnNULL;++ret=update_vars(table,&table->from->field);+if(ret<0)+returnNULL;++match=table->matches;+if(!match)+returnNULL;++ret=test_match(table,match);+if(ret<0)+returnNULL;++start_system=table->from->field.system;+start_event=table->from->field.event;++end_system=table->to->field.system;+end_event=table->to->field.event;++assign_match(start_system,start_event,match,+&start_match,&end_match);++synth=tracefs_synth_init(tep,name,start_system,+start_event,end_system,end_event,+start_match,end_match,NULL);+if(!synth)+returnNULL;++for(match=match->next;match;match=match->next){+ret=test_match(table,match);+if(ret<0)+gotofree;++assign_match(start_system,start_event,match,+&start_match,&end_match);++ret=tracefs_synth_add_match_field(synth,+start_match,+end_match,NULL);+if(ret<0)+gotofree;+}++for(expr=table->selections;expr;expr=expr->next){+if(expr->type==EXPR_FIELD){+field=&expr->field;+if(field->system==start_system&&+field->event==start_event){+ret=tracefs_synth_add_start_field(synth,+field->field,field->label);+}else{+ret=tracefs_synth_add_end_field(synth,+field->field,field->label);+}+if(ret<0)+gotofree;+continue;+}+gotofree;+}++returnsynth;+free:+tracefs_synth_free(synth);+returnNULL;+}++staticvoidfree_sql_table(structsql_table*table)+{+structmatch*match;+structexpr*expr;++if(!table)+return;++while((expr=table->exprs)){+table->exprs=expr->next;+free(expr);+}++while((match=table->matches)){+table->matches=match->next;+free(match);+}++free(table);+}++staticvoidfree_str_hash(structstr_hash**hash)+{+structstr_hash*item;+inti;++for(i=0;i<1<<HASH_BITS;i++){+while((item=hash[i])){+hash[i]=item->next;+free(item->str);+free(item);+}+}+}++staticvoidfree_sb(structsqlhist_bison*sb)+{+free_sql_table(sb->table);+free_str_hash(sb->str_hash);+free(sb->parse_error_str);+}++structtracefs_synth*tracefs_sql(structtep_handle*tep,constchar*name,+constchar*sql_buffer,char**err)+{+structsqlhist_bisonlocal_sb;+structtracefs_synth*synth=NULL;+intret;++if(!tep||!sql_buffer){+errno=EINVAL;+returnNULL;+}++memset(&local_sb,0,sizeof(local_sb));++local_sb.buffer=sql_buffer;+local_sb.buffer_size=strlen(sql_buffer);+local_sb.buffer_idx=0;++sb=&local_sb;+ret=yyparse();++if(ret)+gotofree;++synth=build_synth(tep,name,sb->table);++free:+if(!synth){+if(sb->parse_error_str&&err){+*err=sb->parse_error_str;+sb->parse_error_str=NULL;+}+}+free_sb(sb);+returnsynth;+}
@@ -189,6 +189,56 @@ Simple SQL statements without the *JOIN* *ON* may also be used, which will creat instead. When doing this, the struct tracefs_hist descriptor can be retrieved from the returned synthetic event descriptor via the *tracefs_synth_get_start_hist*(3).+In order to utilize the histogram types (see xxx) the CAST command of SQL can be used.++That is:++[source,c]+--+ select CAST(common_pid AS comm, CAST(id AS syscall) FROM sys_enter+--++Which produces:++[source,c]+--+ # echo 'hist:keys=common_pid.execname,id.syscall' > events/raw_syscalls/sys_enter/trigger++ # cat events/raw_syscalls/sys_enter/hist++{ common_pid: bash [ 18248], id: sys_setpgid [109] } hitcount: 1+{ common_pid: sendmail [ 1812], id: sys_read [ 0] } hitcount: 1+{ common_pid: bash [ 18247], id: sys_getpid [ 39] } hitcount: 1+{ common_pid: bash [ 18247], id: sys_dup2 [ 33] } hitcount: 1+{ common_pid: gmain [ 13684], id: sys_inotify_add_watch [254] } hitcount: 1+{ common_pid: cat [ 18247], id: sys_access [ 21] } hitcount: 1+{ common_pid: bash [ 18248], id: sys_getpid [ 39] } hitcount: 1+{ common_pid: cat [ 18247], id: sys_fadvise64 [221] } hitcount: 1+{ common_pid: sendmail [ 1812], id: sys_openat [257] } hitcount: 1+{ common_pid: less [ 18248], id: sys_munmap [ 11] } hitcount: 1+{ common_pid: sendmail [ 1812], id: sys_close [ 3] } hitcount: 1+{ common_pid: gmain [ 1534], id: sys_poll [ 7] } hitcount: 1+{ common_pid: bash [ 18247], id: sys_execve [ 59] } hitcount: 1+--++Note, string fields may not be cast.++The possible types to cast to are:++*HEX* - convert the value to use hex and not decimal++*SYM* - convert a pointer to symbolic (kallsyms values)++*SYM-OFFSET* - convert a pointer to symbolic and include the offset.++*SYSCALL* - convert the number to the mapped system call name++*EXECNAME* or *COMM* - can only be used with the common_pid field. Will show the task+name of the process.++*LOG* or *LOG2* - bucket the key values in a log 2 values (1, 2, 3-4, 5-8, 9-16, 17-32, ...)++ RETURN VALUE ------------ Returns 0 on success and -1 on failure. On failure, if _err_ is defined, it will be
@@ -50,8 +50,8 @@ extern void yyerror(struct sqlhist_bison *, char *fmt, ...); void *expr; }-%token AS SELECT FROM JOIN ON WHERE PARSE_ERROR-%token <number> NUMBER+%token AS SELECT FROM JOIN ON WHERE PARSE_ERROR CAST+%token <number> NUMBER field_type %token <string> STRING %token <string> FIELD %token <string> LE GE EQ NEQ AND OR
@@ -1204,6 +1216,93 @@ static void where_no_to_error(struct sqlhist_bison *sb, struct expr *expr,event,from_event);}+staticintverify_field_type(structtep_handle*tep,+structsqlhist_bison*sb,+structexpr*expr)+{+structfield*field=&expr->field;+structtep_event*event;+structtep_format_field*tfield;+char*type;+intret;+inti;++if(!field->type)+return0;++sb->line_no=expr->line;+sb->line_idx=expr->idx;++event=tep_find_event_by_name(tep,field->system,field->event);+if(!event){+parse_error(sb,field->raw,+"Event '%s' not found\n",+field->event?:"(null)");+return-1;+}++tfield=tep_find_any_field(event,field->field);+if(!tfield){+parse_error(sb,field->raw,+"Field '%s' not part of event '%s'\n",+field->field?:"(null)",field->event);+return-1;+}++type=strdup(field->type);+if(!type)+return-1;++for(i=0;type[i];i++)+type[i]=tolower(type[i]);++if(!strcmp(type,"hex")){+if(tfield->flags&(TEP_FIELD_IS_STRING|TEP_FIELD_IS_ARRAY))+gotofail_type;+ret=TRACEFS_HIST_KEY_HEX;+}elseif(!strcmp(type,"sym")){+if(tfield->flags&(TEP_FIELD_IS_STRING|TEP_FIELD_IS_ARRAY))+gotofail_type;+ret=TRACEFS_HIST_KEY_SYM;+}elseif(!strcmp(type,"sym-offset")){+if(tfield->flags&(TEP_FIELD_IS_STRING|TEP_FIELD_IS_ARRAY))+gotofail_type;+ret=TRACEFS_HIST_KEY_SYM_OFFSET;+}elseif(!strcmp(type,"syscall")){+if(tfield->flags&(TEP_FIELD_IS_STRING|TEP_FIELD_IS_ARRAY))+gotofail_type;+ret=TRACEFS_HIST_KEY_SYSCALL;+}elseif(!strcmp(type,"execname")||+!strcmp(type,"comm")){+ret=TRACEFS_HIST_KEY_EXECNAME;+if(strcmp(field->field,"common_pid")){+parse_error(sb,field->raw,+"'%s' is only allowed for common_pid\n",+type);+ret=-1;+}+}elseif(!strcmp(type,"log")||+!strcmp(type,"log2")){+if(tfield->flags&(TEP_FIELD_IS_STRING|TEP_FIELD_IS_ARRAY))+gotofail_type;+ret=TRACEFS_HIST_KEY_LOG;+}else{+parse_error(sb,field->raw,+"Cast of '%s' to unknown type '%s'\n",+field->raw,type);+ret=-1;+}+free(type);+returnret;+fail_type:+parse_error(sb,field->raw,+"Field '%s' cast to '%s' but is of type %s\n",+field->field,type,tfield->flags&TEP_FIELD_IS_STRING?+"string":"array");+free(type);+return-1;+}+staticstructtracefs_synth*build_synth(structtep_handle*tep,constchar*name,structsql_table*table)
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:26:13
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Allow tracefs_sql() to take a simple select statement without the
JOIN .. ON clause, that will simply update the start event. This, along
with tracefs_synth_get_start_hist(), will allow a user to utilize
tracefs_sql() to create a synthetic event.
Link: https://lore.kernel.org/linux-rt-users/YQakDYRnId+bK+ue@lx-t490/
Suggested-by: Ahmed S. Darwish <redacted>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
Documentation/libtracefs-sql.txt | 27 +++++-
include/tracefs-local.h | 3 +
src/sqlhist.y | 11 ++-
src/tracefs-hist.c | 60 +++++++++----
src/tracefs-sqlhist.c | 141 +++++++++++++++++++++++++++++--
5 files changed, 212 insertions(+), 30 deletions(-)
@@ -32,6 +32,8 @@ to attach two events together and form another event (table). Utilizing the SQL *SELECT* *FROM* *JOIN* *ON* [ *WHERE* ] syntax, a synthetic event can easily be created from two different events.+For simple SQL queries to make a histogram instead of a synthetic event, see+HISTOGRAMS below. *tracefs_sql*() takes in a *tep* handler (See _tep_local_events_(3)) that is used to verify the events within the _sql_buffer_ expression. The _name_ is the name of the
@@ -160,6 +162,12 @@ select start.pid, (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat from sche WHERE start.prio < 100 || end.prev_prio < 100 --+HISTOGRAMS+----------++Simple SQL statements without the *JOIN* *ON* may also be used, which will create a histogram+instead. When doing this, the struct tracefs_hist descriptor can be retrieved from the+returned synthetic event descriptor via the *tracefs_synth_get_start_hist*(3). RETURN VALUE ------------
@@ -243,9 +251,22 @@ static int do_sql(const char *buffer, const char *name, exit(-1); }- tracefs_synth_show(&seq, NULL, synth);- if (execute)- tracefs_synth_create(NULL, synth);+ if (tracefs_synth_complete(synth)) {+ tracefs_synth_show(&seq, NULL, synth);+ if (execute)+ tracefs_synth_create(NULL, synth);+ } else {+ struct tracefs_hist *hist;+ hist = tracefs_synth_get_start_hist(synth);+ if (!hist) {+ perror("get_start_hist");+ exit(-1);+ }+ tracefs_hist_show(&seq, NULL, hist, 0);+ if (execute)+ tracefs_hist_start(NULL, hist);+ }+ tracefs_synth_free(synth); trace_seq_do_printf(&seq);
@@ -724,6 +724,33 @@ static int add_var(char ***list, const char *name, const char *var, bool is_var)return0;}+__hiddenstructtracefs_synth*+synth_init_from(structtep_handle*tep,constchar*start_system,+constchar*start_event_name)+{+structtep_event*start_event;+structtracefs_synth*synth;++start_event=tep_find_event_by_name(tep,start_system,+start_event_name);+if(!start_event){+errno=ENODEV;+returnNULL;+}++synth=calloc(1,sizeof(*synth));+if(!synth)+returnNULL;++synth->start_event=start_event;++/* Hold onto a reference to this handler */+tep_ref(tep);+synth->tep=tep;++returnsynth;+}+/***tracefs_synth_init-createanewtracefs_synthinstance*@tep:Thetephandlethatholdstheeventstoworkon
@@ -815,10 +834,6 @@ struct tracefs_synth *tracefs_synth_init(struct tep_handle *tep,ret=tracefs_synth_add_match_field(synth,start_match_field,end_match_field,match_name);-/* Hold onto a reference to this handler */-tep_ref(tep);-synth->tep=tep;-if(!synth->name||!synth->start_keys||!synth->end_keys||ret){tracefs_synth_free(synth);synth=NULL;
@@ -1457,6 +1472,11 @@ int tracefs_synth_create(struct tracefs_instance *instance,return-1;}+if(!synth->name||!synth->end_event){+errno=EUNATCH;+return-1;+}+if(verify_state(synth)<0)return-1;
@@ -1539,6 +1559,11 @@ int tracefs_synth_destroy(struct tracefs_instance *instance,return-1;}+if(!synth->name||!synth->end_event){+errno=EUNATCH;+return-1;+}+/* Try to disable the event if possible */tracefs_event_disable(instance,"synthetic",synth->name);
@@ -1595,6 +1620,11 @@ int tracefs_synth_show(struct trace_seq *seq,return-1;}+if(!synth->name||!synth->end_event){+errno=EUNATCH;+return-1;+}+synthetic_event=create_synthetic_event(synth);if(!synthetic_event)return-1;
@@ -591,6 +591,69 @@ static int update_vars(struct sql_table *table, struct field *event)return0;}+/*+*Calledwhenthere'saFROMbutnoJOIN(to),whichmeansthatthe+*selectionscanbefieldsandnotmentiontheeventitself.+*/+staticintupdate_fields(structtep_handle*tep,+structsql_table*table,structfield*event_field)+{+structsqlhist_bison*sb=table->sb;+structtep_format_field*tfield;+structtep_event*event;+structexpr*expr;+structfield*field;+constchar*p;+intlen;++/* First update fields with aliases an such */+update_vars(table,event_field);++/* The update_vars already updated event->system and event->event */+event=tep_find_event_by_name(tep,event_field->system,+event_field->event);+/*+*Ifeventisnotfound,thecreationofthesynthwill+*addapropererror,soreturn"success".+*/+if(!event)+return0;++for_each_field(expr,field,table){+constchar*field_name;++field=&expr->field;++if(field->event)+continue;++field_name=field->raw;++p=strchr(field_name,'.');+if(p){+len=p-field_name;+p=strndup(field_name,len);+if(!p)+return-1;+field_name=store_str(sb,p);+if(!field_name)+return-1;+free((char*)p);+}++tfield=tep_find_any_field(event,field_name);+/* Let it error properly later */+if(!tfield)+continue;++field->system=event_field->system;+field->event=event_field->event;+field->field=field_name;+}++return0;+}+staticintmatch_error(structsqlhist_bison*sb,structmatch*match,structfield*lmatch,structfield*rmatch){
@@ -1105,6 +1168,42 @@ static void compare_error(struct tep_handle *tep,compare->lval->field.raw,compare->rval->field.raw);}+staticvoidcompare_no_to_error(structsqlhist_bison*sb,structexpr*expr)+{+structcompare*compare=&expr->compare;++sb->line_no=compare->lval->line;+sb->line_idx=compare->lval->idx;++parse_error(sb,compare->lval->field.raw,+"Simple SQL (without JOIN/ON) do not allow comparisons\n",+compare->lval->field.raw,compare->rval->field.raw);+}++staticvoidwhere_no_to_error(structsqlhist_bison*sb,structexpr*expr,+constchar*from_event,constchar*event)+{+while(expr){+switch(expr->filter.type){+caseFILTER_OR:+caseFILTER_AND:+caseFILTER_GROUP:+caseFILTER_NOT_GROUP:+expr=expr->filter.lval;+continue;+default:+break;+}+break;+}+sb->line_no=expr->filter.lval->line;+sb->line_idx=expr->filter.lval->idx;++parse_error(sb,expr->filter.lval->field.raw,+"Event '%s' does not match FROM event '%s'\n",+event,from_event);+}+staticstructtracefs_synth*build_synth(structtep_handle*tep,constchar*name,structsql_table*table)
@@ -1123,17 +1222,31 @@ static struct tracefs_synth *build_synth(struct tep_handle *tep,boolstarted_end=false;intret;-if(!table->to||!table->from)+if(!table->from)returnNULL;-ret=update_vars(table,&table->to->field);-if(ret<0)-returnNULL;+/* This could be a simple SQL statement to only build a histogram */+if(!table->to){+ret=update_fields(tep,table,&table->from->field);+if(ret<0)+returnNULL;++start_system=table->from->field.system;+start_event=table->from->field.event;++synth=synth_init_from(tep,start_system,start_event);+if(!synth)+returnsynth_init_error(tep,table);+gotohist_only;+}ret=update_vars(table,&table->from->field);if(ret<0)returnNULL;+start_system=table->from->field.system;+start_event=table->from->field.event;+match=table->matches;if(!match)returnNULL;
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:26:17
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
If the processing of comparing fields fail due to not existing or because
they are not compatible to compare, report a proper error message.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/tracefs-sqlhist.c | 36 +++++++++++++++++++++++++++++++++++-
1 file changed, 35 insertions(+), 1 deletion(-)
@@ -981,6 +981,38 @@ static void selection_error(struct tep_handle *tep,test_field_exists(tep,sb,expr);}+staticvoidcompare_error(structtep_handle*tep,+structsqlhist_bison*sb,structexpr*expr)+{+structcompare*compare=&expr->compare;++switch(errno){+caseENODEV:+caseEBADE:+break;+default:+/* System error */+return;+}++/* ENODEV means that an event or field does not exist */+if(errno==ENODEV){+if(test_field_exists(tep,sb,compare->lval))+return;+if(test_field_exists(tep,sb,compare->rval))+return;+return;+}++/* fields exist, but values are not compatible */+sb->line_no=compare->lval->line;+sb->line_idx=compare->lval->idx;++parse_error(sb,compare->lval->field.raw,+"'%s' is not compatible to compare with '%s'\n",+compare->lval->field.raw,compare->rval->field.raw);+}+staticstructtracefs_synth*build_synth(structtep_handle*tep,constchar*name,structsql_table*table)
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:26:32
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
If a filter has a bad event, or incompatibility with the value assigned to
it, have the error message display it.
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/tracefs-sqlhist.c | 80 +++++++++++++++++++++++++++++++++++++++----
1 file changed, 74 insertions(+), 6 deletions(-)
@@ -792,14 +792,80 @@ static int verify_filter(struct sqlhist_bison *sb, struct filter *filter,}}-staticintbuild_filter(structtracefs_synth*synth,-boolstart,structfilter*filter,bool*started)+staticinttest_field_exists(structtep_handle*tep,structsqlhist_bison*sb,+structexpr*expr);++staticvoidfilter_compare_error(structtep_handle*tep,+structsqlhist_bison*sb,+structexpr*expr)+{+structfield*field=&expr->field;++switch(errno){+caseENODEV:+caseEBADE:+break;+caseEINVAL:+parse_error(sb,field->raw,"Invalid compare\n");+break;+default:+parse_error(sb,field->raw,"System error?\n");+return;+}++/* ENODEV means that an event or field does not exist */+if(errno==ENODEV){+if(test_field_exists(tep,sb,expr))+return;+if(test_field_exists(tep,sb,expr))+return;+return;+}++/* fields exist, but values are not compatible */+sb->line_no=expr->line;+sb->line_idx=expr->idx;++parse_error(sb,field->raw,+"Field '%s' is not compatible to be compared with the given value\n",+field->field);+}++staticvoidfilter_error(structtep_handle*tep,+structsqlhist_bison*sb,structexpr*expr)+{+structfilter*filter=&expr->filter;++sb->line_no=expr->line;+sb->line_idx=expr->idx;++switch(filter->type){+caseFILTER_NOT_GROUP:+caseFILTER_GROUP:+caseFILTER_OR:+caseFILTER_AND:+break;+default:+filter_compare_error(tep,sb,filter->lval);+return;+}++sb->line_no=expr->line;+sb->line_idx=expr->idx;++parse_error(sb,"","Problem with filter entry?\n");+}++staticintbuild_filter(structtep_handle*tep,structsqlhist_bison*sb,+structtracefs_synth*synth,+boolstart,structexpr*expr,bool*started){int(*append_filter)(structtracefs_synth*synth,enumtracefs_filtertype,constchar*field,enumtracefs_comparecompare,constchar*val);+structfilter*filter=&expr->filter;enumtracefs_comparecmp;constchar*val;intand_or=TRACEFS_FILTER_AND;
@@ -829,7 +895,7 @@ static int build_filter(struct tracefs_synth *synth,NULL,0,NULL);if(ret<0)gotoout;-ret=build_filter(synth,start,&filter->lval->filter,NULL);+ret=build_filter(tep,sb,synth,start,filter->lval,NULL);if(ret<0)gotoout;ret=append_filter(synth,TRACEFS_FILTER_CLOSE_PAREN,
@@ -840,14 +906,14 @@ static int build_filter(struct tracefs_synth *synth,and_or=TRACEFS_FILTER_OR;/* Fall through */caseFILTER_AND:-ret=build_filter(synth,start,&filter->lval->filter,NULL);+ret=build_filter(tep,sb,synth,start,filter->lval,NULL);if(ret<0)gotoout;ret=append_filter(synth,and_or,NULL,0,NULL);if(ret)gotoout;-ret=build_filter(synth,start,&filter->rval->filter,NULL);+ret=build_filter(tep,sb,synth,start,filter->rval,NULL);gotoout;default:break;
@@ -881,6 +947,8 @@ static int build_filter(struct tracefs_synth *synth,ret=append_filter(synth,TRACEFS_FILTER_COMPARE,filter->lval->field.field,cmp,val);+if(ret)+filter_error(tep,sb,expr);out:if(!ret&&started){if(*started)
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:26:43
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
If a calculation between event fields is performed and there's no label
(name) for it, it errors out, causing the bison parser to give a strange
error:
FAILED MEMORY: add_selection(sb, (yyvsp[0].expr), NULL)
Failed creating synthetic event!: No such file or directory
Instead, just set the compare->name field to NULL, and report a better
error later on in the processing.
ERROR: 'no name'
Field calculations must be labeled 'AS name'
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/tracefs-sqlhist.c | 13 +++++++++++--
1 file changed, 11 insertions(+), 2 deletions(-)
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-03 04:26:59
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
Allow the start and end events to have filters with the "WHERE" clause.
For example:
SELECT (end.common_timestamp.usecs - start.common_timestamp.usecs) AS
lat FROM sched_waking AS start JOIN sched_switch AS end ON
start.pid = stop.next_pid WHERE start.prio < 100 &&
end.prev_prio < 100
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
src/sqlhist-parse.h | 6 +
src/sqlhist.l | 1 +
src/sqlhist.y | 70 +++++++++++-
src/tracefs-sqlhist.c | 260 ++++++++++++++++++++++++++++++++++++++++++
4 files changed, 335 insertions(+), 2 deletions(-)
@@ -34,7 +34,7 @@ extern void yyerror(char *fmt, ...); void *expr; }-%token AS SELECT FROM JOIN ON PARSE_ERROR+%token AS SELECT FROM JOIN ON WHERE PARSE_ERROR %token <number> NUMBER %token <string> STRING %token <string> FIELD
@@ -410,6 +482,7 @@ __hidden int table_start(struct sqlhist_bison *sb)table->sb=sb;sb->table=table;+table->next_where=&table->where;table->next_match=&table->matches;table->next_selection=&table->selections;
@@ -598,6 +671,167 @@ static int build_compare(struct tracefs_synth *synth,returnret;}+staticintdo_verify_filter(structfilter*filter,+constchar**system,constchar**event)+{+intret;++if(filter->type==FILTER_OR||+filter->type==FILTER_AND){+ret=do_verify_filter(&filter->lval->filter,system,event);+if(ret)+returnret;+returndo_verify_filter(&filter->rval->filter,system,event);+}+if(filter->type==FILTER_GROUP||+filter->type==FILTER_NOT_GROUP){+returndo_verify_filter(&filter->lval->filter,system,event);+}++/*+*systemandeventwillbeNULLuntilwefindtheleftmost+*node.Thenassignit,andcompareonthewaybackup.+*/+if(!*system&&!*event){+*system=filter->lval->field.system;+*event=filter->lval->field.event;+return0;+}++if(filter->lval->field.system!=*system||+filter->lval->field.event!=*event)+return-1;++return0;+}++staticintverify_filter(structfilter*filter,+constchar**system,constchar**event)+{+intret;++switch(filter->type){+caseFILTER_OR:+caseFILTER_AND:+caseFILTER_GROUP:+caseFILTER_NOT_GROUP:+break;+default:+returndo_verify_filter(filter,system,event);+}++ret=do_verify_filter(&filter->lval->filter,system,event);+if(ret)+returnret;++switch(filter->type){+caseFILTER_OR:+caseFILTER_AND:+returndo_verify_filter(&filter->rval->filter,system,event);+default:+return0;+}+}++staticintbuild_filter(structtracefs_synth*synth,+boolstart,structfilter*filter,bool*started)+{+int(*append_filter)(structtracefs_synth*synth,+enumtracefs_filtertype,+constchar*field,+enumtracefs_comparecompare,+constchar*val);+enumtracefs_comparecmp;+constchar*val;+intand_or=TRACEFS_FILTER_AND;+charnum[64];+intret;++if(start)+append_filter=tracefs_synth_append_start_filter;+else+append_filter=tracefs_synth_append_end_filter;++if(started&&*started){+ret=append_filter(synth,and_or,NULL,0,NULL);+ret=append_filter(synth,TRACEFS_FILTER_OPEN_PAREN,+NULL,0,NULL);+}++switch(filter->type){+caseFILTER_NOT_GROUP:+ret=append_filter(synth,TRACEFS_FILTER_NOT,+NULL,0,NULL);+if(ret<0)+gotoout;+/* Fall through */+caseFILTER_GROUP:+ret=append_filter(synth,TRACEFS_FILTER_OPEN_PAREN,+NULL,0,NULL);+if(ret<0)+gotoout;+ret=build_filter(synth,start,&filter->lval->filter,NULL);+if(ret<0)+gotoout;+ret=append_filter(synth,TRACEFS_FILTER_CLOSE_PAREN,+NULL,0,NULL);+gotoout;++caseFILTER_OR:+and_or=TRACEFS_FILTER_OR;+/* Fall through */+caseFILTER_AND:+ret=build_filter(synth,start,&filter->lval->filter,NULL);+if(ret<0)+gotoout;+ret=append_filter(synth,and_or,NULL,0,NULL);++if(ret)+gotoout;+ret=build_filter(synth,start,&filter->rval->filter,NULL);+gotoout;+default:+break;+}++switch(filter->rval->type){+caseEXPR_NUMBER:+sprintf(num,"%ld",filter->rval->number);+val=num;+break;+caseEXPR_STRING:+val=filter->rval->string;+break;+default:+break;+}++switch(filter->type){+caseFILTER_EQ:cmp=TRACEFS_COMPARE_EQ;break;+caseFILTER_NE:cmp=TRACEFS_COMPARE_NE;break;+caseFILTER_LE:cmp=TRACEFS_COMPARE_LE;break;+caseFILTER_LT:cmp=TRACEFS_COMPARE_LT;break;+caseFILTER_GE:cmp=TRACEFS_COMPARE_GE;break;+caseFILTER_GT:cmp=TRACEFS_COMPARE_GT;break;+caseFILTER_BIN_AND:cmp=TRACEFS_COMPARE_AND;break;+caseFILTER_STR_CMP:cmp=TRACEFS_COMPARE_RE;break;+default:+break;+}++ret=append_filter(synth,TRACEFS_FILTER_COMPARE,+filter->lval->field.field,cmp,val);++out:+if(!ret&&started){+if(*started)+ret=append_filter(synth,TRACEFS_FILTER_CLOSE_PAREN,+NULL,0,NULL);+*started=true;+}+returnret;+}+staticstructtracefs_synth*build_synth(structtep_handle*tep,constchar*name,structsql_table*table)
On Tue, Aug 3, 2021 at 6:23 AM Steven Rostedt [off-list ref] wrote:
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
This adds the API tracefs_sql() that takes a tep_handle handler, a name,
and a SQL string and parses it to produce a tracefs_synth synthetic event
handler.
Currently it only supports simple SQL of the type:
SELECT start.common_pid AS pid, end.common_timestamp.usecs AS usecs
FROM sched_waking AS start JOIN sched_switch AS end
ON start.pid = end.next_pid
Special thanks to:
Lukas Bulwahn for first introducing the idea at RT Summit on the Summit
Spring of 2019.
Thanks, Steven, for putting this idea to life.
I hope that the tracing users appreciate this new declarative
interface using SQL and it makes tracing events easier comprehensible
to a larger community of users.
Lukas
From: Ahmed S. Darwish <hidden> Date: 2021-08-04 11:57:09
Hi Steven,
On Tue, Aug 03, 2021 , Steven Rostedt wrote:
Major update since v1:
It was brought to my attention that the man page did not state that the
SQL syntax required JOIN .. ON in the statement. That is, they were not
optional. I decided to fix that. But not by updating the man page, but by
actually making JOIN .. ON optional. If you leave that out, the synthetic
event will not be completely created, but it will have enough to create
a histogram. See the bottom (HISTOGRAMS) for more info!
...
HISTOGRAMS
Simple SQL statements without the JOIN ON may also be used, which will
create a histogram instead. When doing this, the struct tracefs_hist
descriptor can be retrieved from the returned synthetic event descriptor via
the tracefs_synth_get_start_hist(3).
Thanks a lot! Actually, I meant going even one step further ;)
I was imagining something like the following:
$ trace-cmd sql-shell # OR
$ perf tracefs-sql-shell
Welcome to tracefs SQL shell...
> SELECT PNAME(common_pid),msr,val
FROM write_msr
WHERE msr=72 OR msr=2096
.-------------------------------------------.
| PNAME(common_pid) | msr | val |
|---------------------|------ |-------------|
| qemu-system-x86 | 0x48 | 0 |
| qemu-system-x86 | 0x48 | 0 |
| qemu-system-x86 | 0x48 | 0 |
| kworker/u16:2 | 0x830 | 0x1000008fb |
| .... | .... | ..... |
+-------------------------------------------+
> SELECT MAX(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS MaxSystemLatency_us,
PNAME(common_pid)
FROM sched_waking AS start JOIN sched_switch AS end
ON start.pid = stop.next_pid
.-------------------------------------------.
| MaxSystemLatency_us | PNAME(common_pid) |
|---------------------|---------------------|
| 350 | cyclictest |
+-------------------------------------------+
> SELECT (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS latency,
PNAME(common_pid), PRIO(common_pid)
FROM sched_waking AS start JOIN sched_switch AS end
ON start.pid = stop.next_pid
ORDER BY latency DESC
LIMIT 5
.----------------------------------------------------------.
| Latency | PNAME(common_pid) | PRIO(common_pid) |
|---------|-----------------------------|------------------|
| 829 | cyclictest | SCHED_FIFO:98 |
| 400 | cyclictest | SCHED_FIFO:98 |
| 192 | pulseaudio-rt | SCHED_RR:48 |
| 30 | firefox | SCHED_OTHER:0:0 |
| 10 | kworker/0:0H-events_highpri | SCHED_OTHER:0:-20|
+----------------------------------------------------------+
> SELECT (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as MaxIRQLatency_us
FROM irq_disable as start JOIN irq_enable as end
ON start.common_pid = end.common_pid,
start.parent_offs == end.parent_offs
ORDER BY max_irq_disable
LIMIT 1
.------------------.
| MaxIRQLatency_us |
|------------------|
| 37 |
+------------------+
And so on....
The idea was that since the community already picked SQL as a
higher-level tracing language, why hard-code the SQL language with
synthetic events and histograms?
The language can alredy offer something *way more generic*, out of the
box, while still covering the desired special cases.
We can support the standard SQL aggregate functions (e.g., MAX(), MIN(),
SUM(), COUNT(), DISTINCT(), AVG(), etc.) + some kernel-specific
functions (e.g., PROCESS_NAME(), PROCESS_PRIO(), USECS(), etc.) + the
standard SQL keyworkds like ORDER BY, LIMIT, DESC, ASC, etc. This would
offer some nice friendly competition to BPF tracing, while still being a
(relatively) simple *query-only* language.
I'm not sure if you would be OK with this, but I thought a proposal
won't hurt :)
I can also write some patches on top of this series if you are OK with
the principle in general.
Kind regards,
--
Ahmed S. Darwish
Linutronix GmbH
From: Steven Rostedt <rostedt@goodmis.org> Date: 2021-08-04 13:23:51
On Wed, 4 Aug 2021 13:57:00 +0200
"Ahmed S. Darwish" [off-list ref] wrote:
Thanks a lot! Actually, I meant going even one step further ;)
I was imagining something like the following:
$ trace-cmd sql-shell # OR
$ perf tracefs-sql-shell
Welcome to tracefs SQL shell...
> SELECT PNAME(common_pid),msr,val
FROM write_msr
WHERE msr=72 OR msr=2096
.-------------------------------------------.
| PNAME(common_pid) | msr | val |
|---------------------|------ |-------------|
| qemu-system-x86 | 0x48 | 0 |
| qemu-system-x86 | 0x48 | 0 |
| qemu-system-x86 | 0x48 | 0 |
| kworker/u16:2 | 0x830 | 0x1000008fb |
| .... | .... | ..... |
+-------------------------------------------+
Well, the above looks more like a normal trace just being processed
differently. If you want that, I already have this:
https://lore.kernel.org/linux-trace-devel/20200116104804.5d2f71e2@gandalf.local.home/
Which I created to test the idea of using SQL to create synthetic events.
It simply converts the events in a trace.dat file into a sql format
file that can be used to read into a SQL database. As the patch shows:
$ trace-cmd sqldump > dump
$ mysql events < dump
MariaDB [events]> show tables;
+-----------------------------+
| Tables_in_events |
+-----------------------------+
| sched_migrate_task |
| sched_move_numa |
| sched_process_exec |
| sched_process_exit |
| sched_stat_runtime |
| sched_switch |
| sched_wake_idle_without_ipi |
| sched_wakeup |
| sched_waking |
+-----------------------------+
9 rows in set (0.001 sec)
MariaDB [events]> select * from sched_move_numa;
+-------------------+-------------+--------------+----------------------+------------+-------+-------+-------+---------+---------+---------+---------+
| common_timestamp | common_type | common_flags | common_preempt_count | common_pid | pid | tgid | ngid | src_cpu | src_nid | dst_cpu | dst_nid |
+-------------------+-------------+--------------+----------------------+------------+-------+-------+-------+---------+---------+---------+---------+
| 14943901721165973 | 305 | 0 | 0 | 27451 | 27451 | 27451 | 27451 | 5 | 1 | 22 | 0 |
| 14943901722548756 | 305 | 0 | 0 | 3684 | 3684 | 3684 | 3684 | 23 | 1 | 22 | 0 |
| 14943901779987828 | 305 | 0 | 0 | 13693 | 13693 | 13677 | 13693 | 7 | 1 | 22 | 0 |
+-------------------+-------------+--------------+----------------------+------------+-------+-------+-------+---------+---------+---------+---------+
3 rows in set (0.001 sec)
I never applied the patch, but perhaps you would be interested in this?
> SELECT MAX(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS MaxSystemLatency_us,
PNAME(common_pid)
FROM sched_waking AS start JOIN sched_switch AS end
ON start.pid = stop.next_pid
Now the above would require parsing the histogram data, which is next
on our agenda. There's two routes we can take with this:
1) Add a "hist_raw" that shows the raw data from the kernel's
histogram table. It would still be in ASCII, but will be formatted for
machine readability and not for humans (like /proc/$$/stat vs /proc/$$/status)
2) We write another bison parser to parse the current format of the
histogram output, which looks like this:
# sqlhist -n lat -e 'SELECT end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as lat
FROM sched_waking as start JOIN sched_switch as end ON start.pid = end.next_pid'
# trace-cmd start -e lat -R 'hist:keys=common_pid.execname,lat:sort=lat'
# cat /sys/kernel/tracing/events/synthetic/lat/hist
# event histogram
#
# trigger info: hist:keys=common_pid.execname,lat:vals=hitcount:sort=lat:size=2048 [active]
#
{ common_pid: <idle> [ 0], lat: 2 } hitcount: 9
{ common_pid: <idle> [ 0], lat: 3 } hitcount: 3
{ common_pid: kworker/0:0 [ 10041], lat: 3 } hitcount: 7
{ common_pid: kworker/0:0 [ 10041], lat: 4 } hitcount: 5
{ common_pid: <idle> [ 0], lat: 4 } hitcount: 2
{ common_pid: <idle> [ 0], lat: 5 } hitcount: 9
{ common_pid: kworker/0:0 [ 10041], lat: 5 } hitcount: 14
{ common_pid: kworker/0:0 [ 10041], lat: 6 } hitcount: 5
{ common_pid: <idle> [ 0], lat: 6 } hitcount: 16
{ common_pid: <idle> [ 0], lat: 7 } hitcount: 19
[..]
{ common_pid: JS Helper [ 1366], lat: 96 } hitcount: 1
{ common_pid: <idle> [ 0], lat: 97 } hitcount: 1
{ common_pid: <idle> [ 0], lat: 99 } hitcount: 1
{ common_pid: <idle> [ 0], lat: 107 } hitcount: 1
{ common_pid: <idle> [ 0], lat: 108 } hitcount: 3
{ common_pid: <idle> [ 0], lat: 117 } hitcount: 1
{ common_pid: <idle> [ 0], lat: 118 } hitcount: 1
{ common_pid: sendmail [ 1739], lat: 130 } hitcount: 1
Totals:
Hits: 2212
Entries: 130
Dropped: 0
That file is a user space API, and we can write up another bison parser
to parse out the data.
Between the two approaches, #1 is probably the better way, but that
requires a kernel change, and the feature will not be available in
older kernels, and not available until we actually implement it.
Approach #2 can be done today and will work for older kernels too. Also,
if we do #2, it doesn't mean we can't still do #1.
.-------------------------------------------.
| MaxSystemLatency_us | PNAME(common_pid) |
|---------------------|---------------------|
| 350 | cyclictest |
+-------------------------------------------+
> SELECT (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS latency,
PNAME(common_pid), PRIO(common_pid)
FROM sched_waking AS start JOIN sched_switch AS end
ON start.pid = stop.next_pid
ORDER BY latency DESC
LIMIT 5
.----------------------------------------------------------.
| Latency | PNAME(common_pid) | PRIO(common_pid) |
|---------|-----------------------------|------------------|
| 829 | cyclictest | SCHED_FIFO:98 |
| 400 | cyclictest | SCHED_FIFO:98 |
| 192 | pulseaudio-rt | SCHED_RR:48 |
| 30 | firefox | SCHED_OTHER:0:0 |
| 10 | kworker/0:0H-events_highpri | SCHED_OTHER:0:-20|
+----------------------------------------------------------+
> SELECT (end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) as MaxIRQLatency_us
FROM irq_disable as start JOIN irq_enable as end
ON start.common_pid = end.common_pid,
start.parent_offs == end.parent_offs
ORDER BY max_irq_disable
LIMIT 1
.------------------.
| MaxIRQLatency_us |
|------------------|
| 37 |
+------------------+
And so on....
The idea was that since the community already picked SQL as a
higher-level tracing language, why hard-code the SQL language with
synthetic events and histograms?
The language can alredy offer something *way more generic*, out of the
box, while still covering the desired special cases.
We can support the standard SQL aggregate functions (e.g., MAX(), MIN(),
SUM(), COUNT(), DISTINCT(), AVG(), etc.) + some kernel-specific
functions (e.g., PROCESS_NAME(), PROCESS_PRIO(), USECS(), etc.) + the
standard SQL keyworkds like ORDER BY, LIMIT, DESC, ASC, etc. This would
offer some nice friendly competition to BPF tracing, while still being a
(relatively) simple *query-only* language.
I'm not sure if you would be OK with this, but I thought a proposal
won't hurt :)
I can also write some patches on top of this series if you are OK with
the principle in general.
I'm not against it, and was thinking of implementing some kind of
"trace-cmd sql" feature. But before we can get there, we need a way to
get that information out from the kernel.
-- Steve