Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

43107
469
422675


[리눅스커널] 인터럽트 후반부 처리: 라즈베리파이에서 IRQ 스레드 생성 과정 디버깅하기 6. 인터럽트 후반부 처리

라즈베리파이에서 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 스레드가 어떻게 실행하는지 점검해보겠습니다.

"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.  
그리고 혹시 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려드리겠습니다!"



핑백

덧글

댓글 입력 영역