ftrace

1. ftrace란?

printk와 dump_stack을 활용해 커널 디버깅을 하던 리눅스 커널 개발자들은 여러 불편함을 느끼기 시작했다. 즉, 다음과 같은 요건을 충족하는 커널 디버깅 기능이 있었으면 좋겠다고 생각하게 된다.

- 함수 호출 흐름을 소스코드를 수정하지 않고도 보고 싶다.

- 커널의 세부 실행 정보를 출력해 줬으면 좋겠다.

- 1초에 수십 번 호출해도 성능에 부담을 주지 않았으면 좋겠다.

- 커널 로그도 함께 보고 싶다.

이런 요구사항을 모두 충족하는 커널 디버깅 기능이 바로 ftrace이다. ftracce는 리눅스 커널에서 제공하는 가장 강력한 트레이서이다. ftrace는 커널 개발자에게 축복과도 같은데, 커널의 세부 동작을 알기 쉽게 출력하기 때문이다.

ftrace의 특징은 다음과 같다.

- 인터럽트, 스케줄링, 커널 타이머 등의 커널 동작을 상세히 추적한다.

- 함수 필터를 지정하면 지정한 함수를 호출한 함수와 전체 콜 스택까지 출력한다. 물론 코드를 수정할 필요가 없다.

- 함수를 어느 프로세스가 실행하는지 알 수 있다.

- 함수가 실행된 시각 정보를 알 수 있다.

- ftrace 로그를 활성화해도 시스템 동작에 부하를 거의 주지 않는다.

 

2. ftrace 설정

ftrace에서 제공하는 nop, function, function_graph 트레이서를 쓰려면 ftrace 관련 코드가 커널 이미지에 포함돼야 한다. 즉, ftrace 코드가 추가된 커널 소스를 빌드해야 한다. 이를 위해 커널 설정(configuration)을 활성화해야 한다.

참고로 라즈비안에서는 ftrace에 필요한 세부 컨피그가 기본적으로 모두 활성화돼 있다. 따라서 라즈비안을 라즈베리파이에 설치하기만 하면 ftrace 메시지를 볼 수 있다.

 

3. ftrace 메시지 분석

ftrace를 제대로 활용하려면 먼저 ftrace 메시지를 읽고 해석하는 방법을 알아야 한다. 다시 강조하지만 ftrace는 커널 동작을 세부 로그로 출력하기 때문에 임베디드 리눅스 개발자에게 축복과도 같다. 먼저 ftrace 이벤트에서 가장 많이 활용하는 sched_switch, sched_wakeup, irq_handler_entry, irq_handler_exit 이벤트를 해석하는 방법을 알아보자. ftrace 메시지에서 맨 왼쪽에서 ftrace를 출력하는 프로세스의 정보를 볼 수 있다. "프로세스이름-[pid]" 형식이다. 즉, 위 로그에서는 pid가 1436인 chromiun-browse 프로세스가 실행 중이다. 다음의 "[002]"는 CPU 번호이다. 현재 몇 번째 CPU에서 프로세스가 실행 중인지 나타내며, 위 ftrace 메시지를 통해 2번 cpu에서 실행 중이라는 사실을 알 수 있다. 이어서 ftrace 메시지에서 출력하는 컨텍스트 정보를 해석하는 방법을 보자. 별거 아닌 것처럼 보여도 이는 ftrace에서 눈여겨봐야 할 중요 정보이며 다음과 같은 내용이 이곳이 출력된다.

- 인터럽트 활성화/비활성화 여부

- 선점 스케줄링 설정 여부

- 인터럽트 컨텍스트나 Soft IRQ 컨텍스트 여부

- 프로세스의 thread_info 구조체의 preepm_count 값

세부 컨텍스트 정보는 ftrace 메시지에서 항상 출력되며 4개의 알파벳으로 출력된다. 프로세스 컨텍스트의 세부 정보를 표현하는 알파벳의 의미는 다음과 같다.

- d: 해당 CPU 라인의 인터럽트를 비활성화한 상태

- n: 현재 프로세스가 선점 스케줄링될 수 있는 상태

- h/s : h이면 인터럽트 컨텍스트, s이면 Soft IRQ 컨텍스트

- 0~5: 프로세스의 thread_info 구조체의 preept_count 필드값

세부 항목이 활성화돼 있지 않으면 "."을 출력한다.

 

4. ftrace 커널 코드 분석의 안내자

ftrace 메시지는 텍스트 포맷이라서 해석하기 어렵다고 한다. 하지만 ftrace 메시지는 바로 커널 코드 분석의 안내자일 수 있다. 바로 ftrace 이벤트의 이름으로 커널 내부의 어떤 소스코드에서 이벤트를 출력하는지 알 수 있기 때문이다. sched_switch 이벤트는 trace_sched_switch() 함수가 실행될 때 프로세스가 스케줄링되는 정보를 출력한다. irq_handler_entry 이벤트는 trace_irq_handler_entry() 함수가 호출될 때 인터럽트 핸들러가 실행되기 직전에 인터럽트 이름과 번호를 출력한다. 또한 irq_handler_exit 이벤트는 trace_irq_handler_exit() 함수가 실행될 때 인터럽트 핸들러 처리가 끝났다는 정보를 출력한다. sched_switch 이벤트는 __schedule() 함수는 '프로세스가 스케줄링하는 동작'을 출력한다는 사실을 알 수 있다. 이를 통해 컨텍스트 스위칭은 __schedule() 함수에서 context_switch() 코드를 실행할 때 수행된다는 사실을 알 수 있다. 인터럽트 핸들러를 호출하기 직적 trace_irq_handler_entry() 함수를 호출해 irq_handler_entry 이벤트를 통해 인터럽트 정보를 출력한다. 인터럽트 핸들러의 실행을 종료한 후 발로 trace_irq_handler_exit() 함수를 호출해 irq_handler_exit 이벤트로 인터럽트 핸들러 처리가 끝났음을 알려준다.