함수

1. printk() 함수

윈도우 콘솔 프로그램이나 리눅스 시스템 프로그램에서 printf 함수를 호출하면 콘솔로 문자열을 출력하듯이 printk() 함수를 호출하면 커널 로그를 볼 수 있다. 이미 커널의 수많은 내부 함수에서도 printk를 이용해 시스템 에러 정보를 커널 로그로 출력한다.

 

printk로 함수 심벌 정보를 보는 방법

printk로 포인터를 출력하고 싶을 때는 %p를 쓰면 된다. 커널은 심벌 테이블을 갖고 있으므로 %pS를 쓰면 함수 주소를 심벌로 출력한다. 이는 함수 포인터를 디버깅할 때 자주 쓰는 기법이다. 

 

printk를 쓸 때 주의해야 할 점

printk를 사용할 때는 printk의 호출 빈도를 반드시 체크해야 한다. 만약 리눅스 커널에서 1초에 수백번 이상 호출되는 함수에 printk를 사용하면 시스템이 락업(Lockup)되거나 커널 패틱으로 오동작할 수 있다. 여기서 락업은 라즈베리 파이와 같은 리눅스 디바이스에서 마우스를 움직이거나 키보드를 입력해도 아무런 반응이 없는 상황을 말한다. 그 이유는 printk가 커널 입장에서 많은 비용이 드는 함수이기 때문이다. printk는 파일 시스템의 도움으로 로그를 콘솔 버퍼에 저장하는 세부 동작을 수행한다. 이때 커널 세부 동작을 콘솔 드라이버에서 처리하고 커널 로그를 저장하는 동작을 백그라운드로 처리한다. 그럼 printk를 쓰면 안 되는 예시를 들어보자, 스케줄링 코드를 분석한 수 __schedule() 함수에 다음과 같은 코드를 입력했다고 가정하자.

 

static void __sched notrace __schedule(bool preempt)

{

 struct task_struct *prec, *next;

 unsigned long *switch_count;

 struct rq_flags rf;

 struct rq *rq;

 int cpu;

 

 cpu = smp_processor_id();

 rq = cpu_rq(cpu);

 prev = rq->curr;

 

+ printk("[+] process : %s \n", current->comm);

+ printk("[+][debug] message [F: %s, L:%d]: caller:(%pS)\n}",

+                 _-func__, __LINE__, (void *)_builtin_return_address(0));

 

사실 처음 리눅스 커널을 접하는 분들은 어떤 함수의 실행빈도를 알 수 없겠지만 __schedule() 함수는 매우 자주 호출될 수 있다. 따라서 13~15번째 줄에서 printk 함수를 호출하면 시스템은 오동작할 가능성이 높다. 물론 운 좋게 커널 로그를 볼 수도 있다. 하지만 성능이 아주 좋은 리눅스 시스템을 제외하고는 위 코드를 적용하면 안 된다. 어떤 리눅스 시스템은 부팅조차 못한다. 여기서 한가지 중요한 요구사항이 생긴다. 바로 자주 호출되는 함수라도 콜 스택을 보고 싶다는 것이다. 커널에서는 이러한 요구사항을 충족할 수 있는 디버깅 기능을 지원한다. 바로 ftrace이다. ftrace를 쓰면 커널 함수의 흐름과 커널의 세부 동작을 커널 코드를 수정하지 않고도 파악할 수 있다.

 

2. dump_stack() 함수

printk 외에도 커널에서는 커널 로그를 통해 커널 동작을 보여주는 기능을 제공한다. 즉, 커널에서 지원하는 dump_stack() 함수를 호출하면 콜 스택을 커널 로그로 볼 수 있다. dump_stack() 함수의 사용법은 간단하다. 커널 로그로 콜 스택을 보고 싶은 코드에 dump_stack() 함수를 추가하기만 하면 된다. dump_stack() 함수를 호출하려면 코드의 윗부분에 다음과 같이 "linux/kernel.h" 헤더 파일을 추가해야한다. 이어서 dump_stack() 함수의 선언부를 보자.

 

asmlinkage __visible void dump_stack(void);

 

인자와 반환값 타입이 모두 void이다. 커널 소스코드의 어디든 dump_stack() 함수만 추가하면 된다.

 

dump_stack() 함수로 커널 로그에서 콜 스택 확인하기

이번에는 앞에서 설명한 dump_stack() 함수를 써서 커널 로그로 콜 스택을 볼 수 있는 방법을 알아보자. 먼저 패치 코드를 입력하는 방법을 소개하자면, 6번째 줄의 코드와 같이 _do_fork() 함수 바로 위에 debug_kernel_thread 전역 변수를 선언하고 _do_fork() 함수에서 add_latent_entropy(); 다음에 보이는 코드를 입력하면 된다. 이어서 패치 코드의 의미를 알아보자면 프로세스를 생성할 때 _do_fork() 함수가 호출되는데, 이 때 함수 콜 스택을 확인하기 위한 코드이다. 위와 같은 패치 코드를 입력한 다음 커널 이미지를 빌드하고 시스템에 설치한다. 부팅 후 커널 로그에서 다음과 같은 메시지를 볼 수 있다.

 

[   3.819188] CPU: 1 PID: 149 Comm: systemd-udevd not tainted 4.19.30-v7+ #3

[   3.819196] Hardware name: BCM2835

[   3.819237] [<8010ffc0>] (unwind_backtrace) from [<8010cfc>] (show_stack+0x20/0x24)

[   3.819301] [<8011c8ec>] (_do_fork) from [<8011cd68>] (sys_clone+0x30/0x38)

 

[   3.819188] CPU: 1 PID: 149 Comm: systemd-udevd not tainted 4.19.30-v7+ #3

콜 스택을 실행한 프로세스 정보이다. PID가 149인 system-udevd 프로세스가 CPU1에서 실행 중이다. 다음 줄부터는 콜 스택이다. 함수 호출은 끝에 줄에서 위 쪽 방향으로 이뤄진다. _do_fork()  함수 위에 보이는 함수들은 dump_stack() 함수에서 콜 스택을 출력할 때마다 보이는 함수로서 무시해도 되는 함수 호출 정보이다. 

 

[   3.819301] [<8011c8ec>] (_do_fork) from [<8011cd68>] (sys_clone+0x30/0x38)

sys_clone() 함수에서 _do_fork() 함수를 호출한다고 알려준다.

 

 dump_stack() 함수를 사용할 때의 주의사항

1초에 100번 이상 호출되는 함수에 dump_stack() 함수를 추가하면 시스템 응답 속도가 매우 느려질 수 있다. 따라서 dump_stack() 함수를 호출해서 콜 스택을 보려는 코드가 자주 호출되는지 반드시 점검할 필요가 있다. 그런데 dump_stack() 함수 내부에서는 printk보다 훨씬 많은 일을 한다. dump_stack() 함수를 실행하면 내부에서 현재 실행 중인 프로세스 스택 주소를 읽어서 스택에 푸시된 프레임 포인터(Frame Pointer) 레지스터를 읽는다. ARM 아키텍처의 함수 호출 규약에 따라 프레임 포인터 레지스터를 읽어서 함수 호출 내역을 추적하는 동작을 반복한다. 따라서 커널 입장에서 printk보다 dump_stack() 함수를 호출할 때 더 많은 일을 한다.