ftrace

Linux kernel configuration

Ref: https://www.kernel.org/doc/Documentation/trace/ftrace.txt

<board>_defconfig

  • kernel/trace/Kconfig: ์„ค์ • ๊ฐ€๋Šฅํ•œ ์˜ต์…˜, ์˜์กด์„ฑ, ์„ค๋ช… ๋“ฑ์ด ์žˆ์œผ๋ฏ€๋กœ ์ฐธ๊ณ ํ•˜์‹œ๊ธฐ ๋ฐ”๋ž๋‹ˆ๋‹ค.
  • arch/<architecture>/configs/<board>_defconfig

Options

  • CONFIG_FTRACE=y: Enables the kernel tracing infrastructure.
    • CONFIG_FUNCTION_TRACER=y: Enables the kernel to trace every kernel function.
      • CONFIG_FUNCTION_GRAPH_TRACER=y: Enables the kernel to trace a function at both its return and its entry.
      • CONFIG_FUNCTION_PROFILER=y: Enables the kernel function profiler. A file is created in debugfs called function_profile_enabled which defaults to zero. When a 1 is echoed into this file profiling begins, and when a zero is entered, profiling stops. A "functions" file is created in the trace_stats directory; this file shows the list of functions that have been hit and their counters.
    • CONFIG_IRQSOFF_TRACER=y: Measures the time spent in irqs-off critical sections, with microsecond accuracy.
    • CONFIG_SCHED_TRACER=y: Tracks the latency of the highest priority task to be scheduled in, starting from the point it has woken up.
    • CONFIG_TRACER_SNAPSHOT=y: Allows tracing users to take snapshot of the current buffer using the ftrace interface.
    • CONFIG_STACK_TRACER=y: Records the maximum stack footprint of the kernel and displays it in /sys/kernel/debug/tracing/stack_trace.
    • CONFIG_DYNAMIC_FTRACE=y: This option will modify all the calls to function tracing dynamically (will patch them out of the binary image and replace them with a No-Op instruction) on boot up. During compile time, a table is made of all the locations that ftrace can function trace, and this table is linked into the kernel image. When this is enabled, functions can be individually enabled, and the functions not enabled will not affect performance of the system.

trace_printk

<linux/kernel.h>์— ์ •์˜๋˜์–ด ์žˆ๋Š” ํ•จ์ˆ˜์ž…๋‹ˆ๋‹ค.

Ftrace introduces a new form of printk() called trace_printk(). It can be used just like printk(), and can also be used in any context (interrupt code, NMI code, and scheduler code). What is nice about trace_printk() is that it does not output to the console. Instead it writes to the Ftrace ring buffer and can be read via the trace file.

ftrace setup

์„ค์ •์„ ์‹œ์ž‘ํ•˜๊ธฐ ์ „์— ftrace๋ฅผ ๋น„ํ™œ์„ฑํ™”ํ•œ ํ›„ ์„ค์ •ํ•˜์‹œ๊ธฐ ๋ฐ”๋ž๋‹ˆ๋‹ค.

ftrace on(restart)/off

echo 1 > /sys/kernel/debug/tracing/tracing_on && sleep 1
echo 0 > /sys/kernel/debug/tracing/tracing_on && sleep 1
cat /sys/kernel/debug/tracing/tracing_on

ftrace event on/off

echo 1 > /sys/kernel/debug/tracing/events/enable && sleep 1
echo 0 > /sys/kernel/debug/tracing/events/enable && sleep 1
cat /sys/kernel/debug/tracing/events/enable

set_ftrace_filter

/sys/kernel/debug/tracing/available_filter_functions์— ๋“ฑ๋ก๋œ ํ•จ์ˆ˜๋งŒ ์ถ”์ฒ™ ๊ฐ€๋Šฅํ•ฉ๋‹ˆ๋‹ค.

cat /sys/kernel/debug/tracing/available_filter_functions

format์— ๋”ฐ๋ผ ํ•จ์ˆ˜, ๋ชจ๋“ˆ ๋“ฑ์„ ์„ ํƒ์ ์œผ๋กœ ๋“ฑ๋กํ•  ์ˆ˜ ์žˆ์Šต๋‹ˆ๋‹ค.

caution

set_ftrace_filter์— ํ•จ์ˆ˜๋ฅผ ๋“ฑ๋กํ•˜์ง€ ์•Š๊ณ  ftrace๊ฐ€ ์‹คํ–‰๋˜๋ฉด ๋ชจ๋“  ํ•จ์ˆ˜๋ฅผ ์ถ”์ ํ•˜๊ธฐ ๋•Œ๋ฌธ์— ์‹œ์Šคํ…œ์— ๊ณผ๋ถ€ํ•˜๊ฐ€ ๊ฑธ๋ ค ์˜ค๋™์ž‘ํ•  ์ˆ˜ ์žˆ์Šต๋‹ˆ๋‹ค.

