[Linux Kernel] ftrace Log 포맷 해석 및 발생 경로 확인

ftrace 에는 크게 4가지 이벤트가 존재한다.

• sched_switch
• sched_wakeup
• irq_handler_entry
• irq_handler_exit

각 ftrace 이벤트 별로 당연히 발생되는 경로와 이유가 존재한다.

이번 글을 통해 어떻게 해석하고 어떻게 발생되는지를 알아가 보자.

 

ftrace 로그를 분석하기 위해서는 공통 포맷을 알아야 한다.

아래는 sched_switch 로그의 예시이다.

컨텍스트 정보를 자세히 들여다보면,

d... 총 4자리로 

• 인터럽트 활성/비활성 여부
• 선점 스케줄링 설정 여부
• 인터럽트 컨텍스트 or Soft Irq 컨텍스트 여부
• preempt count 값

으로 구성이 되어있다. 

즉 Chromium-browse 프로세스에서 CPU2번에 인터럽트는 비활성된 상태이고 9445.132343초에 컨텍스트 스위칭 이벤트가 발생했으며, 현재chromium 우선순의 120번에서 다음 kworker/2:3 프로세스로 컨텍스트 예정인 것이다.

 

irq 이벤트의 경우도 똑같이 해석이 된다.

irq_handler_entry가 발생하면서 실제 인터럽트가 진행되고 마무리되면서

irq_handler_exit 가 발생하면서 마무리 된다.

 

그러면 실제로 ftrace 이벤트 로그 분석 방법은 알게되었으니,

어떻게 발생이 되는지를 소스코드를 통해 확인해보자.

먼저 sched_switch 를 확인 해 볼 것이다.

egrep -nr sched_switch *

kernel/sched/core.c 4537 번에서 호출이 이루어지는 것을 확인 할 수 있다.

실제로 들어가보면 (vi 에서 number shift + g 로 쉽게 이동 가능하다)

__schedule 함수에서 아래 로직으로 구성된 걸 확인 할 수 있다.

즉 스케줄링이 이루어질때 마다 호출이 되어지는 것이다.

 

아래는 irq_handler_entry 이다.

egrep -nr irq_handler_entry *

kernel/irq/handle.c 155 에서 호출을 확인 할 수 있다.

실제로 156번 handler 함수를 통해 인터럽트가 이루어지는데 그 전과 후로

각 이벤트가 발생되는 것을 확인 가능하다.

즉, 인터럽테 진행 전 알리고 진행 완료 후 알려지는 것이다.