TRACE-CMD-REPORT(1)

📦
version 3.4 · 13 versions
, in arch rolling

🎀 trace-cmd-report(1) 🎀

okay so this page is from the libtracefs Manual, and it's literally the glow-up guide for trace-cmd report 💅 grab a snack, we're going through every single flag together, no skipping, no cap.

✨ NAME ✨

trace-cmd-report — shows you, in plain ASCII, a trace that was made by trace-cmd record 🦋

🌸 SYNOPSIS 🌸

trace-cmd report [OPTIONS] [input-file [input-file ...]]

💜 DESCRIPTION 💜

bestie. the trace-cmd(1) report command is the one that takes your trace (the one trace-cmd record so lovingly made) and prints it out as a human-readable report. that's it, that's the whole vibe. it's giving "make the binary data make sense" ✨

🔥 OPTIONS 🔥

okay this is the long part, stay with me, we're going through ALL of them 🫶

  • -i input-file — by default trace-cmd report reads the file trace.dat. but -i opens up the input-file you hand it instead. also note 👀 the input file can just be the last item on the command line, so you've got options.
  • -e — prints the endianess of the file. and honestly? trace-cmd report is smart enough to read big endian files on little endian machines and vise versa. icon behavior, truly 🌈
  • -f — prints the list of all functions that have been mapped in the trace.dat file. heads up though 🫶 this list may contain functions that don't even appear in the trace, because it's the list of mappings used to translate function addresses into function names.
  • -P — prints the list of "trace_printk()" data. the raw trace data points to static pointers in the kernel, and that has to be stored in the trace.dat file. no storage, no list, iykyk.
  • -E — lists the possible events in the file (but, and this is important, this list is not necessarily the list of events in the file 🙈).
  • --events — lists the event formats that are stored in the trace.dat file.
  • --event regex — prints events that match the given regex. if you put a colon in there, the characters before the colon match the system and the characters after the colon match the event 👑
trace-cmd report --event sys:read

the above will only match events where the system name contains "sys" and the event name contains "read".

trace-cmd report --event read

the above matches all events that contain "read" in their name. also it may list all events of a system that contains "read" as well. generous queen 💅

  • --check-events — parses the event format strings stored in the trace.dat file and returns whether the formats can be parsed correctly. it will load plugins unless -N is specified.
  • -t — prints the full timestamp. the timestamps in the data file are usually recorded to the nanosecond, but the default display only goes to the microsecond 😭 so if you want to see the full timestamp, add -t. she said show me everything.
  • -F filter — adds a filter to limit what events get displayed. filters defined after an input file (specified with -i) only apply to that input file. filters you provide before any input file is given are considered global and apply to all input files 🌍

the format of the filter is:

<events> ':' <filter>
<events> = SYSTEM'/'EVENT  | SYSTEM | EVENT | <events> ',' <events>
<filter> = EVENT_FIELD <op> <value> | <filter> '&&' <filter> |
           <filter> '||' <filter> | '(' <filter> ')' | '!' <filter>
<op> = '==' | '!=' | '>=' | '<=' | '>' | '<' | '&' | '|' | '^' |
       '+' | '-' | '*' | '/' | '%'
<value> = NUM | STRING | EVENT_FIELD

SYSTEM is the name of the system to filter on. if the EVENT is left out, then it applies to all events under the SYSTEM. if only one string is used without the '/' to deliminate between SYSTEM and EVENT, then the filter will be applied to all systems and events that match the given string 💫

whitespace is ignored, such that "sched:next_pid==123" is equivalent to "sched : next_pid == 123". so go ahead and add the dramatic spacing, she doesn't mind.

STRING is defined with single or double quotes (single quote must end with single quote, and double with double). whitespace within quotes is not ignored 🚨

the representation of a SYSTEM or EVENT may also be a regular expression as defined by 'regcomp(3)'.

the EVENT_FIELD is the name of the field of an event that is being filtered. if the event does not contain the EVENT_FIELD, that part of the equation will be considered false.

-F 'sched : bogus == 1 || common_pid == 2'

