Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

0112
737
82110


[라즈베리파이] 인터럽트(6) - 디버깅 5장. 인터럽트 핸들링

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();


덧글

댓글 입력 영역