TRACE-CMD-SQLHIST(1)
💅 trace-cmd-sqlhist ✨
🌸 fresh out of the libtracefs Manual 🎀
🌈 NAME 🌈
trace-cmd-sqlhist — use SQL language to create / show creation of tracefs histograms and synthetic events 💖
🦋 SYNOPSIS 🦋
trace-cmd sqlhist [OPTIONS] [SQL-select-command]👑 DESCRIPTION 👑
Okay so bestie, trace-cmd sqlhist(1) takes an SQL-ish statement and uses it to create tracefs histograms and synthetic events — and those bad boys can perform all kinds of actions for all kinds of handling of your data. it's literally giving "compiler, but make it tracing" 💅
The tracefs filesystem is what talks to the Linux tracing infrastructure, which has a bunch of dynamic and static events all over the kernel. Every single one of those events can have a "histogram" attached to it, and the fields of the event are what define the buckets of that histogram. slay 🌸
A synthetic event is a way to take two separate events and glue them together using the fields and time stamps of those events, creating a brand new dynamic event. And yeah — that new dynamic event is literally called a synthetic event 🦋 The fields of each event can have simple calculations done on them, so for example you can take the delta between a field of one event and a field of the other event. This also works for the time stamps of the events, where the time delta between the two events can also be extracted and dropped into the synthetic event. genuinely obsessed with this 🫶
Other actions can be done from the fields of the events too! A snapshot can be taken of the kernel ring buffer when a variable used in the synthetic event hits a max, or simply changes. main character behavior tbh ✨
Now here's the thing — the commands to actually create histograms and synthetic events are complex and honestly not easy to remember 😭 which is exactly why trace-cmd sqlhist exists: it converts SQL syntax into the commands you need to create the histogram or the synthetic event.
The SQL-select-command is a SQL string defined by tracefs_sqlhist(3).
⚠️ note bestie: this must be run as root (or withsudo), because interacting with the tracefs directory requires root privilege — unless the-toption is given along with a copy of the tracefs directory and its events. no cap.
✨ OPTIONS ✨
-nname — the name of the synthetic event to create. Once it exists, this event can be used just like any other event, and enabled viatrace-cmd record(1). 🎀-ttracefs-dir — so you wanna test this out as a non-root user? valid! just grab a copy of the tracefs directory and pass that directory in with this option, and the program will work with it. Obviously-ewon't work as non-root, because it won't be able to execute. 💀
# mkdir /tmp/tracing
# cp -r /sys/kernel/tracing/events /tmp/tracing
# exit
$ trace-cmd sqlhist -t /tmp/tracing ...-e— not only display the commands that create the histogram, but actually execute them too. requires root privilege, iykyk 👑-ffile — instead of reading the SQL commands from the command line, read them from file. And if file is-, then it reads from standard input. cute 🍓-mvar — do the given action when the variable var hits a new maximum. This can not be used with-c. The var must be defined in the SQL-select-command. 🔥-cvar — do the given action when the variable var changes its value. This can not be used with-m. The var must be defined in the SQL-select-command. 🔥-s— perform a snapshot instead of calling the synthetic event.-T— perform both a snapshot and trace the synthetic event. ✨-Sfields[,fields] — save the given fields. The fields must be fields of the"end"event given in the SQL-select-command. 🎀-Binstance — for simple statements that only produce a histogram, the instance given here is where the histogram will be created. This gets ignored for full synthetic event creation, because synthetic events have a global effect on all tracing instances, whereas histograms only affect a single instance. 💅
🌟 EXAMPLES 🌟
As described above, for testing purposes, make a copy of the event directory:
$ mkdir /tmp/tracing
$ sudo cp -r /sys/kernel/tracing/events /tmp/tracing/
$ sudo chmod -R 0644 /tmp/tracing/Here's an example of simple histogram output using that copy of the tracefs directory:
$ trace-cmd sqlhist -t /tmp/tracing/ 'SELECT CAST(call_site as SYM-OFFSET), bytes_req, CAST(bytes_alloc AS _COUNTER_) FROM kmalloc'which produces the output:
echo 'hist:keys=call_site.sym-offset,bytes_req:vals=bytes_alloc' > /sys/kernel/tracing/events/kmem/kmalloc/triggerand that could be used by root like this:
# echo 'hist:keys=call_site.sym-offset,bytes_req:vals=bytes_alloc' > /sys/kernel/tracing/events/kmem/kmalloc/trigger
# cat /sys/kernel/tracing/events/kmem/kmalloc/hist
# event histogram
#
# trigger info: hist:keys=call_site.sym-offset,bytes_req:vals=hitcount,bytes_alloc:sort=hitcount:size=2048 [active]
#
{ call_site: [ffffffff813f8d8a] load_elf_phdrs+0x4a/0xb0 , bytes_req: 728 } hitcount: 1 bytes_alloc: 1024
{ call_site: [ffffffffc0c69e74] nf_ct_ext_add+0xd4/0x1d0 [nf_conntrack] , bytes_req: 128 } hitcount: 1 bytes_alloc: 128
{ call_site: [ffffffff818355e6] dma_resv_get_fences+0xf6/0x440 , bytes_req: 8 } hitcount: 1 bytes_alloc: 8
{ call_site: [ffffffffc06dc73f] intel_gt_get_buffer_pool+0x15f/0x290 [i915] , bytes_req: 424 } hitcount: 1 bytes_alloc: 512
{ call_site: [ffffffff813f8d8a] load_elf_phdrs+0x4a/0xb0 , bytes_req: 616 } hitcount: 1 bytes_alloc: 1024
{ call_site: [ffffffff8161a44c] __sg_alloc_table+0x11c/0x180 , bytes_req: 32 } hitcount: 1 bytes_alloc: 32
{ call_site: [ffffffffc070749d] shmem_get_pages+0xad/0x5d0 [i915] , bytes_req: 16 } hitcount: 1 bytes_alloc: 16
{ call_site: [ffffffffc07507f5] intel_framebuffer_create+0x25/0x60 [i915] , bytes_req: 408 } hitcount: 1 bytes_alloc: 512
{ call_site: [ffffffffc06fc20f] eb_parse+0x34f/0x910 [i915] , bytes_req: 408 } hitcount: 1 bytes_alloc: 512
{ call_site: [ffffffffc0700ebd] i915_gem_object_get_pages_internal+0x5d/0x270 [i915] , bytes_req: 16 } hitcount: 1 bytes_alloc: 16
{ call_site: [ffffffffc0771188] intel_frontbuffer_get+0x38/0x220 [i915] , bytes_req: 400 } hitcount: 1 bytes_alloc: 512
{ call_site: [ffffffff8161a44c] __sg_alloc_table+0x11c/0x180 , bytes_req: 128 } hitcount: 1 bytes_alloc: 128
{ call_site: [ffffffff813f8f45] load_elf_binary+0x155/0x1680 , bytes_req: 28 } hitcount: 1 bytes_alloc: 32
{ call_site: [ffffffffc07038c8] __assign_mmap_offset+0x208/0x3d0 [i915] , bytes_req: 288 } hitcount: 1 bytes_alloc: 512
{ call_site: [ffffffff813737b2] alloc_bprm+0x32/0x2f0 , bytes_req: 416 } hitcount: 1 bytes_alloc: 512
{ call_site: [ffffffff813f9027] load_elf_binary+0x237/0x1680 , bytes_req: 64 } hitcount: 1 bytes_alloc: 64
{ call_site: [ffffffff8161a44c] __sg_alloc_table+0x11c/0x180 , bytes_req: 64 } hitcount: 1 bytes_alloc: 64
{ call_site: [ffffffffc040ffe7] drm_vma_node_allow+0x27/0xe0 [drm] , bytes_req: 40 } hitcount: 2 bytes_alloc: 128
{ call_site: [ffffffff813cda98] __do_sys_timerfd_create+0x58/0x1c0 , bytes_req: 336 } hitcount: 2 bytes_alloc: 1024
{ call_site: [ffffffff818355e6] dma_resv_get_fences+0xf6/0x440 , bytes_req: 40 } hitcount: 2 bytes_alloc: 128
{ call_site: [ffffffff8139b75a] single_open+0x2a/0xa0 , bytes_req: 32 } hitcount: 2 bytes_alloc: 64
{ call_site: [ffffffff815df715] bio_kmalloc+0x25/0x80 , bytes_req: 136 } hitcount: 2 bytes_alloc: 384
{ call_site: [ffffffffc071e5cd] i915_vma_work+0x1d/0x50 [i915] , bytes_req: 416 } hitcount: 3 bytes_alloc: 1536
{ call_site: [ffffffff81390d0d] alloc_fdtable+0x4d/0x100 , bytes_req: 56 } hitcount: 3 bytes_alloc: 192
{ call_site: [ffffffffc06ff65f] i915_gem_do_execbuffer+0x158f/0x2440 [i915] , bytes_req: 16 } hitcount: 4 bytes_alloc: 64
{ call_site: [ffffffff8137713c] alloc_pipe_info+0x5c/0x230 , bytes_req: 384 } hitcount: 5 bytes_alloc: 2560
{ call_site: [ffffffff813771b4] alloc_pipe_info+0xd4/0x230 , bytes_req: 640 } hitcount: 5 bytes_alloc: 5120
{ call_site: [ffffffff81834cdb] dma_resv_list_alloc+0x1b/0x40 , bytes_req: 40 } hitcount: 6 bytes_alloc: 384
{ call_site: [ffffffff81834cdb] dma_resv_list_alloc+0x1b/0x40 , bytes_req: 56 } hitcount: 9 bytes_alloc: 576
{ call_site: [ffffffff8120086e] tracing_map_sort_entries+0x9e/0x3e0 , bytes_req: 24 } hitcount: 60 bytes_alloc: 1920
Totals:
Hits: 122
Entries: 30
Dropped: 0💡 tiny note bestie: even though the examples use uppercase for the SQL keywords, they do not have to be.SELECTcould also beselector evensElEcT. do with that what you will 🎀
By using the full SQL language, synthetic events can be made and processed. For example, using trace-cmd sqlhist together with trace-cmd record(1), you can record wake up latency by creating a synthetic event that attaches the sched_waking and the sched_switch events. 🌈
...and here's where it all comes together, bestie 💖
# trace-cmd sqlhist -n wakeup_lat -e -T -m lat 'SELECT end.next_comm AS comm, (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 end.next_prio < 100 && end.next_comm == "cyclictest"'
# trace-cmd start -e all -e wakeup_lat -R stacktrace
# cyclictest -l 1000 -p80 -i250 -a -t -q -m -d 0 -b 1000 --tracemark
# trace-cmd show -s | tail -30
<idle>-0 [002] dNh4 23454.902246: sched_wakeup: comm=cyclictest pid=12272 prio=120 target_cpu=002
<idle>-0 [005] ...1 23454.902246: cpu_idle: state=4294967295 cpu_id=5
<idle>-0 [007] d..1 23454.902246: cpu_idle: state=0 cpu_id=7
<idle>-0 [002] dNh1 23454.902247: hrtimer_expire_exit: hrtimer=0000000037956dc2
<idle>-0 [005] d..1 23454.902248: cpu_idle: state=0 cpu_id=5
<idle>-0 [002] dNh1 23454.902248: write_msr: 6e0, value 4866ce957272
<idle>-0 [006] ...1 23454.902248: cpu_idle: state=4294967295 cpu_id=6
<idle>-0 [002] dNh1 23454.902249: local_timer_exit: vector=236
<idle>-0 [006] d..1 23454.902250: cpu_idle: state=0 cpu_id=6
<idle>-0 [002] .N.1 23454.902250: cpu_idle: state=4294967295 cpu_id=2
<idle>-0 [002] dN.1 23454.902251: rcu_utilization: Start context switch
<idle>-0 [002] dN.1 23454.902252: rcu_utilization: End context switch
<idle>-0 [001] ...1 23454.902252: cpu_idle: state=4294967295 cpu_id=1
<idle>-0 [002] dN.3 23454.902253: prandom_u32: ret=3692516021
<idle>-0 [001] d..1 23454.902254: cpu_idle: state=0 cpu_id=1
<idle>-0 [002] d..2 23454.902254: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=cyclictest next_pid=12275 next_prio=19
<idle>-0 [002] d..4 23454.902256: wakeup_lat: next_comm=cyclictest lat=17
<idle>-0 [002] d..5 23454.902258: <stack trace>
=> trace_event_raw_event_synth
=> action_trace
=> event_hist_trigger
=> event_triggers_call
=> trace_event_buffer_commit
=> trace_event_raw_event_sched_switch
=> __traceiter_sched_switch
=> __schedule
=> schedule_idle
=> do_idle
=> cpu_startup_entry
=> secondary_startup_64_no_verifyOkay so here's what all those flags in the example above are actually doing — no gatekeeping 🫶
-n wakeup_lat— this is the name of the synthetic event, so we're calling itwakeup_lat.-e— actually run the commands that get printed. like, do the thing, don't just show me the thing ✨-T— does a double act: first a trace action, then a snapshot action (it swaps the buffer into the static snapshot buffer). two-for-one, iconic 💅-m lat— fires the actions every timelathits a new maximum value. only the record-breakers get through 👑
🌈 Now a breakdown of the SQL statement 🌈
'SELECT end.next_comm AS comm, (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 end.next_prio < 100 && end.next_comm == "cyclictest"'end.next_comm AS comm— grabs thesched_switchfieldnext_command drops it into thecommfield of thewakeup_latsynthetic event. cute little field transplant 🎀(end.TIMESTAMP_USECS - start.TIMESTAMP_USECS) AS lat— takes the delta between the time stamps from thesched_switchevent and thesched_wakingevent. And here's the tea: time stamps are usually recorded in nanoseconds, so plainTIMESTAMPwould hand you the full nanosecond time stamp — butTIMESTAMP_USECStruncates it into microseconds. that value gets saved in the variablelat, which also gets recorded in the synthetic event. periodt.FROM sched_waking AS start JOIN sched_switch AS end ON start.pid = end.next_pid— builds the synthetic event by joiningsched_wakingtosched_switch, matching thesched_wakingpidfield with thesched_switchnext_pidfield. also it makesstartan alias forsched_wakingandendan alias forsched_switch, so you can usestartandendas substitutes forsched_wakingandsched_switchrespectively through out the rest of the SQL statement. nicknames, we love them 💜WHERE end.next_prio < 100 && end.next_comm == "cyclictest"— filters the logic so it only executes if thesched_wakingnext_priofield is less than100. (heads up: in the Kernel, priorities are inverse, and the real-time priorities are represented from0-100where0is the highest priority). also it only traces when thenext_comm(the task scheduling in) of thesched_switchevent has the name"cyclictest". so picky, we stan 🍓
🦋 For the trace-cmd(3) command 🦋
trace-cmd start -e all -e wakeup_lat -R stacktracetrace-cmd start— enables tracing (does not record to a file). it's giving "just turn it on" energy.-e all— enables all events. every single one. no cap.-e wakeup_lat -R stacktrace— has the"wakeup_lat"event (our synthetic event) enable the stacktrace trigger, where for every instance of the"wakeup_lat"event, a kernel stack trace will be recorded in the ring buffer. literally catching it in 4K 📸
After calling cyclictest (a real-time tool to measure wakeup latency), read the snapshot buffer.
trace-cmd show -s—trace-cmd showreads the kernel ring buffer, and the-soption reads the snapshot buffer instead of the normal one. different buffer, same slay.
<idle>-0 [002] d..4 23454.902256: wakeup_lat: next_comm=cyclictest lat=17We see on the "wakeup_lat" event happened on CPU 2, with a wake up latency 17 microseconds. seventeen!! microseconds!! the way that's actually so fast 😭
This can be extracted into a trace.dat file that trace-cmd(3) can read and do further analysis, as well as kernelshark. oh we're archiving this moment 💾✨
# trace-cmd extract -s
# trace-cmd report --cpu 2 | tail -30
<idle>-0 [002] 23454.902238: prandom_u32: ret=1633425088
<idle>-0 [002] 23454.902239: sched_wakeup: cyclictest:12275 [19] CPU:002
<idle>-0 [002] 23454.902241: hrtimer_expire_exit: hrtimer=0xffffbbd68286fe60
<idle>-0 [002] 23454.902241: hrtimer_cancel: hrtimer=0xffffbbd6826efe70
<idle>-0 [002] 23454.902242: hrtimer_expire_entry: hrtimer=0xffffbbd6826efe70 now=23455294430750 function=hrtimer_wakeup/0x0
<idle>-0 [002] 23454.902243: sched_waking: comm=cyclictest pid=12272 prio=120 target_cpu=002
<idle>-0 [002] 23454.902244: prandom_u32: ret=1102749734
<idle>-0 [002] 23454.902246: sched_wakeup: cyclictest:12272 [120] CPU:002
<idle>-0 [002] 23454.902247: hrtimer_expire_exit: hrtimer=0xffffbbd6826efe70
<idle>-0 [002] 23454.902248: write_msr: 6e0, value 4866ce957272
<idle>-0 [002] 23454.902249: local_timer_exit: vector=236
<idle>-0 [002] 23454.902250: cpu_idle: state=4294967295 cpu_id=2
<idle>-0 [002] 23454.902251: rcu_utilization: Start context switch
<idle>-0 [002] 23454.902252: rcu_utilization: End context switch
<idle>-0 [002] 23454.902253: prandom_u32: ret=3692516021
<idle>-0 [002] 23454.902254: sched_switch: swapper/2:0 [120] R ==> cyclictest:12275 [19]
<idle>-0 [002] 23454.902256: wakeup_lat: next_comm=cyclictest lat=17
<idle>-0 [002] 23454.902258: kernel_stack: <stack trace >
=> trace_event_raw_event_synth (ffffffff8121a0db)
=> action_trace (ffffffff8121e9fb)
=> event_hist_trigger (ffffffff8121ca8d)
=> event_triggers_call (ffffffff81216c72)
=> trace_event_buffer_commit (ffffffff811f7618)
=> trace_event_raw_event_sched_switch (ffffffff8110fda4)
=> __traceiter_sched_switch (ffffffff8110d449)
=> __schedule (ffffffff81c02002)
=> schedule_idle (ffffffff81c02c86)
=> do_idle (ffffffff8111e898)
=> cpu_startup_entry (ffffffff8111eba9)
=> secondary_startup_64_no_verify (ffffffff81000107)💅 SEE ALSO 💅
trace-cmd(1), tracefs_sqlhist(3)
🎀 AUTHOR 🎀
Written by Steven Rostedt, <rostedt@goodmis.org[1]>
🦋 RESOURCES 🦋
https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/
👑 COPYING 👑
Copyright (C) 2021 , Inc. Free use of this software is granted under the terms of the GNU Public License (GPL).
🌸 NOTES 🌸
rostedt@goodmis.orgmailto:rostedt@goodmis.org
okay bestie that's the whole page, go forth and trace things 💖
and that's a wrap, fr fr — this lil masterpiece comes to you from libtracefs, dated 03/09/2026, filed under TRACE-CMD-SQLHIST(1). take care of her, she's iconic 🫶✨🎀
📦 where this page comes from
- arch rolling: trace-cmd 3.4-1 · GPL-2.0-only AND LGPL-2.1-only
- 💖 girlified by deepseek-ai/DeepSeek-V4.1-Flash-1017 on : a language model's rewrite of the original, under its terms