Debugging the kernel using Ftrace
이 기사는 Steven Rostedt가 기고했습니다.
Ftrace는 Linux 커널에 직접 내장된 추적 유틸리티입니다. 많은 배포판은 이미 최신 릴리스에서 다양한 Ftrace 구성을 활성화했습니다. Ftrace가 Linux에 제공하는 이점 중 하나는 커널 내부에서 무슨 일이 일어나고 있는지 볼 수 있다는 것입니다. 따라서 문제 영역을 찾거나 이상한 버그를 추적하는 것이 더 쉬워집니다.
Ftrace는 충돌로 이어지는 이벤트를 보여주는 기능을 통해 충돌의 정확한 원인을 찾을 수 있는 가능성이 높아지고 개발자가 올바른 솔루션을 만드는 데 도움이 될 수 있습니다. 이 기사는 Linux 커널을 디버깅하는 데 Ftrace를 사용하는 다양한 방법을 다루는 2부 시리즈입니다. 이 첫 번째 부분에서는 Ftrace 설정, 함수 추적기 사용, 커널 내부에서 Ftrace 버퍼에 쓰기, 문제가 감지되었을 때 추적기를 중지하는 다양한 방법에 대해 간략히 설명합니다.
Ftrace는 두 가지 도구에서 파생되었습니다. 하나는 -rt 트리에서 사용된 Ingo Molnar의 "latency tracer"입니다. 다른 하나는 Linux 커널 디버깅에 주로 사용된 저만의 "logdev" 유틸리티입니다. 이 문서에서는 주로 logdev에서 나온 기능을 설명하지만, 대기 시간 추적기에서 유래한 함수 추적기도 살펴보겠습니다.
1. Ftrace 설정
현재 Ftrace와 인터페이스하는 API는 Debugfs 파일 시스템에 있습니다. 일반적으로 /sys/kernel/debug에 마운트됩니다. 더 쉽게 액세스할 수 있도록 보통 /debug 디렉터리를 만들어서 거기에 마운트합니다. Debugfs에 대한 위치를 자유롭게 선택하세요.
Ftrace가 구성되면 Debugfs 파일 시스템 내에 tracing이라는 자체 디렉터리가 생성됩니다. 이 문서에서는 Debugfs 파일 시스템이 마운트된 위치에 대한 혼란을 피하기 위해 사용자가 먼저 디렉토리를 Debugfs 추적 디렉토리로 변경한 것처럼 해당 디렉토리의 해당 파일을 참조합니다.
[~]# cd /sys/kernel/debug/tracing
[tracing]#
이 문서에서는 Ftrace를 디버깅 도구로 사용하는 데 중점을 둡니다. Ftrace의 일부 구성은 대기 시간을 찾거나 시스템을 분석하는 것과 같은 다른 용도로 사용됩니다. 디버깅을 위해 활성화해야 하는 커널 구성 매개변수는 다음과 같습니다.
CONFIG_FUNCTION_TRACER
CONFIG_FUNCTION_GRAPH_TRACER
CONFIG_STACK_TRACER
CONFIG_DYNAMIC_FTRACE
2. Function tracing - no modification necessary
Ftrace의 가장 강력한 추적기 중 하나는 함수 추적기입니다. gcc의 -pg 옵션을 사용하여 커널의 모든 함수가 특수 함수 "mcount()"를 호출하도록 합니다. 해당 함수는 호출이 일반 C ABI를 따르지 않으므로 어셈블리에서 구현해야 합니다.
CONFIG_DYNAMIC_FTRACE가 구성된 경우 부팅 시 호출이 NOP로 변환되어 시스템이 100% 성능으로 실행됩니다. 컴파일하는 동안 mcount() 호출 사이트가 기록됩니다. 해당 목록은 부팅 시 해당 사이트를 NOP로 변환하는 데 사용됩니다. NOP는 추적에 거의 쓸모가 없으므로 함수(또는 함수 그래프) 추적기가 활성화되면 호출 사이트를 다시 추적 호출로 변환하기 위해 목록이 저장됩니다.
이러한 성능 향상으로 인해 CONFIG_DYNAMIC_FTRACE를 활성화하는 것이 좋습니다. 또한 CONFIG_DYNAMIC_FTRACE는 추적해야 할 함수를 필터링하는 기능을 제공합니다. NOP가 벤치마크에서 아무런 영향을 미치지 않더라도 -pg 옵션과 함께 제공되는 프레임 포인터를 추가하면 약간의 오버헤드가 발생하는 것으로 알려져 있습니다.
사용 가능한 추적기를 알아보려면 추적 디렉토리에 있는 available_tracers 파일을 cat으로 실행하기만 하면 됩니다.
[tracing]# cat available_tracers
function_graph function sched_switch nop
함수 추적기를 활성화하려면 current_tracer 파일에 "function"을 echo하기만 하면 됩니다.
[tracing]# echo function > current_tracer
[tracing]# cat current_tracer
function
[tracing]# cat trace | head -10
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
bash-16939 [000] 6075.461561: mutex_unlock <-tracing_set_tracer
<idle>-0 [001] 6075.461561: _spin_unlock_irqrestore <-hrtimer_get_next_event
<idle>-0 [001] 6075.461562: rcu_needs_cpu <-tick_nohz_stop_sched_tick
bash-16939 [000] 6075.461563: inotify_inode_queue_event <-vfs_write
<idle>-0 [001] 6075.461563: mwait_idle <-cpu_idle
bash-16939 [000] 6075.461563: __fsnotify_parent <-vfs_write
헤더는 출력 형식을 아주 잘 설명합니다. 처음 두 항목은 추적된 작업 이름과 PID입니다. 추적이 실행된 CPU는 괄호 안에 있습니다. 타임스탬프는 부팅 이후 시간이며, 그 뒤에 함수 이름이 옵니다. 이 경우 함수는 추적되는 함수이며, 그 뒤에 부모가 "<-" 기호로 옵니다.
이 정보는 매우 강력하며 함수의 흐름을 잘 보여줍니다. 하지만 따라가기가 약간 어려울 수 있습니다. Frederic Weisbecker가 만든 함수 그래프 추적기는 함수의 진입과 종료를 모두 추적하여 추적기가 호출된 함수의 깊이를 알 수 있게 합니다. 함수 그래프 추적기를 사용하면 인간의 눈으로 커널 내에서 실행 흐름을 따라가는 것이 훨씬 쉬워집니다.
[tracing]# echo function_graph > current_tracer
[tracing]# cat trace | head -20
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
1) 1.015 us | _spin_lock_irqsave();
1) 0.476 us | internal_add_timer();
1) 0.423 us | wake_up_idle_cpu();
1) 0.461 us | _spin_unlock_irqrestore();
1) 4.770 us | }
1) 5.725 us | }
1) 0.450 us | mutex_unlock();
1) + 24.243 us | }
1) 0.483 us | _spin_lock_irq();
1) 0.517 us | _spin_unlock_irq();
1) | prepare_to_wait() {
1) 0.468 us | _spin_lock_irqsave();
1) 0.502 us | _spin_unlock_irqrestore();
1) 2.411 us | }
1) 0.449 us | kthread_should_stop();
1) | schedule() {
이것은 "{"로 시작하는 C와 같은 주석과 끝에 "}"로 표시된 함수의 시작과 끝을 제공합니다. 다른 함수를 호출하지 않는 Leaf 함수는 단순히 ";"로 끝납니다. DURATION 열은 해당 함수에서 소요된 시간을 보여줍니다. 함수 그래프 추적기는 함수에 들어가고 나온 시간을 기록하고 그 차이를 기간으로 보고합니다. 이러한 숫자는 Leaf 함수와 "}" 기호와 함께만 나타납니다. 이 시간에는 중첩된 함수 내의 모든 함수의 오버헤드와 함수 그래프 추적기 자체의 오버헤드도 포함된다는 점에 유의하세요. 함수 그래프 추적기는 함수 종료에 대한 추적 콜백을 삽입하기 위해 함수의 반환 주소를 하이재킹합니다. 이는 CPU의 분기 예측을 깨고 함수 추적기보다 약간 더 많은 오버헤드를 발생시킵니다. 가장 가까운 실제 타이밍은 Leaf 함수에서만 발생합니다.
거기에 있는 외로운 "+"는 주석 마커입니다. 기간이 10마이크로초보다 크면 "+"가 표시됩니다. 기간이 100마이크로초보다 크면 "!" 표시됩니다.
3. trace_printk() 사용
printk()는 모든 디버거의 왕이지만 문제가 있습니다. 타이머 인터럽트, 스케줄러 또는 네트워크와 같이 볼륨이 많은 영역을 디버깅하는 경우 printk()로 인해 시스템이 멈추거나 라이브 잠금이 발생할 수도 있습니다. 몇 개의 printk()를 추가하면 버그가 "사라지는" 경우도 흔합니다. 이는 printk()가 도입하는 엄청난 오버헤드 때문입니다.
Ftrace는 trace_printk()라는 새로운 형태의 printk()를 도입합니다. printk()와 마찬가지로 사용할 수 있으며 모든 컨텍스트(인터럽트 코드, NMI 코드 및 스케줄러 코드)에서 사용할 수도 있습니다. trace_printk()의 장점은 콘솔에 출력하지 않는다는 것입니다. 대신 Ftrace 링 버퍼에 쓰고 추적 파일을 통해 읽을 수 있습니다.
trace_printk()로 링 버퍼에 쓰는 데 걸리는 시간은 약 1/10마이크로초 정도입니다. 하지만 printk()를 사용하면, 특히 직렬 콘솔에 쓸 때, 쓰기당 몇 밀리초가 걸릴 수 있습니다. trace_printk()의 성능 이점을 통해 커널의 가장 민감한 영역을 거의 영향을 미치지 않고 기록할 수 있습니다.
예를 들어, 커널이나 모듈에 다음과 같은 것을 추가할 수 있습니다.
trace_printk("read foo %d out of bar %p\n", bar->foo, bar);
그런 다음 추적 파일을 살펴보면 출력을 확인할 수 있습니다.
[tracing]# cat trace
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<...>-10690 [003] 17279.332920: : read foo 10 out of bar ffff880013a5bef8
위의 예는 실제로 foo와 bar 구조를 가진 모듈을 추가하여 수행되었습니다.
trace_printk() 출력은 함수 및 함수 그래프 트레이서도 모든 트레이서에 나타납니다.
[tracing]# echo function_graph > current_tracer
[tracing]# insmod ~/modules/foo.ko
[tracing]# cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
3) + 16.283 us | }
3) + 17.364 us | }
3) | do_one_initcall() {
3) | /* read foo 10 out of bar ffff88001191bef8 */
3) 4.221 us | }
3) | __wake_up() {
3) 0.633 us | _spin_lock_irqsave();
3) 0.538 us | __wake_up_common();
3) 0.563 us | _spin_unlock_irqrestore();
예, trace_printk() 출력은 함수 그래프 추적기의 주석처럼 보입니다.
4. Starting and stopping the trace
특정 코드 경로만 추적하려는 경우가 분명히 있습니다. 아마도 특정 테스트를 실행할 때 발생하는 일만 추적하고 싶을 것입니다. tracing_on 파일은 링 버퍼가 데이터를 기록하지 못하도록 비활성화하는 데 사용됩니다.
[tracing]# echo 0 > tracing_on
이렇게 하면 Ftrace 링 버퍼가 기록되지 않습니다. 다른 모든 작업은 추적기에서 계속 수행되고 여전히 대부분의 오버헤드가 발생합니다. 추적기는 링 버퍼가 기록되지 않고 데이터를 쓰려고 하지 않는다는 것을 알아차리지만 추적기가 하는 호출은 계속 수행됩니다.
링 버퍼를 다시 활성화하려면 해당 파일에 '1'을 쓰기만 하면 됩니다.
[tracing]# echo 1 > tracing_on
숫자와 ">"보다 큰 기호 사이에 공백이 있어야 합니다. 그렇지 않으면 해당 파일에 표준 입력 또는 출력을 쓸 수 있습니다.
[tracing]# echo 0 > tracing_on /* this will not work! */
일반적인 실행은 다음과 같을 수 있습니다:
[tracing]# echo 0 > tracing_on
[tracing]# echo function_graph > current_tracer
[tracing]# echo 1 > tracing_on; run_test; echo 0 > tracing_on
첫 번째 줄은 링 버퍼가 데이터를 기록하지 못하도록 비활성화합니다. 다음 줄은 함수 그래프 추적기를 활성화합니다. 함수 그래프 추적기의 오버헤드는 여전히 존재하지만 추적 버퍼에 아무것도 기록되지 않습니다. 마지막 줄은 링 버퍼를 활성화하고 테스트 프로그램을 실행한 다음 링 버퍼를 비활성화합니다. 이렇게 하면 함수 그래프 추적기에 저장된 데이터가 대부분 run_test 프로그램에서 축적된 데이터만 포함하도록 좁혀집니다.
5. What's next?
다음 기사에서는 Ftrace로 커널을 디버깅하는 것에 대한 논의를 계속합니다. 추적을 비활성화하는 위의 방법은 충분히 빠르지 않을 수 있습니다. 프로그램 run_test가 끝나고 tracing_on 파일에 0을 에코하는 사이의 지연 시간으로 인해 링 버퍼가 오버플로되어 관련 데이터가 손실될 수 있습니다. 추적을 조금 더 효율적으로 중지하는 다른 방법, 충돌을 디버깅하는 방법, 커널에서 스택을 많이 차지하는 함수를 살펴보는 방법에 대해 논의하겠습니다. 자세한 내용을 알아보는 가장 좋은 방법은 Ftrace를 활성화하고 그냥 사용해 보는 것입니다. 함수 그래프 추적기를 따라가기만 하면 커널이 작동하는 방식에 대해 많은 것을 배울 수 있습니다.
이전 기사에서는 Ftrace 설정, 함수 및 함수 그래프 추적기 사용, trace_printk() 사용, 사용자 공간에서 추적 기록을 중지하는 간단한 방법에 대해 설명했습니다. 이 기사에서는 사용자 공간이 Ftrace와 상호 작용하는 방법, 추적을 중지하는 더 빠른 방법, 충돌 디버깅, 가장 큰 스택 호그인 커널 함수를 찾는 방법에 대해 설명합니다.
6. Trace Markers
커널 내부에서 무슨 일이 일어나는지 보면 사용자는 시스템이 작동하는 방식을 더 잘 이해할 수 있습니다. 하지만 때로는 사용자 공간에서 일어나는 일과 커널 내부에서 일어나는 일 사이에 조정이 필요합니다. 추적에 표시되는 타임스탬프는 모두 추적 내에서 일어나는 일과 관련이 있지만 실제 시간과는 잘 맞지 않습니다.
사용자 공간과 커널 공간에서의 작업을 동기화하는 데 도움이 되도록 trace_marker 파일이 생성되었습니다. 이 파일은 사용자 공간에서 Ftrace 링 버퍼에 쓰는 방법을 제공합니다. 그러면 이 마커가 추적에 나타나 특정 이벤트가 발생한 추적의 위치를 알려줍니다.
[tracing]# echo hello world > trace_marker
[tracing]# cat trace
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<...>-3718 [001] 5546.183420: 0: hello world
<...>는 마커를 작성한 작업의 이름이 기록되지 않았음을 나타냅니다. 향후 릴리스에서 이 문제가 수정될 수 있습니다.
7. Starting, Stopping and Recording in a Program
tracing_on 및 trace_marker 파일은 애플리케이션 소스를 사용할 수 있는 경우 애플리케이션의 활동을 추적하는 데 매우 효과적입니다. 애플리케이션 내에 문제가 있고 애플리케이션의 특정 위치에서 커널 내부에서 무슨 일이 일어나고 있는지 알아내야 하는 경우 이 두 파일이 유용합니다.
애플리케이션을 시작할 때 다음 파일을 열어 파일 설명자를 준비할 수 있습니다.
int trace_fd = -1;
int marker_fd = -1;
int main(int argc, char **argv)
{
char *debugfs;
char path[256];
[...]
debugfs = find_debugfs();
if (debugfs) {
strcpy(path, debugfs); /* BEWARE buffer overflow */
strcat(path,"/tracing/tracing_on");
trace_fd = open(path, O_WRONLY);
if (trace_fd >= 0)
write(trace_fd, "1", 1);
strcpy(path, debugfs);
strcat(path,"/tracing/trace_marker");
marker_fd = open(path, O_WRONLY);
그런 다음 코드의 중요한 위치에 마커를 배치하여 현재 애플리케이션이 있는 위치를 표시할 수 있습니다.
if (marker_fd >= 0)
write(marker_fd, "In critical area\n", 17);
if (critical_function() < 0) {
/* we failed! */
if (trace_fd >= 0)
write(trace_fd, "0", 1);
}
예를 살펴보면 먼저 "find_debugfs()"라는 함수가 보입니다. 디버그 파일 시스템을 마운트하기 위한 적절한 위치는 /sys/kernel/debug이지만 강력한 도구는 디버그 파일 시스템이 거기에 마운트되는 데 의존해서는 안 됩니다. find_debugfs()의 예는 여기에 있습니다. 파일 설명자는 -1로 초기화되어 이 코드가 추적이 활성화된 커널이 있든 없든 작동할 수 있습니다.
문제가 감지되면 trace_fd 파일 설명자에 ASCII 문자 "0"을 쓰면 추적이 중지됩니다. 1부에서 설명한 대로 이렇게 하면 Ftrace 링 버퍼에 기록하는 것만 비활성화되지만 추적기는 여전히 오버헤드를 발생시킵니다.
위의 초기화 코드를 사용하면 추적기가 덮어쓰기 모드로 실행되기 때문에 애플리케이션 시작 시 추적이 활성화됩니다. 즉, 추적 버퍼가 가득 차면 이전 데이터를 제거하고 새 데이터로 대체합니다. 문제가 발생할 때 가장 최근의 추적 정보만 관련이 있으므로 애플리케이션이 정상적으로 실행되는 동안 추적을 중지하고 시작할 필요가 없습니다. 추적기는 문제가 감지될 때만 비활성화하면 되므로 추적에는 오류로 이어진 내역이 있습니다. 애플리케이션 내에서 간격 추적이 필요한 경우 추적을 활성화하기 위해 trace_fd에 ASCII "1"을 쓸 수 있습니다.
위에 설명된 초기화 프로세스를 사용하는 simple_trace.c라는 간단한 프로그램의 예는 다음과 같습니다.
req.tv_sec = 0;
req.tv_nsec = 1000;
write(marker_fd, "before nano\n", 12);
nanosleep(&req, NULL);
write(marker_fd, "after nano\n", 11);
write(trace_fd, "0", 1);
(이것은 예시 목적의 간단한 프로그램이므로 오류 검사는 추가되지 않았습니다.)
다음은 이 간단한 프로그램을 추적하는 프로세스입니다.
[tracing]# echo 0 > tracing_on
[tracing]# echo function_graph > current_tracer
[tracing]# ~/simple_trace
[tracing]# cat trace
첫 번째 줄은 프로그램이 시작 시 추적을 활성화하기 때문에 추적을 비활성화합니다. 그 다음 함수 그래프 추적기를 선택합니다. 프로그램이 실행되어 다음과 같은 추적이 생성됩니다. 출력이 약간 장황할 수 있으므로 많은 부분이 잘려나가고 [...]로 대체되었습니다.
[...]
0) | __kmalloc() {
0) 0.528 us | get_slab();
0) 2.271 us | }
0) | /* before nano */
0) | kfree() {
0) 0.475 us | __phys_addr();
0) 2.062 us | }
0) 0.608 us | inotify_inode_queue_event();
0) 0.485 us | __fsnotify_parent();
[...]
1) 0.523 us | _spin_unlock();
0) 0.495 us | current_kernel_time();
1) | it_real_fn() {
0) 1.602 us | }
1) 0.728 us | __rcu_read_lock();
0) | sys_nanosleep() {
0) | hrtimer_nanosleep() {
0) 0.526 us | hrtimer_init();
1) 0.418 us | __rcu_read_lock();
0) | do_nanosleep() {
1) 1.114 us | _spin_lock_irqsave();
[...]
0) | __kmalloc() {
1) 2.760 us | }
0) 0.556 us | get_slab();
1) | mwait_idle() {
0) 1.851 us | }
0) | /* after nano */
0) | kfree() {
0) 0.486 us | __phys_addr();
trace_marker에 대한 쓰기가 함수 그래프 추적기에서 주석으로 표시되는 것을 주목하세요.
여기 첫 번째 열은 CPU를 나타냅니다. CPU 추적을 이렇게 끼워 넣으면 추적을 읽기 어려울 수 있습니다. grep 도구를 사용하면 이를 쉽게 필터링할 수 있고, per_cpu 추적 파일을 사용할 수도 있습니다. per_cpu 추적 파일은 per_cpu 아래의 debugfs 추적 디렉터리에 있습니다.
[tracing]# ls per_cpu
cpu0 cpu1 cpu2 cpu3 cpu4 cpu5 cpu6 cpu7
이러한 CPU 디렉토리 각각에는 해당 CPU에 대한 추적만 보여주는 추적 파일이 있습니다.
다른 CPU의 간섭 없이 function graph tracer를 쉡게 보려면 per_cpu/cpu0/trace를 살펴보세요.
[tracing]# cat per_cpu/cpu0/trace
0) | __kmalloc() {
0) 0.528 us | get_slab();
0) 2.271 us | }
0) | /* before nano */
0) | kfree() {
0) 0.475 us | __phys_addr();
0) 2.062 us | }
0) 0.608 us | inotify_inode_queue_event();
0) 0.485 us | __fsnotify_parent();
0) 0.488 us | inotify_dentry_parent_queue_event();
0) 1.106 us | fsnotify();
[...]
0) 0.721 us | _spin_unlock_irqrestore();
0) 3.380 us | }
0) | audit_syscall_entry() {
0) 0.495 us | current_kernel_time();
0) 1.602 us | }
0) | sys_nanosleep() {
0) | hrtimer_nanosleep() {
0) 0.526 us | hrtimer_init();
0) | do_nanosleep() {
0) | hrtimer_start_range_ns() {
0) | __hrtimer_start_range_ns() {
0) | lock_hrtimer_base() {
0) 0.866 us | _spin_lock_irqsave();
[...]
0) | __kmalloc() {
0) | get_slab() {
0) 1.851 us | }
0) | /* after nano */
0) | kfree() {
0) 0.486 us | __phys_addr();
8. Disabling the Tracer Within the Kernel
커널 드라이버를 개발하는 동안 테스트 중에 이상한 오류가 발생할 수 있습니다. 아마도 드라이버가 절전 상태에 갇혀서 결코 깨어나지 않을 수도 있습니다. 커널 이벤트가 발생할 때 사용자 공간에서 추적기를 비활성화하려고 하면 어렵고 일반적으로 사용자가 추적을 중지하기 전에 버퍼 오버플로가 발생하고 관련 정보가 손실됩니다.
커널 내부에서 잘 작동하는 두 가지 함수가 있습니다. tracing_on()과 tracing_off()입니다. 이 두 가지는 tracing_on 파일에 각각 "1" 또는 "0"을 에코하는 것과 똑같이 작동합니다. 커널 내부에서 확인할 수 있는 조건이 있는 경우 다음과 같은 것을 추가하여 추적기를 중지할 수 있습니다.
if (test_for_error())
tracing_off();
다음으로 여러 개의 trace_printk()를 추가하고(1부 참조), 다시 컴파일하고 커널을 부팅합니다. 그런 다음 함수 또는 함수 그래프 추적기를 활성화하고 오류 조건이 발생할 때까지 기다리면 됩니다. tracing_on 파일을 검사하면 오류 조건이 발생한 시점을 알 수 있습니다. 커널이 tracing_off()를 호출하면 "1"에서 "0"으로 전환됩니다.
추적을 검사하거나 다음을 사용하여 다른 파일에 저장한 후:
cat trace > ~/trace.sav
추적을 계속하여 다른 히트를 검사할 수 있습니다. 이렇게 하려면 tracing_on에 "1"을 에코하기만 하면 추적이 계속됩니다. tracing_off() 호출을 트리거하는 조건을 합법적으로 트리거할 수 있는 경우에도 유용합니다. 조건이 정상적인 작업으로 트리거된 경우 tracing_on에 "1"을 다시 에코하여 추적을 다시 시작하면 다음에 조건이 히트되는 시점이 비정상성 때문일 것입니다.
9. ftrace_dump_on_oops
커널이 충돌하는 경우가 있으며 충돌의 메모리와 상태를 검사하는 것은 프로그램 디버깅 과학이라기보다는 CSI 과학에 가깝습니다. 크래시 유틸리티와 함께 kdump/kexec를 사용하면 크래시 시점의 시스템 상태를 검사하는 데 유용한 방법이지만 크래시를 일으킨 이벤트 이전에 무슨 일이 있었는지 볼 수는 없습니다.
커널 부팅 매개변수에서 ftrace_dump_on_oops를 구성하고 활성화하거나 /proc/sys/kernel/ftrace_dump_on_oops에 "1"을 에코하면 Ftrace가 oops 또는 패닉 시 ASCII 형식으로 전체 추적 버퍼를 콘솔에 덤프할 수 있습니다. 콘솔 출력을 직렬 로그로 설정하면 크래시 디버깅이 훨씬 쉬워집니다. 이제 크래시로 이어진 이벤트를 추적할 수 있습니다.
기본 Ftrace 링 버퍼는 CPU당 1메가바이트가 넘기 때문에 콘솔에 덤프하는 데 시간이 오래 걸릴 수 있습니다. 링 버퍼의 크기를 줄이려면 링 버퍼가 되기를 원하는 킬로바이트 수를 buffer_size_kb에 쓰세요. 값은 링 버퍼의 총 크기가 아니라 CPU당 값입니다.
[tracing]# echo 50 > buffer_size_kb
위의 내용은 Ftrace 링 버퍼를 CPU당 50킬로바이트로 줄입니다.
sysrq-z를 사용하여 Ftrace 버퍼를 콘솔에 덤프하도록 트리거할 수도 있습니다.
커널 덤프의 특정 위치를 선택하기 위해 커널은 ftrace_dump()를 직접 호출할 수 있습니다. 이렇게 하면 Ftrace가 영구적으로 비활성화될 수 있으며 다시 활성화하려면 재부팅이 필요할 수 있습니다. 이는 ftrace_dump()가 버퍼를 읽기 때문입니다. 버퍼는 모든 컨텍스트(인터럽트, NMI, 스케줄링)에서 쓰도록 만들어졌지만 버퍼를 읽으려면 잠금이 필요합니다. ftrace_dump()를 수행하려면 잠금이 비활성화되고 출력 후 버퍼가 손상될 수 있습니다.
/*
* The following code will lock up the box, so we dump out the
* trace before we hit that location.
*/
ftrace_dump();
/* code that locks up */
10. Stack Tracing
논의할 마지막 주제는 커널 스택의 크기와 각 함수가 사용하는 스택 공간을 검사하는 기능입니다. 스택 추적기(CONFIG_STACK_TRACER)를 활성화하면 스택을 가장 많이 사용하는 곳이 표시됩니다.
스택 추적기는 함수 추적기 인프라에서 빌드됩니다. Ftrace 링 버퍼를 사용하지 않지만 함수 추적기를 사용하여 모든 함수 호출에 연결합니다. 함수 추적기 인프라를 사용하므로 활성화하지 않아도 오버헤드가 추가되지 않습니다. 스택 추적기를 활성화하려면 1을 /proc/sys/kernel/stack_tracer_enabled에 echo합니다. 부팅 중에 최대 스택 크기를 보려면 커널 부팅 매개변수에 "stacktrace"를 추가합니다.
스택 추적기는 모든 함수 호출에서 스택 크기를 확인합니다. 마지막으로 기록된 최대값보다 크면 스택 추적을 기록하고 최대값을 새 크기로 업데이트합니다. 현재 최대값을 보려면 stack_max_size 파일을 살펴보세요.
[tracing]# echo 1 > /proc/sys/kernel/stack_tracer_enabled
[tracing]# cat stack_max_size
2928
[tracing]# cat stack_trace
Depth Size Location (34 entries)
----- ---- --------
0) 2952 16 mempool_alloc_slab+0x15/0x17
1) 2936 144 mempool_alloc+0x52/0x104
2) 2792 16 scsi_sg_alloc+0x4a/0x4c [scsi_mod]
3) 2776 112 __sg_alloc_table+0x62/0x103
[...]
13) 2072 48 __elv_add_request+0x98/0x9f
14) 2024 112 __make_request+0x43e/0x4bb
15) 1912 224 generic_make_request+0x424/0x471
16) 1688 80 submit_bio+0x108/0x115
17) 1608 48 submit_bh+0xfc/0x11e
18) 1560 112 __block_write_full_page+0x1ee/0x2e8
19) 1448 80 block_write_full_page_endio+0xff/0x10e
20) 1368 16 block_write_full_page+0x15/0x17
21) 1352 16 blkdev_writepage+0x18/0x1a
22) 1336 32 __writepage+0x1a/0x40
23) 1304 304 write_cache_pages+0x241/0x3c1
24) 1000 16 generic_writepages+0x27/0x29
[...]
30) 424 64 bdi_writeback_task+0x3f/0xb0
31) 360 48 bdi_start_fn+0x76/0xd7
32) 312 128 kthread+0x7f/0x87
33) 184 184 child_rip+0xa/0x20
이렇게 하면 발견된 최대 스택의 크기를 알 수 있을 뿐만 아니라 각 함수에서 사용하는 스택 크기의 세부 정보도 볼 수 있습니다. write_cache_pages가 304바이트로 가장 큰 스택을 사용했고, 그 다음으로 generic_make_request가 224바이트의 스택을 사용했습니다.
최대값을 재설정하려면 stack_max_size 파일에 "0"을 echo합니다.
[tracing]# echo 0 > stack_max_size
잠시 실행하면 커널이 스택을 너무 많이 사용하는 곳이 표시됩니다. 하지만 스택 추적기는 활성화되지 않은 경우에만 오버헤드가 없다는 점을 기억하세요. 실행 중일 때는 성능이 약간 저하될 수 있습니다.
커널이 별도의 스택을 사용하는 경우 스택 추적기는 최대 스택 크기를 추적하지 않습니다. 인터럽트에는 자체 스택이 있기 때문에 스택 사용량을 추적하지 않습니다. 그 이유는 현재 스택이 현재 작업의 스택이 아닌 다른 것일 때 스택의 맨 위가 무엇인지 빠르게 확인할 수 있는 쉬운 방법이 없기 때문입니다. 분할 스택을 사용할 때 프로세스 스택은 두 페이지일 수 있지만 인터럽트 스택은 하나뿐일 수 있습니다. 이는 나중에 수정될 수 있지만 스택 추적기를 사용할 때 이 점을 명심하세요.
11. 결론 - Conclusion
Ftrace는 매우 강력한 도구이며 구성하기 쉽습니다. 추가 도구가 필요하지 않습니다. 이 튜토리얼에서 보여준 모든 내용은 Busybox만 설치된 임베디드 장치에서 사용할 수 있습니다. Ftrace 인프라를 활용하면 찾기 어려운 경쟁 조건을 디버깅하는 데 필요한 시간을 줄일 수 있습니다. 저는 더 이상 printk()를 거의 사용하지 않습니다. trace_printk() 및 tracing_off()와 함께 함수 및 함수 그래프 추적기를 사용하는 것이 Linux 커널을 디버깅하는 주요 도구가 되었기 때문입니다.
'Embedded : : Linux > : : Linux Kernel' 카테고리의 다른 글
| [Linux Kernel] configuration file (0) | 2024.10.31 |
|---|---|
| 커널 로그 분석: WARN 매크로 (0) | 2024.10.31 |
| 태스크 디스크립터: 프로세스 간 관계 (0) | 2024.10.12 |
| 커널 스레드 (0) | 2024.10.12 |
| do_fork() 함수, 그리고 5.x 이후 (0) | 2024.10.12 |