Arm Linux Kernel Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

5363
1898
209234


[리눅스커널][인터럽트후반부] IRQ 스레드를 만든 후 ftrace로 분석하기 6. 인터럽트 후반부 처리

6.5.2 IRQ 스레드 생성 실습하기

이번에는 IRQ 스레드를 직접 생성하는 실습을 하겠습니다. 직접 손으로 코드를 작성하고 로그로 동작을 확인하면 배운 내용을 더 오랫동안 기억할 수 있습니다.

IRQ 스레드를 생성할 인터럽트 선택하기

다른 리눅스 시스템보다 라즈베리파이는 IRQ 스레드 개수가 많지 않습니다. 아래와 같이 “ps –ely” 을 입력하면 92번 mmc1 인터럽트를 처리하는 IRQ 스레드가 1개만 보입니다.
root@raspberrypi:/home/pi/dev_raspberrian# ps -ely
S   UID   PID  PPID  C PRI  NI   RSS    SZ WCHAN  TTY          TIME CMD
S     0     1     0  0  80   0  6012  6750 SyS_ep ?        00:00:02 systemd
S     0     2     0  0  80   0     0     0 kthrea ?        00:00:00 kthreadd
...
S     0    64     2  0  70 -10     0     0 down_i ?        00:00:00 SMIO
S     0    65     2  0   9   -     0     0 irq_th ?        00:00:00 irq/92-mmc1
I     0    66     2  0  80   0     0     0 worker ?        00:00:00 kworker/0:3

라즈비안에서 어떤 인터럽트를 IRQ 스레드로 생성해 볼까요? 인터럽트 상태를 점검하기 위해 다음 “cat /proc/interrupts” 명령어로 인터럽트의 개수와 상태를 확인합시다. 
root@raspberrypi:/home/pi/dev_raspberrian# cat /proc/interrupts
           CPU0       CPU1       CPU2       CPU3        
16:          0          0          0          0  bcm2836-timer   0 Edge      arch_timer 
17:     129951     132772     128401     128648  bcm2836-timer   1 Edge      arch_timer 
21:          0          0          0          0  bcm2836-pmu     9 Edge      arm-pmu 
23:       1264          0          0          0  ARMCTRL-level   1 Edge      3f00b880.mailbox 
24:       1710          0          0          0  ARMCTRL-level   2 Edge      VCHIQ doorbell 
46:        137          0          0          0  ARMCTRL-level  48 Edge      bcm2708_fb dma 
48:          0          0          0          0  ARMCTRL-level  50 Edge      DMA IRQ 
50:          0          0          0          0  ARMCTRL-level  52 Edge      DMA IRQ 
51:       2375          0          0          0  ARMCTRL-level  53 Edge      DMA IRQ 
54:      32325          0          0          0  ARMCTRL-level  56 Edge      DMA IRQ 
59:          0          0          0          0  ARMCTRL-level  61 Edge      bcm2835-auxirq 
62:    1355025          0          0          0  ARMCTRL-level  64 Edge      dwc_otg, dwc_otg_pcd, dwc_otg_hcd:usb1 
86:       8025          0          0          0  ARMCTRL-level  88 Edge      mmc0 
87:       5121          0          0          0  ARMCTRL-level  89 Edge      uart-pl011 
92:      52579          0          0          0  ARMCTRL-level  94 Edge      mmc1


62번 인터럽트는 너무 자주 발생하고 51번 인터럽트는 발생 빈도가 너무 낮으니 23번 “3f00b880.mailbox” 인터럽트가 적당합니다.

이제 23번 인터럽트를 처리하는 IRQ 스레드를 생성하는 코드를 작성을 시작합니다. 이후 인터럽트 핸들러가 수행한 후 IRQ 스레드가 어떤 흐름으로 호출되는지도 점검하겠습니다.

23번 인터럽트 IRQ 스레드 생성 실습 패치 코드 입력해보기 

우선 전체 패치 코드를 소개합니다.
diff --git a/drivers/mailbox/bcm2835-mailbox.c b/drivers/mailbox/bcm2835-mailbox.c
index d9c6c217c..fe6e52996 100644
--- a/drivers/mailbox/bcm2835-mailbox.c
+++ b/drivers/mailbox/bcm2835-mailbox.c
@@ -72,6 +72,23 @@ static struct bcm2835_mbox *bcm2835_link_mbox(struct mbox_chan *link)
  return container_of(link->mbox, struct bcm2835_mbox, controller);
 }
 
