인터럽트 후반부 기법이 도입된 이유는 다음과 같이 인터럽트를 처리해야 하기 때문입니다.
인터럽트 핸들러에서는 짧고 간결하게 코드가 실행되야 한다.
여기서 한 가지 의문이 생깁니다.
인터럽트 핸들러에서 실행 시간이 오래 걸리면 시스템은 어떻게 동작할까?
인터럽트 컨택스트에서 실행 시간이 오래 걸리면 대부분 시스템은 오동작하게 됩니다. 디바이스 드라이버를 개발하다 보면 다음과 같이 인터럽트 핸들러에 실수로 실행 시간이 오래 걸리는 코드를 입력할 수 있습니다.
I/O을 시작하는 코드
과도한 while loop
유저 공간으로uevent를 전달해서 인터럽트 발생을 알림
스케줄링을 지원하는 커널 함수 호출
위와 같은 코드가 인터럽트 핸들러나 인터럽트 핸들러 서브 함수에서 동작하면 시스템 반응 속도가 아주 느려집니다. 또한 커널 로그를 열어보면 평소에 볼 수 없는 에러 메시지를 볼 수도 있습니다.
개발자들은 더욱 불안해지면서 스스로 다음과 같은 질문을 던지게 됩니다.
인터럽트 컨택스트에서 인터럽트를 핸들링 하는 코드 실행 시간을 어떻게 측정할 수
있을까?
이를 위해 ftrace 기능에서 지원하는 graph_function 트레이서로 인터럽트 핸들링을 할 때 시간을 측정할 필요가 있습니다. 이 방법은 이번 장 디버깅 절에서 소개합니다.
인터럽트 컨택스트에서 발생한 커널 패닉
반복하지만 인터럽트를 처리하는 인터럽트 컨텍스트에서 코드 실행 시간이 오래 걸리면 시스템은 오동작할 가능성이 높다고 설명을 드렸습니다. 그런데 커널에서는 한 걸음 더 나아가 인터럽트 컨택스트에서 다음과 같은 제약을 둡니다.
인터럽트 컨택스트에서 시간이 오래 걸리는 함수를 호출하면 커널 패닉을 유발하자.
이번에 인터럽트 핸들러에서 시간이 오래 걸리는 함수를 실행해 커널 패닉이 발생했던 사례를 소개합니다.
다음은 로그는 인터럽트 핸들러 실행 도중 발생한 커널 패닉 로그입니다.
01 [21.719319] [callstack mxt_interrupt,2449] task[InputReader]=========
02 [21.719382] BUG: scheduling while atomic: InputReader/1039/0x00010001
03 [21.719417] (unwind_backtrace+0x0/0x144) from (dump_stack+0x20/0x24)
04 [21.719432] (dump_stack+0x20/0x24) from (__schedule_bug+0x50/0x5c)
05 [21.719444] (__schedule_bug+0x50/0x5c) from (__schedule+0x7c4/0x890)
06 [21.719455] (__schedule+0x7c4/0x890) from [<c0845d70>] (schedule+0x40/0x80)
07 [21.719468] (schedule+0x40/0x80) from [<c0843bc0>] (schedule_timeout+0x190/0x33c)
08 [21.719480] (schedule_timeout+0x190/0x33c) from (wait_for_common+0xb8/0x15c)
09 [21.719491] (wait_for_common+0xb8/0x15c) from (wait_for_completion_timeout+0x1c/0x20)
10 [21.719504] (wait_for_completion_timeout+0x1c/0x20) from (tegra_i2c_xfer_msg+0x380/0x958)
11 [21.719517] (tegra_i2c_xfer_msg+0x380/0x958) from (tegra_i2c_xfer+0x314/0x438)
12 [21.719531] (tegra_i2c_xfer+0x314/0x438) from (i2c_transfer+0xc4/0x128)
13 [21.719546] (i2c_transfer+0xc4/0x128) from (__mxt_read_reg+0x70/0xc8)
14 [21.719560] (__mxt_read_reg+0x70/0xc8) from (mxt_read_and_process_messages+0x58/0x1648)
15 [21.719572] (mxt_read_and_process_messages+0x58/0x1648) from (mxt_interrupt+0x78/0x144)
16 [21.719588] (mxt_interrupt+0x78/0x144) from (handle_irq_event_percpu+0x88/0x2ec)
17 [21.719601] (handle_irq_event_percpu+0x88/0x2ec) from (handle_irq_event+0x4c/0x6c)
18 [21.719614] (handle_irq_event+0x4c/0x6c) from (handle_level_irq+0xbc/0x118)
19 [21.719626] (handle_level_irq+0xbc/0x118) from (generic_handle_irq+0x3c/0x50)
20 [21.719642] (generic_handle_irq+0x3c/0x50) from (tegra_gpio_irq_handler+0xa8/0x124)
21 [21.719655] (tegra_gpio_irq_handler+0xa8/0x124) from (generic_handle_irq+0x3c/0x50)
22 [21.719669] (generic_handle_irq+0x3c/0x50) from (handle_IRQ+0x5c/0xbc)
23 [21.719682] (handle_IRQ+0x5c/0xbc) from (gic_handle_irq+0x34/0x68)
24 [21.719694] (gic_handle_irq+0x34/0x68) from (__irq_svc+0x40/0x70)
참고로 위 로그가 동작한 시스템은 엔비디아 Tegra4i SoC 디바이스입니다. 그래서 tegra가 붙은 함수들이 보입니다. 라즈베리파이 이외에 다른 리눅스 시스템에서 인터럽트를 어떻게 처리하는지 알면 좋으니 다른 리눅스 시스템에서 발생한 문제를 소개합니다.
로그를 보자마자 어느 부분부터 봐야 하는지 의문이 생깁니다. 함수들이 가장 먼저 실행된 순서로 정렬돼 있으니 가장 아랫부분인 24 번째 로그부터 봐야 합니다.
그러면 함수 호출 방향은 어디일까?
24번째 줄에서 3번째 줄이 함수 호출 방향입니다. 이제부터 5장에서 배운 내용을 떠 올리면서 로그 분석을 시작합니다.
가장 처음 실행된 함수 로그부터 보겠습니다. 24 번째 줄 코드를 눈으로 따라가 보면 __irq_svc 레이블이 보일 것입니다.
21 [21.719655] (tegra_gpio_irq_handler+0xa8/0x124) from (generic_handle_irq+0x3c/0x50)
22 [21.719669] (generic_handle_irq+0x3c/0x50) from (handle_IRQ+0x5c/0xbc)
23 [21.719682] (handle_IRQ+0x5c/0xbc) from (gic_handle_irq+0x34/0x68)
24 [21.719694] (gic_handle_irq+0x34/0x68) from (__irq_svc+0x40/0x70)
함수 이름으로 인터럽트가 발생했다고 알 수 있습니다. 5장에서 배운 대로 인터럽트가 발생하면 인터럽트 벡터인 __irq_svc가 실행합니다. 여기서 24 번째 줄에서 21 번째 줄 방향으로 함수가 호출됩니다. 22 번째 줄에 generic_handle_irq() 함수가 보이니 인터럽트 컨택스트란 사실을 알 수 있습니다.
다음 14~16 번째 로그를 보겠습니다.
14 [21.719560] (__mxt_read_reg+0x70/0xc8) from (mxt_read_and_process_messages+0x58/0x1648)
15 [21.719572] (mxt_read_and_process_messages+0x58/0x1648) from (mxt_interrupt+0x78/0x144)
16 [21.719588] (mxt_interrupt+0x78/0x144) from (handle_irq_event_percpu+0x88/0x2ec)
인터럽트 핸들러로 mxt_interrupt() 함수가 호출됐습니다.
우리는 5장에서 인터럽트 핸들러는 __handle_irq_event_percpu() 함수에서 호출한다고 배웠습니다. 그런데 위 로그에서는 handle_irq_event_percpu() 함수에서 인터럽트 핸들러를 호출합니다.
그 이유는 이 로그를 출력한 시스템의 리눅스 커널 버전이 3.10.77 버전이기 때문입니다. 다음 코드를 보면 5번째 줄 코드에서 인터럽트 핸들러를 호출합니다.
https://elixir.bootlin.com/linux/v3.10.77/source/kernel/irq/handle.c
1 irqreturn_t
2 handle_irq_event_percpu(struct irq_desc *desc, struct irqaction *action)
3 {
...
4 do {
...
5 res = action->handler(irq, action->dev_id);
리눅스 커널 버전에 따라 인터럽트 핸들러를 호출하는 함수 이름이 달라질 수 있습니다.
이어서 다음 로그를 보겠습니다.
05 [21.719444] (__schedule_bug+0x50/0x5c) from (__schedule+0x7c4/0x890)
06 [21.719455] (__schedule+0x7c4/0x890) from [<c0845d70>] (schedule+0x40/0x80)
07 [21.719468] (schedule+0x40/0x80) from [<c0843bc0>] (schedule_timeout+0x190/0x33c)
08 [21.719480] (schedule_timeout+0x190/0x33c) from (wait_for_common+0xb8/0x15c)
09 [21.719491] (wait_for_common+0xb8/0x15c) from (wait_for_completion_timeout+0x1c/0x20)
10 [21.719504] (wait_for_completion_timeout+0x1c/0x20) from (tegra_i2c_xfer_msg+0x380/0x958)
11 [21.719517] (tegra_i2c_xfer_msg+0x380/0x958) from (tegra_i2c_xfer+0x314/0x438)
12 [21.719531] (tegra_i2c_xfer+0x314/0x438) from (i2c_transfer+0xc4/0x128)
13 [21.719546] (i2c_transfer+0xc4/0x128) from (__mxt_read_reg+0x70/0xc8)
위 함수 흐름에서 리눅스 커널의 웨이트 큐를 써서 실행 흐름을 동기화하는 부분이 보입니다.
다음 그림과 같이 wait_for_common() 함수를 호출해서 complete() 함수가 수행되기를 기다리는 상황입니다. 그런데 complete() 함수 호출을 안 하니 schedule_timeout() 함수를 호출합니다.
[그림 6.2] wait_for_common() 함수가 실행 중 타임아웃되는 과정
커널의 웨이트 큐 세부 동작은 이 책의 범위를 벗어나 다루지 않습니다. 세부 내용은 저자의 다음 블로그 페이지를 참고하세요.
[http://rousalome.egloos.com/9989042]
이번에 커널 패닉이 발생하는 이유를 알려주는 로그를 소개합니다.
01 [21.719319] [callstack mxt_interrupt,2449] task[InputReader]=========
02 [21.719382] BUG: scheduling while atomic: InputReader/1039/0x00010001
인터럽트 컨택스트에서 schedule() 함수를 호출해 스케줄링을 시도하니 커널은 이를 감지하고 커널 패닉을 유발합니다.
02 번째 줄 로그를 보면 InputReader는 프로세스 이름, pid는 1039 그리고 0x00010001는 프로세스 struct thread_info 구조체 preempt_count 필드 값입니다.
위 커널 로그에서는 2가지 정보를 말해줍니다.
첫째, 프로세스 struct thread_info 구조체 preempt_count 필드가 0x00010001이니 현재 실행 중인 코드는 인터럽트 컨택스트이다. 0x00010001와 HARDIRQ_MASK(0xF0000) 플래그와 AND 비트 연산한 결과가 1이기 때문이다.
둘째, 인터럽트 컨택스트에서 schedule() 함수를 호출했다.
위 로그에서 “scheduling while atomic”란 메시지가 보입니다. 메시지를 그대로 풀면 “아토믹 도중에 스케줄링 중이다.”입니다.
여기서 atomic이란 무슨 의미일까요? 커널에서는 다음과 같은 상황을 atomic이라고 말합니다.
선점 스케줄링이 되지 않는 실행 단위(어셈블리 명령어)
어떤 코드나 루틴이 실행 도중 스케줄링을 수행하면 안되는 컨택스트
커널에서는 인터럽트 컨택스트도 스케줄링하면 안되는 컨택스트로 판단합니다. 즉 인터럽트 컨택스트는 atomic operation입니다. 따라서 이런 경고 메시지를 출력하는 겁니다. (atomic operation은 커널 동기화 장에서 자세히 다룹니다.)
그러면 인터럽트 컨택스트에서 스케줄링을 시도하니 커널은 이를 감지하고 커널 패닉을 유발하는 이유는 무엇일까요?
스케줄링을 지원하는 함수를 실행하면 시간이 오래 걸리기 때문이다.
이렇게 커널은 인터럽트 컨택스트에서 호출하는 커널 함수 호출을 제한합니다.
리눅스 커널 뿐만 아니라 기존 다른 운영체제에서도 '인터럽트를 처리할 때는 코드를 빨리 실행해야 한다.'는 문제를 안고 있었습니다. 이 과정에서 자연스럽게 임베디드 개발에서 Bottom Half와 Top Half란 개념을 이끌어 냈으며 이 기준으로 인터럽트 후반부를 처리하기 시작했습니다.
다음 소절에서는 Top Half와 Bottom Half에 대해서 알아보겠습니다.
Edited: 4/23/2020
* 유튜브 강의 동영상도 있으니 같이 들으시면 좋습니다.
"이 포스팅이 유익하다고 생각되시면 공감이나 댓글로 응원해주시면 감사하겠습니다."
"혹시 궁금한 점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답변 올려드리겠습니다!"
Thanks,
Austin Kim(austindh.kim@gmail.com)
인터럽트 후반부(IRQ 스레드/Soft IRQ) 처리
인터럽트 후반부 기법이란?
IRQ 스레드(threaded IRQ)
IRQ 스레드는 어떻게 생성할까?
IRQ 스레드는 누가 언제 실행할까?
IRQ 스레드 디버깅 실습
Soft IRQ 소개
Soft IRQ 서비스
Soft IRQ 서비스는 언제 요청할까?
Soft IRQ 서비스는 누가 언제 처리할까?
ksoftirqd 스레드
Soft IRQ 컨텍스트에 대해
태스크릿
Soft IRQ 디버깅
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글