ftrace란?

Ftrace란?

ftrace는 리눅스 커널에서 제공하는 가장 강력한 트레이서이다. 트레이서의 특징은 다음과 같다.

• 인터럽트, 스케줄링, 커널 타이머 등의 커널 동작을 상세히 추적한다.
• 함수 필터를 지정하면 지정한 함수를 호출한 함수와 전체 콜 스택까지 출력한다. 물론 코드 수정이 없다.
• 함수를 어느 프로세스가 실행하는 지 알 수 있다.
• 함수가 실행된 시각 정보를 알 수 있다.
• ftrace 로그를 활성화해도 시스템 동작에 부하를 거의 주지 않는다.

Ftrace 설치 방법

ftrace는 리눅스 커널의 공통 기능이고 라즈비안이 아닌 다른 리눅스 시스템에도 지원한다고 한다. 라즈비안에서는 아래의 패치코드를 통해서 활성화를 할 수 있다.

/arch/arm/configs/your_device_defconfig
CONFIG_FTRACE=y
CONFIG_DYNAMIC_FTRACE=y
CONFIG_FUNCTION_FTRACE=y
CONFIG_FUNCTION_GRAPH_FTRACE=y
CONFIG_IRQSOFF_TRACE=y
CONFIG_SCHED_FTRACE=y
CONFIG_FTRACE_PROFILER=y
CONFIG_STACK_TRACER=y
CONFIG_TRACE_SNAPSHOT=y

 

흐음 라즈비안에서는 ftrace의 기본 기능이 활성화 되어 있다고 한다. 그래서 커널 소스에서 menuconfig를 진행하였을 때 config 옵션이 활성화가 되어 있는지 궁금했다.

???? Kconfig에는 활성화가 되어 있지 않다. ?? 이부분은 다음에 확인하자..????

 

s /sys/kernel/debug/tracing 을 통해 ftrace의 설정 파일을 확인 할 수 있다.

ftrace 설정

#!/bin/bash

echo 0 > /sys/kernel/debug/tracing/tracing_on
sleep 1
echo "tracing_off"

echo 0 > /sys/kernel/debug/tracing/events/enable
sleep 1
echo "events disabled"

echo secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter init"

echo function > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function tracer enabled"

echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable

echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable

echo 1 > /sys/kernel/debug/tracing/events/raw_syscalls/enable
sleep 1
echo "event enable"

echo schedule ttwu_do_wakeup > /sys/kernel/debug/tracing/set_ftrace_filter

sleep 1
echo "set_ftrace_filter enable"

echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"

echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"

Ftrace 내용 추출

#!/bin/bash
echo 0 > /sys/kernel/debug/tracing/tracing_on
echo "ftrace off"
sleep 3
cp /sys/kernel/debug/tracing/trace .
mv trace ftrace_log.c

ftrace 내용 확인

# tracer: function
#
# entries-in-buffer/entries-written: 9006/9006   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
 irq_trace_ftrac-12354 [001] .... 315487.856844: sys_exit: NR 4 = 2

ftrace 이벤트 분석하기

1. sched_switch 로그 분석

"kworker/2:1" 프로세스에서 "ksoftirqd/2" 프로세스로 스케쥴링하는 동작을 출력한다.

1. irq_handler_entry, irq_handler_exit 이벤트 메시지 해석방법

sshd-12289 [000] d.h. 315487.857464: irq_handler_entry: irq=56 name=dwc_otg
sshd-12289 [000] d.h. 315487.857469: irq_handler_exit: irq=56 ret=unhandled
> pid가 12289인 sshd 프로세스가 실행 중 인터럽트 56번(인터럽트 네임 dwc_otg)이 발생했다.
> 인터럽트가 마무리 되었다.

irq_handler_entry : 인터럽트 핸들러를 실행하기 전에 출력.

irq_handler_exit : 인터럽트 핸들러 실행을 마무리한 직후 출력

ftrace는 커널 코드 분석의 안내자

ftrace 이벤트의 이름으로 커널 의 내부의 어떤 소스코드에서 이벤트를 출력하는 지 알 수 있기 때문이다.

"trace_" + "ftrace_event_name"
* ftrace 이벤트 >> 출력 함수 이름
* sched_switch >> trace_sched_switch ( 프로세스가 스케줄링되는 정보 출력 )
* irq_handler_entry >> trace_irq_handler_entry ( irqhandler 이름과 번호 출력 )
* irq_handler_exit >> trace_irq_handler_exit ( irq handler 처리가 끝남을 출력 )

1. sched_switch_ftrace 이벤트 출력하는 코드를 검색하는 방법

kernel/sched/core.c

...
3493     if (likely(prev != next)) {
3494         rq->nr_switches++;
3495         rq->curr = next;
3496         /*
3497          * The membarrier system call requires each architecture
3498          * to have a full memory barrier after updating
3499          * rq->curr, before returning to user-space.
3500          *
3501          * Here are the schemes providing that barrier on the
3502          * various architectures:
3503          * - mm ? switch_mm() : mmdrop() for x86, s390, sparc, PowerPC.
3504          *   switch_mm() rely on membarrier_arch_switch_mm() on PowerPC.
3505          * - finish_lock_switch() for weakly-ordered
3506          *   architectures where spin_unlock is a full barrier,
3507          * - switch_to() for arm64 (weakly-ordered, spin_unlock
3508          *   is a RELEASE barrier),
3509          */
3510         ++*switch_count;
3511
3512         trace_sched_switch(preempt, prev, next);
3513
3514         /* Also unlocks the rq: */
3515         rq = context_switch(rq, prev, next, &rf);
3516     } else {
3517         rq->clock_update_flags &= ~(RQCF_ACT_SKIP|RQCF_REQ_SKIP);
3518         rq_unlock_irq(rq, &rf);
3519     }
3520
3521     balance_callback(rq);
3522 }
....

3512 라인에서 sched_switch_ftrace  출력한다.

2. irq_handler_entry , irq_handler_entry

/kernel/irq/handle.c
....
137 irqreturn_t __handle_irq_event_percpu(struct irq_desc *desc, unsigned int *flags)
138 {
139     irqreturn_t retval = IRQ_NONE;
140     unsigned int irq = desc->irq_data.irq;
141     struct irqaction *action;
142
143     record_irq_time(desc);
144
145     for_each_action_of_desc(desc, action) {
146         irqreturn_t res;
147
148         trace_irq_handler_entry(irq, action);
149         res = action->handler(irq, action->dev_id);
150         trace_irq_handler_exit(irq, action, res);
151
152         if (WARN_ONCE(!irqs_disabled(),"irq %u handler %pF enabled interrupts\\n",
153                   irq, action->handler))
154             local_irq_disable();
....