Linux Kernel(4.14) Hacks

rousalome.egloos.com

포토로그 Kernel Crash




[라즈베리파이][리눅스커널]인터럽트 컨택스트란 (1) #CS [라즈베리파이][커널]인터럽트


인터럽트 컨택스트란
인터럽트 컨택스트란 용어가 좀 낯설진 않나요? 인터럽트 컨택스트를 배우기 전에 우선 컨택스트란 용어를 배울 필요가 있습니다. 

혹시 컨텍스트 스위칭이란 단어 들어보신 적이 있나요? 리눅스 커널에서 많이 쓰는 용어입니다. 어렵게 설명하면 컨텍스트란 현재 실행하고 있는 레지스터 묶음을 의미합니다. ARM 프로세스에서는 15개의 레지스터(r0부터 pc)가 있습니다. 이중에서 pc(Program Counter)란 레지스터는 현재 실행 중인 코드 주소를 담고 있습니다. 만약 현재 커널이 start_kernel이란 함수를 실행하고 있는데 이 함수의 주소가 0xC000D000이면 pc란 레지스터는 0xC000D000 주소입니다. 이렇게 PC 레지스터를 포함한 여러 레지스터 세트로 현재 실행 중인 프로그램 상태를 저장할 수 있습니다.

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

그럼 어떤 프로세스가 스케줄링 될 때 현재 실행 중인 레지스터를 어느 자료 구조로 저장할까요? 이렇게 컨택스트 즉 현재 실행 중인 레지스터 정보를 표현하는 자료구조는 struct thread_info.cpu_context입니다. struct thread_info 구조체 선언 부에 cpu_context란 멤버가 보이죠? 변수 이름도 context입니다.
struct thread_info {
unsigned long flags; /* low level flags */
// .. 생략 ..
struct cpu_context_save cpu_context; /* cpu context */

이 멤버 선언 부를 눈여겨 보면 역시나 레지스터값들입니다. 이 멤버 변수에 현재 동작 중인 프로세스의 레지스터를 저장합니다.
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 */
};

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

이제 컨택스트란 용어의 의미가 조금 덜 낯설지 않나요? 이제 처음으로 돌아가서 인터럽트 컨택스트의 의미를 짚어 보겠습니다. 인터럽트 컨택스트란 용어는 무슨 뜻일까요? “인터럽트 처리 중”이란 의미입니다. 인터럽트가 발생하면 인터럽트 벡터 주소부터 인터럽트 핸들러까지 코드 흐름으로 인터럽트를 처리합니다. 인터럽트 컨택스트란 이 코드 흐름 중 하나라고 볼 수 있습니다.

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

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

ftrace와 커널 로그로 인터럽트 컨택스트 확인하기
리눅스 커널에서 커널 동작을 가장 정밀하게 담고 있는 로그는 뭘까요? 아마 많은 리눅스 전문가들은 ftrace라고 대답할 것입니다. ftrace는 리눅스 커널에서 제공하는 가장 강력한 디버그 로그입니다. 여러분들도 ftrace 로그를 자주 활용해서 리눅스 커널을 익히기를 바랍니다. 자 이제 ftrace로그를 분석하면서 인터럽트가 어떻게 처리되는지 확인해볼까요? 

