6.5.3 IRQ 스레드 핸들러 실행 시각 측정하기
이전 절에서는 ftrace 로 콜스택과 함께 인터럽트가 언제 발생하고 언제 IRQ 스레드를 깨우는지 알아봤습니다. 이번에는 실제 인터럽트 핸들러와 IRQ 스레드 핸들러 함수 실행 시간을 측정하는 방법을 소개합니다. 각 함수의 실행 시간을 측정한 결과 인터럽트 핸들러 실행 시간이 길면 인터럽트 핸들러 함수 코드를 점검할 필요가 있습니다. 나중에 여러분이 인터럽트 핸들러를 작성한 후 이 방법을 써서 실행 시간을 측정해 보시길 바랍니다.
ftrace에서 지원하는 function_graph 트레이서를 쓸려면 다음 config가 설정돼 있어야 합니다.
CONFIG_DYNAMIC_FTRACE=y
CONFIG_DYNAMIC_FTRACE_WITH_REGS=y
CONFIG_FUNCTION_PROFILER=y
CONFIG_FTRACE_MCOUNT_RECORD=y
CONFIG_NOP_TRACER=y
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_HAVE_DYNAMIC_FTRACE=y
CONFIG_HAVE_DYNAMIC_FTRACE_WITH_REGS=y
CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y
라즈비안을 빌드하면 생성하는 .config 파일을 확인하면 위 config들이 기본으로 설정돼 있습니다. 라즈비안에서는 기본으로 컨피그가 설정돼 있으니 이 function_graph 트레이서를 쓰면 됩니다. 라즈비안 이외 다른 리눅스 보드로 function_graph 트레이서를 쓰려면 위에서 설명해 드린 커널 컨피그가 설정됐는지 확인해야 합니다.
인터럽트 핸들러 실행 시각 측정을 위한 function 설정 방법 소개
function_graph 트레이서 설정을 하려면 다음 명령어를 입력해야 합니다. 다음 코드를 입력한 후 timer_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_graph > /sys/kernel/debug/tracing/current_tracer
sleep 1
echo "function_graph tracer enabled"
echo bcm2835_mmc_irq bcm2835_mmc_thread_irq > /sys/kernel/debug/tracing/set_ftrace_filter
echo bcm2835_mbox_irq bcm2835_mbox_threaded_irq >> /sys/kernel/debug/tracing/set_ftrace_filter
echo bcm2835_sdhost_irq >> /sys/kernel/debug/tracing/set_ftrace_filter
sleep 1
echo "set_ftrace_filter enabled"
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
sleep 1
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/tracing_on
echo "tracing_on"
fuction_gragh 트레이서를 설정하고 set_ftrace_filter에 함수를 지정하면 함수 실행 시간을 측정할 수 있습니다. 위 셸 스크립트에서 다음 함수 실행 시각을 측정합니다.
- bcm2835_mmc_irq()
- bcm2835_mmc_thread_irq()
- bcm2835_mbox_irq()
- bcm2835_mbox_threaded_irq()
- bcm2835_sdhost_irq()
이 내용을 참고하면서 “source timer_trace.sh” 명령어로 위 셸 스크립트를 실행한 후 20초 후 ftrace 로그를 받습니다.
ftrace로 인터럽트 핸들러 실행 시간 측정하기
로그를 열어보니 새로운 형태의 ftrace 로그를 볼 수 있습니다. 같이 로그를 살펴 봅시다.
먼저 인터럽트 핸들러가 실행한 시간을 확인하겠습니다.
1 0) | /* irq_handler_entry: irq=92 name=mmc1 */
2 0) 6.823 us | bcm2835_mmc_irq();
3 0) | /* irq_handler_exit: irq=92 ret=handled */
4 0) | /* irq_handler_entry: irq=92 name=mmc1 */
5 0) 2.344 us | bcm2835_mmc_irq();
5 0) | /* irq_handler_exit: irq=92 ret=handled */
92번 mmc1 인터럽트 핸들러인 bcm2835_mmc_irq() 함수 실행 시간이 6.823 us, 2.344 us입니다.
다음은 86번 인터럽트 핸들러인 bcm2835_sdhost_irq() 함수 실행 시간을 확인한 로그입니다.
0) | /* irq_handler_entry: irq=86 name=mmc0 */
0) 4.479 us | bcm2835_sdhost_irq();
0) | /* irq_handler_exit: irq=86 ret=handled */
...
0) | /* irq_handler_entry: irq=86 name=mmc0 */
0) 6.562 us | bcm2835_sdhost_irq();
0) | /* irq_handler_exit: irq=86 ret=handled */
위 로그에서 볼드체로 된 부분을 보면 실행 시간이 4.479 us, 6.562 us 입니다.
인터럽트 핸들러 실행 시간이 10나노초 미만입니다. 이 정도면 빠른 시간에 인터럽트 핸들러가 실행됐습니다.
이번에는 IRQ Thread 핸들러 실행 시간을 확인해 보겠습니다. 관련 함수들 실행 시간과 ftrace 이벤트 로그를 함께 살펴 보겠습니다.
분석하려는 전체 로그는 다음과 같습니다.
1 0) | /* irq_handler_entry: irq=23 name=3f00b880.mailbox */
2 0) 7.084 us | bcm2835_mbox_irq();
3 0) | /* irq_handler_exit: irq=23 ret=handled */
4 ------------------------------------------
5 3) kworker-32 => chromiu-919
6 ------------------------------------------
7
8 3) | /* sched_wakeup: comm=kworker/3:1 pid=32 prio=120 target_cpu=003 */
9 3) | /* sched_switch: prev_comm=chromium-browse prev_pid=919 prev_prio=120 prev_state=R ==> next_comm=kworker/3:1 next_pid=32 next_prio=120 */
10 ------------------------------------------
11 3) chromiu-919 => kworker-32
12 ------------------------------------------
13
14 3) | /* sched_wakeup: comm=irq/23-3f00b880 pid=33 prio=49 target_cpu=003 */
15 3) | /* sched_switch: prev_comm=kworker/3:1 prev_pid=32 prev_prio=120 prev_state=R ==> next_comm=irq/23-3f00b880 next_pid=33 next_prio=49 */
16 ------------------------------------------
17 3) kworker-32 => irq/23--33
18 ------------------------------------------
19
20 3) | bcm2835_mbox_threaded_irq() {
21 3) | /* irq=23, process: irq/23-3f00b880 */
22 3) | /* [+] in_interrupt: 0x00000000,preempt_count = 0x00000000, stack=0xb9714000 */
23 3) ! 153.437 us | }
다음 로그를 보면 23번 인터럽트가 발생 후 bcm2835_mbox_irq() 함수가 7.084us 동안 실행됐습니다.
1 0) | /* irq_handler_entry: irq=23 name=3f00b880.mailbox */
2 0) 7.084 us | bcm2835_mbox_irq();
3 0) | /* irq_handler_exit: irq=23 ret=handled */
다음 10번 줄 로그를 보겠습니다. “irq/23-3f00b880” IRQ 스레드가 깨어난 후 스케줄링되는 동작입니다.
10 ------------------------------------------
11 3) chromiu-919 => kworker-32
12 ------------------------------------------
13
14 3) | /* sched_wakeup: comm=irq/23-3f00b880 pid=33 prio=49 target_cpu=003 */
15 3) | /* sched_switch: prev_comm=kworker/3:1 prev_pid=32 prev_prio=120 prev_state=R ==> next_comm=irq/23-3f00b880 next_pid=33 next_prio=49 */
11번째 줄 로그를 보면 chromiu-919 프로세스에서 kworker-32 프로세스로 스케줄링이 된 상태입니다. 14, 15번째 줄 로그에 보이는 (3)은 kworker-32 프로세스입니다. kworker-32 프로세스가 pid가 33인 “irq/23-3f00b880” 프로세스를 깨우고 스케줄링을 수행합니다.
다음 16번 줄부터 “irq/23-3f00b880” IRQ 스레드가 실행하는 로그입니다.
16 ------------------------------------------
17 3) kworker-32 => irq/23--33
18 ------------------------------------------
19
20 3) | bcm2835_mbox_threaded_irq() {
21 3) | /* irq=23, process: irq/23-3f00b880 */
22 3) | /* [+] in_interrupt: 0x00000000,preempt_count = 0x00000000, stack=0xb9714000 */
23 3) ! 153.437 us | }
무려 153.437 us나 걸렸습니다. bcm2835_mbox_threaded_irq() 함수에서 호출하는 dump_stack() 함수는 다른 인터럽트 핸들러 함수에 비해 실행 속도가 오래 걸립니다. 그래서 인터럽트 핸들러에서 쓰면 안된다고 언급한 것입니다.
여러분의 동료가 혹시 인터럽트 핸들러나 IRQ 스레드 핸들러를 작성했으면 조용히 이 방법으로 실행 시간을 측정한 다음에 인터럽트 핸들러 함수 실행 시간이 짧으면 칭찬해주고 오래 걸리면 조용히 알려줍니다.
만약 다른 팀 개발자가 여러분이 작성한 인터럽트 핸들러나 IRQ 스레드 핸들러 실행이 오래 걸린다고 공격하면 이 방법으로 방어합시다.
* 강의 동영상도 있으니 같이 들으시면 좋습니다.
"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.
혹시 글을 읽고 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려 드리겠습니다!"
# Reference 인터럽트 후반부 처리
6.9 Soft IRQ 서비스는 누가 언제 처리하나?
6.13 Soft IRQ 디버깅
6.13.1 ftrace Soft IRQ 이벤트 분석 방법
6.13.2 /proc/softirqs로 Soft IRQ 서비스 실행 횟수 확인
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글