Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

15192
888
89788


[리눅스커널][인터럽트] ftrace로 인터럽트 동작 디버깅하기 5장. 인터럽트 핸들링

이번 소절에서는 ftrace로 인터럽트를 트레이싱하는 방법을 소개합니다.
리눅스 커널의 가장 강력한 디버그 기능인 ftrace 는 인터럽트를 추적(트레이싱)할 수 있게 다음 이벤트를 지원합니다. 
 - irq_handler_entry: 인터럽트 핸들러 실행 시점
 - irq_handler_exit: 인터럽트 핸들러 종료 시점

인터럽트 동작을 기록하는 각각 이벤트를 설정하는 방법부터 알아봅시다.

ftrace irq_handler_entry와 irq_handler_exit 이벤트 설정해보기

먼저 ftrace에서 irq_handler_entry와 irq_handler_exit 이벤트를 키는 방법을 소개합니다.
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable

위와 같은 명령어로 각각 이벤트를 킬 수 있습니다.

라즈베리파이 리눅스 커널은 아래 ftrace 로그를 볼 수 있는 컨피그가 기본 설정돼 있습니다. 그래서 ftrace만 설정하면 됩니다. 

다음과 같은 코드를 작성해 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초 동안 대기 합니다. 이후 다음 명령어를 입력하면 바로 ftrace 메시지에서 인터럽트 이벤트 메시지를 볼 수 있습니다. 
“tail -400 /sys/kernel/debug/tracing/trace”

ftrace 로 irq_handler_enter와 irq_handler_exit 이벤트를 킨 후 ftrace 로그를 보는 방법을 소개했습니다. 

ftrace: irq_handler_entry/irq_handler_exit 이벤트 메시지 분석하기
이어서 ftrace 메시지에서 인터럽트 이벤트인 irq_handler_entry와 irq_handler_exit를 분석하는 방법을 소개합니다. 분석할 ftrace 메시지를 소개합니다.
01 <idle>-0     [000] d...  4486.577315: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:2 next_pid=20114 next_prio=120
02 kworker/0:2-20114 [000] d.h.  4486.577335: irq_handler_entry: irq=17 name=arch_timer
03 kworker/0:2-20114 [000] d.h.  4486.577340: irq_handler_exit: irq=17 ret=handled
04 kworker/0:2-20114 [000] d.h.  4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
05 kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled
06 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/0 next_pid=0 next_prio=120

위 ftrace 메시지에서 03~04 번째 줄 로그를 분석하겠습니다.
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이니 워커 쓰레드입니다. 

[000]은 해당 프로세스가 돌고 있는 CPU 번호입니다. CPU0에서 돌고 있습니다. 그다음에 보이는 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_irq() 함수입니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/drivers/mailbox/bcm2835-mailbox.c] 
01 static int bcm2835_mbox_probe(struct platform_device *pdev)
02 {
...
03 ret = devm_request_irq(dev, platform_get_irq(pdev, 0),
04        bcm2835_mbox_irq, 0, dev_name(dev), mbox);

bcm2835_mbox_probe() 함수 03~04번째 줄 코드에서 devm_request_irq() 함수 3 번째 인자로 인터럽트 핸들러를 등록합니다. 여기서 dev_name(dev) 인자로 "3f00b880.mailbox" 인터럽트 이름을 지정하고 있습니다.


ftrace irq_handler_entry/irq_handler_exit 이벤트를 출력하는 커널 함수 분석하기

이어서 다음과 같은 irq_handler_entry와 irq_handler_exit 이벤트를 출력하는 커널 코드를 분석합니다.
01 kworker/0:2-20114 [000] d.h.4486.577344: irq_handler_entry: irq=23 name=3f00b880.mailbox
02 kworker/0:2-20114 [000] d.h.  4486.577346: irq_handler_exit: irq=23 ret=handled

인터럽트 핸들러 실행 시작과 마무리 시점을 추적하는 irq_handler_entry와 irq_handler_exit 이벤트는 __handle_irq_event_percpu() 함수에서 출력합니다.
[https://elixir.bootlin.com/linux/v4.19.30/source/kernel/irq/handle.c]
 
[그림 5.16] ftrace: irq_handler_entry/irq_handler_exit 실행 코드

 7번째 줄 코드에서 인터럽트 핸들러를 호출합니다. 6번째와 8번째 코드 전후로 trace_irq_handler_entry()와 trace_irq_handler_exit() 함수를 호출합니다.

trace_irq_handler_entry() 함수는 1번째 로그, trace_irq_handler_exit() 함수는 2번째 로그를 출력합니다.  
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 로그로 인터럽트 정보를 확인했는데 한 가지 부족한 정보가 있습니다. 그것은 인터럽트 핸들러입니다. 다음 소절에서는 각 인터럽트가 발생했을 때 인터럽트 핸들러가 무엇인지 알아보겠습니다.

"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.  
그리고 혹시 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려드리겠습니다!"

# Reference (인터럽트 처리)



핑백

덧글

댓글 입력 영역