[리눅스커널] ftrace: 콜 스택을 메시지로 출력하기(CALLER_ADDR0~CALLER_ADDR3)

Overview

 

ftrace로 다양한 디버깅 정보를 출력할 수 있다.

물론 function, function_graph 트레이서를 활용해 화려한 디버깅 정보를 볼 수 있는데, nop 트레이서로 다음과 같은 정보를 보면 유용할 것이다.

 

rcu_preempt-9     [000] ...1  5429.091523: sched_preemption_execute: delta=8890468(ns) Callers: (schedule<-rcu_nocb_kthread<-kthread<-ret_from_fork)

 

ftrace에서 sched_preemption_trigger 이벤트를 추가하는 방법에 대해서 알아보자.

 

 

추가할 ftrace 이벤트의 스팩은 다음과 같다.

 

   ■ 이름: sched_preemption_execute

   ■ 디버깅 정보

      - delta: 실행 시간

      - 콜스택

 

ftrace 이벤트 정의하기

 

sched_preemption_execute 이벤트를 아래와 같이 정의하자. (참고로 아래 패치 코드는 라즈베리 파이에서 추가했다.)

 

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h

index 9a4bdfa..e192f5b 100644

--- a/include/trace/events/sched.h

+++ b/include/trace/events/sched.h

@@ -587,6 +587,35 @@ TRACE_EVENT(sched_wake_idle_without_ipi,

 

        TP_printk("cpu=%d", __entry->cpu)

 );

+TRACE_EVENT(sched_preemption_execute,

+

+       TP_PROTO(u64 delta,

+                       unsigned long caller_addr0, unsigned long caller_addr1,

+                       unsigned long caller_addr2, unsigned long caller_addr3),

+

+       TP_ARGS(delta, caller_addr0, caller_addr1, caller_addr2, caller_addr3),

+

+       TP_STRUCT__entry(

+               __field(u64, delta)

+               __field(void*, caller_addr0)

+               __field(void*, caller_addr1)

+               __field(void*, caller_addr2)

+               __field(void*, caller_addr3)

+       ),

+

+       TP_fast_assign(

+               __entry->delta = delta;

+               __entry->caller_addr0 = (void *)caller_addr0;

+               __entry->caller_addr1 = (void *)caller_addr1;

+               __entry->caller_addr2 = (void *)caller_addr2;

+               __entry->caller_addr3 = (void *)caller_addr3;

+       ),

+

+       TP_printk("delta=%llu(ns) Callers:(%ps<-%ps<-%ps<-%ps)",

+                               __entry->delta,

+                               __entry->caller_addr0, __entry->caller_addr1,

+                               __entry->caller_addr2, __entry->caller_addr3)

+);

 #endif /* _TRACE_SCHED_H */

 

 /* This part must be outside protection */

 

위 코드에서 핵심은 다음 코드이다.

 

+       TP_printk("delta=%llu(ns) Callers:(%ps<-%ps<-%ps<-%ps)",

+                               __entry->delta,

+                               __entry->caller_addr0, __entry->caller_addr1,

+                               __entry->caller_addr2, __entry->caller_addr3)

 

함수의 시각과 콜스택의 심보를 출력한다.

 

 

ftrace 이벤트를 출력하는 코드

 

ftrace 이벤트를 출력하는 패치 코드는 아래와 같다. __schedule() 함수이다.

 

diff --git a/kernel/sched/core.c b/kernel/sched/core.c

index 2befd2c..2b0e6f7 100644

--- a/kernel/sched/core.c

+++ b/kernel/sched/core.c

@@ -3429,6 +3429,7 @@ static void __sched notrace __schedule(bool preempt)

        struct rq_flags rf;

        struct rq *rq;

        int cpu;

+       u64 delta = 0;

 

        cpu = smp_processor_id();

        rq = cpu_rq(cpu);

@@ -3490,6 +3491,10 @@ static void __sched notrace __schedule(bool preempt)

        clear_tsk_need_resched(prev);

        clear_preempt_need_resched();

 

