[리눅스커널] ftrace: boottime-trace(부트타임 ftrace)

<version: ES1>

 

Overview

 

이번 포스트에서는 커널 v5.10에 반영된 boottime-trace를 소개합니다. 관련 문서는 아래 링크에서 확인할 수 있습니다.

 

https://mjmwired.net/kernel/Documentation/trace/boottime-trace.rst

 

강의 동영상 링크는 다음과 같습니다.

 

https://linuxfoundation.org/webinars/extra-boot-configuration-and-boot-time-tracing/

 

boottime-trace는 커멘드 라인을 통해 ftrace 설정을 해서 부팅 과정에서 ftrace의 주요 기능을 enable하는 기능입니다. 위 링크에서 소개된 패치는 initrd가 존재해야 효과가 있어(ex: 우분투), 배포판마다 활성화가 하기는 어렵습니다. 안드로이드나 크로뮴 OS에서는 initrd을 사용하지 않습니다.

 

소스 분석 

 

v5.15 버전의 리눅스 커널 소스에서 확인한 디렉토리에서 커맨드 라인을 읽는 ftrace 옵션과 콜백 함수 리스트는 아래와 같습니다. ('kernel/trace'에서 서칭 )

 

$ egrep -nr __setup  *

ftrace.c:5526:__setup("ftrace_notrace=", set_ftrace_notrace);

ftrace.c:5534:__setup("ftrace_filter=", set_ftrace_filter);

ftrace.c:5546:__setup("ftrace_graph_filter=", set_graph_function);

ftrace.c:5553:__setup("ftrace_graph_notrace=", set_graph_notrace_function);

ftrace.c:5562:__setup("ftrace_graph_max_depth=", set_graph_max_depth_function);

trace.c:197:__setup("ftrace=", set_cmdline_ftrace);

trace.c:213:__setup("ftrace_dump_on_oops", set_ftrace_dump_on_oops);

trace.c:221:__setup("traceoff_on_warning", stop_trace_on_warning);

trace.c:230:__setup("alloc_snapshot", boot_alloc_snapshot);

trace.c:240:__setup("trace_options=", set_trace_boot_options);

trace.c:251:__setup("trace_clock=", set_trace_boot_clock);

trace.c:263:__setup("tp_printk", set_tracepoint_printk);

trace.c:270:__setup("tp_printk_stop_on_boot", set_tracepoint_printk_stop);

trace.c:1507:__setup("trace_buf_size=", set_buf_size);

trace.c:1522:__setup("tracing_thresh=", set_tracing_thresh);

trace_events.c:3438:__setup("trace_event=", setup_trace_event);

trace_kprobe.c:36:__setup("kprobe_event=", set_kprobe_boot_events);

trace_stack.c:552:__setup("stacktrace", enable_stacktrace);

 

커맨드 라인에 boottime-trace 설정하기

 

크로뮴 OS

 

먼저 크로뮴 OS에서 아래 패치를 적용하면 커멘드 라인이 업데이트됩니다.

 

diff --git a/chromeos/config/x86_64/chromiumos-x86_64.flavour.config b/chromeos/config/x86_64/chromiumos-x86_64.flavour.config

index 084c67d005dd..ad8f8bddc233 100644

— a/chromeos/config/x86_64/chromiumos-x86_64.flavour.config

+++ b/chromeos/config/x86_64/chromiumos-x86_64.flavour.config

 

+CONFIG_CMDLINE="crashkernel=512M ftrace=function ftrace_filter=*_probe*

+CONFIG_CMDLINE_BOOL=y

 

'ftrace=function ftrace_filter=*_probe*'이 핵심 구문입니다.

 

라즈비안

 

이번에는 라즈비안에서 boottime-trace 커맨드 라인을 추가하는 방법을 소개합니다. 라즈비안은 디바이스 트리에서 부트 커멘트 라인을 업데이트할 수 있습니다. 아래는 arm32 기반 라즈비안에서 커멘드 라인을 수정하는 패치입니다. (소스 베이스: v5.15.33)

 

diff --git a/arch/arm/boot/dts/bcm2711-rpi-4-b.dts b/arch/arm/boot/dts/bcm2711-rpi-4-b.dts

index 8c0ab39..47e552e 100644

--- a/arch/arm/boot/dts/bcm2711-rpi-4-b.dts

+++ b/arch/arm/boot/dts/bcm2711-rpi-4-b.dts

