Found a new tool for creating and browsing kernel ftrace events.

The trace-cmd command is a front-end tool to make settings for ftrace(1) to record events. It has a variety of options including “record” to start a command and record events. For example:

mev@popayan:~$ trace-cmd record -e sched phoronix-test-suite batch-run x264

Will record all the scheduler events for a run of the phoronix test suite.

By default this data gets saved in a trace.dat file. The “report” command can then display these events in text form:

mev@popayan:~$ trace-cmd report
cpus=8
       trace-cmd-32128 [004] 306518.582003: sched_stat_runtime:   comm=trace-cmd pid=32128 runtime=432263 [ns] vruntime=45728125598 [ns]
       trace-cmd-32128 [004] 306518.582009: sched_switch:         trace-cmd:32128 [120] S ==> swapper/4:0 [120]
          -0     [004] 306518.582014: sched_waking:         comm=trace-cmd pid=32127 prio=120 target_cpu=005
          -0     [004] 306518.582015: sched_migrate_task:   comm=trace-cmd pid=32127 prio=120 orig_cpu=5 dest_cpu=4
          -0     [004] 306518.582018: sched_wakeup:         trace-cmd:32127 [120] success=1 CPU:004
          -0     [004] 306518.582021: sched_switch:         swapper/4:0 [120] R ==> trace-cmd:32127 [120]
       trace-cmd-32127 [004] 306518.582027: sched_stat_runtime:   comm=trace-cmd pid=32127 runtime=10003 [ns] vruntime=45728135601 [ns]
       trace-cmd-32127 [004] 306518.582029: sched_switch:         trace-cmd:32127 [120] S ==> swapper/4:0 [120]
       trace-cmd-32129 [006] 306518.582030: sched_waking:         comm=gmain pid=1272 prio=120 target_cpu=002
       trace-cmd-32129 [006] 306518.582035: sched_wake_idle_without_ipi: cpu=2
       trace-cmd-32129 [006] 306518.582036: sched_wakeup:         gmain:1272 [120] success=1 CPU:002
          -0     [002] 306518.582038: sched_switch:         swapper/2:0 [120] R ==> gmain:1272 [120]
       trace-cmd-32129 [006] 306518.582040: sched_waking:         comm=gmain pid=1357 prio=120 target_cpu=001
       trace-cmd-32129 [006] 306518.582042: sched_wake_idle_without_ipi: cpu=1
           gmain-1272  [002] 306518.582042: sched_waking:         comm=trace-cmd pid=32125 prio=120 target_cpu=003
       trace-cmd-32129 [006] 306518.582043: sched_wakeup:         gmain:1357 [120] success=1 CPU:001
          -0     [001] 306518.582045: sched_switch:         swapper/1:0 [120] R ==> gmain:1357 [120]
           gmain-1272  [002] 306518.582046: sched_migrate_task:   comm=trace-cmd pid=32125 prio=120 orig_cpu=3 dest_cpu=4
           gmain-1272  [002] 306518.582049: sched_wake_idle_without_ipi: cpu=4
           gmain-1272  [002] 306518.582049: sched_wakeup:         trace-cmd:32125 [120] success=1 CPU:004
           gmain-1357  [001] 306518.582050: sched_waking:         comm=trace-cmd pid=32124 prio=120 target_cpu=001
           gmain-1357  [001] 306518.582052: sched_migrate_task:   comm=trace-cmd pid=32124 prio=120 orig_cpu=1 dest_cpu=5
          -0     [004] 306518.582052: sched_switch:         swapper/4:0 [120] R ==> trace-cmd:32125 [120]
           gmain-1272  [002] 306518.582053: sched_stat_runtime:   comm=gmain pid=1272 runtime=19852 [ns] vruntime=716968878722 [ns]
           gmain-1357  [001] 306518.582053: sched_wake_idle_without_ipi: cpu=5
           gmain-1357  [001] 306518.582054: sched_wakeup:         trace-cmd:32124 [120] success=1 CPU:005
...

There are a variety of ways to filter these text events. In addition, the kernelshark command is a front-end browser that makes it easier to see a timeline of events and filter/zoom to specific areas of interest.

A lwn article about using it to analyze scheduler information and a description page were useful in describing features of kernelshark.

Overall, I’ve found these helpful to further analyze the data. In addition, these interfaces also make it easier to explore other types of ftrace kernel information for subsystems other than the scheduler.