Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

1112
737
82111


[리눅스커널][인터럽트] 인터럽트 컨택스트란 - in_interrupt() 5장. 인터럽트 핸들링

인터럽트 컨택스트는 현재 인터럽트를 핸들링 중이란 뜻입니다.

인터럽트 컨택스트 관련 코드와 세부 동작을 알아보기 전에 인터럽트 컨택스트가 커널에서 어떤 의미인지 짚어 보겠습니다. 먼저 인터럽트 컨택스트란 용어는 인터럽트와 컨택스트란 단어를 합친 것입니다. 달리 보면 인터럽트의 컨택스트라고 볼 수 있습니다. 여기서 컨택스트란 무슨 뜻일까요? 

5.2.1 인터럽트 컨택스트란

인터럽트 컨택스트는 현재 인터럽트를 핸들링 중이란 뜻입니다.

인터럽트 컨택스트 관련 코드와 세부 동작을 알아보기 전에 인터럽트 컨택스트가 커널에서 어떤 의미인지 짚어 보겠습니다. 먼저 인터럽트 컨택스트란 용어는 인터럽트와 컨택스트란 단어를 합친 것입니다. 달리 보면 인터럽트의 컨택스트라고 볼 수 있습니다. 여기서 컨택스트란 무슨 뜻일까요? 

리눅스 커널에서 컨택스트란 무엇인가

커널에서 컨택스트는 실행 그 자체를 의미합니다. 인터럽트 컨택스트의 의미를 파악하기 위해 컨택스트란 무엇인지 살펴보겠습니다.

컨택스트란 현재 실행하고 있는 프로세스 정보가 채워진 레지스터 세트를 의미합니다. ARM 프로세스에서는 15개의 레지스터(r0부터 pc) 세트로 실행 흐름을 표현합니다. 이중에서 프로그램 카운터(Program Counter)란 레지스터는 현재 실행 중인 코드 주소를 저장합니다.

만약 현재 커널이 start_kernel() 함수를 실행하고 있는데 이 함수의 주소가 0xC000D000이면 프로그램 카운터 레지스터는 0xC000D000 입니다. 이렇게 PC 레지스터를 포함한 레지스터 세트로 현재 실행 중인 프로그램 상태를 표현할 수 있습니다.

프로세스가 스케줄링으로 휴면할 때는 현재 실행 중인 레지스터 세트를 특정 공간(자신의 스택 최상단 주소)에 저장합니다. 스케줄링으로 의해 다시 깨어나면 이전에 동작했던 순간부터 실행해야 하기 때문입니다. 프로세스는 다시 실행하기 전에 어떤 동작을 할까요? 프로세스는 휴면할 때 저장했던 레지스터를 로딩합니다. 그 이유는 휴면할 때 저장했던 레지스터가 바로 프로세스 실행 정보를 담고 있기 때문입니다.