ftrace로 인터럽트를 처리하는 인터럽트 핸들러 함수에 필터를 걸고 콜 스택 로그를 받아 보겠습니다. 아래는 라즈베리안에서 dwc_otg 란 인터럽트의 핸들러인 dwc_otg_common_irq 함수에 필터를 걸고 받은 ftrace 로그입니다. dwc_otg_common_irq 함수의 콜스택을 보고 싶을 때 이 함수에 필터를 걸면 됩니다.
kworker/0:0-27338 [000] d.h.  6028.897808: irq_handler_entry: irq=62 name=dwc_otg
kworker/0:0-27338 [000] 6028.897809: dwc_otg_common_irq <-__handle_irq_event_percpu
kworker/0:0-27338 [000] 6028.897847: <stack trace>
 => handle_irq_event
 => handle_level_irq
 => generic_handle_irq
 => bcm2836_chained_handle_irq
 => generic_handle_irq
 => __handle_domain_irq
 => bcm2836_arm_irqchip_handle_irq
 => __irq_svc
 => _raw_spin_unlock_irqrestore
 => _raw_spin_unlock_irqrestore
 => schedule_timeout
 => wait_for_common
 => wait_for_completion_timeout
 => usb_start_wait_urb
 => usb_control_msg
 => __usbnet_read_cmd
 => usbnet_read_cmd
 => __smsc95xx_read_reg
 => __smsc95xx_phy_wait_not_busy
 => __smsc95xx_mdio_read
 => check_carrier
 => process_one_work
 => worker_thread
 => kthread
 => 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 로그는 조금 헷갈릴 수 있으니 조금 더 상세히 살펴볼 필요가 있습니다.
kworker/0:0-27338 [000] 6028.897809: dwc_otg_common_irq <-__handle_irq_event_percpu
kworker/0:0-27338 [000] 6028.897847: <stack trace>
 => handle_irq_event
 => handle_level_irq

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

여기까지 ftrace 로그에서 함수 호출 방향을 알아 봤으니 이제 로그가 어떤 의미인지 간단히 알아볼까요? 

다음은 pid가 27338인 kworker/0:0란 워커 쓰레드가 실행되는 도중 인터럽트가 발생했다는 의미입니다. 워커 쓰레드는 워크 큐를 실행할 용도인 커널 쓰레드인데 커널 공간에서만  실행합니다.
kworker/0:0-27338 [000] d.h.  6028.897808: irq_handler_entry: irq=62 name=dwc_otg

그리고, 인터럽트 번호는 62번이고 이름은 dwc_otg입니다.

이제는 콜 스택을 봐야 할 차례입니다. 콜 스택은 가장 먼저 호출된 함수부터 봐야 하니 로그의 가장 아랫부분부터 봐야 합니다. 우선 kworker/0:0란 워커 쓰레드가 수행되는 콜 스택입니다. check_carrier 란 워크 핸들러가 호출된 후 USB 드라이버 처리를 하고 있었습니다. 
=> _raw_spin_unlock_irqrestore
 => _raw_spin_unlock_irqrestore
 => schedule_timeout
 => wait_for_common
 => wait_for_completion_timeout
 => usb_start_wait_urb
 => usb_control_msg
 => __usbnet_read_cmd
 => usbnet_read_cmd
 => __smsc95xx_read_reg
 => __smsc95xx_phy_wait_not_busy
 => __smsc95xx_mdio_read
 => check_carrier
 => process_one_work
 => worker_thread
 => kthread
 => ret_from_fork

이번에 인터럽트가 발생하고 난 후 로그를 알아 봅시다. kworker/0:0란 워커 쓰레드가 스핀락을 푸는 _raw_spin_unlock_irqrestore 함수 동작 중에 "irq=62 name=dwc_otg"란 인터럽트가 발생했습니다.
kworker/0:0-27338 [000] 6028.897809: dwc_otg_common_irq <-__handle_irq_event_percpu
kworker/0:0-27338 [000] 6028.897847: <stack trace>
 => handle_irq_event
 => handle_level_irq
 => generic_handle_irq
 => bcm2836_chained_handle_irq
 => generic_handle_irq
 => __handle_domain_irq
 => bcm2836_arm_irqchip_handle_irq
 => __irq_svc  // 익셉션 벡터
 => _raw_spin_unlock_irqrestore

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 함수를 호출하는 것입니다.

그럼 위 로그를 받기 위해 어떻게 설정해야 할까요? dwc_otg_common_irq함수로 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"

이번에는 인터럽트 컨택스트 관점으로 ftrace log를 로그를 분석해 봅시다. ret_from_fork 함수부터 _raw_spin_unlock_irqrestore 함수 구간까지 프로세스 컨택스트이고, __irq_svc 함수부터 dwc_otg_common_irq 함수 구간까지가 인터럽트 컨택스트입니다. 즉, 인터럽트가 발생하고 난 다음 서브 루틴 동작 구간을 인터럽트 컨택스트라고 말할 수 있습니다. 그 이외에는 프로세스 컨택스트라고 볼 수 있습니다.

