Gomdol Kim

rousalome.egloos.com

포토로그



[Linux][ftrace]function/function_graph tracer 리눅스 커널

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 msm_cpu_pm_enter_sleep 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, &param);
 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() {
 6)               |        smp_cross_call_common() {
 6)               |          gic_raise_softirq() {
 6)               |            _raw_spin_lock_irqsave() {
 6)   0.312 us    |              preempt_count_add();
 6)   0.416 us    |              do_raw_spin_lock();
 6)   7.396 us    |            }
 6)               |            _raw_spin_unlock_irqrestore() {
 6)   0.417 us    |              do_raw_spin_unlock();
 6)   0.365 us    |              preempt_count_sub();
 6)   7.031 us    |            }
 6) + 21.511 us   |          }
 6) + 25.104 us   |        }
 6) + 28.333 us   |      }
 6) ! 155.730 us  |    }
 6)   0.364 us    |    preempt_count_sub();
 6) ! 167.032 us  |  } 

덧글

댓글 입력 영역