printk는 printf와 유사한 기능입니다. printf는 윈도우 콘솔 프로그램이나 리눅스 시스템 프로그램에서 로그를 출력합니다. 마찬가지로 printk() 함수를 호출하면 커널 로그를 볼 수 있습니다.
printk 를 커널 함수에 적절히 추가하면 유용한 디버깅 정보를 얻을 수 있습니다. 리눅스 커널 핵심 함수도 printk를 이용해 시스템 정보를 출력합니다.
커널 핵심 코드에서 printk를 쓰는 예시 코드를 소개합니다.
[https://elixir.bootlin.com/linux/v4.14.70/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에 전달하는 포멧에 대해 살펴봅시다.
정수형 포멧은 int, long, long long을 지원합니다. C언어의 printf와 같습니다.
변수 타입 타입 % 지정자
Int %d or %x
unsigned int %u or %x
Long %ld or %lx
unsigned long %lu or %lx
long long %lld or %llx
unsigned long long %llu or %llx
size_t %zu or %zx
ssize_t %zd or %zx
s32 %d or %x
u32 %u or %x
s64 %lld or %llx
u64 %llu or %llx
printk 에 전달하는 인자와 % 형식과 매칭이 되야 커널 빌드 시 컴파일 에러가 발생하지 않습니다.
printk로 포인터를 출력하고 싶을 때는 %p를 쓰면 됩니다.
커널은 심볼 테이블을 갖고 있으므로 %pS 포맷을 쓰면 함수 주소를 심볼로 출력합니다.
함수 포인터를 디버깅할 때 자주 쓰는 기법입니다.
이번에는 printk를 쓰는 방법을 소개합니다. 다음 코드를 리눅스 커널 코드에 입력합시다.
[https://elixir.bootlin.com/linux/v4.14.70/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 번째 줄 코드를 보겠습니다.
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 를 쓸 때 주의해야 할 점
리눅스 커널에서 1초에 수 백 번 이상 호출하는 함수에 printk를 호출하면 시스템은 오동작할 수 있습니다. 시스템 응답 속도가 매우 느려지거나 심하면 커널 패닉이 발생할 수 있습니다.
printk는 실행 시간 관점으로 많은 비용이 드는 함수이기 때문입니다. 파일 시스템의 도움으로 로그를 콘솔 버퍼에 저장하는 세부 동작을 수행합니다.
만약 스케줄링 코드 분석 후 __schedule() 함수에 다음과 같은 코드를 입력했다고 가정합시다.
[https://elixir.bootlin.com/linux/v4.14.70/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을 쓰면 됩니다.
by Austin Kim. blog
'SoC : : Architecture > : : Raspberry' 카테고리의 다른 글
| 커널 빌드 / 설치 (0) | 2024.10.14 |
|---|---|
| dump_stack() 함수 (0) | 2024.10.10 |
| (2) 디버깅과 코드 학습 능력 (0) | 2024.10.10 |
| (1) 디버깅은 문제 해결 능력의 지름길 (0) | 2024.10.10 |
| Kernel Source 구조 (1) | 2024.10.10 |