ftrace와 커널 로그로 인터럽트 컨텍스트 확인해보기

ftrace와 커널 로그로 인터럽트 컨텍스트 확인해보기

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


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


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

인터럽트 동작을 확인하기 위한 ftrace 설정
ftrace로 인터럽트의 동작 방식을 분석하기 전에 ftrace를 설정하는 방법을 소개합니다. 먼저 다음 명령어를 입력해 봅시다.

#!/bin/bash

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"

 

 

이 같은 명령어를 입력한 후 irq_stack_trace.sh라는 이름으로 저장합니다. 그러고 나서 다음과 같은 명령어를 입력해 irq_stack_trace.sh 셸스크립트를 실행하면 ftrace를 빨리 설정할 수 있습니다.

root@raspberrypi:/home/pi # ./irq_stack_trace.sh

ftrace 설정 명령어 중 다음 코드를 함께 봅시다.

echo dwc_otg_common_irq > /sys/kernel/debug/tracing/set_ftrace_filter

이 명령어는 set_ftrace_filter에 다음 함수를 설정합니다.

dwc_otg_common_irq()

dwc_otg_common_irq() 함수가 호출될 때 함수 콜스택을 ftrace로 보기 위해 set_ftrace_filter 파일에 함수를 지정하는 것입니다.

이어서 ftrace를 받는 방법을 소개합니다.

#!/bin/bash

echo 0 > /sys/kernel/debug/tracing/tracing_on
echo "ftrace off"

sleep 3

cp /sys/kernel/debug/tracing/trace . 
mv trace ftrace_log.c

위 명령어를 입력해 get_ftrace.sh 셸 스크립트로 저장합니다. 그러고 나서 다음 명령어로 이 셸 스크립트를 실행하면 같은 폴더에 ftrace 로그를 저장한 ftrace_log.c 파일이 만들어집니다.

root@raspberrypi:/home/pi # ./get_ftrace.sh 

지금까지 설명한 실습 과정을 정리해 봅시다.

1. irq_stack_trace.sh 셸 스크립트를 실행해 ftrace를 설정한다.
2. get_ftrace.sh 셸 스크립트를 실행해 ftrace 로그를 받는다.

라즈베리 파이에서 받은 ftrace로 인터럽트 컨텍스트 확인
이제 ftrace 로그 분석을 시작하겠습니다. 먼저 ftrace 로그를 소개합니다.

1 kworker/0:0-27338 [000] d.h.  6028.897808: irq_handler_entry: irq=56 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=56 name=dwc_otg

위 ftrace 메시지는 다음과 같은 사실을 말해줍니다.
 pid가 27338인 kworker/0:0 프로세스 실행 중 인터럽트가 발생
 인터럽트 번호는 56번이고 이름은 dwc_otg
 인터럽트 핸들러가 실행을 시작한 시간은 6028.897808임

이번에는 콜 스택을 볼 차례입니다. 콜 스택에서는 맨 먼저 호출된 함수부터 봐야 하니 로그의 가장 아랫부분부터 봐야 합니다. 

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 로그는 인터럽트가 발생하기 전의 함수 호출 흐름입니다. 콜스택을 보니 kworker/0:0 프로세스가 실행 중입니다. check_carrier() 워크 핸들러 함수가 호출된 후 USB 드라이버가 동작 중입니다. 

이어서 인터럽트가 발생하고 난 후의 로그를 보겠습니다. 

1 kworker/0:0-27338 [000] d.h.  6028.897808: irq_handler_entry: irq=56 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

여기서 어떤 함수가 실행되던 도중에 인터럽트가 발생한 것일까요? 이 질문을 받으면 다음과 같이 대답할 수 있습니다. 

_raw_spin_unlock_irqrestore() 함수 실행 중 "irq=56 name=dwc_otg" 인터럽트가 발생했다.
 
