Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

6363
1898
209235


[리눅스커널][인터럽트후반부] IRQ 스레드 동작 확인하기 6. 인터럽트 후반부 처리

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

여러분이 갖고 있는 리눅스 보드가 라즈베리파이가 아니더라도 이 방법으로 IRQ 스레드가 어떤 흐름으로 실행하는지 점검하길 바랍니다. 리눅스 커널 코드를 분석할 때 보다 훨씬 더 많은 정보를 얻을 수 있습니다.

# Reference 인터럽트 후반부 처리
IRQ 스레드 
IRQ 스레드는 어떻게 생성할까?
IRQ 스레드는 누가 언제 실행할까?
IRQ 스레드 디버깅
Soft IRQ 소개
Soft IRQ 서비스
Soft IRQ 서비스는 누가 언제 처리할까?
   Soft IRQ 서비스 실행 진입점
   Soft IRQ 서비스 요청 점검
   Soft IRQ 서비스 실행
   ksoftirq 스레드 깨우기
ksoftirqd 스레드
   ksoftirqd 스레드란
   ksoftirqd 스레드는 언제 깨울까?
   ksoftirqd 핸들 run_softirqd() 함수 분석
Soft IRQ 컨택스트
   Soft IRQ 컨택스트란
   Soft IRQ 컨택스트 시작점
   Soft IRQ 컨택스트 종료
   Soft IRQ 컨택스트 관련 주요 함수 
태스크릿
   태스크릿은 무엇일까?
   태스크릿은 어떻게 등록할까?
   태스크릿은 언제 실행할까?
Soft IRQ 디버깅
   ftrace Soft IRQ 이벤트 소개
   Soft IRQ 서비스 핸들러 실행 확인

핑백

덧글

댓글 입력 영역