C 프로그래밍을 공부할 때 가장 먼저 만나는 함수가 main과 printf입니다.
printf("Hello World \n");
윈도우 콘솔 프로그램이나 리눅스 시스템 프로그램에서 printf 함수를 호출하면 콘솔로 문자열을 출력하듯이 printk() 함수를 호출하면 커널 로그를 볼 수 있습니다. 이미 커널의 수많은 내부 함수에서도 printk를 이용해 시스템 에러 정보를 커널 로그로 출력합니다.
printk를 사용하는 예제 코드 확인해보기
이번에는 커널의 핵심 코드에서 printk를 쓰는 사례를 소개합니다.
https://elixir.bootlin.com/linux/v4.19.30/source/arch/arm/kernel/process.c
01 void __show_regs(struct pt_regs *regs)
02 {
...
03 printk("pc : [<%08lx>] lr : [<%08lx>] psr: %08lx\n",
04 regs->ARM_pc, regs->ARM_lr, regs->ARM_cpsr);
05 printk("sp : %08lx ip : %08lx fp : %08lx\n",
06 regs->ARM_sp, regs->ARM_ip, regs->ARM_fp);
07 printk("r10: %08lx r9 : %08lx r8 : %08lx\n",
08 regs->ARM_r10, regs->ARM_r9,
09 regs->ARM_r8);
10 printk("r7 : %08lx r6 : %08lx r5 : %08lx r4 : %08lx\n",
11 regs->ARM_r7, regs->ARM_r6,
12 regs->ARM_r5, regs->ARM_r4);
__show_regs() 함수가 실행되면 레지스터 세트를 커널 로그로 출력합니다. 즉, 03~12번째 줄과 같이 레지스터 정보를 출력합니다.
printk 자료형에 따른 서식 지정
이번에는 printk에 전달하는 서식 지정자에 대해 살펴볼까요? 예를 들어, 정수형 포맷으로는 int, long, long long을 지원합니다. C 언어의 printf와 같습니다.
변수 타입 서식 지정자
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
printk에 전달하는 인자와 서식 지정자가 일치해야 커널을 빌드할 때 컴파일 에러가 발생하지 않습니다.
printk로 함수 심벌 정보를 보는 방법
이번에는 printk를 써서 함수의 심벌 정보를 출력하는 방법을 소개합니다.
printk로 포인터를 출력하고 싶을 때는 %p를 쓰면 됩니다. 커널은 심벌 테이블을 갖고 있으므로 %pS를 쓰면 함수 주소를 심벌로 출력합니다. 이는 함수 포인터를 디버깅할 때 자주 쓰는 기법입니다.
라즈비안 리눅스 커널 코드에 직접 printk 코드를 입력하는 실습을 해봅시다. 다음 코드를 리눅스 커널 코드에 입력합시다.
https://elixir.bootlin.com/linux/v4.19.30/source/kernel/workqueue.c
01 static void insert_wq_barrier(struct pool_workqueue *pwq,
02 struct wq_barrier *barr,
03 struct work_struct *target, struct worker *worker)
04 {
05 struct list_head *head;
06 unsigned int linked = 0;
07
08 + printk("[+] process: %s \n", current->comm);
09 + printk("[+][debug] message [F: %s, L:%d]: caller:(%pS)\n",
10 + __func__, __LINE__, (void *)_builtin_return_address(0));
08~10 번째 줄의 맨 왼쪽에 보이는 ‘+’ 기호는 원래 코드에서 추가되는 코드를 의미합니다. 즉, 원래 코드에서 다음 코드를 입력하면 되는 것입니다.
08 + printk("[+] process: %s \n", current->comm);
09 + printk("[+][debug] message [F: %s, L:%d]: caller:(%pS)\n",
10 + __func__, __LINE__, (void *)_builtin_return_address(0));
코드 내용을 간단히 알아봅시다. 08번째 줄 코드를 보겠습니다.
08 + printk("[+] process: %s \n", current->comm);
이 줄에서는 프로세스 이름을 출력합니다. current는 현재 프로세스의 태스크 디스크립터 주소를 가리킵니다.
다음으로 09~10번째 줄을 보겠습니다.
09 + printk("[+][debug] message [F: %s, L:%d]: caller:(%pS)\n",
10 + __func__, __LINE__, (void *)_builtin_return_address(0));
09~10번째 줄에 나오는 함수 인자의 내용은 다음과 같습니다.
__func__: 현재 실행 중인 함수의 이름
__LINE__: 현재 실행 중인 코드 라인
_builtin_return_address(0): 현재 실행 중인 함수를 호출한 함수의 주소
모두 GCC 컴파일러에서 제공하는 매크로입니다. 이 코드를 통해 커널 코드가 실행되는 위치와 현재 실행 중인 함수를 어떤 함수가 호출했는지 알 수 있습니다.
09 번째 줄 가장 왼쪽 코드를 보면 “%pS”가 보입니다. %pS는 아규먼트로 지정한 주소를 심벌로 변환해 출력합니다.
위 코드를 커널 함수에 입력하고 빌드한 후 커널 이미지를 설치하면 다음과 같은 커널 로그를 볼 수 있습니다.
1 [+] process: kworker/2:3
2 [+][debug] message [F:insert_wq_barrier, L:2354] caller(workqueue_cpu_down_callback+0x90/0xac)
로그에 담긴 디버깅 정보는 다음과 같습니다.
printk 로그를 실행한 프로세스의 이름은 kworker/2:3이다.
printk가 추가된 곳은 insert_wq_barrier() 함수의 2354번째 줄이다.
insert_wq_barrier() 함수는 workqueue_cpu_down_callback() 함수가 호출했다.
이 같은 방식으로 분석하고 싶은 함수에 printk를 추가하고 커널을 빌드하면 더 많은 정보를 얻을 수 있습니다.
printk를 쓸 때 주의해야 할 점
printk를 사용할 때는 printk 호출 빈도를 반드시 체크해야 합니다. 만약 리눅스 커널에서 1초에 수백 번 이상 호출하는 함수에 printk를 사용하면 시스템이 락업(Lockup)되거나 커널 패닉으로 오동작할 수 있습니다. 여기서 락업은 라즈베리 파이와 같은 리눅스 디바이스에서 마우스를 움직이거나 키보드를 입력해도 아무런 반응이 없는 상황을 말합니다.
그 이유는 무엇일까요? printk가 커널 입장에서 많은 비용이 드는 함수이기 때문입니다. printk는 파일 시스템의 도움으로 로그를 콘솔 버퍼에 저장하는 세부 동작을 수행합니다. 이때 커널 세부 동작을 콘솔 드라이버에서 처리하고 커널 로그를 저장하는 동작을 동시에 처리합니다.
그럼 printk를 쓰면 안 되는 한 가지 예시를 들어볼까요? 스케줄링 코드를 분석한 후 __schedule() 함수에 다음과 같은 코드를 입력했다고 가정해 봅시다.
https://elixir.bootlin.com/linux/v4.19.30/source/kernel/sched/core.c
01 static void __sched notrace __schedule(bool preempt)
02 {
03 struct task_struct *prev, *next;
04 unsigned long *switch_count;
05 struct rq_flags rf;
06 struct rq *rq;
07 int cpu;
08
09 cpu = smp_processor_id();
10 rq = cpu_rq(cpu);
11 prev = rq->curr;
12
13 + printk("[+] process: %s \n", current->comm);
14 + printk("[+][debug] message [F: %s, L:%d]: caller:(%pS)\n",
15 + __func__, __LINE__, (void *)_builtin_return_address(0));
사실 처음 리눅스 커널을 접하는 분들은 어떤 함수의 실행 빈도를 알 수 없겠지만 __schedule() 함수는 매우 자주 호출됩니다. 따라서 13~15번째 줄에서 printk 함수를 호출하면 시스템은 오동작할 것입니다. 물론 운 좋게 커널 로그를 볼 수도 있습니다. 하지만 성능이 아주 좋은 리눅스 시스템을 제외하고는 위 코드를 적용하면 안 됩니다. 어떤 리눅스 시스템은 부팅조차 못합니다. 여기서 한 가지 중요한 요구사항이 생깁니다. 바로 자주 호출되는 함수라도 콜스택을 보고 싶다는 것입니다.
커널에서는 이러한 요구사항을 충족할 수 있는 디버깅 기능을 지원합니다. 바로 ftrace입니다. ftrace를 쓰면 커널 함수의 흐름과 커널의 세부 동작을 커널 코드를 수정하지 않고도 파악할 수 있습니다(ftrace는 3.4절에서 상세히 다룹니다).
"혹시 궁금한 점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답변 올려드리겠습니다!"
Thanks,
Austin Kim(austindh.kim@gmail.com)
* 유튜브 강의 동영상도 있으니 같이 들으시면 좋습니다.
커널 디버깅과 코드 학습
디버깅이란
ftrace
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글