Useful trace-cmd and ftrace commands

This article is a collection of useful trace-cmd and ftrace commands.
Don't hesitate to update them and add new commands.

Important Notes:

• RHEL6 uses: trace-cmd version 1.0.5
• RHEL7 uses: trace-cmd version 2.2.2

To install:

yum install trace-cmd

Options and arguments may be different among different versions of RHEL. It is possible to upgrade to the latest version of trace-cmd. See:
https://git.kernel.org/cgit/linux/kernel/git/rostedt/trace-cmd.git/

To upgrade from upstream:

yum group install "Development Tools"
git clone git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git
cd trace-cmd
make
make install

However the above version of trace-cmd is not supported by Red Hat and should only be upgraded if extra functionality is required at the behest of the Red Hat Engineer working on your case. You can get most of the functionality from the supported versions so please use those by default.

Wakeup Tracer: see how long it takes for a task from being ready to run to being run

[root@localhost]# cd /sys/kernel/debug/tracing

echo wakeup > current_tracer
echo 0 > tracing_max_latency
echo 1 > events/enable
echo 1 > tracing_on && sleep 1 && echo 0 > tracing_on
cat trace 

Function Profiler: find out how long each function takes

echo 0 > function_profile_enabled (clear previous profiler data)
echo 1 > function_profile_enabled
echo nop > current_tracer
echo *icmp* > set_ftrace_filter
echo 1 > tracing_on && ping -c 1000000 -i 0 127.0.0.1 > /dev/null && echo 0 > tracing_on
cat trace_stat/functionX (CPU Core)

IRQ Latencies: find high latency ones

trace-cmd record -p function_graph -e irq_handler_entry -l do_IRQ sleep 10
trace-cmd report

Sample output:

SpiderOakBlue-5699  [002] 20507.754014: irq_handler_entry:    irq=59 name=enp0s25
SpiderOakBlue-5699  [002] 20507.754019: funcgraph_exit:         4.330 us   |  }
gnome-shell-5405  [001] 20507.773000: funcgraph_entry:                   |  __irqentry_text_start() {
gnome-shell-5405  [001] 20507.773003: irq_handler_entry:    irq=62 name=i915
gnome-shell-5405  [001] 20507.773021: funcgraph_exit:       + 19.418 us  |  }

Check Soft IRQs: get an idea of what softirqs are doing and how long they are taking
RHEL7

trace-cmd record -p function_graph --profile -g do_softirq -e irq:softirq_entry sleep 10
trace-cmd report
trace-cmd report --profile

RHEL6

trace-cmd record -p function_graph -g do_softirq -e irq:softirq_entry sleep 10
trace-cmd report

Sample Output:

  Event: softirq_raise:TIMER (1) Total: 53150 Avg: 53150 Max: 53150(ts:20644.345014) Min:53150(ts:20644.345014)
          | 
          + tick_sched_handle.isra.15 (0xffffffff810d5b45)
              100% (1) time:53150 max:53150(ts:20644.344985) min:53150(ts:20644.344985) avg:53150
               tick_sched_timer (0xffffffff810d5bc1)
               __run_hrtimer (0xffffffff8109f637)
               hrtimer_interrupt (0xffffffff8109fe77)
               local_apic_timer_interrupt (0xffffffff810471c7)
               smp_trace_apic_timer_interrupt (0xffffffff816316b6)
               trace_apic_timer_interrupt (0xffffffff8162fd9d)
               __schedule (0xffffffff81623ac8)
               schedule (0xffffffff81624119)
               worker_thread (0xffffffff81094279)
               kthread (0xffffffff8109b68f)
               ret_from_fork (0xffffffff8162f018)

Some times it be necessary to increase the per CPU ftrace buffer. You will need to test this to find the optimum balance between the ftrace buffer not over-flowing and losing information vs kernel memory consumption in your environment. Use the "-b option. e.g:

# trace-cmd record -p function_graph -g do_softirq -e irq:softirq_entry -b 1048576 sleep 10

Check what userspace task is doing in kernel space: get an idea of what is happening in kernel space when task (or its children) is executed due to activities caused by such task. For instance, useful when some syscall experiences unexpected slowness. Collection of trace.dat should be run from root:

trace-cmd record -p function_graph -F -c <executable_command>

or under sudo:

[user@machine test]$ sudo trace-cmd record -p function_graph -F -c <executable_command>

trace-cmd can also attach to an already running process using its PID:

[user@machine test]$ sudo trace-cmd record -p function_graph -F -P <PID>

After enough data is collected, the user should hit Ctrl-C to stop.