함수 흐름을 보면 62번 인터럽트가 발생해서 스핀락을 해제하는 함수 실행(_raw_spin_unlock_irqrestore)를 멈추고 인터럽트 벡터가 실행된 후 인터럽트 서브 루틴 (__irq_svc-> bcm2836_arm_irqchip_handle_irq)이 실행됐네요. 

자 이제 정리하면 위 동작은 다음 다이어그램으로 표현할 수 있습니다. 

위 블록 다이어그램은 프로세스가 스택 공간에서 어떻게 동작하는지 보여줍니다. 간단한 그림인데 이를 제대로 이해하기 위해 알아야 하는 내용이 조금 많습니다. 

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

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

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

프로세스별로 할당된 스택 주소는 태스크 디스크립터 멤버 struct task_struct.stack로 확인할 수 있습니다. 그런데 이 주소는 스택 Top 주소입니다. 프로세스에서 함수들을 실행할 때는 스택 Bottom 주소인 struct task_struct.stack + 0x2000(스택 사이즈)에서 스택 Top 주소인struct task_struct.stack 방향으로 즉 높은 주소에서 낮은 주소로 스택을 사용합니다. 

이렇게 프로세스가 스택 메모리 공간에서 실행 중 인터럽트가 발생하면 인터럽트 벡터와 인터럽트 서비스 루틴은 어느 공간에서 실행할까요? 정답은 프로세스 스택 공간에서 실행됩니다. 전세 살 듯이 잠시 프로세스 스택 공간을 활용하는 거죠. 조금 더 구체적으로 인터럽트 벡터인 __irq_svc 함수부터 인터럽트 핸들러인 dwc_otg_common_irq 함수까지 현재 실행 중인 프로세스의 스택 공간에서 실행됩니다.

그런데 모든 아키텍처에서 인터럽트 발생 시 프로세스 스택 공간을 써서 인터럽트 서비스 루틴을 실행하지는 않습니다. 참고로 ARM64 아키텍처에서는 인터럽트 전용 스택인 IRQ Stack을 할당해서 인터럽트 벡터부터 이 스택 공간에서 처리되도록 합니다. 하지만 ARM 32비트 아키텍처인 라즈베리파이는 프로세스가 쓰는 스택 공간을 쓴다는 점 기억하세요.

전 리눅스 커뮤니티에서 여러 리눅스 커널 초고수를 만났는데요. 이분들의 공통점은 어떤 로그이든 많이 상상하고 고민하면서 분석한다는 점입니다. 이렇게 함수 흐름 하나에도 조금만 깊이 생각하면 그 뒷면에 여러 가지 공학적 의미가 있거든요. 여러분도 혹시 고수가 되기 바라면 이런 방식으로 코드나 로그를 보셨으면 좋겠습니다.

이번에 커널 로그로 인터럽트 컨택스트 구간을 확인 합시다. 아래 커널 로그는 __irq_svc(asm)--unwind_backtrace() 함수들은 인터텁트 컨택스트에서 수행되며, start_kernel() --arch_cpu_idle() 함수 구간은 프로세스 컨택스트라고 볼 수 있습니다. 참고로 아래 콜스택은 WARN() 매크로가 수행되면 출력되는 커널 로그인데 보통 콜스택을 출력합니다.
[출처: 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 로그가 보이면 “아, 인터럽트가 발생해서 인터럽트를 처리 중이구나”라고 해석하면 됩니다. 

이번 장에서는 인터럽트 컨택스트에 대해서 알아봤습니다. 정리하면 현재 수행 중인 코드가 인터럽트를 처리하는 중이란 의미죠. 그럼 인터럽트 컨택스트를 알려주는 함수가 있을 것 같지 않나요? 


핑백

덧글

댓글 입력 영역