@@ -282,7 +282,7 @@

 

 / {

        chosen {

-               bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

+               bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 ftrace=function ftrace_filter=*_probe*";

        };

 

        aliases {

 

위 패치는 Arm64 기반 라즈비안에 적용됩니다. bcm2711-rpi-4-b.dts 파일을 열면 "arm/boot/dts/bcm2711-rpi-4-b.dts"을 include하기 때문입니다. 

 

arch/arm64/boot/dts/broadcom/bcm2711-rpi-4-b.dts

#include "../../../../arm/boot/dts/bcm2711-rpi-4-b.dts"

 

(리서치 1)

검색 과정에서 사용한 명령어는 다음과 같습니다. 

 

rpi_5_15_src/linux/arch/arm/boot/dts$ find . -name "bcm271*.*" -type f | xargs grep bootargs

./bcm2711-rpi-cm4.dts:          bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2711-rpi-4-b.dts:          bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 ftrace=function ftrace_filter=*_probe*";

./bcm2711-rpi-400.dts:          bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2710-rpi-3-b.dts:          bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2710-rpi-zero-2-w.dts:             bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2710-rpi-3-b-plus.dts:             bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

./bcm2711-rpi-cm4s.dts:         bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1";

 

각각 서로 다른 라즈베리 파이에 대해 다음 파일이 적용됩니다. 

 

modified: arch/arm/boot/dts/bcm2711-rpi-4-b.dts

modified: arch/arm/boot/dts/bcm2711-rpi-400.dts

modified: arch/arm/boot/dts/bcm2711-rpi-cm4s.dts

 

(리서치 2)

 

CONFIG_ARCH_BCM_2835가 bcm2711_defconfig에 enable돼 있습니다.

 

out64/.config

...

 293 # CONFIG_ARCH_APPLE is not set

 294 CONFIG_ARCH_BCM2835=y

 295 # CONFIG_ARCH_BCM4908 is not set

 296 # CONFIG_ARCH_BCM_IPROC is not set

 

ARCH_BCM_2835를 Makefile에서 검색해 bcm27* dtb 파일이 빌드에 포함됨을 확인했습니다. 

 

arch/arm64/boot/dts/broadcom/Makefile 

# SPDX-License-Identifier: GPL-2.0

dtb-$(CONFIG_ARCH_BCM2835) += bcm2711-rpi-400.dtb \

                  bcm2711-rpi-4-b.dtb \

                  bcm2837-rpi-3-a-plus.dtb \

                  bcm2837-rpi-3-b.dtb \

                  bcm2837-rpi-3-b-plus.dtb \

                  bcm2837-rpi-cm3-io3.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-zero-2.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-2-b.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-3-b.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-3-b-plus.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2711-rpi-4-b.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2711-rpi-400.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2710-rpi-cm3.dtb

dtb-$(CONFIG_ARCH_BCM2835) += bcm2711-rpi-cm4.dtb

 

subdir-y    += bcm4908

subdir-y    += northstar2

subdir-y    += stingray

 

# Enable fixups to support overlays on BCM2835 platforms

ifeq ($(CONFIG_ARCH_BCM2835),y)

    DTC_FLAGS += -@

endif

 

샘플 ftrace 메시지 

 

부트 커멘드 라인으로 "ftrace=function ftrace_filter=*initcall*"을 적용한 후 

받은 ftrace 메시지는 다음과 같습니다.

 

# tracer: function

#

# entries-in-buffer/entries-written: 6800/6800   #P:4

#

#                                _-----=> irqs-off

#                               / _----=> need-resched

#                              | / _---=> hardirq/softirq

#                              || / _--=> preempt-depth

#                              ||| /     delay

#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION

#              | |         |   ||||      |         |

          <idle>-0       [000] d..1     0.250968: arch_probe_nr_irqs <-early_irq_init

          <idle>-0       [000] ...1     0.252607: physflat_probe <-default_setup_apic_routing

          <idle>-0       [000] ...1     0.252608: flat_probe <-default_setup_apic_routing

            init-1       [000] ....     0.270282: watchdog_nmi_probe <-lockup_detector_init

            init-1       [000] ....     0.281332: bus_probe_device <-device_add

            init-1       [000] ....     0.281348: add_probe_files <-bus_register 

...

            init-1       [002] d..2     0.641288: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120

          <idle>-0       [003] d..2     0.641309: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

    kworker/u8:1-76      [003] d..2     0.641337: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=R+ ==> next_comm=irq/42-mmc1 next_pid=107 next_prio=49

     irq/42-mmc1-107     [003] d..2     0.641396: sched_switch: prev_comm=irq/42-mmc1 prev_pid=107 prev_prio=49 prev_state=S ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

    kworker/u8:1-76      [003] d..2     0.641407: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120

          <idle>-0       [002] d..2     0.641408: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=125 next_prio=120

          <idle>-0       [001] d..2     0.641414: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/1:0 next_pid=20 next_prio=120

     kworker/1:0-20      [001] d..2     0.641458: sched_switch: prev_comm=kworker/1:0 prev_pid=20 prev_prio=120 prev_state=D ==> next_comm=swapper/1 next_pid=0 next_prio=120

    kworker/u8:1-125     [002] d..2     0.641476: signal_generate: sig=17 errno=0 code=1 comm=kworker/u8:1 pid=76 grp=1 res=1

    kworker/u8:1-125     [002] d..2     0.641482: sched_switch: prev_comm=kworker/u8:1 prev_pid=125 prev_prio=120 prev_state=Z ==> next_comm=swapper/2 next_pid=0 next_prio=120

          <idle>-0       [003] d..2     0.641483: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

    kworker/u8:1-76      [003] d..2     0.641492: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=I ==> next_comm=swapper/3 next_pid=0 next_prio=120

          <idle>-0       [002] d..2     0.641494: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=swapper/0 next_pid=1 next_prio=120

            init-1       [002] d..2     0.641502: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120

          <idle>-0       [003] d..2     0.641504: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

    kworker/u8:1-76      [003] d..2     0.641520: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120

          <idle>-0       [002] d..2     0.641521: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=126 next_prio=120

    kworker/u8:1-126     [002] d..2     0.641543: signal_generate: sig=17 errno=0 code=1 comm=kworker/u8:1 pid=76 grp=1 res=1

    kworker/u8:1-126     [002] d..2     0.641548: sched_switch: prev_comm=kworker/u8:1 prev_pid=126 prev_prio=120 prev_state=Z ==> next_comm=swapper/2 next_pid=0 next_prio=120

          <idle>-0       [003] d..2     0.641549: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u8:1 next_pid=76 next_prio=120

    kworker/u8:1-76      [003] d..2     0.641555: sched_switch: prev_comm=kworker/u8:1 prev_pid=76 prev_prio=120 prev_state=I ==> next_comm=swapper/3 next_pid=0 next_prio=120

          <idle>-0       [002] d..2     0.641557: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=swapper/0 next_pid=1 next_prio=120

            init-1       [002] d..2     0.641565: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120

          <idle>-0       [001] d..2     0.641586: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kthreadd next_pid=2 next_prio=120

        kthreadd-2       [001] d..2     0.641612: sched_switch: prev_comm=kthreadd prev_pid=2 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120

          <idle>-0       [002] d..2     0.641613: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kthreadd next_pid=127 next_prio=120

 cryptomgr_probe-127     [002] d..2     0.641619: sched_switch: prev_comm=kthreadd prev_pid=127 prev_prio=120 prev_state=D ==> next_comm=swapper/2 next_pid=0 next_prio=120

          <idle>-0       [003] d..2     0.641620: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=swapper/0 next_pid=1 next_prio=120

            init-1       [003] d..2     0.641628: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=swapper/3 next_pid=0 next_prio=120

          <idle>-0       [002] d..2     0.641629: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=cryptomgr_probe next_pid=127 next_prio=120

 cryptomgr_probe-127     [002] ....     0.641630: cryptomgr_probe <-kthread

...

            init-1       [001] ....     0.642319: driver_deferred_probe_trigger <-deferred_probe_initcall

            init-1       [001] d..2     0.642321: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=kworker/1:4 next_pid=109 next_prio=120

     kworker/1:4-109     [001] ....     0.642321: deferred_probe_work_func <-process_one_work

     kworker/1:4-109     [001] d..2     0.642323: sched_switch: prev_comm=kworker/1:4 prev_pid=109 prev_prio=120 prev_state=R+ ==> next_comm=swapper/0 next_pid=1 next_prio=120

            init-1       [001] d..1     0.642327: console: [    0.640227] PM:   Magic number: 10:467:470

          <idle>-0       [002] d.h3     0.642461: console: [    0.640361] atkbd serio0: Unknown key released (translated set 2, code 0x7c on isa0060/serio0).

          <idle>-0       [002] d.h3     0.642464: console: [    0.640365] atkbd serio0: Use 'setkeycodes 7c <keycode>' to make it known.

            init-1       [001] d..1     0.642535: console: [    0.640435] ALSA device list:

            init-1       [001] d..1     0.642539: console: [    0.640440]   No soundcards found.

            init-1       [001] d..1     0.642558: console: [    0.640459] Warning: unable to open an initial console. Fallback to ttynull.

            init-1       [001] d..1     0.642563: console: [    0.640464] printk: console [ttynull0] enabled

            init-1       [001] d..2     0.642587: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D ==> next_comm=kworker/1:4 next_pid=109 next_prio=120

     kworker/1:4-109     [001] d..2     0.642590: sched_switch: prev_comm=kworker/1:4 prev_pid=109 prev_prio=120 prev_state=I ==> next_comm=swapper/1 next_pid=0 next_prio=120

          <idle>-0       [002] d..2     0.642630: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=irq/39-mmc0 next_pid=105 next_prio=49

          <idle>-0       [001] d..2     0.642670: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/1:0 next_pid=20 next_prio=120