디버깅을 통해 배우는 리눅스 커널의 구조와 원리 1, 도서 공부하기 27 - IRQ 스레드 디버깅 실습

 

 

안녕하세요.

 

 이번에는 이전 글에 본 IRQ 스레드에 대해서 라즈베리 파이에서 디버깅을 하는 내용입니다.

 

---

 

1. ftrace를 이용한 IRQ 스레드 동작 확인

  

1) IRQ 스레드를 확인하기 위한 ftrace 설정

 

 아래 내용으로 셀 스크립트를 만들어 저장합니다.  중요한 부분만 보면

echo bcm2835_mmc_thread_irq bcm2835_mmc_irq > /sys/kernel/debug/tracing/set_ftrace_filter

 

bcm2835_mmc_thread_irq() 함수와 bcm2835_mmc_irq() 함수에 대해 set_ftrace_filter에 저장합니다.

 

echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable

 

IRQ 스레드를 누가 깨우고 IRQ 스레드가 언제 스케줄링되는 점검하기 위해서 이벤트를 활성화합니다.

 

<irq_thread_trace_6_5_1.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 bcm2835_mmc_thread_irq bcm2835_mmc_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 1 > /sys/kernel/debug/tracing/options/sym-offset
echo "function stack trace enabled"

echo 1 > /sys/kernel/debug/tracing/tracing_on
echo "tracing_on"

 

 

이전에 스크립트 사용한 것과 동일한 방식으로 실행합니다.

그런데 irq_thread_trace_6_5_1.sh 설정하고 약 10초 지난 후에 ftrace_log/get_ftrace.sh 실행해서 이벤트가 발생하는 시간을 기다려줍니다.

 

linux# sh ../ftrace_log/irq_thread_trace_6_5_1.sh
linux# sh ../ftrace_log/get_ftrace.sh

 

 

 

2) IRQ 스레드의 ftrace 메시지 확인

 

 

218번 줄은 mmc1 인터럽트가 발생했다고 알려줍니다.

219번 줄은 인터럽트 핸들러인 bcm2835_mmc_irq() 함수가 호출되는 흐름을 알 수 있습니다.

229번 줄 __irq_svc 주변을 보면 arch_cpu_idle() 함수 실행 중 36번 인터럽트가 발생한 것을 알 수 있습니다.

 

238번 줄에서 sched_wakeup 이벤트는 커널 내부에서 해당 프로세스를 깨우는 동작을 합니다. 즉, pid가 83이고, 프로세스 이름이 irq/36-mmc1인 IRQ 스레드를 깨우라는 의미가 됩니다.

 

그러면 인터럽트 핸들러에서  IRQ_WAKE_THREAD를 반환하고 __irq_wake_thread() 함수가 호출합니다. 241번 줄을 보면 irq/36-mm1 프로세스가 스케줄링된다는 것을 알 수 있습니다.

 

242~248줄에서 irq/86-mmc1 IRQ 스레드 처리 함수인 bcm2835_mmc_thread_irq() 함수를 호출하는 것까지 확인할 수 있습니다.

 

  

 

2. IRQ 스레드 생성 실습

 

 이번에는 IRQ 스레드를 직접 생성하고 로그로 분석하는 것을 해보겠습니다.

 

1) IRQ 스레드 생성할 인터럽트 선택

 

ps 명령어를 이용해서 IRQ 스레드를 확인합니다. 책에서 나온 라즈베리 파이 3에서는 1개만 보인다고 하지만, 파이 4에서는 전체로 보면 4개까지 보였습니다.

 

pi# ps -ely

 

 

  

 어떤 인터럽트를 IRQ 스레드로 생성할지 확인 위해 아래 명령어로 확인합니다. 31번(fe00b880.mailbox) 이 책 내용과 비슷하고, 발생빈도도 비슷하여 선택합니다.

 

pi# cat /proc/interrupts

 

linux# vim drivers/mailbox/bcm2835-mailbox.c

 

2) 실습 패치코드 추가

 

아래 파일에 소스코드를 추가합니다.

 

linux# vim drivers/mailbox/bcm2835-mailbox.c

 

첫 번째, 210번 줄의 devm_request_irq() 함수가 인터럽트 핸들러만 등록 함수인데

  213번 줄의 devm_request_threaded_irq() 함수로 변경해 인터럽트 핸들러와 IRQ 스레드 처리 함수를 추가하도록 변경된 함수로 변경합니다.

 

 

 

두 번째,  87번 줄에 IRQ_WAKE_THREAD로 변경해서 바로 인터럽트 핸들러에서 IRQ 스레드를 깨우기를 시도합니다.

 

 

 

세 번째로, interrupt_debug_irq_desc() 함수를 추가합니다.

 프로세스 이름과 인터럽트 번호, in_interrupt() 함수 반환값을 출력하고 dump_stack() 함수를 호출해서 콜 스택을 출력합니다.

 

 실전에서 인터럽트 핸들러나 인터럽트 컨텍스트에서 이렇게 디버깅용이 아닌 용도로 사용하면 시스템이 느려지거나 오동작할 수 있으니 주의해야 합니다.

 

 

 

 파일을 저장하고 커널을 빌드와 설치하는 스크립트를 실행하고 재부팅합니다.

 

linux# sh ../build_rpi_kernel.sh
linux# sh ../install_rpi_kernel_img.sh

 

 

3) 생성한 IRQ 스레드의 ftrace 메시지 확인

 

 위에서 ftrace 로그를 확인한 것과 동일하게 작업을 합니다.

 스크립트가 조금 수정된 것은 새로 추가한 함수를 위해서 set_ftrace_filter 지정을 바꿔 줍니다.

 

echo bcm2835_mbox_irq bcm2835_mbox_threaded_irq > /sys/kernel/debug/tracing/set_ftrace_filter

 

 

linux# sh ../ftrace_log/irq_thread_trace_6_5_2.sh
linux# sh ../ftrace_log/get_ftrace.sh

 

 

198번 줄을 보면 fe00b880.mailbox 인터럽트가 발생한 것을 알 수 있습니다.

함수 호출 흐름을 보면 PID 993인 kworker/2:0 워커 스레드가 arch_cpu_idle() 함수에서 실행 중이었습니다.

 

219번 줄을 보면 irq/31-fe00b880 프로세스를 깨우는 동작을 하고 있습니다.

그 아래 줄에서 IRQ 스레드로 스케줄링된 후 irq/31-fe00b880 IRQ 스레드 처리 함수인 bcm2835_mbox_threaded_irq() 함수가 호출되는 것을 알 수 있습니다.

 

231번 줄은 bcm2835_mbox_threaded_irq()에서 추가한 디버깅 로그 정보입니다.

 

 

 

4) 생성한 IRQ 스레드의 전체 실행 흐름

 

 첫 번째, 31번 인터럽트가 발생해 인터럽트 벡터를 통해 브랜치 되는 __irq_svc 레이블이 실행됩니다.

 

 두 번째, 31번 인터럽트 핸들러인 bcm2385_mbox_irq() 함수가 호출됩니다. IRQ_WAKE_THREAD 플래그를 반환해 "irq/31-fe00b880" IRQ 스레드를 깨웁니다.

 

 세 번째, "irq/31-fe00b880" IRQ 스레드 처리 함수인 bcm2835_mbox_threaded_irq() 함수가 호출됩니다.

 

 

 

 

고생하셨습니다.

 

감사합니다.

 

 

<참고 자료>

1. [도서] 디버깅을 통해 배우는 리눅스 커널의 구조와 원리 p426 ~ 442, wikibook