![[Linux Kernel] IRQ 스레드 실습](https://img1.daumcdn.net/thumb/R750x0/?scode=mtistory2&fname=https%3A%2F%2Fblog.kakaocdn.net%2Fdn%2FnX4xD%2FbtrhZmlBf6g%2Fkhr7A5JetkJ2lZ2VmvlkTk%2Fimg.png)
본 실습은 책 「디버깅을 통한 리눅스 커널의 구조와 원리」 p.438를 기준으로 진행했다.
IRQ 스레드 생성 실습
IRQ 스레드를 생성할 인터럽트 선택
라즈베리 파이에 존재하는 IRQ 스레드의 개수는 많지 않다. 먼저 존재하는 IRQ 스레드를 확인해보면,
책과는 달리 166번 인터럽트에 대한 IRQ 스레드도 보인다. usb 관련 인터럽트 같은데 지금은 그냥 넘어가도 된다. 이제 IRQ 스레드를 생성해 볼 인터럽트를 선택하기 위해 "cat /proc/interrupts" 명령어로 확인해본다.
각 cpu 번호 별로 실행된 횟수를 참고해서 선택할 예정이다. 위에서 이미 돌고 있던 86, 166번 인터럽트를 제외하고 선택하면, 적당한 횟수로 도는 17번 인터럽트 3f00b880.mailbox가 좋겠다.
17번 인터럽트 IRQ 스레드 생성 패치 코드
/drivers/mailbox/bcm2835-mailbox.c
원래 존재하지 않던 threaded_irq 핸들러 함수를 구현하고 원래 있던 IRQ 핸들러에서는 IRQ_HANDLED가 아닌 IRQ_WAKE_THREAD가 리턴되도록 바꿨다. 이렇게 해야 __handle_irq_event_percput() 함수에서 인터럽트 핸들러의 반환 값을 보고 IRQ 스레드를 깨울 수 있기 때문이다.
패치 코드를 모두 입력하고 저장했으면 꼭 컴파일해서 빌드하고 설치까지 한 다음 재부팅한다. 다시 프로세스 리스트를 확인해보면 "irq/17-3f00b880" IRQ 스레드가 생성된 것을 확인할 수 있다.
ftrace 및 kernel 로그 확인
ftrace 로그를 보기 위한 쉘 스크립트 start_ftrace.sh를 작성하고 실행한다.
#!/bin/bash
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 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_free/enable
# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exec/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
sleep 1
echo "event enabled"
echo bcm2835_mbox_thread_irq bcm2835_mbox_irq > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"
echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on""./start_ftrace.sh"를 실행하고 10초 정도 기다려준 뒤에 get_ftrace.sh 쉘 스크립트로 로그를 따온다. 로그에서 우리가 봐야할 부분을 분석해보자.
잘 안보이면 새 탭에서 보시길...
3~24번째 줄: 16번째 줄에서 인터럽트가 걸린 걸 확인할 수 있는데 인터럽트가 불리기 전까지 arch_cpu_idle() 함수를 실행하고 있었다는 걸 알 수 있다.
27번째 줄 : irq/17-3f00b880 프로세스를 깨우는 동작.
28~37번째 줄: IRQ 스레드로 스케줄링 되고 나서 아까 정의해놓았던 bcm2835_mbox_threaded_irq() 함수가 IRQ 스레드 처리 함수로서 호출됨.
38~39번째 줄: bcm2835_mbox_threaded_irq() 함수에 추가해놓았던 디버깅 정보가 출력되었음을 확인할 수 있다.
마지막으로 bcm2835_mbox_threaded_irq() 함수에 있던 dump_stack() 함수의 로그 출력을 "cat /var/log/kern.log"에서 확인한다.
[ 0.037829] CPU: 2 PID: 35 Comm: irq/17-3f00b880 Not tainted 4.19.127-v7+ #7
[ 0.037834] Hardware name: BCM2835
[ 0.037869] [<80112018>] (unwind_backtrace) from [<8010d364>] (show_stack+0x20/0x24)
[ 0.037888] [<8010d364>] (show_stack) from [<80851cd4>] (dump_stack+0xd8/0x11c)
[ 0.037910] [<80851cd4>] (dump_stack) from [<8071640c>] (bcm2835_mbox_threaded_irq+0x80/0x94)
[ 0.037930] [<8071640c>] (bcm2835_mbox_threaded_irq) from [<80182814>] (irq_thread_fn+0x2c/0x88)
[ 0.037945] [<80182814>] (irq_thread_fn) from [<80182ba0>] (irq_thread+0x164/0x240)
[ 0.037959] [<80182ba0>] (irq_thread) from [<801428c8>] (kthread+0x16c/0x174)
[ 0.037974] [<801428c8>] (kthread) from [<801010ac>] (ret_from_fork+0x14/0x28)콜 스택을 확인하면 bcm2835_mbox_threaded_irq() 함수가 dump_stack() 함수를 불러 해당 로그를 남겼다는 걸 알 수 있다.
IRQ 스레드 처리 함수 실행 시각 측정
IRQ 스레드 처리 함수의 실행 시각을 측정하는 실습을 진행하는 이유는 인터럽의 특징인 "인터럽트 핸들러는 짧고 간결하게 실행되어야" 하기 때문이다.
ftrace 인터럽트 핸들러 실행 시간 측정
먼저 ftrace에서 지원하는 function_graph 트레이서를 사용해서 측정할 건데 먼저 라즈베리 파이의 설정 파일인 ".config"에서 다음과 같은 설정이 필요하다. 그런데 라즈비안 OS에서는 기본으로 설정되어 있으니 잘 설정되어 있는지만 확인해준다. start_ftrace.sh 쉘 스크립트를 다음과 같이 수정하고 실행해준다.
#!/bin/bash
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
echo function_graph > /sys/kernel/debug/tracing/current_tracer
sleep 1
# echo "function tracer enabled"
echo "function_graph tracer enabled"
# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exit/enable
# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_fork/enable
# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_free/enable
# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_process_exec/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/irq/irq_handler_exit/enable
sleep 1
echo "event enabled"
echo bcm2835_mmc_thread_irq bcm2835_mmc_irq > /sys/kernel/debug/tracing/set_ftrace_filter
echo bcm2835_mbox_threaded_irq bcm2835_mbox_irq >> /sys/kernel/debug/tracing/set_ftrace_filter
echo bcm2835_sdhost_irq >> /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"
#! these options are just for "function" tracer
# echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
# echo 1 > /sys/kernel/debug/tracing/options/sym-offset
# echo "function stack trace enabled"
echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"1. 86번 인터럽트 핸들러인 bcm2835_sdhost_irq() 함수의 실행 시간
0) | /* irq_handler_entry: irq=80 name=mmc0 */
0) 4.636 us | bcm2835_sdhost_irq();
0) | /* irq_handler_exit: irq=80 ret=handled */
...
0) | /* irq_handler_entry: irq=80 name=mmc0 */
0) 6.666 us | bcm2835_sdhost_irq();
0) | /* irq_handler_exit: irq=80 ret=handled */대략 10마이크로초 미만이므로 빠른 시간 내에 인터럽트 핸들러가 실행되었다고 볼 수 있다.
2. 17번 인터럽트 핸들러 bcm2835_mbox_irq() ~ bcm2835_mbox_threaded_irq() 함수의 실행 시간
0) | /* irq_handler_entry: irq=17 name=3f00b880.mailbox */
0) 7.656 us | bcm2835_mbox_irq();
3) | /* sched_switch: prev_comm=kworker/3:2 prev_pid=3160 prev_prio=120 prev_state=D ==> next_comm=swapper/3 next_pid=0 next_prio=120 */
------------------------------------------
3) kworker-3160 => <idle>-0
------------------------------------------
3) | /* sched_wakeup: comm=kworker/3:2 pid=3160 prio=120 target_cpu=003 */
0) | /* irq_handler_exit: irq=17 ret=handled */
3) | /* sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/3:2 next_pid=3160 next_prio=120 */
------------------------------------------
2) rcu_sch-10 => <idle>-0
------------------------------------------
2) | /* sched_wakeup: comm=irq/17-3f00b880 pid=35 prio=49 target_cpu=002 */
------------------------------------------
3) <idle>-0 => kworker-3160
------------------------------------------
3) | /* sched_switch: prev_comm=kworker/3:2 prev_pid=3160 prev_prio=120 prev_state=I ==> next_comm=swapper/3 next_pid=0 next_prio=120 */
2) | /* sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=irq/17-3f00b880 next_pid=35 next_prio=49 */
------------------------------------------
2) <idle>-0 => irq/17--35
------------------------------------------
2) | bcm2835_mbox_threaded_irq() {
2) | /* irq=17, process: irq/17-3f00b880 */
2) | /* [+] in_interrupt: 0x00000000, preempt_count = 0x00000000, stack = 0xb97e4000 */
2) ! 140.573 us | }bcm2835_mbox_irq() 함수는 7.656 마이크로초만큼의 실행 시간이 걸렸다. 이 정도면 준수하다고 할 수 있는데 이에 bcm2835_mbox_irq() 함수가 스케줄링 되고 나서 실행하면 140.573 마이크로초나 걸리는 것을 확인할 수 있다. 이걸로 얻을 수 있는 교훈은 dump_stack() 같은 실행 속도가 오래 걸리는 함수는 인터럽트 핸들러 내부에서는 쓰면 안 된다는 것이다.
앞으로 인터럽트 핸들러 같은 함수의 실행 시간 같은 걸 측정할 때는 ftrace의 funciton_graph 트레이서를 이용하면 성능 측정에 아주 유용할 것이다.