TRACE-CMD-REPORT(1) libtracefs Manual TRACE-CMD-REPORT(1) (NAME) trace-cmd-report - trace-cmd record ASCII (SYNOPSIS) trace-cmd report [OPTIONS] [input-file [input-file ...]] (DESCRIPTION) trace-cmd(1) report (trace) trace-cmd record . (OPTIONS) -i input-file trace-cmd report trace.dat -i input-file . . -e (endianness) . trace-cmd report big-endian little-endian . -f trace.dat . . -P <> . . trace.dat . -E ( ). --events trace.dat . --event regex regex . (:) (system) (event) . trace-cmd report --event sys:read "sys" "read" . trace-cmd report --event read "read" . "read" . --check-events trace.dat . -N . -t (timestamp) . . -t . -F filter . ( -i) . . : ':' = SYSTEM'/'EVENT | SYSTEM | EVENT | ',' = EVENT_FIELD | '&&' | '||' | '(' ')' | '!' = '==' | '!=' | '>=' | '<=' | '>' | '<' | '&' | '|' | '^' | '+' | '-' | '*' | '/' | '%' = NUM | STRING | EVENT_FIELD SYSTEM . EVENT SYSTEM . '/' SYSTEM EVENT . "sched:next_pid==123" "sched : next_pid == 123" . STRING ( ). . SYSTEM EVENT (regular expression) 'regcomp(3)' . EVENT_FIELD () . EVENT_FIELD (false) . -F 'sched : bogus == 1 || common_pid == 2' "bogus == 1" FALSE "bogus" "common_pid == 2" "common_pid" . "sched" PID . EVENT_FIELD ( *--events* ) . "ID:foo" "foo" "name" "name" . . . (context switch) : -F 'sched/sched_switch : prev_state==0' 'R' 'prev_stat=="R"' . : 'COMM' EVENT_FIELD . ( comm) . "trace-cmd": -F '.*:COMM != "trace-cmd"' -I HARDIRQ . (interrupt context) . "in interrupt" . -S SOFTIRQ . (soft interrupt context) . -v -F . -v -F 'sched/sched_switch : prev_state == 0' sched_switch prev_state 0 . *-v* . -T -F . . . . -F -T . -V ( --verbose ) -L . (<>) ~/.trace-cmd/plugins . -N . -n event-re ( ) . . event-re regcomp(3) . --profile --profile <> (wake up latencies) . trace-cmd-profile(1) . -G ( ) ( CPU ). --profile . -H event-hooks . trace-cmd-profile(1) . -R <<>> (raw) . -r event-re . event-re regcomp(3) . -l << >> (latency output) . soft irq <> (preempt count) (big kernel lock) . . . N/A '.\' . -0 0d.h1. 106467.859747: function: ktime_get <-- tick_check_idle 0d.h1. . . CPU . : 'd' - '.' - 'X' - trace-cmd << >> (need rescheduling) . 'N' - '.' - 'h' - 's' - 'H' - '.' - ( ) (preemption depth) ( preempt_disable() preempt_enable() ). '.' . <> '.' (migration) . lockdep . '.' . -w sched_switch sched_wakeup . -q . -O trace-cmd. -O plugin:var=value 'plugin:' '=value' . (boolean) . 'plugin:' . : -O fgraph:tailprint --cpu <<,>> <<:>> . <> cpuX cpuY . . : "--cpu 0,3" - 0 3 "--cpu 2-4" - 2 3 4 --cpus . --first-event . --last-event . --stat trace.dat ( ) --stat . --uname trace.dat uname . --version trace.dat . --ts-offset offset ( ) () -i. trace.dat . 1000 : trace-cmd report -i host.dat --ts-offset -1000 -i guest.dat guest.dat 1000 . . ( ) . --ts2secs HZ ( ). x86-tsc () . trace.dat *-i* . *-i* trace.dat . --ts2secs trace.dat *-i* . : 3.4 trace-cmd record -p function -C x86-tsc trace-cmd report --ts2ns 3400000000 (cycles) . *-t* . --ts-offset . . --ts-diff . . --ts-check . --nodate --date trace-cmd record(3) . --raw-ts . --align-ts . --verbose[=level] . "none" "crit" "err" "warn" "info" "debug" "all" "0" "1" "2" "3" "4" "5" "6". . "info" . : trace-cmd report --verbose=warning trace.dat : # trace-cmd record -p function -e all sleep 5 : # 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 [...] : sleep-89998 [002] ...1. 223087.004011: lock_acquire: 0xffff892b7cf32c20 lock sleep-89998 [002] ...1. 223087.004011: lock_acquire: 0xffffffff85517f00 read rcu_read_lock -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 /sys/kernel/tracing/trace . # 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 # | | | ||||| | | -l . : '.' - bottom half 'd' - bottom half : 'N' - "NEED_RESCHED" . : '.' - / 's' - (soft interrupt) 'h' - (hard interrupt) 'H' - preempt count : 'pass:[.]' - preemption '#' - preemption () (migration disabled counter) : '.' - (migration) '#' - () (function): # 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 [...] kmalloc : # 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 [...] (wakeups) sched running : # 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 -0 [000] dNh7. 162573.216219: sched_waking: comm=trace-cmd pid=89134 prio=120 target_cpu=007 -0 [000] d..2. 162573.216423: sched_switch: swapper/0:0 [120] R ==> trace-cmd:89135 [120] -0 [007] dNh7. 162573.216511: sched_waking: comm=trace-cmd pid=89141 prio=120 target_cpu=002 -0 [007] d..2. 162573.216698: sched_switch: swapper/7:0 [120] R ==> trace-cmd:89134 [120] -0 [002] dNh7. 162573.216776: sched_waking: comm=trace-cmd pid=89136 prio=120 target_cpu=001 -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 -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 -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 . <> . <> FALSE . sched_switch . <<-F>> sched_waking . # 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] -0 [001] dNh4. 162583.268747: sched_wakeup: sleep:89142 [120] CPU:001 -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 (wakeup latencies) . <> . . (real-time) . # trace-cmd report -w -F 'sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100' cpus=8 -0 [001] dNh5. 162573.291142: sched_wakeup: migration/1:23 [0] CPU:001 -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 -0 [004] dNh5. 162573.490944: sched_wakeup: migration/4:38 [0] CPU:004 -0 [004] d..2. 162573.491098: sched_switch: swapper/4:0 [120] R ==> migration/4:38 [0] Latency: 153.913 usecs -0 [005] dNh5. 162573.574955: sched_wakeup: migration/5:43 [0] CPU:005 -0 [005] d..2. 162573.575107: sched_switch: swapper/5:0 [120] R ==> migration/5:43 [0] Latency: 152.875 usecs -0 [006] dNh5. 162573.646878: sched_wakeup: migration/6:48 [0] CPU:006 -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 (context switches) Real Time . prio 0 . prio 0 (user space) . prio 100 Real Time . RT . 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 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 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 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) 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) (AUTHOR) Steven Rostedt (RESOURCES) https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git (COPYING) (C) 2010 Red Hat, Inc. (GPL) . (NOTES) 1. rostedt@goodmis.org mailto:rostedt@goodmis.org libtracefs 03/09/2026 TRACE-CMD-REPORT(1)