커널 디버깅 기법 소개
커널 디버깅 기법의 종류
- Brain
- printk
- dump_stack
- ftrace
- TRACE32 : 메모리 덤프 분석
- Crash Utility : 오픈 소스 프로젝트 + 메모리 덤프
커널 디버깅에 대한 의견 : 소스 코드를 읽으세요!
커널디버거에 대한 리누스 토발즈의 의견
- 코드를 읽고 이해하는 게 중요하다!
- 디버거의 출력 결과에만 갖히지 말자!
printk 소개
printk란
- printf와 같은 커널 프린트 함수로 커널 로그에 저장
- 어느 커널 코드에도 사용 가능
#include <linux/module.h>
#include <linux/kernel.h>
int init_module(void)
{
printk(KERN_INFO "Hello world 1.\n");
return 0;
}
void cleanup_module(void)
{
printk(KERN_INFO "Goodbye world 1.\n");
}printk 예제 코드
drivers/firmware/efi/efivars.c
static int efivars_sysfs_init(void)
{
...
printk(KERN_INFO "EFI Variables Facility v%s %s\n, EFIVARS_VERSION, EFIVARS_DATE);
drivers/crypto/geode-aes.c
static int fallback_init_cip(struct crypto_tfm *tfm)
{
...
if(IS_ERR(tctx->fallback.cip)) {
printk(KERN_ERR "Error allocating fallback algo %s\n", name);
return PTR_ERR(tctx->fallback.cip);
}
- 어느 커널 코드 혹은 드라이버에서 사용
printk: 로그 레벨 소개
로그 레벨이란
linux/kern_levels.h
#define KERN_EMERG KERN_SOH "0" /* system is unusable */
#define KERN_ALERT KERN_SOH "1" /* action must be taken immediately */
#define KERN_CRIT KERN_SOH "2" /* critical conditions */
#define KERN_ERR KERN_SOH "3" /* error conditions */
#define KERN_WARNING KERN_SOH "4" /* warning conditions */
#define KERN_NOTICE KERN_SOH "5" /* normal but significant condition */
#define KERN_INFO KERN_SOH "6" /* informational */
#define KERN_DEBUG KERN_SOH "7" /* debug-level messages */- 설정된 로그 레벨에 따라 메시지를 출력하는 범위가 달라짐
- 낮은 로그 레벨, 더 적은 메시지
- 높은 로그 레벨, 더 많은 메시지
- KERN_WARNING Default Log Level
- 브링업을 할 때 KERN_DEBUG로 설정
printk: 로그 레벨 설정하기-1
로그 레벨 확인하기
root@raspberrypi:/home/austin# echo 7 > /proc/sys/kernel/printk
root@raspberrypi:/home/austin# cat /proc/sys/kernel/printk
7 4 1 3
[current, default, minimum, boot-time-default]터미널로 설정
root@raspberrypi:/home/austin# dmesg -n 5
root@raspberrypi:/home/austin# cat /proc/sys/kernel/printk
5 4 1 3
[current, default, minimum, boot-time-default]-> 현재 log 레벨 5로 변경한 결과
printk: 로그 레벨 설정하기-2
Device Tree로 로그 레벨 설정
{ chosen {
- bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 and snd_bcm2835.enable_hdmi=1 crashkernel=256M";
+ bootargs = "coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 crashkernel=256M loglevel=7";
};
aliases {- loglevel='로그 레벨'
- 예제 : "loglevel=7"
printk: 로그 레벨 설정하기-3
Kernel Config로 로그 레벨 설정
+CONFIG_MESSAGE_LOGLEVEL_DEFAULT=3printk: 로그 레벨 설정하기(실전 프로젝트)
프로젝트 진행 상황과 로그 레벨
printk 주의 사항
printk를 사용할 때 주의해야 하는 상황
- printk를 추가한 함수가 자주 호출될 때 (e.g: __schedule(), interrupt handler)
- 타이머 관련 루틴
printk는 overhead가 걸리는 동작
- console driver는 print buffer를 flush함
- kernel log가 도배되면 시스템에 overhead 유발
- 성능이 낮은 시스템은 Hang에 걸릴 수 있음
- 부팅 실패
printk_ratelimit()함수
printk_ratelimit()함수의 역할
...
# kernel log가 너무 많은 경우 이를 방지하기 위해 메시지 속도를 제한합니다.
if(lport->vport){
- QEDF_ERR(NULL, "Cannot issue host reset on NPIV port.\n");
+ printk_ratelimited("Cannot issue host reset on NPIV port.\n");
return;
}- Console에 메시지가 쌓이면
printk_ratelimit() failure상태 리턴 - 1초에 5번 출력
printk 대신 어떤 로그를 쓰면 될까 ?
- FTRACE 사용 권장
printk를 사용하는 예제 코드 확인해보기
raspberrypi/linux/blob/rpi-4.19.y/arch/arm/kernel/process.c
void __show_regs(struct pt_regs *regs)
{
printk("PC is at %pS\n", (void *)instruction_pointer(regs));
printk("LR is at %pS\n", (void *)regs->ARM_lr);
printk("pc : [<%08lx>] lr : [<%08lx>] psr: %08lx\n",
regs->ARM_pc, regs->ARM_lr, regs->ARM_cpsr);
printk("sp : %08lx ip : %08lx fp : %08lx\n",
regs->ARM_sp, regs->ARM_ip, regs->ARM_fp);
printk("r10: %08lx r9 : %08lx r8 : %08lx\n",
regs->ARM_r10, regs->ARM_r9,
regs->ARM_r8);
printk("r7 : %08lx r6 : %08lx r5 : %08lx r4 : %08lx\n",
regs->ARM_r7, regs->ARM_r6,
regs->ARM_r5, regs->ARM_r4);
printk("r3 : %08lx r2 : %08lx r1 : %08lx r0 : %08lx\n",
regs->ARM_r3, regs->ARM_r2,
regs->ARM_r1, regs->ARM_r0);
}[ 디바이스 드라이버 개발 : printk 사용 ]
- 정상 동작을 모니터링하는 루틴 : 온도, 배터리 사용, 주요 디버깅 정보
- 오류, 예외 처리 : 반드시 printk 추가
printk로 함수 심벌 정보 보는 법
printk로 포인터를 출력하고 싶을 때 %p 사용
커널은 symbol table을 갖고 있으므로 %pS를 쓰면 함수 주소를 symbol로 출력함
printk("[+] process: %s\, current->comm);
printk("[+][debug] message [F: %s, L:%d]: caller:(%pS)\n", __func__, __LINE__, (void*)__builtin_return_address(0);current : 현재 프로세스의 task_descriptor 주소를 가리킴
task_struct 구조체 : comm (프로세스의 이름)
GCC 컴파일러에서 제공하는 매크로
커널 코드가 실행되는 위치와 현재 실행중인 함수를 어떤 함수가 호출했는지 알 수 있음
__func__: 현재 실행중인 함수의 이름__LINE__: 현재 실행중인 코드 라인__builtin_return_address: 현재 실행중인 함수를 호출한 함수의 주소
[+] process: kworker/2:3
[+][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()함수가 호출함
