<version: ES1>
Overview
이번 포스트에서는 커널 v5.10에 반영된 boottime-trace를 소개합니다. 관련 문서는 아래 링크에서 확인할 수 있습니다.
강의 동영상 링크는 다음과 같습니다.
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