이렇게 프로세스 실행은 레지스터 세트로 표현할 수 있습니다. 여기서 말하는 레지스터 세트는 어떤 자료구조일까요?
정답은 struct cpu_context_save 구조체입니다.
[https://elixir.bootlin.com/linux/v4.19.30/source/arch/arm/include/asm/thread_info.h]
struct cpu_context_save {
__u32 r4;
__u32 r5;
__u32 r6;
__u32 r7;
__u32 r8;
__u32 r9;
__u32 sl;
__u32 fp;
__u32 sp;
__u32 pc;
__u32 extra[2]; /* Xscale 'acc' register, etc */
};

struct cpu_context_save 구조체 필드는 프로세스가 실행 중인 레지스터값들입니다. 이 필드에 현재 동작 중인 프로세스의 레지스터를 저장합니다.

그러면 struct cpu_context_save 구조체를 어디에 저장할까요? 프로세스 스택 최상단 주소 struct thread_info 구조체 cpu_context 필드에 저장합니다. 
[https://elixir.bootlin.com/linux/v4.19.30/source/arch/arm/include/asm/thread_info.h]
01 struct thread_info {
02 unsigned long flags; /* low level flags */
03 struct cpu_context_save cpu_context; /* cpu context */

struct thread_info 구조체 03 번째 플래그를 눈여겨봅시다. 필드 이름도 cpu_context 입니다.

 쉽게 설명해서 컨택스트란 무엇일까요? 정답은 “실행 중” 이란 뜻입니다. 레지스터 세트로 현재 실행 중인 상태를 저장하기 때문입니다. 

이제 처음으로 돌아가서 인터럽트 컨택스트의 의미를 짚어 보겠습니다. 

인터럽트 컨택스트란 무엇인가

인터럽트 컨택스트란 용어는 무슨 뜻일까요? 
“인터럽트 처리 중”이란 의미입니다. 인터럽트가 발생하면 인터럽트 벡터 주소부터 인터럽트 핸들러까지 함수 흐름으로 인터럽트를 처리합니다. 인터럽트 컨택스트란 이 흐름 중 하나라고 볼 수 있습니다.

그래도 인터럽트 컨택스트란 의미는 좀 파악하기 어렵습니다. 커널은 이론으로 아무리 자세하게 읽어도 이해가 안 되고 머릿속에 잘 남지 않는 것 같습니다. 그렇다고 실망하지 맙시다. 우리에겐 커널 코드와 ftrace란 강력한 도구가 있습니다. ftrace 로그을 열어서 실제 어느 로그가 인터럽트 컨택스트인지 알아보면 더 빨리 오래 기억할 수 있습니다. 

인터럽트 컨택스트란 용어는 왜 배워야 할까
 
인터럽트 컨택스트란 용어를 알아야 하는 이유는 간단합니다. 
리눅스 커널 전반에 이 용어를 많이 쓰고 이 개념을 적용한 커널 코드가 많기 때문입니다. 이 인터럽트 컨택스트에 대한 공학적인 의미를 이해하지 못하면 다른 코드를 이해하기 어렵습니다.

인터럽트 컨택스트란 인터럽트 처리 중이란 의미입니다. 다음 소절에서는 인터럽트 컨택스트를 ftrace와 커널 로그로 조금 더 알아보겠습니다.

5.2.2 ftrace와 커널 로그로 인터럽트 컨택스트 확인하기

이번 절에서는 ftrace로그를 분석하면서 커널이 인터럽트를 어떻게 처리되는지 배워 봅시다. 

리눅스 커널에서 커널 동작을 가장 정밀하게 담고 있는 로그는 뭘까요? 아마 많은 리눅스 전문가들은 ftrace라고 대답할 겁니다. ftrace는 리눅스 커널에서 제공하는 가장 강력한 디버그 로그입니다. 리눅스 커널의 공식 트레이서입니다. 여러분들도 ftrace 로그를 자주 활용해서 리눅스 커널을 익히기를 바랍니다.

ftrace로 인터럽트를 처리하는 인터럽트 핸들러 함수에 필터를 걸고 콜 스택 로그를 받아 보겠습니다. 

인터럽트 동작을 확인하기 위한 ftrace 설정 방법
ftrace로 인터럽트 동작을 분석하기 전에 ftrace 설정 방법을 소개합니다.

다음과 같은 shell script를 작성한 후 irq_stack_trace.sh 이름으로 저장하고, “./irq_stack_trace.sh”를 입력해서 스크립트를 실행하면 됩니다.
#!/bin/sh

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 dwc_otg_common_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 "event enabled"

echo 1 > /sys/kernel/debug/tracing/options/func_stack_trace
echo "function stack trace enabled"

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

dwc_otg_common_irq() 함수로 ftrace 스택 트레이서를 설정하는 셸 스크립트입니다.  (라즈베리파이에서 ftrace 설정하는 방법은 2.2장을 참고하세요). 

라즈베리파이에서 받은 ftrace로 인터럽트 컨택스트 확인하기
다음은 위에서 소개한 dwc_otg 인터럽트의 인터럽트 핸들러인 dwc_otg_common_irq() 함수에 필터를 걸고 받은 ftrace 로그입니다. 
1 kworker/0:0-27338 [000] d.h.  6028.897808: irq_handler_entry: irq=62 name=dwc_otg
2 kworker/0:0-27338 [000] 6028.897809: dwc_otg_common_irq <-__handle_irq_event_percpu
3 kworker/0:0-27338 [000] 6028.897847: <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 => _raw_spin_unlock_irqrestore
13 => _raw_spin_unlock_irqrestore
14 => schedule_timeout
15 => wait_for_common
16 => wait_for_completion_timeout
17 => usb_start_wait_urb
18 => usb_control_msg
19 => __usbnet_read_cmd
20 => usbnet_read_cmd
21 => __smsc95xx_read_reg
22 => __smsc95xx_phy_wait_not_busy
23 => __smsc95xx_mdio_read
24 => check_carrier
25 => process_one_work
26 => worker_thread
27 => kthread
28 => ret_from_fork

ftrace로그에서 콜스택을 보는 방법을 먼저 소개합니다. 아래에 있는 함수에서 윗 방향이 함수 호출 흐름입니다. ret_from_fork() 함수가 가장 먼저 실행된 후 다음 함수 흐름을 확인할 수 있습니다.
 kthread -> worker_thread -> process_one_work

이후 handle_level_irq() -> handle_irq_event() -> __handle_irq_event_percpu() -> dwc_otg_common_irq() 순서가 함수 호출 흐름입니다. 

다음 ftrace 로그는 조금 헷갈릴 수 있어 상세히 볼 필요가 있습니다.
2 kworker/0:0-27338 [000] 6028.897809: dwc_otg_common_irq <-__handle_irq_event_percpu
3 kworker/0:0-27338 [000] 6028.897847: <stack trace>
4  => handle_irq_event
5  => handle_level_irq

handle_irq_event() 함수까지 함수 호출이 수행된 듯합니다. 실제로는 다음 흐름으로 가장 마지막에 수행된 함수는 dwc_otg_common_irq() 입니다. 함수 흐름은 다음과 같습니다.
handle_irq_event -> __handle_irq_event_percpu -> dwc_otg_common_irq


먼저 1번째 줄 로그를 보겠습니다.
1 kworker/0:0-27338 [000] d.h.  6028.897808: irq_handler_entry: irq=62 name=dwc_otg

pid가 27338인 kworker/0:0란 워커 쓰레드가 실행되는 도중 인터럽트가 발생했습니다. 워커 쓰레드는 워크 큐를 실행하는 커널 스레드로 커널 공간에서만 실행합니다. 이 로그가 실행된 시간은 6028.897808 입니다. 인터럽트 번호는 62번이고 이름은 dwc_otg입니다.

이번엔 콜 스택을 볼 차례입니다. 
콜 스택은 가장 먼저 호출된 함수부터 봐야 하니 로그의 가장 아랫부분부터 봐야 합니다. 콜스택을 보니 kworker/0:0란 워커 쓰레드가 수행하는 중입니다. check_carrier() 워크 핸들러 함수가 호출된 후 USB 드라이버 동작 중입니다. 
12 => _raw_spin_unlock_irqrestore
13 => _raw_spin_unlock_irqrestore
14 => schedule_timeout
15 => wait_for_common
16 => wait_for_completion_timeout
17 => usb_start_wait_urb
18 => usb_control_msg
19 => __usbnet_read_cmd
20 => usbnet_read_cmd
21 => __smsc95xx_read_reg
22 => __smsc95xx_phy_wait_not_busy
23 => __smsc95xx_mdio_read
24 => check_carrier
25 => process_one_work
26 => worker_thread
27 => kthread
28 => ret_from_fork

이어서 인터럽트가 발생하고 난 후 로그를 봅시다. 
1 kworker/0:0-27338 [000] d.h.  6028.897808: irq_handler_entry: irq=62 name=dwc_otg
2 kworker/0:0-27338 [000] 6028.897809: dwc_otg_common_irq <-__handle_irq_event_percpu
3 kworker/0:0-27338 [000] 6028.897847: <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 => _raw_spin_unlock_irqrestore

kworker/0:0란 워커 스레드가 스핀락을 해제하는 _raw_spin_unlock_irqrestore() 함수 실행 중 "irq=62 name=dwc_otg" 인터럽트가 발생했습니다. 

ARM 프로세스는 인터럽트가 발생하면 익셉션을 유발해 __irq_svc 인터럽트 벡터를 실행합니다. 이후 리눅스 커널 내부 인터럽트 공통 함수가 다음 흐름으로 호출됩니다.
handle_level_irq -> handle_irq_event -> __handle_irq_event_percpu -> dwc_otg_common_irq

이후 “irq=62 name=dwc_otg” 인터럽트의 인터럽트의 핸들러인 dwc_otg_common_irq() 함수를 호출합니다.

이번에는 인터럽트 컨택스트 관점으로 ftrace log를 로그를 분석해 봅시다. 
 1| 프로세스 컨택스트: ret_from_fork() ~ _raw_spin_unlock_irqrestore() 함수 구간
 2| 인터럽트 컨택스트: __irq_svc ~ dwc_otg_common_irq() 함수 구간

인터럽트가 발생하고 난 다음 서브 루틴 동작 구간이 인터럽트 컨택스트입니다. 그 이외에는 프로세스 컨택스트입니다. 

인터럽트 벡터가 실행되기 직전 로그를 조금 상세히 보겠습니다.
10 => bcm2836_arm_irqchip_handle_irq
11 => __irq_svc
12 => _raw_spin_unlock_irqrestore

복잡해 보이는 로그는 다음 그림을 보면 쉽게 이해할 수 있습니다. 
 
 [그림 5.6] 인터럽트 발생 시 프로세스 스택 공간에서 함수 호출 흐름  

62번 인터럽트가 발생해서 스핀락을 해제하는 _raw_spin_unlock_irqrestore() 함수 실행을 멈추고 인터럽트 벡터가 실행 흐름이 바뀌었습니다. 이 후 커널 인터럽트 내부 함수가 호출해 62번 인터럽트 핸들러가 호출됐습니다.  

커널 로그로 인터럽트 컨택스트 확인하기

이번엔 다른 리눅스 시스템에서 추출한 커널 로그를 보면서 인터럽트 컨택스트를 배워봅시다. 같이 분석할 커널 로그는 다음과 같습니다.
[https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git/commit/?id=bbe097f092b0d13e9736bd2794d0ab24547d0e5d]

WARNING: CPU: 0 PID: 0 at include/linux/usb/gadget.h:405
 ecm_do_notify+0x188/0x1a0
 Modules linked in:
 CPU: 0 PID: 0 Comm: swapper Not tainted 4.7.0+ #15
 Hardware name: Atmel SAMA5
 [<c010ccfc>] (unwind_backtrace) from [<c010a7ec>] (show_stack+0x10/0x14)
 [<c010a7ec>] (show_stack) from [<c0115c10>] (__warn+0xe4/0xfc)
 [<c0115c10>] (__warn) from [<c0115cd8>] (warn_slowpath_null+0x20/0x28)
 [<c0115cd8>] (warn_slowpath_null) from [<c04377ac>] (ecm_do_notify+0x188/0x1a0)
 [<c04377ac>] (ecm_do_notify) from [<c04379a4>] (ecm_set_alt+0x74/0x1ac)
 [<c04379a4>] (ecm_set_alt) from [<c042f74c>] (composite_setup+0xfc0/0x19f8)
 [<c042f74c>] (composite_setup) from [<c04356e8>] (usba_udc_irq+0x8f4/0xd9c)
 [<c04356e8>] (usba_udc_irq) from [<c013ec9c>] (handle_irq_event_percpu+0x9c/0x158)
 [<c013ec9c>] (handle_irq_event_percpu) from [<c013ed80>] (handle_irq_event+0x28/0x3c)
 [<c013ed80>] (handle_irq_event) from [<c01416d4>] (handle_fasteoi_irq+0xa0/0x168)
 [<c01416d4>] (handle_fasteoi_irq) from [<c013e3f8>] (generic_handle_irq+0x24/0x34)
 [<c013e3f8>] (generic_handle_irq) from [<c013e640>] (__handle_domain_irq+0x54/0xa8)
 [<c013e640>] (__handle_domain_irq) from [<c010b214>] (__irq_svc+0x54/0x70)
 [<c010b214>] (__irq_svc) from [<c0107eb0>] (arch_cpu_idle+0x38/0x3c)
 [<c0107eb0>] (arch_cpu_idle) from [<c0137300>] (cpu_startup_entry+0x9c/0xdc)
 [<c0137300>] (cpu_startup_entry) from [<c0900c40>] (start_kernel+0x354/0x360)
 [<c0900c40>] (start_kernel) from [<20008078>] (0x20008078)
 ---[ end trace e7cf9dcebf4815a6 ]---J6

위 커널 로그에서 __irq_svc(asm) ~ unwind_backtrace() 함수들은 인터텁트 컨택스트에서 수행되며, start_kernel() ~ arch_cpu_idle() 함수 구간은 프로세스 컨택스트라고 볼 수 있습니다. 

커널 로그에서 __irq_svc 레이블은 개발 도중 자주 보게 됩니다. 위와 같이 콜스택에서 인터럽트 벡터인 __irq_svc 레이블을 보면 “아, 인터럽트가 발생해서 인터럽트를 처리 중이구나”라고 해석합시다.
 
이번 절에서는 인터럽트 컨택스트에 대해서 알아봤습니다. 인터럽트 컨택스트란 현재 수행 중인 코드가 인터럽트를 처리하는 중이란 의미입니다. 다음 소절에서는 인터럽트 컨택스트를 알려주는 함수를 소개합니다.

프로세스는 높은 주소에서 낮은 주소 방향으로 스택을 씁니다. 사실 꼭 높은 주소에서 낮은 주소 방향으로 스택을 사용하도록 설정할 필요는 없습니다. 대신 반대로 낮은 주소에서 높은 주소 방향으로 스택을 쓰게 설정할 수 있습니다. 그런데 커널 고수들이 프로세스를 높은 주소에서 낮은 주소 방향으로 설정하니 업계의 사실상 표준이 된 것 같습니다. 

프로세스가 실행 중인 프로세스 스택 공간에 대해서 배워 볼까요? 프로세스가 생성될 때는 커널은 프로세스에게 0x2000 크기만큼 스택 공간을 할당합니다. 또한 프로세스 입장에서 스택 공간은 운동장으로 볼 수 있습니다. 프로세스는 스택 메모리 공간 내에서만 실행할 수 있습니다. 함수를 호출하거나 로컬 변수 사용할 때 자신에게 부여된 고유 스택 메모리를 사용합니다. 프로세스별로 할당된 스택 주소는 어떻게 확인할 수 있나요? 이 내용을 알기 전에 잠깐 태스크 디스크립터에 대해 배워야 합니다. 

여러분 혹시 TCB(Task Control Block)란 용어 들어본 적 있나요? 임베디드 시스템에서 태스크 혹은 프로세스 정보를 담고 있는 자료구조입니다. 리눅스 커널의 프로세스 정보를 담고 있는 자료 구조는 뭘까요? 여기서 임베디드 시스템에서 말하는 태스크와 리눅스 커널의 프로세스는 같은 개념으로 봐야 합니다. 정답은 struct task_struct입니다. 이 자료 구조에서 프로세스의 속성과 상태 정보를 확인할 수 있습니다.

프로세스별로 할당된 스택 주소는 태스크 디스크립터 struct task_struct 구조체 stack 필드에서 확인할 수 있습니다. 이 값은 스택 최상단 주소입니다. 프로세스에서 함수들을 실행할 때는 스택 최하단 주소에서 스택 최상단 주소 방향으로 스택을 씁니다. 즉, 높은 주소에서 낮은 주소로 스택을 사용합니다.

만약 프로세스가 스택 메모리 공간에서 실행 중 인터럽트가 발생하면 인터럽트 벡터와 인터럽트 서비스 루틴은 어느 공간에서 실행할까요? 정답은 프로세스 스택 공간에서 실행됩니다. 전세 살 듯이 잠시 프로세스 스택 공간을 활용하는 것입니다.

# Reference (인터럽트 처리)


핑백

덧글

댓글 입력 영역