Linux Kernel(4.14) Hacks

rousalome.egloos.com

포토로그 Kernel Crash




[라즈베리파이] 인터럽트 디버깅 - ftrace 인터럽트 이벤트 #CS [라즈베리파이][커널]인터럽트

라즈베리안 리눅스 커널은 아래 ftrace 로그를 볼 수 있는 컨피그가 기본 설정돼 있습니다. 그래서 ftrace만 설정하면 됩니다. 그럼ftrace로 인터럽트 동작을 어떻게 확인할 수 있을까요? ftrace event 중에 인터럽트가 있으니 다음 명령어로 해당 event를 키면 됩니다. 
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable

다음과 같은 코드를 작성하고 irq_ftrace.sh란 스크립트로 저장한 후 이 스크립트를 실행하면 ftrace로 인터럽트를 로그를 볼 수 있습니다. 
[irq_ftrace.sh]
#!/bin/sh

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

echo nop > /sys/kernel/debug/tracing/current_tracer
echo 0 > /sys/kernel/debug/tracing/events/enable
sleep 1

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

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/tracing_on
echo "tracing_on"
 
참고로, ftrace 을 설정하기 위해서 여러 커맨드를 입력해야 하는데 이 명령어들을 하나의 셸 스크립트로 모으면 효율적으로 ftrace를 설정할 수 있습니다. 아래에서 sched_switch 이벤트를 추가한 이유는 어떤 프로세스에서 인터럽트를 처리하는지 확인할 수 있기 때문입니다.

이렇게 설정한 후 5초 후 “tail -400 /sys/kernel/debug/tracing/trace” 명령어로 ftrace log을 열어보면 다음 정보를 볼 수 있습니다.

<idle>-0     [000] d.h. 4486.576254: irq_handler_entry: irq=62 name=dwc_otg_hcd:usb1

<idle>-0     [000] d.h. 4486.576258: irq_handler_exit: irq=62 ret=handled

<idle>-0     [000] d.h. 4486.577287: irq_handler_entry: irq=17 name=arch_timer

<idle>-0     [000] d.h. 4486.577294: irq_handler_exit: irq=17 ret=handled

<idle>-0     [000] d... 4486.577315: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120prev_state=R ==>

    next_comm=kworker/0:2 next_pid=20114 next_prio=120

kworker/0:2-20114[000] d.h.  4486.577335:irq_handler_entry: irq=17 name=arch_timer

kworker/0:2-20114[000] d.h.  4486.577340:irq_handler_exit: irq=17 ret=handled

kworker/0:2-20114[000] d.h.  4486.577344:irq_handler_entry: irq=23 name=3f00b880.mailbox

kworker/0:2-20114[000] d.h.  4486.577346:irq_handler_exit: irq=23 ret=handled

kworker/0:2-20114[000] d...  4486.577377: sched_switch:prev_comm=kworker/0:2 prev_pid=20114 prev_prio=120 prev_state=D ==>

    next_comm=swapper/0next_pid=0next_prio=120

<idle>-0     [000] d.h. 4486.577380: irq_handler_entry: irq=17 name=arch_timer

<idle>-0     [000] dnh. 4486.577385: irq_handler_exit: irq=17 ret=handled

<idle>-0     [000] d... 4486.577387: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120prev_state=R ==>

        next_comm=kworker/0:2 next_pid=20114next_prio=120

kworker/0:2-20114[000] d...  4486.577391: sched_switch:prev_comm=kworker/0:2 prev_pid=20114 prev_prio=120 prev_state=D ==>

        next_comm=swapper/0 next_pid=0next_prio=120

<idle>-0     [000] d.h. 4486.578509: irq_handler_entry: irq=23 name=3f00b880.mailbox

<idle>-0     [000] dnh. 4486.578517: irq_handler_exit: irq=23 ret=handled

<idle>-0     [000] d... 4486.578528: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120prev_state=R ==>

     next_comm=kworker/0:2 next_pid=20114next_prio=120

kworker/0:2-20114[000] d...  4486.578549: sched_switch:prev_comm=kworker/0:2 prev_pid=20114 prev_prio=120 prev_state=t ==>

            next_comm=swapper/0 next_pid=0next_prio=120


그럼 이제 ftrace log에서 아래 로그가 어떤 의미인지 차근차근 분석해볼까요?
kworker/0:2-20114 [000] d.h.  4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled
 