+static irqreturn_t bcm2835_mbox_threaded_irq(int irq, void *dev_id)
+{
+ void *stack;
+ struct thread_info *current_thread;
+
+ stack = current->stack;
+ current_thread = (struct thread_info*)stack;
+
+ trace_printk("irq=%d, process: %s \n", irq, current->comm);
+ trace_printk("[+] in_interrupt: 0x%08x,preempt_count = 0x%08x, stack=0x%08lx \n",
+ (unsigned int)in_interrupt(), (unsigned int)current_thread->preempt_count, (long unsigned int)stack);
+
+    dump_stack();
+
+ return IRQ_HANDLED;
+}
+
 static irqreturn_t bcm2835_mbox_irq(int irq, void *dev_id)
 {
  struct bcm2835_mbox *mbox = dev_id;
@@ -83,13 +100,13 @@ static irqreturn_t bcm2835_mbox_irq(int irq, void *dev_id)
  dev_dbg(dev, "Reply 0x%08X\n", msg);
  mbox_chan_received_data(link, &msg);
  }
- return IRQ_HANDLED;
+ return IRQ_WAKE_THREAD;
 }
 
 static int bcm2835_send_data(struct mbox_chan *link, void *data)
 {
  struct bcm2835_mbox *mbox = bcm2835_link_mbox(link);
- u32 msg = *(u32 *)data;
+ u32 msg = *(u32 *)data;
 
  spin_lock(&mbox->lock);
  writel(msg, mbox->regs + MAIL1_WRT);
@@ -154,8 +171,12 @@ static int bcm2835_mbox_probe(struct platform_device *pdev)
  return -ENOMEM;
  spin_lock_init(&mbox->lock);
 
- ret = devm_request_irq(dev, platform_get_irq(pdev, 0),
-        bcm2835_mbox_irq, 0, dev_name(dev), mbox);
+        
+ ret = devm_request_threaded_irq(dev, platform_get_irq(pdev, 0),
+        bcm2835_mbox_irq, bcm2835_mbox_threaded_irq, 0, dev_name(dev), mbox);
+        
  if (ret) {
  dev_err(dev, "Failed to register a mailbox IRQ handler: %d\n",
  ret);

이제 패치 코드를 입력하는 방법을 설명해 드리겠습니다.

우선 bcm2835_send_data() 함수에 있는 devm_request_irq() 함수 코드 대신 devm_request_threaded_irq() 함수로 바꿉니다. 아래 – 표시가 된 코드가 원래 코드이고 +로 표시된 코드가 새롭게 입력해야 할 코드입니다.
- ret = devm_request_irq(dev, platform_get_irq(pdev, 0),
-        bcm2835_mbox_irq, 0, dev_name(dev), mbox);
+        
+ ret = devm_request_threaded_irq(dev, platform_get_irq(pdev, 0),
+        bcm2835_mbox_irq, bcm2835_mbox_threaded_irq, 0, dev_name(dev),

devm_request_irq() 함수는 인터럽트 핸들러만 등록하는 함수인데 devm_request_threaded_irq() 함수로 인터럽트 핸들러와 IRQ 스레드 핸들러를 등록할 수 있습니다. 여기서 IRQ 스레드 핸들러 함수는 bcm2835_mbox_threaded_irq()로 지정합니다. 

인터럽트 컨택스트에서 빨리해야 할 일은 bcm2835_mbox_irq() 함수, 조금 있다가 프로세스 레벨에서 처리할 일은 bcm2835_mbox_threaded_irq() 함수에서 처리하는 것입니다. 

다음엔 bcm2835_mbox_irq() 함수를 어떻게 수정했는지 알아볼 차례입니다. 
01 static irqreturn_t bcm2835_mbox_irq(int irq, void *dev_id)
02 {
03 struct bcm2835_mbox *mbox = dev_id;
@@ -83,13 +100,13 @@ static irqreturn_t bcm2835_mbox_irq(int irq, void *dev_id)
04 dev_dbg(dev, "Reply 0x%08X\n", msg);
05 mbox_chan_received_data(link, &msg);
06 }
07 - return IRQ_HANDLED;
08 + return IRQ_WAKE_THREAD;
09 }

원래 이 함수는 07 번째 줄과 같이 IRQ_HANDLED을 반환했습니다. 그런데 IRQ 스레드를 실행시키려면 위 코드와 같이 IRQ_HANDLED 대신 IRQ_WAKE_THREAD를 입력해야 합니다. 

이렇게 코드를 수정하는 이유는 뭘까요? 이전 절에 배운 바와 같이 대부분 인터럽트 핸들러는 __handle_irq_event_percpu() 함수에서 호출합니다. 그런데 __handle_irq_event_percpu() 함수가 인터럽트 핸들러에서 IRQ_WAKE_THREAD를 반환해야 __irq_wake_thread() 함수를 호출해서 IRQ 스레드를 깨우기 때문입니다.

이번에는 bcm2835_mbox_threaded_irq() 구현부 코드를 보겠습니다.
이 코드는 bcm2835_mbox_irq() 함수 윗부분에 입력하시면 됩니다. 혹시 숫자와 + 기호까지 코드로 입력하면 안됩니다. + 기호는 리눅스 패치 코드에서 새롭게 추가되는 코드를 표현하는 것일 뿐입니다.
1 +static irqreturn_t bcm2835_mbox_threaded_irq(int irq, void *dev_id)
2 +{
3 + void *stack;
4 + struct thread_info *current_thread;
5 +
6 + stack = current->stack;
7 + current_thread = (struct thread_info*)stack;
8 +
9 + trace_printk("irq=%d, process: %s \n", irq, current->comm);
10+ trace_printk("[+] in_interrupt: 0x%08x,preempt_count = 0x%08x, stack=0x%08lx \n",
11+ (unsigned int)in_interrupt(), (unsigned int)current_thread->preempt_count, (long unsigned int)stack);
12+
13+    dump_stack();
14+
15+ return IRQ_HANDLED;
16+}
+

이번에 bcm2835_mbox_threaded_irq() 함수 구현부 코드를 소개합니다.

9번째부터 11번째 줄 코드는 프로세스 이름과 인터럽트 번호 그리고 in_interrupt() 함수 반환값을 출력합니다. 이후 13번째 줄 코드에서 dump_stack() 함수를 호출해서 콜스택을 출력합니다.

dump_stack() 함수는 생각보다 많은 일을 합니다. 현재 구동 중인 프로세스의 스택 주소를 얻어서 스택에 푸시된 R14와 Frame Pointer(이전 스택 주소) 레지스터를 읽어 콜스택을 커널 로그로 출력하기 때문입니다. 그래서 인터럽트 핸들러나 인터럽트 컨택스트에서 이 함수를 호출하면 시스템이 느려지거나 오동작을 하니 주의해야 합니다.

이렇게 코드를 입력한 후 컴파일 후 라즈비안에 설치를 합니다. 라즈베리파이를 재부팅시키고  6.1.2 절에 소개한 irq_thread_trace.sh 셸 스크립트에서 아래부분만 수정한 다음에 스크립트를 실행해서 ftrace 로그를 설정합니다.
echo bcm2835_mbox_threaded_irq bcm2835_mbox_irq   > /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"

bcm2835_mbox_threaded_irq() 함수와 bcm2835_mbox_irq() 함수를 set_ftrace_filter에 지정하는 코드입니다.

이 셸 스크립트를 실행한 후 20초 후에 ftrace 로그를 받으면 됩니다. 그 사이 23번 인터럽트가 여러 번 발생할 것입니다.

실습으로 만든 IRQ 스레드를 ftrace로 분석해보기

우리가 같이 분석할 로그는 다음과 같습니다.
1 kworker/0:1-31    [000] d.h.   592.790968: irq_handler_entry: irq=23 name=3f00b880.mailbox
2 kworker/0:1-31    [000] d.h.   592.790970: bcm2835_mbox_irq <-__handle_irq_event_percpu
3 kworker/0:1-31    [000] d.h.   592.791014: <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 => schedule_timeout
13 => schedule_timeout
14 => wait_for_completion_timeout
15 => mbox_send_message
16 => rpi_firmware_transaction
17 => rpi_firmware_property_list
18 => rpi_firmware_property
19 => rpi_firmware_get_throttled
20 => get_throttled_poll
21 => process_one_work
22 => worker_thread
23 => kthread
24 => ret_from_fork
25 kworker/0:1-31    [000] d.h.   592.791016: irq_handler_exit: irq=23 ret=handled 
26 <idle>-0 [003] dnh.   592.791033: sched_wakeup: comm=irq/23-3f00b880 pid=33 prio=49 target_cpu=003
27 <idle>-0   [003] d...   592.791048: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=irq/23-3f00b880 next_pid=33 next_prio=49
28 irq/23-3f00b880-33    [003] ....   592.791052: bcm2835_mbox_threaded_irq <-irq_thread_fn
29 irq/23-3f00b880-33    [003] ....   592.791064: <stack trace>
30 => kthread
31 => ret_from_fork
32     kworker/0:1-31    [000] ....   592.791065: workqueue_execute_end: work struct b97a0d44
33 irq/23-3f00b880-33    [003] ....   592.791073: bcm2835_mbox_threaded_irq: irq=23, process: irq/23-3f00b880 
34 irq/23-3f00b880-33    [003] ....   592.791076: bcm2835_mbox_threaded_irq: [+] in_interrupt: 0x00000000,preempt_count = 0x00000000, stack=0xb9714000

우선 첫 번째 줄 로그는 3f00b880.mailbox 인터럽트가 발생했다고 말해줍니다. 
1 kworker/0:1-31    [000] d.h.   592.790968: irq_handler_entry: irq=23 name=3f00b880.mailbox

그 다음 두 번째 줄부터 25번 줄 로그까지 여러 함수들이 늘어서 있습니다.
2 kworker/0:1-31    [000] d.h.   592.790970: bcm2835_mbox_irq <-__handle_irq_event_percpu
3 kworker/0:1-31    [000] d.h.   592.791014: <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 => schedule_timeout
13 => schedule_timeout
14 => wait_for_completion_timeout
15 => mbox_send_message
16 => rpi_firmware_transaction
17 => rpi_firmware_property_list
18 => rpi_firmware_property
19 => rpi_firmware_get_throttled
20 => get_throttled_poll
21 => process_one_work
22 => worker_thread
23 => kthread
24 => ret_from_fork
25 kworker/0:1-31    [000] d.h.   592.791016: irq_handler_exit: irq=23 ret=handled 

함수 호출 흐름을 살펴보면 pid가 31인 kworker/0:1워커 스레드가 schedule_timeout() 함수에서 실행 중이었습니다. 이때 인터럽트가 발생해서 인터럽트 벡터인 __irq_svc 레이블이 실행 한 후 인터럽트 핸들러인 bcm2835_mbox_irq() 함수가 호출됐습니다.

다음 26 번째 줄 로그입니다. 
26 <idle>-0     [003] dnh.   592.791033: sched_wakeup: comm=irq/23-3f00b880 pid=33 prio=49 target_cpu=003

“irq/23-3f00b880” 프로세스를 깨우는 동작입니다. “irq/23-3f00b880”는 3f00b880.mailbox 인터럽트의 IRQ 스레드 이름입니다. 이번에 작성한 패치로 실제 “irq/23-3f00b880” IRQ 스레드가 생성되서 실행하고 있습니다.

이어서 27 번째 줄을 보겠습니다.
27 <idle>-0     [003] d...   592.791048: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=irq/23-3f00b880  next_pid=33 next_prio=49
28 irq/23-3f00b880-33    [003] ....   592.791052: bcm2835_mbox_threaded_irq <-irq_thread_fn
29 irq/23-3f00b880-33    [003] ....   592.791064: <stack trace>
30 => kthread
31 => ret_from_fork

“irq/23-3f00b880”이란 IRQ 스레드로 스케줄링 된 후 “irq/23-3f00b880” IRQ 스레드 핸들러인 bcm2835_mbox_threaded_irq() 함수가 호출됩니다.

마지막 33~34 번째 줄입니다.
33 irq/23-3f00b880-33    [003] ....   592.791073: bcm2835_mbox_threaded_irq: irq=23, process: irq/23-3f00b880 
34 irq/23-3f00b880-33    [003] ....   592.791076: bcm2835_mbox_threaded_irq: [+] in_interrupt: 0x00000000,preempt_count = 0x00000000, stack=0xb9714000

 bcm2835_mbox_threaded_irq() 함수에 추가한 디버깅 로그 정보입니다.

in_interrupt() 함수와 프로세스 struct thread_info 필드 preempt_count가 0x0입니다. 이 값이 0x10000(HARDIRQ_OFFSET)이면 인터럽트 컨택스트인데 0이니 인터럽트 컨택스트가 아닙니다.

패치 코드를 떠 올리면 bcm2835_mbox_threaded_irq() 함수 13번째 줄 코드에 dump_stack 함수를 입력했습니다. 커널 로그로 콜스택을 출력하는 디버깅 코드입니다. 커널 로그를 열어보면 같은 디버깅 정보를 확인할 수 있습니다.
[4.151743] CPU: 3 PID: 33 Comm: irq/23-3f00b880 Tainted: G         C      4.19.30-v7+ #15
[4.151756] Hardware name: BCM2835
[4.151796] [<8010ffe0>] (unwind_backtrace) from [<8010c21c>] (show_stack+0x20/0x24)
[4.151815] [<8010c21c>] (show_stack) from [<8078703c>] (dump_stack+0xc8/0x10c)
[4.151841] [<8078703c>] (dump_stack) from [<8066ab14>] (bcm2835_mbox_threaded_irq+0x80/0x94)
[4.151862] [<8066ab14>] (bcm2835_mbox_threaded_irq) from [<80176c50>] (irq_thread_fn+0x2c/0x64)
[4.151880] [<80176c50>] (irq_thread_fn) from [<80176f78>] (irq_thread+0x148/0x20c)
[4.151895] [<80176f78>] (irq_thread) from [<8013daac>] (kthread+0x144/0x174)
[4.151915] [<8013daac>] (kthread) from [<801080cc>] (ret_from_fork+0x14/0x28)

커널 로그로 bcm2835_mbox_threaded_irq() 함수는 irq/23-3f00b880 IRQ 스레드에서 실행됐다고 알 수 있습니다. ftrace 로그에서 봤던 정보와 같습니다.

생성한 IRQ 스레드 실행 전체 흐름도 파악해보기

우리는 23번 인터럽트 후반부를 처리하는 "irq/23-3f00b880" IRQ 스레드를 만들어 ftrace로 실행 과정을 확인했습니다. 이번 소절에 실습한 "irq/23-3f00b880" IRQ 스레드 실행 전체 흐름도는 다음 그림과 같습니다.
 
[그림 6.8] "irq/23-3f00b880" IRQ 스레드 전체 실행 흐름도

각 단계별 동작을 리뷰하면서 이번 실습 과정을 마무리합시다.

[1] 단계: 23 번 인터럽트가 발생해 인터럽트 벡터인 __irq_svc 레이블이 실행합니다. 커널 인터럽트 공통 함수가 호출돼 인터럽트 핸들러를 실행합니다.

[2] 단계: 23 번 인터럽트 핸들러인 bcm2835_mbox_irq() 함수가 호출됩니다. 이 함수에 우리가 실습 코드를 입력했습니다. IRQ_WAKE_THREAD 플래그를 반환해 "irq/23-3f00b880" IRQ 스레드를 깨웁니다.

[3] 단계: "irq/23-3f00b880" IRQ 스레드 핸들러인 bcm2835_mbox_threaded_irq() 함수가 호출됩니다. bcm2835_mbox_threaded_irq() 는 이번 실습 과정에서 입력한 함수입니다. 

이번 소절에 소개된 패치 원리를 이해하면 여러분이 갖고 있는 다른 리눅스 보드에도 IRQ 스레드를 만들 수 있습니다. 이번에 소개한 패치 코드를 이해하고 실습한 다음 다른 코드에도 적용해보면 IRQ 스레드가 더 오랫동안 머리 속에 남을 것입니다.

그리고 이번 시간에는 ftrace를 활용해 함수 콜스택을 분석했습니다. 분석하고 싶은 함수에 필터를 걸고 콜스택을 확인한 것입니다. 그런데 ftrace 에서는 함수 실행 시간을 알려주는 더 정교한 기능을 제공합니다. 이어서 함수 실행 시간을 측정할 수 있는 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





핑백

덧글

댓글 입력 영역