6.5 IRQ 스레드 디버깅
이번 절에서는 IRQ 스레드 디버깅 방법을 소개합니다.
- ftrace로 IRQ Thread 동작 확인하기
- IRQ 스레드를 생성하는 실습
- ftrace function_gragh 트레이서로 IRQ 스레드 핸들러 실행 시각 측정하기
언제나 실습이 중요한 것 같습니다. 코드를 분석한 시간을 다지기 위해 꼭 필요한 과정입니다.
6.5.1 ftrace로 IRQ 스레드 동작 확인하기
이제 실제 라즈베리안에서 IRQ 스레드가 어떻게 수행되는지 ftrace 로그로 분석할 시간입니다.
IRQ 스레드를 확인도록 ftrace 설정하기
IRQ 스레드를 확인할 수 있는 ftrace 설정 명령어를 소개합니다.
#!/bin/sh
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 bcm2835_mbox_threaded_irq bcm2835_mbox_irq > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"
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/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
sleep 1
echo "event enabled"
echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo "function stack trace enabled"
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"
이전 5장 5.2.2 절에서 설정한 ftrace log 대비 달라진 점은 두 가지입니다.
우선bcm2835_mbox_threaded_irq()와 bcm2835_mbox_irq() 함수를 다음과 같이 set_ftrace_filter에 저장합니다. 이 함수 콜스택을 보기 위해서입니다.
echo bcm2835_mbox_threaded_irq bcm2835_mbox_irq > /sys/kernel/debug/tracing/set_ftrace_filter
그다음으로 sched_switch, sched_wakeup event를 킵니다. IRQ 스레드를 누가 깨우고 IRQ 스레드가 언제 스케쥴링 되는지 점검하기 위해서입니다
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
위 셸 스크립트를 irq_thread_trace.sh 파일 이름으로 저장하고 “source irq_thread_trace.sh” 명령어로 실행하면 ftrace 를 빨리 설정할 수 있습니다.
이렇게 ftrace를 설정 후 10초 후에 ftrace 로그(/sys/kernel/debug/tracing/trace)을 열어봅니다. 그러면 10초 동안 커널이 동작한 ftrace 로그를 볼 수 있습니다. 이 로그에서 92번 인터럽트가 발생하고 나서 “irq/92-mmc1” IRQ 스레드가 실행하는 흐름까지 살펴보겠습니다.
ftrace 메시지 분석으로 IRQ 스레드 동작 확인하기
분석하려는 전체 ftrace 로그는 다음과 같습니다.
1 <idle>-0 [000] d.h. 2207.201353: irq_handler_entry: irq=92 name=mmc1
2 <idle>-0 [000] d.h. 2207.201359: bcm2835_mmc_irq <-__handle_irq_event_percpu
3 <idle>-0 [000] d.h. 2207.201404: <stack trace>
4 => handle_irq_event
5 => handle_level_irq
6 => generic_handle_irq
7 => bcm2836_chained_handle_irq
8 => generic_handle_irq
9 => __handle_domain_irq
10 => bcm2836_arm_irqchip_handle_irq
11 => __irq_svc
12 => arch_cpu_idle
13 => arch_cpu_idle
14 => default_idle_call
15 => do_idle
16 => cpu_startup_entry
17 => rest_init
18 => start_kernel
19 <idle>-0 [000] d.h. 2207.201414: irq_handler_exit: irq=92 ret=handled
20 <idle>-0 [000] dnh. 2207.201425: sched_wakeup: comm=irq/92-mmc1 pid=65 prio=49 target_cpu=000
21 <idle>-0 [000] d... 2207.201436: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=irq/92-mmc1 next_pid=65 22 next_prio=49
23 irq/92-mmc1-65 [000] .... 2207.201441: bcm2835_mmc_thread_irq <-irq_thread_fn
24 irq/92-mmc1-65 [000] .... 2207.201459: <stack trace>
25 => kthread
26 => ret_from_fork
이제부터 위 ftrace 로그를 실행 순서별로 차근차근 분석해 보겠습니다.
우선, 아래 로그는 mmc1 인터럽트가 발생했다고 말해줍니다. pid가 0인 idle 프로세스의 동작을 멈추고 인터럽트가 발생했습니다. 이제 인터럽트 핸들러가 호출될 것입니다.
1 <idle>-0 [000] d.h. 2207.201353: irq_handler_entry: irq=92 name=mmc1
다음 로그로 인터럽트 핸들러인 bcm2835_mmc_irq() 함수가 콜스택을 알 수 있습니다.
2 <idle>-0 [000] d.h. 2207.201359: bcm2835_mmc_irq <-__handle_irq_event_percpu
3 <idle>-0 [000] d.h. 2207.201404: <stack trace>
4 => handle_irq_event
5 => handle_level_irq
6 => generic_handle_irq
7 => bcm2836_chained_handle_irq
8 => generic_handle_irq
9 => __handle_domain_irq
10 => bcm2836_arm_irqchip_handle_irq
11 => __irq_svc
12 => arch_cpu_idle
13 => arch_cpu_idle
14 => default_idle_call
15 => do_idle
16 => cpu_startup_entry
17 => rest_init
18 => start_kernel
idle 프로세스가 arch_cpu_idle() 함수에서 일하고 있는 도중에 92번 “mmc1” 인터럽트가 발생한 것입니다. 11번째 줄 로그에서 __irq_svc가 보입니다. 인터럽트 벡터 함수입니다.
다음은 소절에서 장에서 가장 중요한 로그이니 조금 집중해서 볼 필요가 있습니다.
20 <idle>-0 [000] dnh. 2207.201425: sched_wakeup: comm=irq/92-mmc1 pid=65 prio=49 target_cpu=000
21 <idle>-0 [000] d... 2207.201436: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=irq/92-mmc1 next_pid=65 22 next_prio=49
20번째 줄 로그에서 sched_wakeup이란 메시지가 보입니다. 이는 프로세스를 깨우는 동작을 표현하는 ftrace 이벤트 로그입니다. 오른쪽 메시지인 “comm=irq/92-mmc1” 을 보면 깨우려는 프로세스 정보를 알 수 있습니다. 즉, pid가 65이고 프로세스 이름이 irq/92-mmc1인 IRQ 스레드를 깨우는 동작입니다.
인터럽트 핸들러에서 IRQ_WAKE_THREAD를 반환하니 __irq_wake_thread() 함수가 호출되어 wake_up_process() 함수를 호출한 것입니다.
21번 줄 로그를 보면 swapper/0 프로세스에서 irq/92-mmc1 프로세스로 스케줄링합니다. 이제 irq/92-mmc1 프로세스를 실행할 것입니다.
다음은 IRQ 스레드인 irq/92-mmc1 프로세스가 실행을 시작합니다.
23 irq/92-mmc1-65 [000] .... 2207.201441: bcm2835_mmc_thread_irq <-irq_thread_fn
24 irq/92-mmc1-65 [000] .... 2207.201459: <stack trace>
25 => kthread
26 => ret_from_fork
위 콜스택을 조금 더 쉽게 보이게 다시 정렬해보면 다음 번호 순서 흐름으로 irq/92-mmc1 IRQ 스레드 핸들인 bcm2835_mmc_thread_irq() 함수를 호출합니다.
4 => bcm2835_mmc_thread_irq
3 => irq_thread_fn
2 => kthread
1 => ret_from_fork
여러분이 갖고 있는 리눅스 보드가 라즈베리파이가 아니더라도 이 방법으로 IRQ 스레드가 어떤 흐름으로 실행하는지 점검하길 바랍니다. 리눅스 커널 코드를 분석할 때 보다 훨씬 더 많은 정보를 얻을 수 있습니다.
* 유튜브 강의 동영상도 있으니 같이 들으시면 좋습니다.
"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.
혹시 글을 읽고 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려 드리겠습니다!"
# Reference 인터럽트 후반부 처리
6.9 Soft IRQ 서비스는 누가 언제 처리하나?
6.13 Soft IRQ 디버깅
6.13.1 ftrace Soft IRQ 이벤트 분석 방법
6.13.2 /proc/softirqs로 Soft IRQ 서비스 실행 횟수 확인
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글