라즈베리파이에서 IRQ 스레드 생성 과정 디버깅하기
이번 절에선 request_threaded_irq() 함수를 호출하면 결국 kthread_create() 함수를 실행해서 IRQ 스레드를 생성하는 과정까지 짚어 봤습니다. 이제 디버깅 과정을 통해 배운 내용을 다지는 시간을 갖겠습니다.
먼저 디버깅을 위한 패치 코드를 소개합니다.
+기호로 볼드체로 된 부분이 추가할 코드입니다.
패치 코드를 입력할 함수는 __kthread_create_on_node() 입니다. 이전 절에서 분석하지 않은 __kthread_create_on_node() 함수에 IRQ 스레드를 생성하는 코드를 작성한 이유는 무엇일까요?
그 이유을 알게 위해서 다음 setup_irq_thread() 함수 코드를 살펴볼 필요가 있습니다.
1 static int
2 setup_irq_thread(struct irqaction *new, unsigned int irq, bool secondary)
3 {
...
4 if (!secondary) {
4 t = kthread_create(irq_thread, new, "irq/%d-%s", irq,
5 new->name);
4 번째 줄 코드와 같이 set_up_irqthread() 함수에서 kthread_create() 함수를 호출하면 IRQ 스레드를 생성한다고 알고 있습니다. kthread_create() 함수 구현부 코드를 보면 kthread_create_on_node() 함수를 바로 호출하고 이어서 __kthread_create_on_node() 함수를 호출합니다. 그래서 __kthread_create_on_node() 함수에 디버깅 코드를 작성한 것입니다.
다음 코드에서 볼드체로 된 부분을 눈여겨봅시다.
1 #define kthread_create(threadfn, data, namefmt, arg...) \
2 kthread_create_on_node(threadfn, data, NUMA_NO_NODE, namefmt, ##arg)
3
4 struct task_struct *kthread_create_on_node(int (*threadfn)(void *data),
5 void *data, int node,
6 const char namefmt[],
7 ...)
8 {
9 struct task_struct *task;
10 va_list args;
11
12 va_start(args, namefmt);
13 task = __kthread_create_on_node(threadfn, data, node, namefmt, args);
우리는 kthread_create() 함수를 호출하면 커널 쓰레드를 생성한다고 알고 있습니다. kthread_create() 함수를 보면 2 번째 줄 코드와 같이 kthread_create_on_node() 함수로 치환됩니다.
이어서 kthread_create_on_node() 함수를 열어보면 13 번째 줄 코드와 같이 __kthread_create_on_node() 함수를 호출합니다.
__kthread_create_on_node() 함수에 디버깅 코드를 작성한 이유를 살펴봤습니다. 이제 패치 코드를 분석할 차례입니다.
먼저 수정한 4번째 줄 코드부터 분석합니다.
struct task_struct *__kthread_create_on_node(int (*threadfn)(void *data),
void *data, int node,
const char namefmt[],
va_list args)
4 +
5 + int irq_thread_enable = !strncmp(namefmt, "irq", 3);
6 + char *process_name = &namefmt[0];
__kthread_create_on_node() 함수로 전달되는 namefmt란 파라미터를 “irq” 문자열과 비교합니다. Strncmp() 함수는 지정한 문자열 개수만큼만 스트링을 비교하는 라이브러리 함수입니다. 이때 namefmt 변수 첫 번째 주소 기준으로 세 개 스트링이 “irq” 이면 irq_thread_enable 변수를 1로 설정합니다.
IRQ 스레드 이름은 setup_irq_thread() 함수에서 "irq/%d-%s" 인자로 kthread_create() 함수를 호출할 때 지정한다고 알고 있습니다.
다음 5번째 줄 코드를 보겠습니다.
setup_irq_thread() 함수에서 지정한 "irq/%d-%s" 가 __kthread_create_on_node() 함수의 namefmt 인자로 전달됩니다. 그래서 이 앞 세 개의 스트링이 “irq”인지 비교하는 코드를 작성한 것입니다.
1 static int
2 setup_irq_thread(struct irqaction *new, unsigned int irq, bool secondary)
3 {
...
4 if (!secondary) {
5 t = kthread_create(irq_thread, new, "irq/%d-%s", irq, // <<-[1]
6 new->name);
다음 디버깅 정보를 출력하는 13번째 줄 코드를 볼 차례입니다.
13+ if (irq_thread_enable) {
14+ void *irq_threadfn = (void*)threadfn;
15+
16+ printk("[+] irq_thread handler: %pS caller:(%pS) \n",
17+ irq_threadfn, (void *)__builtin_return_address(0));
18+ dump_stack();
19+ }
13~19번째 줄 코드는irq_thread_enable 지역변수가 1이면 실행합니다.
irq_thread_enable 변수가 1이면 무엇을 의미할까요? 쓰레드 이름이 “irq”로 시작하니 IRQ 스레드를 생성하는 조건입니다. 14번째 줄 코드에서 IRQ 스레드 핸들 함수 포인터를 저장하고 있는 threadfn을 irq_threadfn 포인터에 캐스팅합니다. threadfn인자는 irq_thread() 함수 주소를 저장하고 있습니다.
16번째 줄 코드는 IRQ 스레드 핸들 함수와 자신을 호출한 함수 정보를 출력합니다.
16+ printk("[+] irq_thread handler: %pS caller:(%pS) \n",
17+ irq_threadfn, (void *)__builtin_return_address(0));
이어서 18번째 줄 코드는 콜스택을 출력하는 dump_stack 함수를 호출합니다.
18+ dump_stack();
이렇게 코드를 입력하고 커널 빌드를 완료한 후 라즈베리파이에 커널 이미지를 설치합니다.
이후 라즈베리파이를 리부팅 시키고 커널 로그(/var/log/kern.log)을 열어봅시다.
이번에는 패치 코드가 실행하면서 출력한 커널 로그를 분석하겠습니다. 분석할 전체 로그는 다음과 같습니다.
1 [0.722882] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0
2 [0.722892] mmc-bcm2835 3f300000.mmc: DMA channel allocated
3 [0.722933] [+] process_name: irq/%d-%s caller:(kthread_create_on_node+0x30/0x38)
4 [0.722947] [+] irq_thread handler: irq_thread+0x0/0x20c
caller:(kthread_create_on_node+0x30/0x38)
5 [0.722958] CPU: 0 PID: 31 Comm: kworker/0:1 Not tainted 4.14.39-v7+ #15
6 [0.722962] Hardware name: BCM2835
7 [0.722980] Workqueue: events deferred_probe_work_func
8 [0.723006] (unwind_backtrace) from [<8010c21c>] (show_stack+0x20/0x24)
9 [0.723022] (show_stack) from (dump_stack+0xc8/0x10c)
10 [0.723039] (dump_stack) from (__kthread_create_on_node+0x1c4/0x1e0)
11 [0.723055] (__kthread_create_on_node) from (kthread_create_on_node+0x30/0x38)
12 [0.723070] (kthread_create_on_node) from (setup_irq_thread+0x54/0xe4)
13 [0.723086] (setup_irq_thread) from (__setup_irq+0x260/0x730)
14 [0.723101] (__setup_irq) from (request_threaded_irq+0xec/0x160)
15 [0.723118] (request_threaded_irq) from (devm_request_threaded_irq+0x78/0xcc)
16 [0.723140] (devm_request_threaded_irq) from (bcm2835_mmc_probe+0x514/0x644)
17 [0.723159] (bcm2835_mmc_probe) from (platform_drv_probe+0x60/0xc0)
18 [0.723176] (platform_drv_probe) from (driver_probe_device+0x244/0x2f8)
19 [0.723193] (driver_probe_device) from (__device_attach_driver+0xa8/0xdc)
20 [0.723210] (__device_attach_driver) from (bus_for_each_drv+0x70/0xa4)
21 [0.723228] (bus_for_each_drv) from (__device_attach+0xc0/0x124)
22 [0.723245] (__device_attach) from (device_initial_probe+0x1c/0x20)
23 [0.723261] (device_initial_probe) from (bus_probe_device+0x94/0x9c)
24 [0.723278] (bus_probe_device) from (deferred_probe_work_func+0x68/0x150)
25 [0.723296] (deferred_probe_work_func) from (process_one_work+0x224/0x518)
26 [0.723317] (process_one_work) from (worker_thread+0x60/0x5f0)
27 [0.723333] (worker_thread) from (kthread+0x144/0x174)
28 [0.723348] (kthread) from (ret_from_fork+0x14/0x28)
먼저 커널 쓰레드 이름과 쓰레드 핸들 함수를 분석해 봅시다.
3 [0.722933] [+] process_name: irq/%d-%s caller:(kthread_create_on_node+0x30/0x38)
4 [0.722947] [+] irq_thread handler: irq_thread+0x0/0x20c
caller:(kthread_create_on_node+0x30/0x38)
쓰레드 이름은 irq/%d-%s 이고 자신을 호출한 함수가 kthread_create_on_node+0x30입니다.
또한 IRQ 스레드 핸들 함수는 irq_thread()란 정보를 알 수 있습니다.
다음 5~6 번째 줄 로그입니다.
5 [0.722958] CPU: 0 PID: 31 Comm: kworker/0:1 Not tainted 4.14.39-v7+ #15
6 [0.722962] Hardware name: BCM2835
이 함수가 어느 프로세스에서 실행됐는지 알려주는 로그입니다. PID가 31인 kworker/0:1란 워커쓰레드가 CPU0에서 수행됐음을 알 수 있습니다.
이번에는 콜스택을 살펴보겠습니다.
platform_drv_probe() 함수에서 bcm2835_mmc_probe() 함수를 호출하고 있습니다. 이 정보로 부팅 과정에 IRQ 스레드를 생성한다는 사실을 알 수 있습니다. 보통 드라이버에서 짠 코드의 함수 이름에 probe가 보이면 부팅 도중 한 번 실행합니다.
11 [0.723055] (__kthread_create_on_node) from (kthread_create_on_node+0x30/0x38)
12 [0.723070] (kthread_create_on_node) from (setup_irq_thread+0x54/0xe4)
13 [0.723086] (setup_irq_thread) from (__setup_irq+0x260/0x730)
14 [0.723101] (__setup_irq) from (request_threaded_irq+0xec/0x160)
15 [0.723118] (request_threaded_irq) from (devm_request_threaded_irq+0x78/0xcc)
16 [0.723140] (devm_request_threaded_irq) from (bcm2835_mmc_probe+0x514/0x644)
17 [0.723159] (bcm2835_mmc_probe) from (platform_drv_probe+0x60/0xc0)
18 [0.723176] (platform_drv_probe) from (driver_probe_device+0x244/0x2f8)
콜스택을 보면 이번 절에서 분석한 함수를 볼 수 있습니다.
request_threaded_irq() 함수로 출발해서 __kthread_create_on_node() 함수까지 호출되고 있습니다. kthread_create() 함수 대신 실제 kthread_create_on_node() 함수가 실행한다는 점도 확인할 수 있습니다.
이번 소절에선 IRQ 스레드를 생성하는 흐름을 점검했습니다.
request_threaded_irq() 함수를 호출하면 __kthread_create_on_node() 함수를 호출해서 IRQ 스레드를 생성합니다.
다음 절에서는 IRQ 스레드가 어떻게 실행하는지 점검해보겠습니다.
