Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

6363
1898
209235


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

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


핑백

덧글

  • 박진혁 2021/01/13 10:01 # 삭제 답글

    안녕하세요. 저자님의 책으로 공부중인 학생입니다.
    다름이 아니라 이상한 부분이 있어서요.
    이 블로그 내용에 해당하는 책의 페이지는 427페이지 입니다. 그리고 이 코드에서는 bcm2835_mbox_threaded_irq 함수에 filter를 걸고 있습니다.
    그런데 bcm2835_mbox_threaded_irq() 함수는 433페이지에서 처음으로 저자님이 직접 정의하신 함수입니다.그래서 책을 순서대로 읽으면 427페이지의 .sh파일이 정상적으로 작동하지를 않습니다.

    확인 부탁드립니다.
  • AustinKim 2021/01/13 10:34 #

    먼저 책을 진지하게 읽어 주셔서 감사합니다.
    알려주신 내용은 이미 다른 독자분들이 제보를 주셨는데요.

    아래 페이지의 내용을 참고하시면 좋겠습니다.
    http://rousalome.egloos.com/10016613

    오타를 잡기 위해 최선을 다했으나 미비한 점이 있어 죄송하고요.
    추가로 다른 독자분들이 주신 문의사항이나 오타는 아래 페이지에서 확인할 수 있습니다.
    http://rousalome.egloos.com/category/Question_Announcement

    혹시 추가로 궁금한 점이 있으면 블로그에 댓글을 남겨주시거나 이메일로 보내주세요.
    감사합니다.
댓글 입력 영역