Arm Linux Kernel Hacks : [리눅스커널][인터럽트후반부] IRQ 스레드 동작 확인하기

IRQ 스레드 동작 확인하기

이제 실제 라즈베리안에서 IRQ Thread가 어떻게 수행되는지 ftrace 로그로 분석할 시간입니다. 이를 위해 다음과 같이 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 로그는 다음과 같습니다.

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 Thread를 깨우는 동작입니다.

인터럽트 핸들러에서 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