Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

119199
1107
135847


[리눅스커널] 인터럽트: 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 로그를 그림으로 정리하면 다음과 같습니다. 

 
[그림 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() 함수를 소개합니다.
 
이번 절에서는 인터럽트 컨택스트에 대해서 알아봤습니다. 인터럽트 컨택스트란 현재 수행 중인 코드가 인터럽트를 처리하는 중이란 의미입니다. 다음 소절에서는 인터럽트 컨택스트를 알려주는 함수를 소개합니다.

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

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

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

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

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

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

Thanks,
Austin Kim(austindh.kim@gmail.com)


덧글

댓글 입력 영역