리눅스 커널 디버깅 기능의 핵심 ftrace에 대해서 여러 번 소개했는데요.
한 가지 재미있는 패치를 소개하려고 해요.
ftrace 로깅을 하기 위해서는 아래와 같은 방식으로 시스 노드에 있는 파라미터를 설정해야 해요.
"echo 0 > /d/tracing/events/enable"
"echo 1 > /d/tracing/events/sched/sched_switch/enable"
"echo 1 > /d/tracing/events/power/wakeup_source_activate/enable"
"echo 1 > /d/tracing/events/power/wakeup_source_deactivate/enable"
"echo 1 > /d/tracing/events/irq/irq_handler_entry/enable"
" echo 1 > /d/tracing/tracing_on"
그런데 가끔 부팅 초반에 ftrace log를 보면서 디버깅을 해야 할 때가 있어요.
예를 들면 부팅 초반부터 시작되는 락업, 커널 크래시이런 짜증나는 이슈죠.
문제가 발생하는 시점이 그냥 초반이 아니라 부팅의 시작점인 경우도 있죠.
이런 상황에서는 shell이 붙기 전이라 "echo 1 > /d/tracing/events/sched/sched_switch/enable" 명령어를 칠 수는 없는 상태이잖아요?
이럴 때 아래 패치를 적용하면, 부팅 초반부터 ftrace log를 잡을 수 있습니다.
trace_set_clr_event() 함수로 혹시 추가로 필요한 ftrace event가 있으면 설정하면 되는데요.
아래 패치에서는 sched_switch/irq_handler_entry/workqueue_execute_start/workqueue_execute_end event만 추가했어요.
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 7f879c8..92b93f0 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -2491,7 +2491,46 @@
init_ftrace_syscalls();
event_trace_enable();
}
+static void ftrace_events_enable(int enable)
+{
+ if (enable) {
+ trace_set_clr_event(NULL, "sched_switch", 1);
+ trace_set_clr_event(NULL, "irq_handler_entry", 1);
+ trace_set_clr_event(NULL, "workqueue_execute_start", 1);
+ trace_set_clr_event(NULL, "workqueue_execute_end", 1);
+ } else {
+ tracing_off();
+ trace_set_clr_event(NULL, NULL, 0);
+ }
+}
+static __init int trace_enable_ftrace_boot(void)
+{
+ struct trace_array *tr;
+ int ret = 0;
+
+ tr = top_trace_array();
+ if (!tr) {
+ pr_err("%s: Invalid tr from top_trace_array \n", __func__);
+ return -ENODEV;
+ }
+
+ ret = tracing_update_buffers();
+ if (ret != 0) {
+ pr_err("%s: invalid buffer ret=%d\n", __func__, ret);
+ return -ENODEV;
+ }
+
+ ftrace_events_enable(1);
+ set_tracer_flag(tr, TRACE_ITER_OVERWRITE, 0);
+
+ tracing_on();
+
+ return 0;
+}
+
+late_initcall(trace_enable_ftrace_boot);
fs_initcall(event_trace_init);
#ifdef CONFIG_FTRACE_STARTUP_TEST
위 패치를 적용하고 ftrace log를 받아보면, 1.009365초부터 ftrace log를 볼 수 있네요.
ftrace driver가 초기화된 후 바로 ftrace log를 찍고 있어요.
<idle>-0 [004] 1.009365: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcuos/0 next_pid=11 next_prio=120
<idle>-0 [005] 1.009399: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_sched next_pid=8 next_prio=120
rcuos/0-11 [004] 1.009402: sched_switch: prev_comm=rcuos/0 prev_pid=11 prev_prio=120 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120
rcu_sched-8 [005] 1.009413: sched_switch: prev_comm=rcu_sched prev_pid=8 prev_prio=120 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
<idle>-0 [007] 1.009736: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=hwrng next_pid=193 next_prio=120
hwrng-193 [007] 1.009748: sched_switch: prev_comm=hwrng prev_pid=193 prev_prio=120 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120
<idle>-0 [007] 1.009761: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=hwrng next_pid=193 next_prio=120
hwrng-193 [007] 1.009768: sched_switch: prev_comm=hwrng prev_pid=193 prev_prio=120 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120
<idle>-0 [006] 1.009802: sched_switch: prev_comm=swapper/6 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u16:5 next_pid=348 next_prio=120
init-1 [000] 1.009804: sched_switch: prev_comm=swapper/0 prev_pid=1 prev_prio=120 prev_state=D|K ==> next_comm=swapper/0 next_pid=0 next_prio=120
kworker/u16:5-348 [006] 1.009806: workqueue_execute_start: work struct 0xec0d7f40: function __call_usermodehelper
위 패치에서 중요한 점은 late_initcall을 써서 trace_enable_ftrace_boot() 함수 콜이 이루어져야 한다는 거에요.
왜냐며 ftrace driver가 올라온 다음에 위 함수가 호출되야 하기 때문에, core_initcall(), early_initcall()으로 초기화를 하면 안돼요.
#Reference 시스템 콜
Reference(프로세스)
Reference(워크큐)
워크큐(Workqueue) Overview
최근 덧글