the "bogus == 1" will always evaluate to FALSE because no event has a field called "bogus", but the "common_pid == 2" will still be evaluated since all events have the field "common_pid". any "sched" event that was traced by the process with the PID of 2 will be shown ✨

note: the EVENT_FIELD is the field name as shown by an events format (as displayed with --events), and not what is found in the output. if the output shows "ID:foo" but the field that "foo" belongs to was called "name" in the event format, then "name" must be used in the filter. same energy for values — if the value that is displayed is converted to a string symbol, the filter checks the original value and not the value displayed. for example, to filter on all tasks that were in the running state at a context switch:

-F 'sched/sched_switch : prev_state==0'

although the output displays 'R', having 'prev_stat=="R"' will not work 😭 (yes, that typo is in the original, love that journey for us)

note: you can also specify 'COMM' as an EVENT_FIELD. this will use the task name (or comm) of the record to compare. for example, to filter out all of the "trace-cmd" tasks: -F '.*:COMM != "trace-cmd"'
  • -I — do not print events where the HARDIRQ latency flag is set. this filters out most events that are from interrupt context. but note 🫶 it may not filter out function traced functions that are in interrupt context but were called before the kernel "in interrupt" flag was set. sneaky little things.
  • -S — do not print events where the SOFTIRQ latency flag is set. this filters out most events that are from soft interrupt context.
  • -v — this causes the following filters of -F to filter out the matching events. so:
-v -F 'sched/sched_switch : prev_state == 0'

will not display any sched_switch events that have a prev_state of 0. removing the -v will only print out those events. flip the vibe, flip the output 💅

  • -T — tests the filters of -F. after processing a filter string, the resulting filter is displayed for each event. this is useful for using a filter for more than one event where a field may not exist in all events. also it can be used to make sure there are no misspelled event field names, because they'll simply be ignored 🙈 -T is ignored if -F is not specified.
  • -V — show verbose messages (see --verbose but only for the numbers).
  • -L — this will not load system wide plugins. it loads "local only". that is what it finds in the ~/.trace-cmd/plugins directory 🏠
  • -N — this will not load any plugins. none. zero. bye 👋
  • -n event-re — causes all events that match the option to ignore any registered handler (by the plugins) to print the event. the normal event will be printed instead. the event-re is a regular expression as defined by regcomp(3).
  • --profile — with the --profile option, "trace-cmd report" will process all the events first, and then output a format showing where tasks have spent their time in the kernel, as well as where they are blocked the most, and where wake up latencies are. the whole main character arc of your tasks 😭

see trace-cmd-profile(1) for more details and examples.

  • -G — sets interrupt (soft and hard) events as global (associated to CPU instead of tasks). only works for --profile.
  • -H event-hooks — adds custom event matching to connect any two events together 🔗

see trace-cmd-profile(1) for the format.

  • -R — shows the events in "raw" format. that is, it ignores the event's print formatting and just prints the contents of each field. no makeup, just face.
  • -r event-re — causes all events that match the option to print its raw fields. the event-re is a regular expression as defined by regcomp(3).
  • -l — this adds a "latency output" format. information about interrupts being disabled, soft irq being disabled, the "need_resched" flag being set, preempt count, and big kernel lock are all being recorded with every event. but the default display does not show this information. this option sets display this information with 6 characters. when one of the fields is zero or N/A a '.\' is shown.
      <idle>-0       0d.h1. 106467.859747: function:             ktime_get <-- tick_check_idle

the 0d.h1. denotes this information. let's break it down because it's a lot 🫶

it starts with a number. this represents the CPU number that the event occurred on.

the second character is one of the following:

  • 'd' — interrupts are disabled
  • '.' — interrupts are enabled
  • 'X' — has flags that are not yet known by trace-cmd

the third character is the "need rescheduling" flag.

  • 'N' — a schedule is set to take place
  • '.' — no scheduling is set

the fourth character represents the context the event was in when it triggered.

  • 'h' — hard interrupt context
  • 's' — soft interrupt context
  • 'H' — hard interrupt context that interrupted a soft interrupt
  • '.' — normal context

