#리눅스 커널: 인터럽트
ftrace
라즈베리안 리눅스 커널은 아래 ftrace 로그를 볼 수 있는 컨피그가 기본 설정돼 있습니다.
CONFIG_FUNCTION_TRACER
CONFIG_DYNAMIC_FTRACE
CONFIG_FUNCTION_GRAPH_TRACER
ftrace드라이버에서 리눅스 커널 동작을 확인할 수 있는 기본 이벤트들을 정의했습니다. 그 중 인터럽트는 리눅스 커널 동작에 가장 중요한 동작 중 하나 이므로 /d/tracing/events/irq 폴더에 이벤트를 확인할 수 있습니다.
라즈베리파이 보드에서 아래와 같이 설정하면 인터럽트를 ftrace 로그에서 볼 수 있습니다.
참고로 sched_switch 이벤트를 추가한 이유는 어떤 프로세스에서 인터럽트를 처리하는지 확인할 수 있기 때문입니다.
"echo 0 > /d/tracing/tracing_on"
"echo nop > /d/tracing/current_tracer
"echo 0 > /d/tracing/events/enable"
"echo 1 > /d/tracing/events/sched/sched_switch/enable"
"echo 1 > /d/tracing/events/irq/irq_handler_entry/enable"
"echo 1 > /d/tracing/events/irq/irq_handler_exit/enable"
" echo 1 > /d/tracing/tracing_on"
위 명령어는 irq_debug.sh란 스크립트 파일로 저장해서 사용하면 손 쉽게 ftrace 이벤트를 설정할 수 있습니다.
아래 명령어로 ftrace 로그를 열어볼 수 있습니다.
"tail -300 /d/tracing/trace"
rcuop/2-25 [004] d.H1 217.151739: irq_handler_entry: irq=55 name=mmc0
rcuop/2-25 [004] d.H1 217.151759: irq_handler_exit: irq=55 ret=handled
rcuop/2-25 [004] d..3 217.151980: sched_switch: prev_comm=rcuop/2 prev_pid=25 prev_prio=120 prev_state=R+ ==> next_comm=kworker/4:1H next_pid=392 next_prio=100
kworker/4:1H-392 [004] d..3 217.152006: sched_switch: prev_comm=kworker/4:1H prev_pid=392 prev_prio=100 prev_state=S ==> next_comm=rcuop/2 next_pid=25 next_prio=120
rcuop/2-25 [004] d..3 217.152105: sched_switch: prev_comm=rcuop/2 prev_pid=25 prev_prio=120 prev_state=S ==> next_comm=kernel_logger next_pid=1364 next_prio=120
<...>-1364 [004] d..3 217.152150: sched_switch: prev_comm=kernel_logger prev_pid=1364 prev_prio=120 prev_state=D ==> next_comm=jbd2/dm-1-8 next_pid=841 next_prio=120
<...>-841 [004] d..3 217.152455: sched_switch: prev_comm=jbd2/dm-1-8 prev_pid=841 prev_prio=120 prev_state=D ==> next_comm=mmc-cmdqd/0 next_pid=340 next_prio=120
mmc-cmdqd/0-340 [004] d..3 217.152529: sched_switch: prev_comm=mmc-cmdqd/0 prev_pid=340 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120
<idle>-0 [004] d.h2 217.152549: irq_handler_entry: irq=55 name=mmc0 // [1]
<idle>-0 [004] d.h2 217.152563: irq_handler_exit: irq=55 ret=handled
<idle>-0 [004] d..3 217.152664: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/4 next_pid=36 next_prio=120
ksoftirqd/4-36 [004] d..3 217.152733: sched_switch: prev_comm=ksoftirqd/4 prev_pid=36 prev_prio=120 prev_state=R+ ==> next_comm=kworker/4:1H next_pid=392 next_prio=100
kworker/4:1H-392 [004] d..3 217.152754: sched_switch: prev_comm=kworker/4:1H prev_pid=392 prev_prio=100 prev_state=S ==> next_comm=ksoftirqd/4 next_pid=36 next_prio=120
ksoftirqd/4-36 [004] d..3 217.152768: sched_switch: prev_comm=ksoftirqd/4 prev_pid=36 prev_prio=120 prev_state=S ==> next_comm=jbd2/dm-1-8 next_pid=841 next_prio=120
<...>-841 [004] d..3 217.152949: sched_switch: prev_comm=jbd2/dm-1-8 prev_pid=841 prev_prio=120 prev_state=D ==> next_comm=mmc-cmdqd/0 next_pid=340 next_prio=120
mmc-cmdqd/0-340 [004] d..3 217.153000: sched_switch: prev_comm=mmc-cmdqd/0 prev_pid=340 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120
<idle>-0 [004] d.h2 217.153583: irq_handler_entry: irq=55 name=mmc0
<idle>-0 [004] d.h2 217.153598: irq_handler_exit: irq=55 ret=handled
<idle>-0 [004] d..3 217.153649: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/4 next_pid=36 next_prio=120
ksoftirqd/4-36 [004] d..3 217.153702: sched_switch: prev_comm=ksoftirqd/4 prev_pid=36 prev_prio=120 prev_state=R+ ==> next_comm=kworker/4:1H next_pid=392 next_prio=100
kworker/4:1H-392 [004] d..3 217.153763: sched_switch: prev_comm=kworker/4:1H prev_pid=392 prev_prio=100 prev_state=S ==> next_comm=ksoftirqd/4 next_pid=36 next_prio=120
ksoftirqd/4-36 [004] d..3 217.153776: sched_switch: prev_comm=ksoftirqd/4 prev_pid=36 prev_prio=120 prev_state=S ==> next_comm=mmc-cmdqd/0 next_pid=340 next_prio=120
mmc-cmdqd/0-340 [004] d..3 217.153837: sched_switch: prev_comm=mmc-cmdqd/0 prev_pid=340 prev_prio=120 prev_state=D ==> next_comm=swapper/4 next_pid=0 next_prio=120
<idle>-0 [004] d.h2 217.154177: irq_handler_entry: irq=55 name=mmc0
<idle>-0 [004] d.h2 217.154189: irq_handler_exit: irq=55 ret=handled
위 로그에서 [1]로 마킹한 부분을 보면 0.00004초 동안 인터럽트가 처리됐음을 알 수 있습니다.
<idle>-0 [004] d.h2 217.152549: irq_handler_entry: irq=55 name=mmc0 // <<--[1]
<idle>-0 [004] d.h2 217.152563: irq_handler_exit: irq=55 ret=handled
인터럽트 핸들러는 빨리 실행돼야 한다는 소리는 마르고 닳도록 듣지 않았나요?
그래서 저는 실제 보드에서 인터럽트 핸들러가 얼마나 빨리 처리되는지 측정해봤습니다.
ftrace graph tracer 기능을 활용하면 함수 실행 시간을 측정할 수 있는데요.
아래와 같이 설정하면 됩니다.
echo > d/tracing/set_event"
adb shell "sleep 1"
"echo 0 > d/tracing/tracing_on"
"echo function_graph > d/tracing/current_tracer"
"echo > d/tracing/set_event"
"echo touch_irq_handler > d/tracing/set_ftrace_filter"
"echo 1 > d/tracing/tracing_on"
아래 명령어로 ftrace 로그를 열어보니 10us 이내로 실행되는군요.
"tail -300 /d/tracing/trace"
------------------------------------------
5) core_ct-356 => AudioTr-4407
------------------------------------------
5) | /* + comm : AudioTrack, prio : 97, pid : 4407, nr_thread : 88 */
5) | /* - comm : AudioTrack, prio : 97, pid : 4407 */
0) 2.135 us | touch_irq_handler();
0) 2.343 us | touch_irq_handler();
0) 2.239 us | touch_irq_handler();
0) 3.802 us | touch_irq_handler();
0) 2.448 us | touch_irq_handler();
0) 1.667 us | touch_irq_handler();
0) 1.875 us | touch_irq_handler();
0) 9.427 us | touch_irq_handler();
0) 2.396 us | touch_irq_handler();
0) 2.187 us | touch_irq_handler();
0) 2.136 us | touch_irq_handler();
0) 1.667 us | touch_irq_handler();
최근 덧글