Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

0112
737
82110


[Linux] ftrace 사용방법: function/function_graph tracer [Kernel] Debug Feature

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, &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() {
 %

Reference(프로세스 관리)
4.9 프로세스 컨택스트 정보는 어떻게 저장할까?
 4.9.1 컨택스트 소개
 4.9.2 인터럽트 컨택스트 정보 확인하기
 4.9.3 Soft IRQ 컨택스트 정보 확인하기
 4.9.4 선점 스케줄링 여부 정보 저장
4.10 프로세스 디스크립터 접근 매크로 함수
 4.10.1 current_thread_info()
 4.10.2 current 매크로란
4.11 프로세스 디버깅
 4.11.1 glibc fork 함수 gdb 디버깅
 4.11.2 유저 프로그램 실행 추적 

덧글

댓글 입력 영역