the next is a number (should be less than 10), that represents the preemption depth (the number of times preempt_disable() is called without preempt_enable()). '.' means preemption is enabled.

on some systems, "migrate disable" may exist, in which case a number will be shown for that, or '.' meaning migration is enabled.

if lockdep is enabled on the system, then the number represents the depth of locks that are held when the event triggered. '.' means no locks are held. obsessed with how much one tiny string can tell you 💀

  • -w — if both the sched_switch and sched_wakeup events are enabled, then this option will report the latency between the time the task was first woken, and the time it was scheduled in. the "how long did you keep me waiting" metric ⏰
  • -q — quiet non critical warnings. shhh. only the important things get to speak 🤫
  • -O — pass options to the trace-cmd plugins that are loaded.
-O plugin:var=value

the 'plugin:' and '=value' are optional. value may be left off for options that are boolean. if the 'plugin:' is left off, then any variable that matches in all plugins will be set.

example: -O fgraph:tailprint

  • --cpu <cpu list> — list of CPUs, separated by "," or ":", used for filtering the events. a range of CPUs can be specified using "cpuX-cpuY" notation, where all CPUs in the range between cpuX and cpuY will be included in the list. the order of CPUs in the list must be from lower to greater 🚨
Example:  "--cpu 0,3" - show events from CPUs 0 and 3
          "--cpu 2-4" - show events from CPUs 2, 3 and 4
  • --cpus — lists the CPUs that have data in the trace file, then exits. a little peek at who showed up to the party 🎉
  • --first-event — shows the timestamp of the first event across all CPUs that actually have data. first-event flex ✨
  • --last-event — shows the timestamp of the last event across all CPUs that have data. closing-time energy 🎀
  • --stat — if the trace.dat file recorded the final stats (the ones output at the end of record), this pulls them back out. stats retrieval slay
  • --uname — if the trace.dat file recorded uname during the run, this grabs that info. uname reveal 🫶
  • --version — if the trace.dat file recorded the version of the executable used to create it, this reports that version. version check, iconic
  • --ts-offset offset — adds an offset (or subtracts if it's negative) for all timestamps of the previous data file specified with -i. This is useful for merge-sorting multiple trace.dat files when you know the timestamp difference. For example, if one trace is done on a virtual guest and another trace is done on the host, and the host timestamp is 1000 units ahead of the guest, you can do:
trace-cmd report -i host.dat --ts-offset -1000 -i guest.dat

This subtracts 1000 timestamp units from all the host events as it merges with the guest.dat events. Note: the units are the raw units recorded in the trace. If the units are nanoseconds, the addition (or subtraction) from the offset will be nanoseconds even if the displayed units are microseconds. raw units stay raw, no cap

  • --ts2secs HZ — converts the current clock source into a second (nanosecond resolution) output. When using clocks like x86-tsc, if the frequency is known, passing in the clock frequency converts the time to seconds.

This option affects any trace.dat file given with -i after it. If this option comes before any -i option, that value becomes the default conversion for all other trace.dat files. If another --ts2secs option appears after an -i trace.dat file, that option overrides the default value.

Example: on a 3.4 GHz machine

trace-cmd record -p function -C x86-tsc

trace-cmd report --ts2ns 3400000000

The report will convert the cycles timestamps into a readable second display. The default display resolution is microseconds, unless -t is used.

The value of --ts-offset must still be in the raw timestamp units, even with this option. The offset will be converted as well. offset gets converted too, bestie

  • --ts-diff — shows the time differences between events. The difference appears in parenthesis just after the timestamp. diff o'clock 🕰️
  • --ts-check — makes sure no timestamp goes backwards, and if one does, prints out a warning message about it. time travel? not on my watch 💀
  • --nodate — ignores converting the timestamps to the date set by trace-cmd record(3)'s --date option. no date, just vibes
  • --raw-ts — displays raw timestamps, without any corrections. raw and unfiltered ✨
  • --align-ts — displays timestamps aligned to the first event. line 'em up 🎯
  • --verbose[=level] — sets the log level. Supported log levels are "none", "crit", "err", "warn", "info", "debug", "all" or their identifiers "0", "1", "2", "3", "4", "5", "6". Setting the log level to a specific value enables all logs from that level and all previous levels. The level defaults to "info" if one is not specified.

Example: enable all critical, error and warning logs

trace-cmd report --verbose=warning

✨ EXAMPLES ✨

Okay bestie, let's say your trace.dat came from this little beauty:

# trace-cmd record -p function -e all sleep 5

The default report hits you with this:

# trace-cmd report
cpus=8
           sleep-89142 [001] ...1. 162573.215752: function:             mutex_unlock
           sleep-89142 [001] ...1. 162573.215754: function:             __mutex_unlock_slowpath
           sleep-89142 [001] ..... 162573.215755: lock_release:         0xffffffff855e7448 trace_types_lock
           sleep-89142 [001] ..... 162573.215757: lock_release:         0xffff892a01b54420 sb_writers
           sleep-89142 [001] ...1. 162573.215757: function:             preempt_count_add
           sleep-89142 [001] ...1. 162573.215758: preempt_disable:      caller=vfs_write+0x147 parent=vfs_write+0x147
           sleep-89142 [001] ...2. 162573.215758: function:             rcu_read_lock_any_held
           sleep-89142 [001] ...2. 162573.215759: function:                rcu_lockdep_current_cpu_online
           sleep-89142 [001] ...2. 162573.215759: function:             preempt_count_sub
           sleep-89142 [001] ...1. 162573.215760: preempt_enable:       caller=vfs_write+0x176 parent=vfs_write+0x176
           sleep-89142 [001] ...1. 162573.215761: function:             __f_unlock_pos
           sleep-89142 [001] ...1. 162573.215761: function:             mutex_unlock
[...]

The note on the third column:

           sleep-89998 [002] ...1. 223087.004011: lock_acquire:         0xffff892b7cf32c20 lock
           sleep-89998 [002] ...1. 223087.004011: lock_acquire:         0xffffffff85517f00 read rcu_read_lock
          <idle>-0     [005] dNh2. 223087.004012: sched_wakeup:         trace-cmd:89992 [120] CPU:005
           sleep-89998 [002] ...1. 223087.004012: lock_acquire:         0xffffffff85517f00 read rcu_read_lock
           sleep-89998 [002] ...1. 223087.004013: lock_release:         0xffffffff85517f00 rcu_read_lock

It follows the same as shown in the Linux kernel /sys/kernel/tracing/trace file.

# cat /sys/kernel/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:8
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |

Same energy as explained in the -l option. Where the first position is:

  • '.' — means interrupts and bottom halves enabled
  • 'd' — means interrupts and bottom halves are disabled

The second position:

  • 'N' — means that the "NEED_RESCHED" flag is set and the kernel should try to schedule as soon as possible.

The third position:

  • '.' — in normal/schedulable context
  • 's' — in soft interrupt context
  • 'h' — in hard interrupt context
  • 'H' — in hard interrupt context that interrupted a soft interrupt

The forth position is the preempt count depth:

  • 'pass:[.]' — preemption is enabled
  • '#' — the depth of preemption disabled (nested)

The fifth column is the migration disabled counter:

  • '.' — migration is enabled
  • '#' — the depth of migration being disabled (nested)

To see everything but the function traces:

# trace-cmd report -v -F 'function'
cpus=8
           sleep-89142 [001] ..... 162573.215755: lock_release:         0xffffffff855e7448 trace_types_lock
           sleep-89142 [001] ..... 162573.215757: lock_release:         0xffff892a01b54420 sb_writers
           sleep-89142 [001] ...1. 162573.215758: preempt_disable:      caller=vfs_write+0x147 parent=vfs_write+0x147
           sleep-89142 [001] ...1. 162573.215760: preempt_enable:       caller=vfs_write+0x176 parent=vfs_write+0x176
           sleep-89142 [001] ..... 162573.215762: lock_release:         0xffff892a19601ac8 &f->f_pos_lock
           sleep-89142 [001] ..... 162573.215764: sys_exit:             NR 1 = 1
           sleep-89142 [001] ..... 162573.215766: sys_exit_write:       0x1
           sleep-89142 [001] d.... 162573.215767: irq_disable:          caller=syscall_exit_to_user_mode+0x15 parent=0x0
           sleep-89142 [001] d.... 162573.215768: irq_enable:           caller=syscall_exit_to_user_mode+0xed parent=0x0
           sleep-89142 [001] ..... 162573.215773: lock_acquire:         0xffff892a4ad29318 read &mm->mmap_lock
           sleep-89142 [001] ..... 162573.215775: lock_release:         0xffff892a4ad29318 &mm->mmap_lock
           sleep-89142 [001] ..... 162573.215778: lock_acquire:         0xffff892a4ad29318 read &mm->mmap_lock
[...]

To see only the kmalloc calls that were greater than 1000 bytes:

# trace-cmd report -F 'kmalloc: bytes_req > 1000'
cpus=8
           sleep-89142 [001] ..... 162573.219401: kmalloc:              (tomoyo_find_next_domain+0x84) call_site=tomoyo_find_next_domain+0x84 ptr=0xffff892a176c0000 bytes_req=4096 bytes_alloc=4096 gfp_flags=0xd40 node=-1 accounted=false
           sleep-89142 [001] ..... 162573.219511: kmalloc:              (tomoyo_realpath_from_path+0x42) call_site=tomoyo_realpath_from_path+0x42 ptr=0xffff892a176c6000 bytes_req=4096 bytes_alloc=4096 gfp_flags=0xc40 node=-1 accounted=false
       trace-cmd-89135 [000] ..... 162573.244301: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a63f84000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89135 [000] ..... 162573.244471: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a63f84000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89134 [007] ..... 162573.267148: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a628d4000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89134 [007] ..... 162573.267403: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a628d4000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89141 [002] ..... 162573.290583: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a12d3c000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89141 [002] ..... 162573.290754: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a12d3c000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
       trace-cmd-89139 [004] ..... 162573.784636: kmalloc:              (kvmalloc_node_noprof+0x43) call_site=kvmalloc_node_noprof+0x43 ptr=0xffff892a63d70000 bytes_req=8193 bytes_alloc=16384 gfp_flags=0x12dc0 node=-1 accounted=false
[...]

To see wakeups and sched switches that left the previous task in the running state:

# trace-cmd report -F 'sched: prev_state == 0' -F 'sched_waking'
cpus=8
     sleep-89142 [001] d.h6. 162573.215941: sched_waking:         comm=trace-cmd pid=89135 prio=120 target_cpu=000
    <idle>-0     [000] dNh7. 162573.216219: sched_waking:         comm=trace-cmd pid=89134 prio=120 target_cpu=007
    <idle>-0     [000] d..2. 162573.216423: sched_switch:         swapper/0:0 [120] R ==> trace-cmd:89135 [120]
    <idle>-0     [007] dNh7. 162573.216511: sched_waking:         comm=trace-cmd pid=89141 prio=120 target_cpu=002
    <idle>-0     [007] d..2. 162573.216698: sched_switch:         swapper/7:0 [120] R ==> trace-cmd:89134 [120]
    <idle>-0     [002] dNh7. 162573.216776: sched_waking:         comm=trace-cmd pid=89136 prio=120 target_cpu=001
    <idle>-0     [002] d..2. 162573.216951: sched_switch:         swapper/2:0 [120] R ==> trace-cmd:89141 [120]
     sleep-89142 [001] d.s3. 162573.231260: sched_waking:         comm=rcu_preempt pid=17 prio=120 target_cpu=002
    <idle>-0     [002] d..2. 162573.231568: sched_switch:         swapper/2:0 [120] R ==> rcu_preempt:17 [120]
     sleep-89142 [001] d.s2. 162573.240425: sched_waking:         comm=rcu_preempt pid=17 prio=120 target_cpu=002
    <idle>-0     [002] d..2. 162573.240719: sched_switch:         swapper/2:0 [120] R ==> rcu_preempt:17 [120]
     sleep-89142 [001] d.h7. 162573.241983: sched_waking:         comm=trace-cmd pid=89135 prio=120 target_cpu=000

Okay so this one needs a lil explainer, bestie, because at first glance it's giving "why are there switches in my waking filter" 😭 so let me break it down 💅

The filter specifies the "sched" subsystem, which includes all scheduling events. Any event that does not have the format field prev_state will evaluate those expressions as FALSE, and will not produce a match — like, it's not being mean, it just doesn't have the field so it can't pass the vibe check 🫶. Only the sched_switch event will match that. The second -F will include the sched_waking event. See? Teamwork ✨

And now the wakeup-latency era 🌸 — -w girlies rise:

# trace-cmd report -w -F 'sched_switch, sched_wakeup.*'
[...]
    trace-cmd-89141 [007] d..2. 162583.263060: sched_switch:         trace-cmd:89141 [120] R ==> trace-cmd:89135 [120]
kworker/u36:1-51219 [000] d..2. 162583.266957: sched_switch:         kworker/u36:1:51219 [120] R ==> kworker/u33:2:49692 [120] Latency: 4024.977 usecs
    trace-cmd-89135 [007] d..2. 162583.267109: sched_switch:         trace-cmd:89135 [120] R ==> trace-cmd:89141 [120]
    trace-cmd-89139 [001] d..2. 162583.267147: sched_switch:         trace-cmd:89139 [120] D ==> swapper/1:0 [120]
kworker/u36:2-88857 [002] d..2. 162583.267913: sched_switch:         kworker/u36:2:88857 [120] R ==> trace-cmd:89136 [120]
kworker/u33:2-49692 [000] d..2. 162583.268334: sched_switch:         kworker/u33:2:49692 [120] I ==> kworker/u36:1:51219 [120]
       <idle>-0     [001] dNh4. 162583.268747: sched_wakeup:         sleep:89142 [120] CPU:001
       <idle>-0     [001] d..2. 162583.268833: sched_switch:         swapper/1:0 [120] R ==> sleep:89142 [120] Latency: 85.751 usecs
        sleep-89142 [001] d.h4. 162583.269022: sched_wakeup:         trace-cmd:89139 [120] CPU:001
    trace-cmd-89141 [007] d..2. 162583.271009: sched_switch:         trace-cmd:89141 [120] R ==> trace-cmd:89135 [120]
    trace-cmd-89136 [002] d..2. 162583.271020: sched_switch:         trace-cmd:89136 [120] R ==> kworker/u36:2:88857 [120]
kworker/u36:2-88857 [002] d..2. 162583.271079: sched_switch:         kworker/u36:2:88857 [120] I ==> trace-cmd:89136 [120]
    trace-cmd-89137 [006] d.h2. 162583.273950: sched_wakeup:         trace-cmd:89133 [120] CPU:006
        sleep-89142 [001] d..2. 162583.274064: sched_switch:         sleep:89142 [120] Z ==> trace-cmd:89139 [120] Latency: 5042.285 usecs
    trace-cmd-89135 [007] d..2. 162583.275043: sched_switch:         trace-cmd:89135 [120] R ==> trace-cmd:89141 [120]
    trace-cmd-89137 [006] d..2. 162583.275158: sched_switch:         trace-cmd:89137 [120] R ==> trace-cmd:89133 [120] Latency: 1207.327 usecs
    trace-cmd-89136 [002] dNh3. 162583.275229: sched_wakeup:         rcu_preempt:17 [120] CPU:002
    trace-cmd-89136 [002] d..2. 162583.275294: sched_switch:         trace-cmd:89136 [120] R ==> rcu_preempt:17 [120] Latency: 65.255 usecs
  rcu_preempt-17    [002] d..2. 162583.275399: sched_switch:         rcu_preempt:17 [120] I ==> trace-cmd:89136 [120]

 Average wakeup latency: 20082.580 usecs
 Maximum Latency: 1032049.277 usecs at timestamp: 162574.787022
 Minimum Latency: 29.023 usecs at timestamp: 162583.189731

 RT task timings:

 Average wakeup latency: 139.568 usecs
 Maximum Latency: 220.583 usecs at timestamp: 162577.347038
 Minimum Latency: 75.902 usecs at timestamp: 162577.719121

The above trace produces the wakeup latencies of the tasks 🔥. The "sched_switch" event reports each individual latency after writing the event information. At the end of the report, the average wakeup latency is reported, as well as the maximum and minimum latency and the timestamp they happened at. And it does this for both normal tasks and real-time tasks — equal opportunity icon behavior 👑.

Now watch this glow-up 💖 — same -w, but filtered down to the RT girlies:

# trace-cmd report -w -F 'sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100'
cpus=8
       <idle>-0     [001] dNh5. 162573.291142: sched_wakeup:         migration/1:23 [0] CPU:001
       <idle>-0     [001] d..2. 162573.291237: sched_switch:         swapper/1:0 [120] R ==> migration/1:23 [0] Latency: 94.643 usecs
    trace-cmd-89141 [002] dNh6. 162573.346785: sched_wakeup:         migration/2:28 [0] CPU:002
    trace-cmd-89141 [002] d..2. 162573.346929: sched_switch:         trace-cmd:89141 [120] R ==> migration/2:28 [0] Latency: 143.971 usecs
    trace-cmd-89134 [003] dNh4. 162573.410852: sched_wakeup:         migration/3:33 [0] CPU:003
    trace-cmd-89134 [003] d..2. 162573.411039: sched_switch:         trace-cmd:89134 [120] R ==> migration/3:33 [0] Latency: 187.640 usecs
       <idle>-0     [004] dNh5. 162573.490944: sched_wakeup:         migration/4:38 [0] CPU:004
       <idle>-0     [004] d..2. 162573.491098: sched_switch:         swapper/4:0 [120] R ==> migration/4:38 [0] Latency: 153.913 usecs
       <idle>-0     [005] dNh5. 162573.574955: sched_wakeup:         migration/5:43 [0] CPU:005
       <idle>-0     [005] d..2. 162573.575107: sched_switch:         swapper/5:0 [120] R ==> migration/5:43 [0] Latency: 152.875 usecs
       <idle>-0     [006] dNh5. 162573.646878: sched_wakeup:         migration/6:48 [0] CPU:006
       <idle>-0     [006] d..2. 162573.646992: sched_switch:         swapper/6:0 [120] R ==> migration/6:48 [0] Latency: 113.788 usecs
    trace-cmd-89140 [002] dNh7. 162577.346818: sched_wakeup:         migration/2:28 [0] CPU:002
    trace-cmd-89140 [002] d..2. 162577.347038: sched_switch:         trace-cmd:89140 [120] R ==> migration/2:28 [0] Latency: 220.583 usecs
    trace-cmd-89134 [003] dNh5. 162577.410869: sched_wakeup:         migration/3:33 [0] CPU:003
    trace-cmd-89141 [005] dNh6. 162577.574792: sched_wakeup:         migration/5:43 [0] CPU:005
    trace-cmd-89141 [005] d..2. 162577.574915: sched_switch:         trace-cmd:89141 [120] R ==> migration/5:43 [0] Latency: 122.648 usecs
    trace-cmd-89136 [007] dNh6. 162577.719045: sched_wakeup:         migration/7:53 [0] CPU:007
    trace-cmd-89136 [007] d..2. 162577.719121: sched_switch:         trace-cmd:89136 [120] R ==> migration/7:53 [0] Latency: 75.902 usecs
    trace-cmd-89140 [005] dNh4. 162581.574827: sched_wakeup:         migration/5:43 [0] CPU:005
    trace-cmd-89140 [005] d..2. 162581.574957: sched_switch:         trace-cmd:89140 [120] R ==> migration/5:43 [0] Latency: 129.717 usecs
kworker/u46:1-51211 [006] dNh4. 162581.646809: sched_wakeup:         migration/6:48 [0] CPU:006

 Average wakeup latency: 139.568 usecs
 Maximum Latency: 220.583 usecs at timestamp: 162577.347038
 Minimum Latency: 75.902 usecs at timestamp: 162577.719121

 RT task timings:

 Average wakeup latency: 139.568 usecs
 Maximum Latency: 220.583 usecs at timestamp: 162577.347038
 Minimum Latency: 75.902 usecs at timestamp: 162577.719121

The above version will only show the wakeups and context switches of Real Time tasks 👑. Now the prio lore, because this trips everyone up: the prio used inside the kernel starts at 0 for highest priority. That is, prio 0 is equivalent to user space real time priority 99, and priority 98 is equivalent to user space real time priority 1. Prios less than 100 represent Real Time tasks. And notice — the total wake up timings are identical to the RT task timings. Not a glitch, bestie, that's literally the point 💅

An example of the profile 🎀:

# trace-cmd record --profile sleep 1
# trace-cmd report --profile --comm sleep
task: sleep-21611
  Event: sched_switch:R (1) Total: 99442 Avg: 99442 Max: 99442 Min:99442
     <stack> 1 total:99442 min:99442 max:99442 avg=99442
       => ftrace_raw_event_sched_switch (0xffffffff8105f812)
       => __schedule (0xffffffff8150810a)
       => preempt_schedule (0xffffffff8150842e)
       => ___preempt_schedule (0xffffffff81273354)
       => cpu_stop_queue_work (0xffffffff810b03c5)
       => stop_one_cpu (0xffffffff810b063b)
       => sched_exec (0xffffffff8106136d)
       => do_execve_common.isra.27 (0xffffffff81148c89)
       => do_execve (0xffffffff811490b0)
       => SyS_execve (0xffffffff811492c4)
       => return_to_handler (0xffffffff8150e3c8)
       => stub_execve (0xffffffff8150c699)
  Event: sched_switch:S (1) Total: 1000506680 Avg: 1000506680 Max: 1000506680 Min:1000506680
     <stack> 1 total:1000506680 min:1000506680 max:1000506680 avg=1000506680
       => ftrace_raw_event_sched_switch (0xffffffff8105f812)
       => __schedule (0xffffffff8150810a)
       => schedule (0xffffffff815084b8)
       => do_nanosleep (0xffffffff8150b22c)
       => hrtimer_nanosleep (0xffffffff8108d647)
       => SyS_nanosleep (0xffffffff8108d72c)
       => return_to_handler (0xffffffff8150e3c8)
       => tracesys_phase2 (0xffffffff8150c304)
  Event: sched_wakeup:21611 (1) Total: 30326 Avg: 30326 Max: 30326 Min:30326
     <stack> 1 total:30326 min:30326 max:30326 avg=30326
       => ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653)
       => ttwu_do_wakeup (0xffffffff810606eb)
       => ttwu_do_activate.constprop.124 (0xffffffff810607c8)
       => try_to_wake_up (0xffffffff8106340a)