echo <format_1> <format_2> ... > /sys/kernel/debug/tracing/set_ftrace_filter

format: <function>:<command>:<parameter>

  • function
  • command
    • mod: ํ•จ์ˆ˜๋ฅผ ๋ชจ๋“ˆ๋กœ ํ•„ํ„ฐ๋งํ•  ์ˆ˜ ์žˆ์Šต๋‹ˆ๋‹ค.
      • ex) :mod:spi_gpio๋ฅผ ์„ค์ •ํ•˜๋ฉด spi_gpio ๊ด€๋ จ ๋ชจ๋“ˆ ๋‚ด์—์„œ ์‚ฌ์šฉํ•˜๋Š” ๋ชจ๋“  ํ•จ์ˆ˜๋ฅผ ์ถ”์ ํ•ฉ๋‹ˆ๋‹ค.
      • module์˜ ๊ฒฝ์šฐ modprobe๋‚˜ insmod์— ์˜ํ•ด ์ถ”๊ฐ€๋˜๊ธฐ ์ „์— ๋“ฑ๋กํ•  ์ˆ˜ ์—†์Šต๋‹ˆ๋‹ค.
    • traceon/traceoff
    • snapshot
    • enable_event/disable_event
    • dump
    • cpudump
  • parameter
cat /sys/kernel/debug/tracing/set_ftrace_filter

ftrace tracer setup

/sys/kernel/debug/tracing/available_tracers์— ๋“ฑ๋ก๋œ tracer๋งŒ ์„ค์ • ๊ฐ€๋Šฅํ•ฉ๋‹ˆ๋‹ค.

cat /sys/kernel/debug/tracing/available_tracers
echo <tracer> > /sys/kernel/debug/tracing/current_tracer && sleep 1
  • nop: ftrace event๋งŒ ์ถœ๋ ฅ
  • function: set_ftrace_filter์— ๋“ฑ๋ก๋œ ํ•จ์ˆ˜๋ฅผ ์–ด๋””์—์„œ ํ˜ธ์ถœํ–ˆ๋Š”์ง€ ์ถœ๋ ฅ
  • function_graph: ํ•จ์ˆ˜ ์‹คํ–‰ ์‹œ๊ฐ„, ์„ธ๋ถ€ ํ˜ธ์ถœ ์ •๋ณด ์ถœ๋ ฅ
echo nop > /sys/kernel/debug/tracing/current_tracer && sleep 1
echo function > /sys/kernel/debug/tracing/current_tracer && sleep 1
echo function_graph > /sys/kernel/debug/tracing/current_tracer && sleep 1
cat /sys/kernel/debug/tracing/current_tracer

Trace

cat /sys/kernel/debug/tracing/trace
cat /sys/kernel/debug/tracing/trace | head -n <number>
cat /sys/kernel/debug/tracing/trace | grep -n -C <number> <function>

tracer๊ฐ€ ๋ณ€๊ฒฝ๋˜๋ฉด ์ดˆ๊ธฐํ™” ๋ฉ๋‹ˆ๋‹ค.

Example

spidev์˜ bus ๋ฒˆํ˜ธ๊ฐ€ ์–ด๋–ป๊ฒŒ ์„ค์ •๋˜๋Š”์ง€ ํ™•์ธํ•˜๋Š” ํ…Œ์ŠคํŠธ ์˜ˆ์ œ์ž…๋‹ˆ๋‹ค. ํ…Œ์ŠคํŠธ๋Š” Hardkernel Odroid-C2์—์„œ ์ง„ํ–‰ํ–ˆ์Šต๋‹ˆ๋‹ค.

Linux kernel configuration

<board>_defconfig

arch/<architecture>/configs/<board>_defconfig
CONFIG_FTRACE=y
CONFIG_FUNCTION_TRACER=y
CONFIG_FUNCTION_GRAPH_TRACER=y
CONFIG_STACK_TRACER=y
CONFIG_DYNAMIC_FTRACE=y

Linux kernel driver

