디버깅을 통해 배우는 리눅스 커널의 구조와 원리 1, 도서 공부하기 6

IT/Linux Kernel

디버깅을 통해 배우는 리눅스 커널의 구조와 원리 1, 도서 공부하기 6 - printk와 dump_stack 함수

변화의 물결1 2025. 3. 1. 00:03

안녕하세요.

이번 시간은 printk()와 dump_stack()함수에 대해 학습하고 간단하게 디버깅 하는 방법을 알아 보겠습니다.

1. printk 함수

이미 C언어를 접해본 분이라면 printf 함수에 대해 잘 알고 있을 거라 생각됩니다. 함수 끝에 k가 붙은 것처럼 kernel에서 사용하기 위한 함수라는 것을 느낄 수 있을 것입니다.

이미 커널의 수많은 내부 함수에서도 printk 함수를 이용해서 에러 정보를 커널 로그에 출력하고 있습니다.

아래 내용은 책에서 소개한 porcess.c 파일의 일부 내용입니다. __show_regs 함수가 실행되면 레지스터 내용을 커널 로그에 출력하는 일부 코드입니다.

1) printk 형식

int printk(const char *fmt, ...);

printf처럼 사용 가능하며 앞쪽에 Log Levels를 추가하여 커널의 메시지를 출력하고 관리할 수 있습니다. Log Level를 넣지 않으면 기본적으로 "KERN_WARNING"/<4>입니다.

printk(KERN_INFO "Message: %s\n", arg);

값	레 벨	의 미
<0>	KERN_EMERG	시스템이 사용 불가능한 긴급 상태
<1>	KERN_ALERT	즉시 조치가 필요한 상태
<2>	KERN_CRIT	심각한 오류 발생
<3>	KERN_ERR	오류 발생
<4>	KERN_WARNING	경고 메시지
<5>	KERN_NOTICE	정상적인 중요 정보
<6>	KERN_INFO	시스템 정보
<7>	KERN_DEBUG	디버깅 정보

<사용 예제>

printk(KERN_DEBUG "Message: %s\n", arg);
printk("<7>" "Message: %s\n", arg);
printk("<7>Message: %s\n", arg);

2) printk 메시지 로깅 수준을 제어하는 설정

라즈베리 파이 시스템에 적용된 로그 레벨을 확인하기 위해서 아래와 같이 명령어를 입력해서 확인 가능합니다.

쉽게 말해 콘솔창에 출력하는 단계를 조절해서 보여줄 것과 아닌 것을 제어하기 위해서 사용합니다.

디바이스 드라이버 개발 등 나중을 위해서도 알아 두면 좋을 것 같아서 정리했습니다.

(1) printk 메시지 로깅 수준 확인

# cat /proc/sys/kernel/printk

3 4 1 3 값을 알아보면

- console_loglevel (3)

현재 콘솔에 출력될 최소한의 로그 레벨, KERN_ERR (3) 이상의 로그만 콘솔에 출력됨.

즉, 오류 메시지(KERN_ERR), 심각한 오류(KERN_CRIT), 경고(KERN_ALERT 등)만 출력됨

KERN_WARNING (4) 이상의 일반적인 경고 메시지는 콘솔에 출력되지 않음.

- default_message_loglevel (4)

printk() 호출 시 로그 레벨이 명시되지 않은 경우 기본적으로 설정되는 레벨

여기서는 KERN_WARNING (4)이므로, 기본적으로 KERN_WARNING로 로그가 남음.

- minimum_console_loglevel (1)

console_loglevel이 최소한 이 값(1, KERN_ALERT) 보다 낮아지지 않도록 제한

즉, console_loglevel을 0(KERN_EMERG)으로 설정하고 싶어도 최소한 KERN_ALERT (1)까지만 가능함

- default_console_loglevel (3)

부팅 시 기본적으로 설정되는 console_loglevel 값

즉, 부팅 직후에는 console_loglevel이 3(KERN_ERR)으로 설정됨.

부팅 중 KERN_WARNING (4) 이하의 메시지는 출력되지 않음.

(2) printk 메시지 로깅 수준 설정

기본 메시지(KERN_WARNING (4))를 보기 위해서 로그레벨을 바꿔 줍니다.

설정이 저장되지 않고 현재 상태에서 적용하는 방법은 아래와 같습니다.

# echo '4 4 1 4' > /proc/sys/kernel/printk
# cat /proc/sys/kernel/printk

4) printk 서식 지정자

printk 자료형에 따른 서식 지정자는 printf와 거의 동일하며, 조금 특별한 지정자 %pS가 있습니다. 의미는 %p 포인터를 출력하고 추가로 문자 스트링 %s을 출력하는 지정자와 결합되어, 주소의 심벌 출력합니다. 이것은 커널이 심벌 테이블을 가지고 있어서 가능합니다.

변수 타입	서식 지정자
int	%d 또는 %x
unsigned int	%u 또는 %x
long	%ld 또는 %lx
unsigned long	%lu 또는 %lx
long long	%lld 또는 %llx
unsigned long long	%llu 또는 %llx
size_t	%zu 또는 %zx
ssize_t	%zd 또는 %zx
s32	%d 또는 %x
u32	%u 또는 %x
s64	%lld 또는 %llx
u64	%llu 또는 %llx

2. printk로 심벌 정보 보는 방법

1) printk 코드 추가

실제 커널 printk 실습을 진행합니다. 패치코드를 추가할 파일은 workqueue.c입니다.

linux # vim kernel/workqueue.c

void insert_wq_barrier() 함수 아래쪽에 2개의 printk 문을 추가합니다.

