디버깅은 'debug'와 '-ing' 합성어로 버그를 잡는 과정을 뜻합니다. 누군가 '디버깅하고 있다'라고 말하면 '버그를 수정하고 있다'고 볼 수 있습니다.
필자는 디버깅을 단지 버그를 잡는 과정만으로 보지는 않습니다. 리눅스 커널과 드라이버가 정상 동작할 때 자료구조와 함수 호출 흐름까지 파악하는 과정을 디버깅이라고 생각합니다.
이번 절에서는 구체적인 디버깅 방법을 소개하기에 앞서 디버깅이 중요한 다음과 같은 이유를 좀 더 구체적으로 알아보겠습니다.
문제 해결 능력
커널 코드 학습 능력
디버깅은 문제 해결 능력의 지름길
신입 개발자들은 실전 리눅스 개발에서 어떤 업무를 하는지 궁금해합니다. 임베디드 리눅스는 ‘클라우드 서버’, ‘휴대폰’, ‘전기자동차’ 분야까지 다양한 분야에서 쓰이고 있습니다. 따라서 실전 개발 업무가 어떻다고 설명하긴 어렵습니다. 하지만 어떤 리눅스 업무를 맡고 있더라도 공통적으로 리눅스 커널 디버깅에 관심을 갖고 배우려고 합니다.
커널 디버깅을 잘해야 문제 해결 능력을 키울 수 있는 이유는 무엇일까?
대부분의 임베디드 및 BSP 개발자들은 커널 디버깅 능력을 키우기 위해 노력합니다. 그렇다면 커널 디버깅 능력을 업그레드하려는 이유는 무엇일까요? 그 이유는 간단합니다. 커널 디버깅은 문제 해결 능력 그 자체이기 때문입니다.
그렇다면 임베디드 및 BSP 개발 도중 어떤 문제를 만날까요? 임베디드 리눅스는 활용 분야가 다양하지만 대표적인 문제를 추리면 다음과 같습니다.
부팅 도중 커널 크래시 발생
인터럽트 핸들러를 설정했는데 인터럽트 핸들러가 호출되지 않음
시스템 응답 속도가 매우 느려짐
파일 복사가 안 됨
그런데 위와 같은 문제는 누가 해결해야 할까요? 바로 임베디드 BSP 리눅스 개발자입니다. 여기서 의문이 생깁니다. 그렇다면 문제를 해결하기 위해서는 어떤 과정을 거칠까요?
먼저 문제 발생 원인을 정확히 분석해야 합니다. 정확히 문제를 분석해야 이에 따른 해결책이 나옵니다. 문제를 제대로 분석하지 못하면 문제를 해결하지 못합니다. 그럼 문제 발생의 원인은 어떻게 분석할 수 있을까요?
실전 개발에서는 문제가 발생했을 때 확보한 커널 로그와 메모리 덤프로 문제 원인을 분석할 수 있습니다. 커널 로그와 메모리 덤프를 정확히 분석해야 문제 발생의 원인을 분석할 수 있습니다.
임베디드 BSP 개발에서 커널 로그와 메모리 덤프를 정확히 분석하는 스킬을 '커널 디버깅'이라고 말합니다. '커널 디버깅' 능력은 정확한 문제 원인 분석으로 이어지고, 이를 통해 '문제를 해결'하게 됩니다. 그래서 커널 디버깅은 문제 해결 능력 그 자체라고 할 수 있습니다.
앞에서 디버깅이 문제 해결에 필요한 능력이라고 언급했습니다. 이번에는 임베디드 BSP 개발에서의 디버깅에 대한 필자의 생각을 조금 더 이야기해보려 합니다.
규모가 작은 소프트웨어 프로젝트를 진행할 때는 버그와 관련된 개발자가 디버깅을 했습니다. 즉, 일반적으로 자신이 작성한 코드의 논리적 문제점을 분석하고 해당 코드를 작성한 엔지니어가 버그를 잡았습니다.
그런데 리눅스 커널을 디버깅할 때는 상황이 다릅니다. 커널 로그나 메모리 덤프로 함수나 자료구조를 분석할 때는 자신이 작성한 코드보다 다른 개발자가 작성한 커널 코드를 만날 가능성이 매우 높습니다. 여기에는 그럴만한 이유가 있습니다. 바로 디바이스 드라이버는 커널 함수로 구성돼 있고, 커널 함수는 각 서브시스템을 담당한 개발자가 작성한 코드이기 때문입니다.
임베디드 BSP 개발 과정에서 디버깅할 때 우리가 작성한 코드만 분석하면 얼마나 좋겠습니까? 하지만 난이도가 높은 문제일수록 커널 내부 함수를 분석할 가능성이 높아집니다. 그래서 커널을 디버깅할 때 자신이 작성한 코드만 들여다보는 과정에서 그치지 말고 한 발짝 더 나가야 합니다. 리눅스 커널을 구성하는 서브시스템이 정상 동작을 할 때는 다음 내용을 파악할 필요가 있습니다.
함수가 실행될 때 변경되는 자료구조
함수가 실행되는 빈도와 실행 시각
실행 중인 코드를 어떤 프로세스가 실행하는지 확인
위와 같은 내용을 잘 알아야 하는 또 다른 이유는 무엇일까요? 바로 프로그램이 정상적으로 동작할 때의 함수 호출 흐름과 자료구조를 알고 있어야 오류나 버그가 발생했을 때 무엇이 문제인지 식별할 수 있기 때문입니다.
사실 개발 도중에 커널 로그에서 에러 메시지를 만날 경우가 많습니다. 그런데 커널 로그는 커널이나 디바이스 드라이버가 정상 동작을 한다는 정보를 출력하기도 하고 시스템에 심각한 오류가 있다는 사실을 알려주기도 합니다.
커널 로그에서 오류 정보를 바로 식별할 수 있으면 좋겠지만 '정상 동작'을 할 때의 메시지와 '오류 정보' 메시지가 뒤섞여 있는 경우도 많습니다. 그래서 로그에서 오류 정보를 잘 알아채려면 '정상 동작' 시 출력되는 로그의 패턴을 미리 잘 숙지해야 합니다.
커널 디버깅 따라해보기: 커널 로그 분석
임베디드 리눅스 개발을 하다가 문제가 생기면 대부분 커널 로그를 봅니다. 그런데 디바이스 드라이버 코드에 오류가 있으면 우리가 작성한 드라이버 코드에서 오류 메시지를 출력하지 않습니다. 대부분의 경우 디바이스 드라이버가 호출한 커널 함수 내부에서 에러 메시지를 출력합니다.
자, 그러면 실제 커널 에러 로그를 분석하면서 커널 디버깅을 하는 방법을 알아볼까요? 다음 URL에서는 리눅스 포럼에서 논의된 커널 로그를 볼 수 있습니다.
https://www.unix.com/programming/148285-what-unbalanced-irq.html
01 WARNING: at kernel/irq/manage.c:225 __enable_irq+0x3b/0x57()
02 Unbalanced enable for IRQ 4
03 Modules linked in: svsknfdrvr [last unloaded: osal_linux]
04 Pid: 634, comm: ash Tainted: G W 2.6.28 #1
05 Call Trace:
06 [<c011a7f9>] warn_slowpath+0x76/0x8d
07 [<c012fac8>] profile_tick+0x2d/0x57
08 [<c011ed72>] irq_exit+0x32/0x34
09 [<c010f22c>] smp_apic_timer_interrupt+0x41/0x71
10 [<c01039ec>] apic_timer_interrupt+0x28/0x30
11 [<c011b2b4>] vprintk+0x1d3/0x300
12 [<c013a2af>] __setup_irq+0x11c/0x1f2
13 [<c013a177>] __enable_irq+0x3b/0x57
14 [<c013a506>] enable_irq+0x37/0x54
15 [<c68c9156>] svsknfdrvr_open+0x5e/0x65 [svsknfdrvr]
16 [<c016440a>] chrdev_open+0xce/0x1a4
17 [<c016433c>] chrdev_open+0x0/0x1a4
18 [<c01602f7>] __dentry_open+0xcc/0x23a
19 [<c016049a>] nameidata_to_filp+0x35/0x3f
20 [<c016b3c5>] do_filp_open+0x16f/0x6ef
21 [<c0278fd5>] tty_write+0x1a2/0x1c9
22 [<c0160128>] do_sys_open+0x42/0xcb
신입 개발자 입장에서는 굉장히 어려운 커널 로그를 예시로 들었습니다. 하지만 위와 같은 커널 로그는 실전 개발에서 언제든 만날 수 있습니다.
먼저 첫 번째 에러 로그를 보겠습니다.
01 WARNING: at kernel/irq/manage.c:225 __enable_irq+0x3b/0x57()
__enable_irq() 함수에서 뭔가 오류 조건을 검출한 듯합니다. 에러 메시지를 유심히 보면서 어느 코드에서 오류를 유발했는지 분석해 봅시다.
첫째, 오류 메시지를 커널 어느 코드에서 출력했는지 확인합니다.
먼저 콜스택을 어느 코드에서 출력했는지 살펴봐야 합니다. 위 로그는 아래 __enable_irq() 함수의 6번째 줄에서 출력합니다.
https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/irq/manage.c
1 void __enable_irq(struct irq_desc *desc)
2 {
3 switch (desc->depth) {
4 case 0:
5 err_out:
6 WARN(1, KERN_WARNING "Unbalanced enable for IRQ %d\n",
7 irq_desc_get_irq(desc));
인터럽트 디스크립터 자료구조인 irq_desc 구조체의 depth 필드는 인터럽트를 활성화하면 0, 비활성화하면 1을 설정합니다. 만약 4 번째 인터럽트를 활성화하면 4 번째 인터럽트의 인터럽트 디스크립터의 depth 필드를 0으로 설정합니다. 그런데 6번째 줄 코드는 인터럽트를 2번 활성화했을 때 실행됩니다. 이미 인터럽트를 활성화했으면 depth 필드가 0인데 다시 활성화했으니 경고 메시지와 함께 콜스택을 출력합니다.
WARN() 매크로 함수는 콜스택을 출력합니다.
둘째, 소스코드에서 에러 메시지를 출력한 이유를 살펴봐야 합니다.
이번에는 어떤 인터럽트를 연속으로 활성화했는지 파악해 보겠습니다.
01 WARNING: at kernel/irq/manage.c:225 __enable_irq+0x3b/0x57()
02 Unbalanced enable for IRQ 4
02번째 줄 로그를 보면 “IRQ 4”라는 메시지가 보입니다. 정리하면 4번 인터럽트를 두 번 활성화했으므로 해당 오류 메시지를 출력한 것입니다.
위와 같은 에러 메시지는 enable_irq() 함수에서 출력합니다. 그렇다면 enable_irq() 함수 내부에 논리적 오류가 있어서 위와 같은 에러 메시지를 출력할까요? 그렇지 않습니다. enable_irq() 함수 내 코드에 오류가 있다기보다는 enable_irq() 함수를 호출한 드라이버 코드에 무엇인가 오류가 있을 가능성이 높습니다. 그래서 어떤 함수에서 4번 인터럽트를 2번 연속으로 활성화하는지 점검해야 합니다.
그런데 에러 메시지는 커널 내부 함수인 __enable_irq() 함수에서 출력했습니다. 만약 커널이 정상 동작할 때 irq_desc 구조체의 depth 필드를 알고 있으면 이제까지 분석한 에러 메시지의 의미를 바로 알 수 있습니다.
그럼 위와 같은 문제는 어떻게 해결할까요? 물론 관련 드라이버 코드를 상세히 분석해 힌트를 얻을 수 있습니다.
https://www.unix.com/programming/148285-what-unbalanced-irq.html
01 WARNING: at kernel/irq/manage.c:225 __enable_irq+0x3b/0x57()
02 Unbalanced enable for IRQ 4
03 Modules linked in: svsknfdrvr [last unloaded: osal_linux]
커널 에러 메시지를 보면 svsknfdrvr 드라이버 모듈이 보입니다. 먼저 svsknfdrvr 드라이버 코드를 분석한 후 논리적인 오류가 있는지 점검해야 합니다.
만약 위와 같은 문제가 할당되면 어떻게 문제를 좁힐까요? svsknfdrvr 드라이버 코드를 분석하면 좋겠지만 드라이버 개발 업체가 드라이버 코드를 공유하지 않고 모듈(ko) 형태로 배포할 수도 있습니다. 가끔은 자신이 작성한 드라이버는 문제가 없다고 주장할 수 있습니다. 이럴 때는 다음과 같은 방법을 활용하면 문제의 범인을 알아낼 수 있습니다.
필요에 따라 디버깅 코드를 작성해 다시 문제가 발생했을 때 추가 커널 로그 확보를 시도합니다.
다음과 같은 패치 코드를 입력해 문제 현상을 재현한 후 커널 로그를 받아보면 커널 로그가 누가 4번 인터럽트를 2번 활성화했는지 알려줄 것입니다. 다음과 같은 패치 코드를 입력한 다음 커널을 빌드해서 커널 이미지를 설치한 후 다시 재현해야 합니다.
diff --git a/kernel/irq/manage.c b/kernel/irq/manage.c
--- a/kernel/irq/manage.c
+++ b/kernel/irq/manage.c
@@ -388,6 +388,8 @@ setup_affinity(unsigned int irq, struct irq_desc *desc, struct cpumask *mask)
1 void __disable_irq(struct irq_desc *desc, unsigned int irq)
2 {
3 + if ( irq == 4 )
4 + WARN(1, KERN_WARNING " irq 4 is disbled %d, desc->depth %d \n", irq, desc->depth);
5 if (!desc->depth++)
6 irq_disable(desc);
7 }
@@ -442,6 +444,9 @@ EXPORT_SYMBOL(disable_irq);
8
9 void __enable_irq(struct irq_desc *desc, unsigned int irq)
10 {
11 + if ( irq == 4 )
12 + WARN(1, KERN_WARNING " irq 4 is enabled %d, desc->depth\n", irq, desc->depth);
13 +
14 switch (desc->depth) {
15 case 0:
16 err_out:
위와 같은 코드를 디버깅 패치라고 합니다. 이를 통해 문제의 원인을 좁힐 수 있는 단서를 찾을 수 있습니다.
그럼 패치 코드를 자세히 설명하겠습니다. __disable_irq() 함수와 __enable_irq() 함수의 2 번째 인자는 인터럽트 번호를 나타내는 irq입니다. 위 코드에서는 이 인터럽트 번호가 4일 때 콜스택을 호출합니다.
위 패치 코드를 작성해 커널을 빌드하면 4번 인터럽트를 활성화 혹은 비활성화할 때 콜스택을 커널 로그로 출력합니다. 따라서 어떤 코드에서 4 번 인터럽트를 하는지 알 수 있습니다.
리눅스 커널의 고수 중 디버깅을 잘 못하는 개발자는 한 번도 만나본 적이 없습니다. 디버깅 능력은 문제 해결 능력 그 자체이므로 평소에 디버깅을 꾸준히 해서 리눅스 커널을 익힐 필요가 있습니다.
"혹시 궁금한 점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답변 올려드리겠습니다!"
Thanks,
Austin Kim(austindh.kim@gmail.com)
커널 디버깅과 코드 학습
디버깅이란
ftrace
"혹시 궁금한 점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답변 올려드리겠습니다!"
Thanks,
Austin Kim(austindh.kim@gmail.com)
동영상 강의
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글