커널 디버깅 맛보기

책을 따라 커널 로그를 분석하며 커널 디버깅을 연습해보자.

WARNING: at kernel/irq/manage.c:225 __enable_irq+0x3b/0x57()
Unbalanced enable for IRQ 4
Modules linked in: svsknfdrvr [last unloaded: osal_linux]
Pid: 634, comm: ash Tainted: G W 2.6.28 #1
Call Trace:
[<c011a7f9>] warn_slowpath+0x76/0x8d
[<c012fac8>] profile_tick+0x2d/0x57
[<c011ed72>] irq_exit+0x32/0x34
[<c010f22c>] smp_apic_timer_interrupt+0x41/0x71
[<c01039ec>] apic_timer_interrupt+0x28/0x30
[<c011b2b4>] vprintk+0x1d3/0x300
[<c013a2af>] __setup_irq+0x11c/0x1f2
[<c013a177>] __enable_irq+0x3b/0x57
[<c013a506>] enable_irq+0x37/0x54
[<c68c9156>] svsknfdrvr_open+0x5e/0x65 [svsknfdrvr]
[<c016440a>] chrdev_open+0xce/0x1a4
[<c016433c>] chrdev_open+0x0/0x1a4
[<c01602f7>] __dentry_open+0xcc/0x23a
[<c016049a>] nameidata_to_filp+0x35/0x3f
[<c016b3c5>] do_filp_open+0x16f/0x6ef
[<c0278fd5>] tty_write+0x1a2/0x1c9
[<c0160128>] do_sys_open+0x42/0xcb
[<c0160201>] sys_open+0x23/0x2a
[<c0102e71>] sysenter_do_call+0x12/0x25
---[ end trace 4eaa2a86a8e2da22 ]---

위 커널 에러 로그는 아래 리눅스 포럼에 올라온 질문 글의 내용이다.

https://community.unix.com/t/what-is-unbalanced-irq/277220

 

에러 로그를 순서대로 살펴보자.

WARNING: at kernel/irq/manage.c:225 __enable_irq+0x3b/0x57()

__enable_irq() 함수에서 오류를 검출했다.

manage.c 파일의 __enable_irq() 함수 코드를 보자.

void __enable_irq(struct irq_desc *desc)
{
	switch (desc->depth) {
	case 0:
 err_out:
		WARN(1, KERN_WARNING "Unbalanced enable for IRQ %d\n",
		     irq_desc_get_irq(desc));
		break;
	...
}

https://github.com/raspberrypi/linux/blob/rpi-4.19.y/kernel/irq/manage.c#L577

WARN() 매크로 함수에서 오류를 찾을 수 있다.

 

인터럽트 디스크립터의 자료구조인 irq_desc 구조체의 depth 필드는 인터럽트를 활성화하면 0, 비활성화하면 1로 설정된다. 위 오류 메세지는 인터럽트를 두 번 활성화했을 때 실행된다.

(WARN() 매크로 함수가 호출되면 커널 로그로 콜 스택을 출력함, Call Trace)

 

그럼 두 번 활성화된 인터럽트가 무엇인지를 찾아보자.

Unbalanced enable for IRQ 4

IRQ 4 즉, 4번 인터럽트를 두 번 활성화했기 때문에 해당 오류 메세지가 출력된 것이다.

 

위에 있는 __enable_irq() 함수의 코드를 보면 함수 내부에서 4번 인터럽트를 두 번 활성화한 것 같지는 않다.

아마 __enable_irq() 함수를 호출한 드라이버 코드에 오류가 있을 가능성이 높다.

Modules linked in: svsknfdrvr [last unloaded: osal_linux]

커널 에러 메세지를 보면 svsknfdrvr 드라이버 모듈을 확인할 수 있다.

 

이제 디버깅 코드를 작성해 다시 같은 문제가 발생했을 때 추가 커널 로그를 확보할 수 있도록 코드를 수정하자.

void __disable_irq(struct irq_desc *desc)
{
+	if (irq == 4)
+    	WARN(1, KERN_WARNING " irq 4 is disabled %d, desc->depth %d \n", irq, desc->depth);
+
	if (!desc->depth++)
		irq_disable(desc);
}

void __enable_irq(struct irq_desc *desc)
{
+	if (irq == 4)
+    	WARN(1, KERN_WARNING " irq 4 is enabled %d, desc->depth %d \n", irq, desc->depth);
+
	switch (desc->depth) {
	case 0:
 err_out:
 	...
}

__disable_irq()와 __enable__irq() 함수에 패치 코드를 추가했고, 이를 통해 원인을 좁힐 수 있는 단서를 얻을 수 있다.
(위와 같은 코드를 디버깅 패치라고 한다고 한다)

두 함수에 추가된 패치 코드는 4번 인터럽트를 활성화/비활성화할 때 콜 스택을 커널 로그로 출력한다.