+       delta = sched_clock();

+       trace_sched_preemption_execute(delta, CALLER_ADDR0, CALLER_ADDR1,

+                               CALLER_ADDR2, CALLER_ADDR3);

+

        if (likely(prev != next)) {

                rq->nr_switches++;

                rq->curr = next;

 

위 패치에서 핵심 코드 조각은 아래와 같다.

 

+       trace_sched_preemption_execute(delta, CALLER_ADDR0, CALLER_ADDR1,

+                               CALLER_ADDR2, CALLER_ADDR3);

 

함수가 실행되는 시간과 함수의 콜 스택을 출력하는 기능이다.

 

CALLER_ADDR0~CALLER_ADDR3의 정체

 

이번에 소개한 패치 코드에서 CALLER_ADDR0~CALLER_ADDR3 매크로가 핵심이다.

CALLER_ADDR0~CALLER_ADDR3 매크로의 정체를 확인하기 위해 전처리 코드를 열어보자.

 

kernel/sched/.tmp_core.i

..

 delta = sched_clock();

 trace_sched_preemption_execute(delta, ((unsigned long)__builtin_return_address(0)), ((unsigned long)return_address(1)),

    ((unsigned long)return_address(2)), ((unsigned long)return_address(3)));

 

코드를 통해 CALLER_ADDR0~CALLER_ADDR3 매크로의 정체는 return_address(n) 함수라는 사실을 알 수 있다.

 

   ■ CALLER_ADDR1 = ((unsigned long)return_address(1)

   ■ CALLER_ADDR2 = ((unsigned long)return_address(2)

   ■ CALLER_ADDR3 = ((unsigned long)return_address(3)

 

 

sched_preemption_execute 이벤트의 출력 결과

 

위 패치 코드를 반영한 후 출력되는 결과는 아래와 같다.

 

rcu_preempt-9     [000] ...1  5429.091523: sched_preemption_execute: delta=8890468(ns) Callers: (schedule<-rcu_nocb_kthread<-kthread<-ret_from_fork)

 

ftrace 메시지로 콜 스택을 바로 확인할 수 있다.

 

헤더 파일

 

이 패치를 적용하기 위해서 다음 목록과 같은 헤더 파일을 추가해야 한다.

 

   ■ #include <trace/events/sched.h>

   ■ #include <linux/ftrace.h>

   ■ #include <linux/sched/clock.h>

 

샘플 패치 코드를 보자. fs/proc/interrupts.c에 있는 int_seq_start() 함수를 수정했다.

 

diff --git a/fs/proc/interrupts.c b/fs/proc/interrupts.c

index cb0edc7..a4bbc19 100644

--- a/fs/proc/interrupts.c

+++ b/fs/proc/interrupts.c

@@ -5,12 +5,23 @@

 #include <linux/irqnr.h>

 #include <linux/proc_fs.h>

 #include <linux/seq_file.h>

-

+#include <trace/events/sched.h>

+#include <linux/ftrace.h>

+#include <linux/sched/clock.h>

 /*

  * /proc/interrupts

  */

 static void *int_seq_start(struct seq_file *f, loff_t *pos)

 {

+       u64 delta = 0;

+

+       delta = sched_clock();

+       trace_sched_preemption_execute(delta, CALLER_ADDR0, CALLER_ADDR1,

+                               CALLER_ADDR2, CALLER_ADDR3);

+

+       printk("delta=%llu(ns) Callers:(%ps<-%ps<-%ps<-%ps)",

+                       delta, CALLER_ADDR0, CALLER_ADDR1, CALLER_ADDR2, CALLER_ADDR3);

+

        return (*pos <= nr_irqs) ? pos : NULL;

 }

 

이 코드를 참고하면 다양한 방식으로 디버깅할 수 있다.

 

# Reference: For more information on 'Linux Kernel';

 

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1

http://www.yes24.com/Product/Goods/90085976

 

디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2

http://www.yes24.com/Product/Goods/90087307