ftrace 메시지는 어떻게 분석할까?
ftrace를 제대로 활용하려면 먼저 ftrace 메시지를 읽고 해석하는 방법을 알아야 합니다. 다시 강조하지만 ftrace는 커널 동작을 세부 로그로 출력하기 때문에 임베디드 리눅스 개발자에게 축복과도 같습니다.
먼저 ftrace 이벤트에서 가장 많이 활용하는 sched_switch, sched_wakeup, irq_handler_entry, irq_handler_exit 이벤트를 해석하는 방법을 살펴보겠습니다.
먼저 ftrace 로그를 하나 소개합니다.
chromium-browse-1436 [002] d... 9445.131875: sched_switch: prev_comm=chromium-browse prev_pid=1436 prev_prio=120 prev_state=S ==> next_comm=kworker/2:3 next_pid=1454 next_prio=120
위 ftrace는 sched_switch 이벤트의 로그입니다. sched_switch 이벤트의 메시지를 분석하기에 앞서 ftrace의 공통 포맷을 살펴보겠습니다.
그림 3.2 ftrace 메시지 내의 세부 디버깅 정보
ftrace 메시지에서 맨 왼쪽에서 ftrace를 출력하는 프로세스의 정보를 볼 수 있습니다. “프로세스이름-[pid]” 형식입니다. 즉, 위 로그에서는 pid가 1436인 chromium-browse 프로세스가 실행 중입니다.
다음의 “[002]”는 CPU 번호입니다. 현재 몇 번째 CPU에서 프로세스가 실행 중인지 나타내며, 위 ftrace 메시지를 통해 2번 CPU에서 실행 중이라는 사실을 알 수 있습니다.
이어서 ftrace 메시지에서 출력하는 컨텍스트 정보를 해석하는 방법을 알아 보겠습니다. ftrace에서 컨텍스트 정보는 어디서 확인할까요?
그림 3.2에서 “컨텍스트 정보”라고 표기된 부분을 보면 “d...”으로 알파벳이 적혀 있습니다. 별거 아닌 것처럼 보여도 이는 ftrace에서 눈여겨봐야 할 중요 정보이며 다음과 같은 내용이 이곳에 출력됩니다.
인터럽트 활성화/비활성화 여부
선점 스케줄링 설정 여부
인터럽트 컨텍스트나 Soft IRQ 컨텍스트 여부
프로세스의 thread_info 구조체의 preempt_count 값
세부 컨텍스트 정보는 ftrace 메시지에서 항상 출력되며 4개의 알파벳으로 출력됩니다.
그림 3.3 ftrace 메시지에서 세부 컨텍스트 정보 파악하기
프로세스 컨텍스트의 세부 정보를 표현하는 알파벳의 의미는 다음과 같습니다.
d: 해당 CPU 라인의 인터럽트를 비활성화한 상태입니다.
n: 현재 프로세스가 선점 스케줄링이 요청된 대상입니다.
h/s: h이면 인터럽트 컨텍스트, s이면 Soft IRQ 컨텍스트입니다.
0~5: 프로세스의 thread_info 구조체의 preempt_count 필드값입니다.
세부 항목이 활성화돼 있지 않으면 “.”를 출력합니다.
다음으로 소개할 ftrace 공통 포맷은 타임스탬프입니다.
이 ftrace 메시지에서 타임스탬프는 9445.131875입니다. 커널 로그에서 출력하는 타임스탬프와 같은 시간 정보입니다. 마지막으로 sched_switch는 이벤트 이름입니다.
ftrace 이벤트 분석하기
이어서 ftrace 중에서 가장 많이 쓰는 아래의 두 가지 이벤트를 분석하는 방법을 소개합니다.
sched_switch
irq_handler_entry/irq_handler_exit
먼저 sched_switch 이벤트를 분석하는 방법을 소개합니다. sched_switch 메시지의 세부 내용은 다음과 같습니다.
다음 메시지는 스케줄링될 프로세스 정보입니다.
prev_comm=kworker/2:1 prev_pid=1106 prev_prio=120 prev_state=T
prev 프로세스의 PID는 1106이고 이름은 "kworker/2:1"입니다. 프로세스 우선순위는 120이고 프로세스 상태는 T입니다.
다음 메시지는 스케줄링 동작으로 다음에 실행될 프로세스입니다.
next_comm=ksoftirqd/2 next_pid=19 next_prio=120
프로세스 이름은 "ksoftirqd/2"이고 PID는 19입니다. 또한 프로세스 우선순위가 120입니다.
위 정보를 토대로 ftrace 로그를 해석하면 다음과 같습니다.
"kworker/2:1" 프로세스에서 "ksoftirqd/2" 프로세스로 스케줄링하는 동작을 출력합니다.
이어서 irq_handler_entry와 irq_handler_exit 이벤트 메시지를 해석하는 방법을 배워봅시다.
1 kworker/0:1-31 [000] d.h. 592.790968: : irq=17 name=3f00b880.mailbox
2 kworker/0:1-31 [000] d.h. 592.791016: irq_handler_exit: irq=17 ret=handled
먼저 ftrace의 공통 실행 정보를 확인하겠습니다.
ftrace 메시지를 볼 때 맨 왼쪽에 보이는 메시지는 ftrace 로그를 출력하는 프로세스 정보입니다. 1번째 줄의 메시지는 다음과 같이 해석할 수 있습니다.
pid가 31인 kworker/0:1 프로세스가 실행되는 도중 인터럽트가 발생했습니다.
이어서 추가 디버깅 정보를 확인해볼까요?
[000]: CPU0에서 실행 중
“d.h.”: d이므로 CPU0번 인터럽트 라인을 비활성화했으며, h이므로 현재 인터럽트 컨텍스트임
이어서 2번째 줄의 메시지를 보겠습니다.
2 kworker/0:1-31 [000] d.h. 592.791016: irq_handler_exit: irq=23 ret=handled
17번 인터럽트 핸들러의 실행을 마무리했다는 정보입니다. 1~2번째 줄의 로그에 보이는 디버깅 정보를 토대로 다음과 같이 해석할 수 있습니다.
17번 "3f00b880.mailbox" 인터럽트 핸들러를 592.790968 초에 실행하고 592.791016 초에 마무리했다.
irq_handler_entry 이벤트의 출력 시점은 다음과 같습니다.
irq_handler_entry: 인터럽트 핸들러를 실행하기 직전에 출력
irq_handler_exit: 인터럽트 핸들러 실행을 마무리한 직후 출력
"혹시 궁금한 점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답변 올려드리겠습니다!"
Thanks,
Austin Kim(austindh.kim@gmail.com)
커널 디버깅과 코드 학습
디버깅이란
ftrace
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글