current(현재 프로세스의 태스크 디스크립터 주소)가 가리키는 프로세서 이름 출력하고, 현재 실행 중인 함수 이름(__func__), 현재 실행 중인 코드라인(__LINE__), 현재 실행 중인 함수를 호출한 함수의 주소(__builtin_return_address)를 통해 심벌 이름을 출력합니다.

    printk("[+] process : %s \n", current->comm);
    printk("[+][debug] message [F:%s, L:%d]: caller:(%pS)\n",
                      __func__, __LINE__, (void*)__builtin_return_address(0));

2) 실행 결과 확인

커널 코드를 수정했다면 앞에서 만들어 놓은 빌드와 설치 셀 스크립트를 실행합니다. 그리고 재부팅을 하고 커널 로그를 확인합니다.

 linux# ../build_rpi_kernel.sh
 linux# ../install_rpi_kernel_img.sh
 linux# reboot
 ...
 $ dmesg 혹은 cat /var/log/kern.log | more

캡처한 화면의 첫 번째 디버깅 정보를 보면 프로세서 이름은 kworker/u8:1이며, printk가 있는 곳은 insert_wq_barrier 함수 2542번째 줄입니다. insert_wq_barrier함수는 flush_work함수가 호출한 것을 알 수 있습니다.

[유용한 TIP]

현재 테스트는 git branch rpi-4.19.y_test 해서 하고 있습니다. 위의 코드를 추가하고 빌드까지 했을 때 문제가 없다면 commit 한 후 git diff로 명령어로 원본 코드와 비교해 볼 수 있습니다.

(commit 이전에도 비교 가능함) 간단하게 2가지 방법으로 확인할 수 있습니다.

1. 다른 브런치에 있는 파일과 비교하는 방법

linux# git diff rpi-4.19.y..rpi-4.19.y_test -- kernel/workqueue.c

2. 커밋 이전 파일과 비교하는 방법

linux# git diff HEAD~1 kernel/workqueue.c

3. printk 사용 시 주의점

printk 호출 빈도 확인이 필요합니다. 자주 호출하는 커널 함수에 printk를 사용하면 시스템이 락업(Lockup) 되거나 커널 패닉으로 아무런 반응이 없는 상태가 될 수 있습니다.

이유는 커널 입장에서 많은 비용이 드는 함수이기 때문입니다. 그리고 커널 세부 동작을 콘솔 드라이버에서 처리하고 커널 로그를 저장하는 동작을 백그라운드에서 처리하기 때문입니다.

책에서는 sched/core.c 파일에 printk() 코드 추가하는 내용이 나오지만, 추천하지는 않습니다.

대신 자주 호출되는 함수라도 콜 스택을 보고 싶다면 ftrace를 사용하는 것이라고 알려줍니다.

4. dump_stack() 함수

printk 외에 커널 로그를 통해 커널 동작을 보여주는 것 중에 하나는 커널에서 지원하는 dump_stack() 함수를 호출하는 것이 있습니다.

커널 로그로 콜 스택을 보고 싶은 코드에 dump_stack() 함수만 추가하면 됩니다.

1) 사용방법

dump_stack() 함수를 사용할 파일에 헤더파일 하나 추가합니다.

 #include <linux/kernel.h>

함수 선언부는 asmlinkage __visible void dump_statck(void); 와 같이 인자와 반환값 타입이 void이다 보니 dump_stack() 함수만 추가하면 됩니다.

2) dump_stack() 코드 추가

콜 스택 확인을 위해 예제로 kernel/fork.c 파일에 패치 코드를 추가합니다. _do_fork에 위와 add_lasten_entropy() 함수 아래에 코드를 추가합니다.

 linux# vim kernel/fork.c

static int debug_kernel_thread = 1;
...
if (debug_kernel_thread) {
               printk("[+][%s] process n", current->comm);
               dump_stack();
       }

3) 실행 결과

커널 코드를 수정했다면 앞에서 만들어 놓은 빌드와 설치 셀스크립트를 실행합니다.

그리고 재부팅을 하고 커널 로그를 확인합니다.

 linux# ../build_rpi_kernel.sh
 linux# ../install_rpi_kernel_img.sh
 linux# reboot
 ...
 $ dmesg 혹은 cat /var/log/kern.log | more

로그 내용 중 캡처한 내용을 확인하면 1줄에 [+] 프로세서 명이 나오고, 2줄에 PID가 1033인 resolvconf 프로세스가 cpu2에서 실행 중인 것을 알 수 있습니다.

콜 스택이므로 sys_clone -> _do_fork -> dump_statck -> show_statck -> unwind_backtrace 순으로 함수가 호출된다는 것을 알 수 있습니다. 여기서 볼 것은 sys_clone함수에서 _do_fork함수를 호출한다는 것을 확인하는 것입니다.

5. dump_stack() 사용 시 주의점

printk와 유사하게 여러 번 호출되는 함수 내에서 사용하면 시스템 응답속도가 느려질 수 있습니다. 특히 printk보다 훨씬 많을 일을 합니다.

현재 실행 중인 프로세스 스택 주소를 읽어서 스택에 푸시된 프레임 포인터 레지스터를 읽고, 함수 호출 내역을 추적하는 동작을 반복합니다.

이번에는 printk와 dump_stack 함수에 대해서 알아봤습니다.

그런데 디버깅하기 좋은 함수이긴 한데, 이 두 함수는 주의해야 할 점이 있습니다.

이것을 주의해야 할 것을 해소하기 위한 방법으로 ftrace가 있습니다. 다음 글에서 확인해 보겠습니다.

감사합니다.

<참고 자료>

1. [도서] 디버깅을 통해 배우는 리눅스 커널의 구조와 원리, wikibook

2. printk

https://en.wikipedia.org/wiki/Printk

저작자표시