아래 로그에서 볼드체로 된 부분은 눈여겨보시면 kworker/0:2-20114는 pid가 20114인 kworker/0:2란 이름의 프로세스란 의미입니다. 프로세스 이름이 kworker/0:2이니 워커 쓰레드이네요. 
kworker/0:2-20114 [000] d.h.  4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled

[000]은 해당 프로세스가 돌고 있는 CPU 번호입니다. 0번 CPU에서 돌고 있었네요. 그 다음에 보이는 4486.577344는 초 단위 타임스탬프로 시간을 나타내죠.
kworker/0:2-20114 [000] d.h.  4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled
 
irq_handler_entry는 인터럽트 핸들러가 실행 직전을 의미하고, irq_handler_exit는 인터럽트 핸들러가 종료됐다는 것을 의미합니다. 
kworker/0:2-20114 [000] d.h.  4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled
 
위 타임스탬프 정보와 함께 이 ftrace log을 해석하면 4486.577344초에 인터럽트 핸들러가 실행했고 4486.577346초에 핸들러가 종료됐네요. 이 정보로 0.002 밀리 초 동안 인터럽트 핸들러가 실행했음을 알 수 있네요. 
0.000002 = 4486.577346 - 4486.577344
 
다음은 인터럽트 번호입니다. 23번 인터럽트이네요.
kworker/0:2-20114 [000] d.h.  4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled

name=3f00b880.mailbox 로그는 인터럽트 이름을 알려줍니다.
kworker/0:2-20114 [000] d.h.  4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled
 
3f00b880.mailbox 인터럽트 핸들러는 bcm2835_mbox_probe 함수에서 다음 코드에서 초기화됩니다. dev_name(dev) 인자로 "3f00b880.mailbox" 인터럽트 이름을 지정하고 있군요.
static int bcm2835_mbox_probe(struct platform_device *pdev)
{
//...
ret = devm_request_irq(dev, platform_get_irq(pdev, 0),
       bcm2835_mbox_irq, 0, dev_name(dev), mbox);

여기서 devm_request_irq란 낯선 함수가 등장했네요.

그동안 인터럽트 설정은 request_irq 함수로만 설정하는 것으로 알고 있는데요. 디바이스 드라이버에서 devm_request_irq 함수를 써서 인터럽트를 설정하면 irq란 리소스를 struct device 구조체 내에서 체계적으로 관리할 수 있습니다. 이 점만 빼고 request_threaded_irq 함수로 인터럽트 핸들러를 초기화하는 동작은 같습니다.

이제 다음 인터럽트 발생하는 ftrace 로그를 리눅스 커널의 어느 코드에서 실행하는지 궁금하지는 않나요?
kworker/0:2-20114 [000] d.h.4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled
 
우리는 다음 __handle_irq_event_percpu 함수 7번째 줄 코드에서 인터럽트 핸들러를 호출한다고 배웠습니다. 이 코드 전후로 trace_irq_handler_entry, trace_irq_handler_exit 코드가 보이죠?
1 irqreturn_t __handle_irq_event_percpu(struct irq_desc *desc, unsigned int *flags)
2 {
//…
3 for_each_action_of_desc(desc, action) {
4 irqreturn_t res;
5
6 trace_irq_handler_entry(irq, action);
7 res = action->handler(irq, action->dev_id); 
8 trace_irq_handler_exit(irq, action, res);

trace_irq_handler_entry 함수는 아래 첫 번째 ftrace 로그를 출력하고 trace_irq_handler_exit 함수는 그다음 ftrace 로그를 출력합니다. 
1 kworker/0:2-20114 [000] d.h.4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
2 kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled

이렇게 ftrace 로그로 인터럽트 이벤트를 키고 인터럽트를 분석하면 어떤 인터럽트가 얼마나 자주 호출하는지 상세히 알 수 있습니다. ftrace 로그를 열어 보면 아시겠지만 1초 동안 보통 수 백 개의 인터럽트가 발생하고 있음을 알 수 있습니다. 그러니 당연히 인터럽트 핸들러는 짧고 굵게 빨리 실행해야겠죠?

ftrace 로그로 인터럽트 정보를 확인했는데 한 가지 부족한 정보가 있습니다. 그것은 인터럽트 핸들러입니다. 다음 시간에 각 인터럽트가 발생했을 때 인터럽트 핸들러가 무엇인지 알아보겠습니다.


핑백

덧글

댓글 입력 영역