Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

130199
1107
135858


[리눅스커널] 커널 디버깅과 코드 학습: ftrace 메시지는 어떻게 분석할까? 3. 커널 디버깅과 코드 학습

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)


핑백

덧글

  • 주니어개발자 2019/08/06 10:48 # 삭제 답글

    안녕하세요, 우선 글 너무 감사드립니다. 커널 개발 처음하는 주니어고 앞으로도 좋은 글 부탁드립니다!

    다름이 아니라 시스템 종료시(Halt또는 Reboot) 과정을 ftrace로 트레이싱하고 싶은데 종료시 로그가 날아가니 어느 방식으로 남기면 좋을지 궁금합니다.

    감사합니다!
  • AustinKim 2020/02/23 11:50 #

    아이고, 이제야 댓글을 봤네요. 커널에서 제공하는 CONFIG_PSTORE 컨피그를 활용하시면 됩니다.
댓글 입력 영역