#커널 크래시 디버깅 및 TroubleShooting
- Race로 mmc_wait_data_done() 함수에서 커널 패닉
- "cat /d/shrinker" 입력 시 커널 패닉
- 함수 포인터 미지정으로 xfrm_local_error() 커널 패닉
- preempt 조건으로 ___might_sleep() 함수 크래시
- 스택 카나리: __stack_chk_fail() 함수 크래시
- 스택 카나리: tcp_v4_rcv -> __stack_chk_fail 크래시
- 뮤텍스 데드락(Mutex Deadlock)으로 락업(lockup)
- 디바이스 드라이버 Signature 문제로 커널 크래시
- 메모리 불량 커널 크래시 @find_vma_links()
- 메모리 불량 커널 크래시 @ttwu_do_activate()
- Race로 ipv6_ifa_notify() Stuck - watchdog reset
- tty_wakeup() 함수 Data Abort
- irq_affinity_notify() 함수 Data Abort
- cpuacct_charge() 함수 Data Abort
- 워크큐(workqueue) 락업(1)
- 워크큐(workqueue) 락업(2)
- 워크큐(workqueue) 락업(3)
CPU3에서 실행 중인 "Binder:15701_2" 프로세스가 데이터 어보트로 커널 크래시가 발생했습니다.
커널 로그가 데이터 어보트 발생 시 어떤 동작을 했는지 레지스터 정보와 함께 알려주네요.
[69350.929482] <26>Unable to handle kernel paging request at virtual address 11ad4e80
[69350.929511] <26>pgd = d57f0000
[69350.929527] <22>[11ad4e80] *pgd=00000000
[69350.929548] <6>Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[69350.929563] <c2>Modules linked in: texfat(PO)
[69350.929590] <c6>CPU: 5 PID: 15728 Comm: Binder:15701_2 Tainted: P W O 3.18.71-ge77ee2f-00001-g0988851 #1
[69350.929608] <c6>task: d2fb2b80 ti: ce4f8000 task.ti: ce4f8000
[69350.929635] <c2>PC is at cpuacct_charge+0x30/0x58
[69350.929653] <c2>LR is at cpuacct_charge+0x1c/0x58
[69350.929671] <c2>pc : [<c01709a4>] lr : [<c0170990>] psr: 20070193
sp : ce4f9cb8 ip : 03bd1201 fp : ce4f9d9c
[69350.929695] <c2>r10: d2fb2b80 r9 : 000068cc r8 : 00000005
[69350.929711] <c2>r7 : 00000000 r6 : 0016a175 r5 : e6188290 r4 : d2fb2b80
[69350.929727] <c2>r3 : e17bbe80 r2 : 30319000 r1 : e97bbe80 r0 : c1a0e538
[69350.929744] <c2>Flags: nzCv IRQs off FIQs on Mode SVC_32 ISA ARM Segment none
[69350.929760] <c2>Control: 10c0383d Table: 957f006a DAC: 00000051
[69350.929776] <6>Process Binder:15701_2 (pid: 15728, stack limit = 0xce4f8210)
크래시 유틸리티 프로그램으로 콜스택을 잡아 봤습니다. 아래와 같이 이쁘게 콜스택이 출력되네요.
함수 흐름을 살펴보면 IRQ가 Trigger된 후 current_thread_info의 preempt_count가 0이라 스케쥴링이 되었습니다.
svc_preempt -> preempt_schedule_irq -> __schedule
crash> bt -I C01709A4 -S CE4F9CB8 d2fb2b80
PID: 15728 TASK: d2fb2b80 CPU: 5 COMMAND: "Binder:15701_2"
bt: WARNING: stack address:0xce4f9da8, program counter:0xc0ff4658
#0 [<c01709a4>] (cpuacct_charge) from [<c01592a8>]
#1 [<c01592a8>] (update_curr) from [<c015c00c>]
#2 [<c015c00c>] (put_prev_entity) from [<c015c61c>]
#3 [<c015c61c>] (put_prev_task_fair) from [<c0167a14>]
#4 [<c0167a14>] (pick_next_task_rt) from [<c0ff4364>]
#5 [<c0ff4364>] (__schedule) from [<c0ff4e2c>]
#6 [<c0ff4e2c>] (preempt_schedule_irq) from [<c0ff97d8>]
#7 [<c0ff97d8>] (svc_preempt) from [<c039b9dc>]
#8 [<c039b9e0>] (blk_flush_plug_list) from [<c039bd88>]
#9 [<c039bd88>] (blk_finish_plug) from [<c02d3c44>]
#10 [<c02d3c44>] (ext4_writepages) from [<c01f0218>]
#11 [<c01f0218>] (__filemap_fdatawrite_range) from [<c01f0318>]
#12 [<c01f0318>] (filemap_write_and_wait_range) from [<c02caa4c>]
#13 [<c02caa4c>] (ext4_sync_file) from [<c0267980>]
#14 [<c0267980>] (vfs_fsync) from [<c0267a68>]
#15 [<c0267a68>] (do_fsync) from [<c0106a00>]
pc : [<b1d5a520>] lr : [<b0cb491b>] psr: 80070010
sp : a51a5cc0 ip : 00000000 fp : 00000000
r10: 00000006 r9 : b001e400 r8 : 00000200
r7 : 00000094 r6 : 00000000 r5 : 00000000 r4 : b001e5b8
r3 : 00000000 r2 : b0cb4905 r1 : 00000002 r0 : 00000033
Flags: Nzcv IRQs on FIQs on Mode USER_32 ISA ARM
Trace32로 콜스택을 잡으면 더 직관적으로 디버깅 정보를 표현해줍니다.
__irq_svc 심볼이 콜스택에 보이는데요. 이는 IRQ가 Trigger될 시 프로그램 카운터가 이동하는 함수입니다.
__irq_svc -> svc_preempt -> preempt_schedule_irq -> __schedule
-000|cpuacct_charge()
-001|account_group_exec_runtime(inline)
-001|update_curr()
-002|check_spread(inline)
-002|put_prev_entity()
-003|put_prev_task_fair()
-004|pick_next_task_rt(inline)
-004|pick_next_task_rt()
-005|pick_next_task(inline)
-005|__schedule()
-006|arch_local_irq_disable(inline)
-006|preempt_schedule_irq()
-007|svc_preempt(asm)
-008|__irq_svc(asm)
-->|exception
-009|blk_flush_plug_list()
-010|current_thread_info(inline)
-010|blk_finish_plug()
-011|ext4_writepages()
-012|__filemap_fdatawrite_range()
-013|filemap_write_and_wait_range()
-014|ext4_sync_file()
-015|vfs_fsync()
-016|fdput(inline)
-016|do_fsync()
-017|ret_fast_syscall(asm)
이제 커널 패닉이 왜 발생했는지 점검해봐야 겠습니다.
C01709A4 주소에서 커널 패닉이 일어났는데, 이 당시 r3은 e17bbe80 r2는 30319000입니다.
"ldrd r4,r5,[r3,+r2]" 명령어는 r3에서 r2를 더한 주소의 메모리 덤프를 8바이트 만큼 r4, r5에 로딩합니다.
그런데, r2와 r3를 더하면 결과는 111AD4E80 인데, MMU에서 11AD4E80 주소를 물리 주소로 변환하지 못합니다.
NSR:C01709A0|E5913060 ldr r3,[r1,#0x60] ; _________p1,[r1,#96]
NSR:C01709A4|E18340D2 ldrd r4,r5,[r3,+r2] //<<-- 커널 패닉
그래서 커널 메시지가 아래 로그를 토해내는 것이죠.
[69350.929482] <26>Unable to handle kernel paging request at virtual address 11ad4e80
[69350.929511] <26>pgd = d57f0000
그럼, R3나 R2값이 잘못됐다고 볼 수 있고 이 레지스터들이 어떻게 실행됐는지 추적해봐야 합니다.
커널 소스를 열어서 보면, 커널 패닉이 발생한 코드는 아래 cpuacct_charge() 함수 247 라인 per_cpu_ptr(ca->cpuusage, cpu); 임을 알 수 있어요.
235void cpuacct_charge(struct task_struct *tsk, u64 cputime)
236{
237 struct cpuacct *ca;
238 int cpu;
239
240 cpu = task_cpu(tsk);
241
242 rcu_read_lock();
243
244 ca = task_ca(tsk);
245
246 while (true) {
247 u64 *cpuusage = per_cpu_ptr(ca->cpuusage, cpu); //<<--
248 *cpuusage += cputime;
그럼 R2나 R3가 per-cpu offset 정보를 담고 있다고 봐야 하는데요.
__per_cpu_offset 변수를 보면 다섯 번째 per-cpu 오프셋이 0x30319000 이군요.
커널 패닉 발생 시 r2: 30319000은 정상 값이라고 봐야 겠습니다.
crash> p __per_cpu_offset
__per_cpu_offset = $3 =
{0x302dd000, 0x302e9000, 0x302f5000, 0x30301000, 0x3030d000, 0x30319000, 0x30325000, 0x30331000}
NSR:C0170974|E92D4DF0 cpuacct_charge: push {r4-r8,r10-r11,r14}
NSR:C0170978|E1A07003 cpy r7,r3
NSR:C017097C|E5903004 ldr r3,[r0,#0x4]
NSR:C0170980|E1A04000 cpy r4,r0 ; r4,tsk
NSR:C0170984|E1A06002 cpy r6,r2
NSR:C0170988|E5938014 ldr r8,[r3,#0x14]
NSR:C017098C|EB004241 bl 0xC0181298 ; __rcu_read_lock
NSR:C0170990|E594367C ldr r3,[r4,#0x67C] //<<--[1]
NSR:C0170994|E59F002C ldr r0,0xC01709C8
NSR:C0170998|E593102C ldr r1,[r3,#0x2C] //<<--[2]
NSR:C017099C|E7902108 ldr r2,[r0,+r8,lsl #0x2]
NSR:C01709A0|E5913060 ldr r3,[r1,#0x60] ; _________p1,[r1,#96] //<<--[3]
NSR:C01709A4|E18340D2 ldrd r4,r5,[r3,+r2] //<<--[4]
이제 R3가 e17bbe80으로 어떻게 업데이트 됐는지 추적해봐야 겠습니다. 위 어셈블리 코드를 분석 시작할께요.
[1]: R4: 0xD2FB2B80는 task descriptor 포인터를 가르키고 있는데, 0x67C 오프셋에 위치한 메모리 덤프 로딩을 실행합니다.
크래시 유틸리티 프로그램으로 확인하면 task_struct.cgroups 멤버에 접근하네요.
crash> struct -o task_struct.cgroups
struct task_struct {
[0x67c] struct css_set *cgroups;
}
R3 = 0xDFB18800 = *D2FB31FC= *(0xD2FB2B80 + 0x67C) = *(R4 + 0x67C)
crash> struct task_struct.cgroups 0xD2FB2B80
cgroups = 0xdfb18800
[2]: R1 = 0xE97BBE80 = *(0xDFB1882C) = *(0xDFB18800 + 0x2C) = *(R3 + 0x2C)
crash> rd 0xDFB1882C
dfb1882c: e97bbe80
[3]: R3 = 0xCECCA980 = *0xE97BBEE0 *(0xE97BBE80 + 0x60) = *(R1 + 0x60)
crash> rd 0xE97BBEE0
e97bbee0: cecca980
[4]: 커널 패닉 발생 시 R3이 0xCECCA980값이 아니라 0xE17BBE80입니다.
#커널 패닉 시 메시지
[69350.929711] <c2>r7 : 00000000 r6 : 0016a175 r5 : e6188290 r4 : d2fb2b80
[69350.929727] <c2>r3 : e17bbe80 r2 : 30319000 r1 : e97bbe80 r0 : c1a0e538
다른 관점으로 cgroups 자료 구조를 분석해보면,
커널 패닉 시 cgroups 정보와 init_css_set 정보 확인 후 0xe97bbe80 메모리 덤프가 0xc1a1f480값 일 것 같은데요.
crash> struct css_set.subsys 0xdfb18800
subsys = {0xc1bf2d58 <root_task_group>, 0xe97bbe80, 0xf15e5000, 0xf15e5080}
crash> struct css_set.subsys 0xc1a21a84
subsys = {0xc1bf2d58 <root_task_group>, 0xc1a1f480 <root_cpuacct>, 0xf15e5000, 0xf15e5080}
crash> p &init_css_set
$4 = (struct css_set *) 0xc1a21a84 <init_css_set>
크래시 덤프 분석을 정리하면 아래와 2가지 이유 중 하나로 데이터 어보트가 생겼다고 추정할 수 있습니다.
1. @C01709A0 메모리 주소의 "ldr r3,[r1,#0x60]" 명령어 오동작
2. struct css_set.subsys 멤버가 잘못된 주소를 가르키고 있음(0xc1a1f480 -> 0xe97bbe80)
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글
| [Kernel][Panic] panic@ttwu_do_activate (메모리 불량 보드) (0) | 2023.05.07 |
|---|---|
| [Kernel][Stability] tcp_v4_rcv -> __stack_chk_fail (0) | 2023.05.07 |
| [Linux][Kernel] data abort@irq_affinity_notify - 리눅스 커널 (0) | 2023.05.07 |
| [Linux][Kernel] data abort @tty_wakeup - 리눅스 커널 (0) | 2023.05.07 |
| watchdog reset - race in ipv6_ifa_notify() - 리눅스 커널 (0) | 2023.05.07 |