driver/spi/spi.c
int spi_register_master(struct spi_master *master) {
...
trace_printk("bus_num: %d\n", master->bus_num);
trace_printk("dev.of_node: %d\n", master->dev.of_node);
if ((master->bus_num < 0) && master->dev.of_node)
master->bus_num = of_alias_get_id(master->dev.of_node, "spi");
trace_printk("bus_num: %d\n", master->bus_num);
/* convention: dynamically assigned bus IDs count down from the max */
if (master->bus_num < 0) {
/* FIXME switch to an IDR based scheme, something like
* I2C now uses, so we can't run out of "dynamic" IDs
*/
master->bus_num = atomic_dec_return(&dyn_bus_id);
dynamic = 1;
}
trace_printk("bus_num: %d\n", master->bus_num);
...
}
EXPORT_SYMBOL_GPL(spi_register_master);

Build Linux kernel

ftrace setup

echo 0 > /sys/kernel/debug/tracing/tracing_on && sleep 1 &&\
echo 0 > /sys/kernel/debug/tracing/events/enable && sleep 1 &&\
echo '*spi_*' > /sys/kernel/debug/tracing/set_ftrace_filter && sleep 1 &&\
echo nop > /sys/kernel/debug/tracing/current_tracer && sleep 1 &&\
echo function_graph > /sys/kernel/debug/tracing/current_tracer && sleep 1 &&\
echo 1 > /sys/kernel/debug/tracing/tracing_on && sleep 1

Trace

cat /sys/kernel/debug/tracing/trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) + 47.000 us | spi_register_driver();
------------------------------------------
0) modprob-1885 => modprob-1891
------------------------------------------
0) 4.000 us | spi_alloc_master();
0) | spi_register_master() {
0) | /* bus_num: -1 */
0) | /* dev.of_node: 1948176240 */
0) | /* bus_num: -19 */
0) | /* bus_num: 32764 */
0) 1.000 us | spi_start_queue();
0) 4.000 us | spi_alloc_device();
------------------------------------------
0) modprob-1891 => spi3276-1893
------------------------------------------
0) 1.000 us | spi_pump_messages();
------------------------------------------
0) spi3276-1893 => modprob-1891
------------------------------------------
0) | spi_add_device() {
0) + 35.000 us | spi_setup();
0) 1.000 us | spi_uevent();
0) 5.000 us | spi_match_device();
0) ! 131.000 us | spi_drv_probe();
0) ! 318.000 us | }
0) ! 3811.000 us | } /* spi_register_master */
1) 2.000 us | spi_uevent();
1) 2.000 us | spi_uevent();

Consequence

์ˆ˜์ •๋œ spi.c ์ฝ”๋“œ์™€ trace ๋‚ด์šฉ์„ ๋น„๊ตํ•ด๋ณด๋ฉด bus ๋ฒˆํ˜ธ๊ฐ€ ์ฒ˜์Œ๋ถ€ํ„ฐ ํ• ๋‹น๋˜์ง€ ์•Š์•„ ์Œ์ˆ˜์˜€๊ณ , of_alias_get_id()ํ•จ์ˆ˜ ํ˜ธ์ถœ ํ›„์—๋„ ํ• ๋‹น๋˜์ง€ ์•Š์•„ ์Œ์ˆ˜์ธ ๊ฒƒ์„ ํ™•์ธํ•  ์ˆ˜ ์žˆ์Šต๋‹ˆ๋‹ค.

/* convention: dynamically assigned bus IDs count down from the max */ ๋ผ๋Š” ์ฃผ์„์ด ์žˆ์Šต๋‹ˆ๋‹ค. ๋”ฐ๋ผ์„œ ๋™์  ํ• ๋‹น๋œ bus๋Š” 32766, 32765 ๋“ฑ์˜ ๋ฒˆํ˜ธ๋ฅผ ํ• ๋‹น ๋ฐ›์Šต๋‹ˆ๋‹ค.

์ •์ ์œผ๋กœ ํ• ๋‹นํ•ด์ฃผ๊ธฐ ์œ„ํ•ด์„œ of_alias_get_id()์— ์˜ํ•ด ๋ฒˆํ˜ธ๋ฅผ ํ• ๋‹น ๋ฐ›์„ ์ˆ˜ ์žˆ๊ฒŒ ํ•˜๋ฉด ๋ฉ๋‹ˆ๋‹ค.

์˜ˆ๋ฅผ ๋“ค์–ด bus ๋ฒˆํ˜ธ๋ฅผ 0์œผ๋กœ ์„ค์ •ํ•˜๊ณ  ์‹ถ์€ ๊ฒฝ์šฐ dts์˜ spi ๋…ธ๋“œ์— spi_0: ๊ฐ™์€ ๋ผ๋ฒจ์„ ๋ถ™์—ฌ์ฃผ๊ณ , aliases์— spi0 = &spi_0๋ฅผ ์ถ”๊ฐ€ํ•˜๋ฉด ๋ฉ๋‹ˆ๋‹ค.

Last updated on