Like, the stacks? The totals? The => chain? Genuinely iconic 🧚✨

🌈 SEE ALSO 🌈

trace-cmd(1), trace-cmd-record(1), trace-cmd-start(1), trace-cmd-stop(1), trace-cmd-extract(1), trace-cmd-reset(1), trace-cmd-split(1), trace-cmd-list(1), trace-cmd-listen(1), trace-cmd-profile(1)

The whole friend group, all linked up 🫶 go read them too, iykyk.

💜 AUTHOR 💜

Written by Steven Rostedt, <rostedt@goodmis.org[1]>

Shoutout to the author, fr fr 👑

🦋 RESOURCES 🦋

https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/

That's the repo, bestie — go lurk 💻

🎀 COPYING 🎀

Copyright (C) 2010 Red Hat, Inc. Free use of this software is granted under the terms of the GNU Public License (GPL).

Not me actually reading the license... but yes, that's the deal 💅

📝 NOTES

okay so this is literally just the footnote for the author line up above — nothing scary, promise 🫶

  • 1. rostedt@goodmis.org — mailto:rostedt@goodmis.org ✨
that's it. that's the note. if you were bracing for some cursed edge case, breathe bestie, this one's just an email address 💖

and that's the whole page, no cap 🎀 go forth and trace-cmd report like the main character you are 💅🔥

this little beauty lives in libtracefs, it's the TRACE-CMD-REPORT(1) page, and it's dated 03/09/2026 — screenshot-worthy, honestly 🦋

📦 where this page comes from