config 설정
아래와 같이 CONFIG를 설정하면 function/functin_graph Trace가 enable됩니다.
diff --git a/arch/arm/configs/pompeii_com_defconfig b/arch/arm/configs/pompeii_com_defconfig
index cb0ff09..e76a947 100644
--- a/arch/arm/configs/pompeii_com_defconfig
+++ b/arch/arm/configs/pompeii_com_defconfig
@@ -772,6 +770,9 @@ CONFIG_FREE_PAGES_RDONLY=y
CONFIG_DEBUG_SET_MODULE_RONX=y
CONFIG_SECURITY=y
CONFIG_SECURITY_NETWORK=y
+CONFIG_DYNAMIC_FTRACE=y
+CONFIG_FUNCTION_TRACER=y
+CONFIG_FUNCTION_GRAPH_TRACER=y
CONFIG_LSM_MMAP_MIN_ADDR=4096
CONFIG_SECURITY_SELINUX=y
CONFIG_CRYPTO_NULL=y
아래와 같이 설정하면 function tracer가 enable됩니다.
adb shell "echo > d/tracing/set_event"
adb shell "sleep 1"
adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"
adb shell "echo function > d/tracing/current_tracer"
: adb shell "echo function_graph > d/tracing/current_tracer"
adb shell "sleep 1"
: Do not trace trash logs
:adb shell "echo msm_* > d/tracing/set_ftrace_notrace"
adb shell "sleep 1"
adb shell "echo __fd_install smpboot_thread_fn process_one_work > d/tracing/set_ftrace_filter"
adb shell "sleep 1"
adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1"
function tracer를 키고 받은 ftrace log는 아래와 같은데, caller 함수를 확인할 수 있습니다.
top-7786 [000] ...1 961.518100: __fd_install <-fd_install
top-7786 [000] ...1 961.518416: __fd_install <-fd_install
kworker/u16:4-341 [005] d..2 961.518468: process_one_work <-worker_thread
kworker/u16:4-341 [005] d..2 961.518513: process_one_work <-worker_thread
top-7786 [000] ...1 961.518646: __fd_install <-fd_install
kworker/5:2-2599 [005] d..2 961.518785: process_one_work <-worker_thread
top-7786 [000] ...1 961.518875: __fd_install <-fd_install
top-7786 [000] ...1 961.519139: __fd_install <-fd_install
top-7786 [000] ...1 961.519379: __fd_install <-fd_install
top-7786 [000] ...1 961.519637: __fd_install <-fd_install
Function Graph Trace는 아래와 같이 설정할 수 있습니다. 한 가지 주의할 점은 set_ftrace_filter을 설정하지 않으면, 많은 로깅으로 와치독 리셋이 발생한다는 것입니다.
adb shell "echo > d/tracing/set_event"
adb shell "sleep 1"
adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"
adb shell "echo function_graph > d/tracing/current_tracer"
adb shell "sleep 1"
: Do not trace trash logs
:adb shell "echo msm_* > d/tracing/set_ftrace_notrace"
adb shell "sleep 1"
adb shell "echo __fd_install smpboot_thread_fn process_one_work > d/tracing/set_ftrace_filter"
adb shell "sleep 1"
adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1"
샘플 Ftrace log
4) + 11.406 us | process_one_work();
------------------------------------------
4) kworker-7886 => pompeii_irq-8041
------------------------------------------
4) 1.198 us | __fd_install();
4) 0.885 us | __fd_install();
4) 1.094 us | __fd_install();
4) 0.886 us | __fd_install();
4) 0.937 us | __fd_install();
4) 0.990 us | __fd_install();
4) 0.938 us | __fd_install();
4) 4.375 us | __fd_install();
4) 0.938 us | __fd_install();
4) 0.833 us | __fd_install();
4) 0.781 us | __fd_install();
4) 0.782 us | __fd_install();
4) 0.781 us | __fd_install();
------------------------------------------
5) kworker-2599 => kworker-341
------------------------------------------
5) ! 884.322 us | process_one_work();
4) 0.990 us | __fd_install();
4) 0.729 us | __fd_install();
5) + 43.229 us | process_one_work();
5) ! 189.166 us | process_one_work();
------------------------------------------
5) kworker-341 => kworker-2599
------------------------------------------
5) + 10.156 us | process_one_work();
4) 0.834 us | __fd_install();
4) 0.729 us | __fd_install();
4) 0.833 us | __fd_install();
4) 0.781 us | __fd_install();
4) 0.625 us | __fd_install();
4) 0.886 us | __fd_install();
4) 0.781 us | __fd_install();
4) 0.625 us | __fd_install();
4) 0.729 us | __fd_install();
------------------------------------------
4) msm_irq-8041 => logd.wr-436
------------------------------------------
4) 1.406 us | __fd_install();
4) 0.729 us | __fd_install();
4) 0.729 us | __fd_install();
4) 0.730 us | __fd_install();
------------------------------------------
multi_cpu_stop를 function_graph filter로 설정하면 아래와 같은 로그를 확인할 수 있습니다.
2) ! 1474.479 us | multi_cpu_stop();
4) ! 1459.688 us | multi_cpu_stop();
5) ! 1460.105 us | multi_cpu_stop();
6) ! 1446.406 us | multi_cpu_stop();
7) ! 1442.136 us | multi_cpu_stop();
5) ! 2408.698 us | multi_cpu_stop();
4) ! 2408.698 us | multi_cpu_stop();
6) ! 2405.000 us | multi_cpu_stop();
7) ! 2401.354 us | multi_cpu_stop();
2) ! 2100.209 us | multi_cpu_stop();
아래와 같은 필터를 설정하면
adb shell "echo psci_enter_sleep cluster_prepare > d/tracing/set_ftrace_filter"
ftrace log 확보가 아래와 같이 가능합니다. power collapse 문제로 재현이 잘되는 디바이스를 확보하면 한번 테스트 해보아야 겠습니다.
0) + 11.198 us | psci_enter_sleep();
3) 0.781 us | cluster_prepare();
0) | cluster_prepare() {
3) + 21.875 us | psci_enter_sleep();
0) | cluster_prepare() {
0) 0.364 us | cluster_prepare();
0) 7.292 us | }
0) + 14.688 us | }
0) + 11.094 us | psci_enter_sleep();
3) 0.782 us | cluster_prepare();
0) | cluster_prepare() {
3) + 22.031 us | psci_enter_sleep();
0) | cluster_prepare() {
0) 0.365 us | cluster_prepare();
0) 7.344 us | }
0) + 14.791 us | }
0) + 11.198 us | psci_enter_sleep();
3) 0.834 us | cluster_prepare();
0) | cluster_prepare() {
function_graph tracer는 설정 방법이 약간 다릅니다.
가장 많이 호출되는 함수 __fd_install와 scm_call2를 아래와 같이 설정 해보겠습니다.
adb shell "echo > d/tracing/set_event"
adb shell "sleep 1"
adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"
adb shell "echo function_graph > d/tracing/current_tracer"
adb shell "sleep 1"
adb shell "echo > d/tracing/set_ftrace_filter"
adb shell "sleep 1"
adb shell "echo __fd_install scm_call2 > d/tracing/set_graph_function"
adb shell "sleep 1"
adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1"
ftrace를 열어서 보면 scm_call2() 함수가 수행되는데에 23.229 us시간이 걸렸음을 알 수 있습니다.
------------------------------------------
7) Thread--2524 => kworker-1553
------------------------------------------
7) | scm_call2() {
7) 0.260 us | is_scm_armv8();
7) | allocate_extra_arg_buffer.part.3() {
7) | kmem_cache_alloc_trace() {
7) 0.312 us | __might_sleep();
7) 0.365 us | preempt_count_add();
7) 0.260 us | preempt_count_sub();
7) | __slab_alloc.constprop.8() {
7) | get_partial_node() {
7) | _raw_spin_lock() {
7) 0.313 us | preempt_count_add();
7) 0.312 us | do_raw_spin_lock();
7) 5.990 us | }
7) 0.312 us | preempt_count_add();
7) 0.312 us | preempt_count_sub();
7) | _raw_spin_unlock() {
7) 0.364 us | do_raw_spin_unlock();
7) 0.261 us | preempt_count_sub();
7) 5.937 us | }
7) + 23.646 us | }
또 다른 흥미로운 점은 함수 콜 도중에 IRQ가 Fire되었을 때 화살표를 찍어줍니다.
7) | _raw_spin_lock() {
7) 0.365 us | preempt_count_add();
7) 0.312 us | do_raw_spin_lock();
7) 5.937 us | }
7) 0.260 us | preempt_count_add();
7) 0.313 us | preempt_count_sub();
7) | _raw_spin_unlock() {
7) 0.313 us | do_raw_spin_unlock();
7) 0.261 us | preempt_count_sub();
7) 5.937 us | }
7) + 57.187 us | }
7) ==========> |
7) | gic_handle_irq() {
7) | handle_IPI() {
7) 0.521 us | scheduler_ipi();
7) 4.219 us | }
7) 9.322 us | }
7) <========== |
7) | preempt_schedule_irq() {
7) | __schedule() {
7) 0.261 us | preempt_count_add();
7) | rcu_note_context_switch() {
__fd_install() 함수는 17.136 us 시간이 걸렸군요.
3) | __fd_install() {
3) | _raw_spin_lock() {
3) 0.365 us | preempt_count_add();
3) 0.364 us | do_raw_spin_lock();
3) 5.937 us | }
3) | _raw_spin_unlock() {
3) 0.312 us | do_raw_spin_unlock();
3) 0.313 us | preempt_count_sub();
3) 5.730 us | }
3) + 17.136 us | }
그럼 이제 __fd_install() 함수가 수행되는 시간을 Tracing해보겠습니다.
참고로, __fd_install() 함수는 시스템 콜을 통해 file descriptor를 설정하는 중요한 커널 API입니다.
adb shell "echo __fd_install > d/tracing/set_ftrace_filter"
adb shell "sleep 1"
adb shell "echo __fd_install > d/tracing/set_graph_function"
adb shell "sleep 1"
아래와 같이 __fd_install() 함수가 수행된 시간을 확인할 수 있습니다.
------------------------------------------
5) gbmd-822 => pompeii_irq-10671
------------------------------------------
5) 1.458 us | __fd_install();
5) 1.146 us | __fd_install();
5) 1.041 us | __fd_install();
5) 0.989 us | __fd_install();
5) 0.885 us | __fd_install();
5) 1.041 us | __fd_install();
5) 1.407 us | __fd_install();
5) 0.990 us | __fd_install();
5) 1.145 us | __fd_install();
5) 0.886 us | __fd_install();
5) 0.834 us | __fd_install();
5) 0.886 us | __fd_install();
5) 0.782 us | __fd_install();
5) 0.834 us | __fd_install();
5) 0.885 us | __fd_install();
5) 0.833 us | __fd_install();
5) 0.885 us | __fd_install();
scm_call2() 함수를 둘다 d/tracing/set_ftrace_filter d/tracing/set_graph_function 필터로 지정하면 아래와
같은 시간을 확인할 수 있습니다.
6) + 48.854 us | scm_call2();
6) + 47.136 us | scm_call2();
4) + 48.489 us | scm_call2();
4) + 47.292 us | scm_call2();
4) + 48.177 us | scm_call2();
4) + 46.771 us | scm_call2();
5) + 47.708 us | scm_call2();
5) + 47.239 us | scm_call2();
function/function_graph tracer의 강력한 기능 중의 하나는 ftrace event와 같이 로그를 볼 수 있다는 점입니다.
그럼 하나의 예제로 watchdog kick이 수행될 때의 동작을 점검해보겠습니다.
watchdog_kthread() 함수에서 watchdog kick을 하는 함수는 pet_watchdog() 인데,
ping_other_cpus() 함수 콜을 수행합니다.
static __ref int watchdog_kthread(void *arg)
{
struct pompeii_watchdog_data *wdog_dd =
(struct pompeii_watchdog_data *)arg;
unsigned long delay_time = 0;
struct sched_param param = {.sched_priority = MAX_RT_PRIO-1};
sched_setscheduler(current, SCHED_FIFO, ¶m);
while (!kthread_should_stop()) {
while (wait_for_completion_interruptible(
&wdog_dd->pet_complete) != 0)
;
reinit_completion(&wdog_dd->pet_complete);
if (enable) {
delay_time = msecs_to_jiffies(wdog_dd->pet_time);
if (wdog_dd->do_ipi_ping)
ping_other_cpus(wdog_dd); // <<--
pet_watchdog(wdog_dd);
static void ping_other_cpus(struct msm_watchdog_data *wdog_dd)
{
int cpu;
cpumask_clear(&wdog_dd->alive_mask);
smp_mb();
for_each_cpu(cpu, cpu_online_mask) {
if (!cpu_idle_pc_state[cpu])
smp_call_function_single(cpu, keep_alive_response, // <<--
wdog_dd, 1);
}
}
아래와 같이 설정하겠습니다.
adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"
adb shell "echo > d/tracing/set_event"
adb shell "sleep 1"
adb shell "echo 1 > d/tracing/events/sched/sched_switch/enable"
adb shell "sleep 1"
adb shell "echo function > d/tracing/current_tracer"
adb shell "sleep 1"
: Do not trace trash logs
:adb shell "echo msm_* > d/tracing/set_ftrace_notrace"
adb shell "sleep 1"
adb shell "echo smp_call_function_single > d/tracing/set_ftrace_filter"
adb shell "sleep 1"
adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1"
2분 동안 타겟을 구동시킨 다음에 ftrace log를 받아 msm_watchdog 스트링으로 검색하면 아래와 같은 ftrace log 확인이 가능합니다.
100% 재현되는 watchdog reset 이슈가 있으면 유용하게 디버깅할 수 있습니다.
<...>-334 [007] d..3 6904.620469: sched_switch: prev_comm=cfinteractive prev_pid=334 prev_prio=0 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120
<idle>-0 [006] d..3 6904.640143: sched_switch: prev_comm=swapper/6 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=msm_watchdog next_pid=66 next_prio=0
msm_watchdog-66 [006] ...1 6904.640151: smp_call_function_single <-watchdog_kthread "//<<--"
msm_watchdog-66 [006] ...1 6904.640160: smp_call_function_single <-watchdog_kthread "//<<--"
msm_watchdog-66 [006] ...1 6904.640169: smp_call_function_single <-watchdog_kthread "//<<--"
msm_watchdog-66 [006] ...1 6904.640178: smp_call_function_single <-watchdog_kthread "//<<--"
msm_watchdog-66 [006] ...1 6904.640187: smp_call_function_single <-watchdog_kthread "//<<--"
msm_watchdog-66 [006] ...1 6904.640189: smp_call_function_single <-watchdog_kthread "//<<--"
msm_watchdog-66 [006] d..3 6904.640250: sched_switch: prev_comm=msm_watchdog prev_pid=66 prev_prio=0 prev_state=S ==> next_comm=kworker/u16:2 next_pid=10199 next_prio=120
<...>-10199 [006] d..3 6904.640387: sched_switch: prev_comm=kworker/u16:2 prev_pid=10199 prev_prio=120 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120
smp_call_function_single() 함수 콜 내부 동작을 좀 더 확인하고 싶으면, 아래와 같이 설정하면 됩니다.
adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"
adb shell "echo > d/tracing/set_event"
adb shell "sleep 1"
adb shell "echo 1 > d/tracing/events/sched/sched_switch/enable"
adb shell "sleep 1"
adb shell "echo function > d/tracing/current_tracer"
adb shell "sleep 1"
: Do not trace trash logs
:adb shell "echo msm_* > d/tracing/set_ftrace_notrace"
adb shell "sleep 1"
adb shell "echo smp_call_function_single > d/tracing/set_ftrace_filter"
adb shell "sleep 1"
adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1"
아래 로그를 해석해보겠습니다.
6) | /* sched_switch: prev_comm=swapper/6 prev_pid=0 prev_prio=120 prev_state=R+ ==> next_comm=msm_watchdog next_pid=66 next_prio=0 */
------------------------------------------
6) <idle>-0 => msm_wat-66
------------------------------------------
6) | smp_call_function_single() {
6) 0.469 us | preempt_count_add();
6) | generic_exec_single() {
6) | arch_send_call_function_single_ipi() {
6) | smp_cross_call_common() {
6) | gic_raise_softirq() {
6) | _raw_spin_lock_irqsave() {
6) 0.365 us | preempt_count_add();
6) 0.468 us | do_raw_spin_lock();
6) 8.437 us | }
6) | _raw_spin_unlock_irqrestore() {
6) 0.416 us | do_raw_spin_unlock();
6) 0.365 us | preempt_count_sub();
6) 7.083 us | }
6) + 23.021 us | }
6) + 26.719 us | }
6) + 30.000 us | }
6) + 34.375 us | }
6) 0.364 us | preempt_count_sub();
6) + 47.396 us | } // <<-- smp_call_function_single() 수행된 시간입니다.
6) | smp_call_function_single() {
6) 0.521 us | preempt_count_add();
6) | generic_exec_single() {
6) | arch_send_call_function_single_ipi() {
6) | smp_cross_call_common() {
6) | gic_raise_softirq() {
6) | _raw_spin_lock_irqsave() {
6) 0.313 us | preempt_count_add();
6) 0.417 us | do_raw_spin_lock();
6) 7.240 us | }
6) | _raw_spin_unlock_irqrestore() {
6) 0.417 us | do_raw_spin_unlock();
6) 0.365 us | preempt_count_sub();
6) 7.083 us | }
6) + 21.250 us | }
6) + 24.948 us | }
6) + 28.229 us | }
6) ! 148.229 us | }
6) 0.312 us | preempt_count_sub();
6) ! 160.469 us | } // <<-- smp_call_function_single() 수행된 시간인데 느낌표가 있는 이유는 smp_call_function_single() 함수가 수행된 시간이 100.us 시간을 넘었기 때문입니다.
6) | smp_call_function_single() {
6) 0.416 us | preempt_count_add();
6) | generic_exec_single() {
6) | arch_send_call_function_single_ipi() {
6) | smp_cross_call_common() {
6) | gic_raise_softirq() {
6) | _raw_spin_lock_irqsave() {
6) 0.365 us | preempt_count_add();
6) 0.365 us | do_raw_spin_lock();
6) 6.927 us | }
6) | _raw_spin_unlock_irqrestore() {
6) 0.417 us | do_raw_spin_unlock();
6) 0.312 us | preempt_count_sub();
6) 6.979 us | }
6) + 20.937 us | }
6) + 24.322 us | }
6) + 27.500 us | }
6) ! 163.802 us | }
6) 0.365 us | preempt_count_sub();
6) ! 174.739 us | }
6) | smp_call_function_single() {
6) 0.469 us | preempt_count_add();
6) | generic_exec_single() {
6) | arch_send_call_function_single_ipi() {
6) | smp_cross_call_common() {
6) | gic_raise_softirq() {
6) | _raw_spin_lock_irqsave() {
6) 0.365 us | preempt_count_add();
6) 0.417 us | do_raw_spin_lock();
6) 6.979 us | }
6) | _raw_spin_unlock_irqrestore() {
6) 0.417 us | do_raw_spin_unlock();
6) 0.312 us | preempt_count_sub();
6) 6.979 us | }
6) + 21.094 us | }
6) + 24.479 us | }
6) + 27.709 us | }
6) ! 155.104 us | }
6) 0.417 us | preempt_count_sub();
6) ! 166.250 us | }
6) | smp_call_function_single() {
6) 0.469 us | preempt_count_add();
6) | generic_exec_single() {
6) 0.521 us | keep_alive_response();
6) 4.218 us | }
6) 0.365 us | preempt_count_sub();
6) + 14.687 us | }
6) | smp_call_function_single() {
6) 0.416 us | preempt_count_add();
6) | generic_exec_single() {
6) | arch_send_call_function_single_ipi() {
%
"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.
그리고 혹시 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려드리겠습니다!"
* 유튜브 강의 동영상도 있으니 같이 들으시면 더 많은 걸 배울 수 있습니다.
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글