ARM 프로세스는 인터럽트가 발생하면 익셉션을 유발해 __irq_svc 인터럽트 벡터를 실행합니다. 이후 리눅스 커널 내부의 인터럽트를 처리하는 커널 내부의 함수가 다음 순서로 호출되는 것입니다.

 handle_level_irq()
 handle_irq_event()
 __handle_irq_event_percpu()
 dwc_otg_common_irq()

이후 “irq=56 name=dwc_otg” 인터럽트를 처리하는 인터럽트 핸들러인 dwc_otg_common_irq() 함수를 호출합니다.

다소 복잡해 보이는 ftrace 로그를 그림으로 정리하면 다음과 같습니다. 

 

 

그림 5.6 인터럽트 발생 시 프로세스 스택 공간에서의 함수 호출 흐름  

그림 5.6은 56 번 인터럽트가 발생한 후의 함수 실행 흐름입니다. 오른쪽 상단에 인터럽트 컨텍스트라고 표시된 함수 구간이 있습니다. 이 구간에서 어떤 함수가 실행 중이면 '현재 인터럽트 컨텍스트다'라고 말할 수 있습니다.

ftrace 로그와 위 그림을 토대로 전체 실행 흐름은 다음과 같이 정리할 수 있습니다. 

 pid가 27338인 kworker/0:0 프로세스가 _raw_spin_unlock_irqrestore() 함수를 실행
 "irq=56 name=dwc_otg" 인터럽트가 발생해 인터럽트 벡터인 __irq_svc() 함수로 브랜치
 인터럽트 핸들러인 dwc_otg_common_irq() 함수가 실행됨

커널 로그를 이용한 인터럽트 컨텍스트 확인
이번에는 다른 리눅스 시스템에서 추출한 커널 로그를 보면서 인터럽트 컨텍스트를 배워봅시다. 먼저 커널 로그를 소개합니다.

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 레이블을 보면 “아, 인터럽트가 발생해서 인터럽트를 처리 중이구나”라고 해석하면 됩니다. 임베디드 개발 중에는 이 같은 패턴의 커널 로그를 자주 만나니 잘 기억해둡시다.

이번 절에서는 인터럽트 컨텍스트에 대해 알아봤습니다. 지금까지 배운 내용을 정리해 봅시다.

 인터럽트 컨텍스트란 무엇인가?
    인터럽트가 발생해 인터럽트를 핸들링하는 동작입니다.

 인터럽트 컨텍스트를 왜 정의할까?
     인터럽트를 핸들링하는 시점에서 더 빠르고 간결하게 코드를 실행하기 위해서입니다.

다음 절에서는 인터럽트 컨텍스트를 알려주는 in_interrupt() 함수를 살펴보겠습니다.


프로세스는 높은 주소에서 낮은 주소 방향으로 스택을 씁니다. 사실 꼭 높은 주소에서 낮은 주소 방향으로 스택을 사용하도록 설정할 필요는 없습니다. 반대로 낮은 주소에서 높은 주소 방향으로 스택을 쓰도록 설정할 수도 있습니다. 그런데 대부분의 리눅스 벤더나 SoC에서 프로세스를 높은 주소에서 낮은 주소 방향으로 설정해 업계의 사실상 표준이 된 것입니다.

이번에는 프로세스가 실행 중인 프로세스 스택 공간에 대해 알아봅시다. 프로세스가 생성될 때 커널은 프로세스에게 0x2000 크기만큼 스택 공간을 할당합니다. 프로세스는 자신의 스택 공간에서 실행되므로 프로세스 입장에서 스택 공간은 운동장으로 볼 수 있습니다. 프로세스는 스택 메모리 공간 내에서만 실행되면서 다음과 같은 상황에서 스택 공간을 사용합니다.

 함수를 호출할 때 돌아올 주소를 스택에 저장
 지역변수를 스택을 써서 저장 

프로세스별로 할당된 스택 주소는 어떻게 확인할 수 있나요? 이 질문에 답하려면 태스크 디스크립터를 알아야 합니다. 프로세스별로 할당된 스택 주소는 태스크 디스크립터를 나타내는 task_struct 구조체의 stack 필드에서 확인할 수 있습니다.