#커널 크래시 디버깅 및 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)
특정 시점부터 갑자기 디바이스가 락업되는 현상이 리포트가 되었거든요. 엄청 락업된 디바이스가 쏟아 졌었는데요.
이번 시간에는 그 때 어떻게 디버깅을 해서 문제를 해결했는지 업데이트하고자 해요.
락업이 된 상태에서 디바이스를 받아 강제로 코어 덤프를 뜬 다음에 콜 트레이스를 봤는데요.
아래 콜 스택이 확인되었어요. 프로세스 이름은 "atd" 이에요.
reboot 시스템콜을 trigger한 다음에 각 종 시스템 드라이버를 종료하는 과정에서 mutex lock을 계속 기다리는 현상이 확인되네요.
-000|context_switch(inline)
-000|__schedule()
-001|schedule_preempt_disabled()
-002|spin_lock(inline)
-002|__mutex_lock_common(inline)
-002|__mutex_lock_slowpath(lock_count = 0xC1327164)
-003|current_thread_info(inline)
-003|mutex_set_owner(inline)
-003|mutex_lock(lock = 0xC1327164) // cpu_add_remove_lock
-004|cpu_hotplug_disable()
-005|migrate_to_reboot_cpu()
-006|kernel_restart(cmd = 0x0)
-007|SYSC_reboot(inline)
-007|sys_reboot(magic1 = -18751827, ?, cmd = 19088743, arg = 0)
-008|ret_fast_syscall(asm)
-->|exception
-009|__reboot(asm) // android/bionic/libc/arch-arm/syscalls/__reboot.S|9
-010|restart(?)
-011|__pthread_start(arg = 0xB55F7930)
-012|__start_thread(?, ?)
뮤텍스 데드락 현상이 의심되네요. 어떤 프로세스가 뮤텍스 락을 잡고 나서 실행 도중 잠들어버려 다른 프로세스가
그 뮤텍스 락을 못잡는 시나리오를 생각해볼 수 있는데요.
뮤텍스 락을 잡고 슬립에 빠지거나 뮤텍스 락을 기다리리며 잠들어 있는 프로세스들은 Interrupt을 받으면 안되기 때문에, 프로세스 상태가 Uninterruptible 상태(struct task_struct->state = TASK_UNINTERRUPTIBLE)이거든요.
이럴 때 "ps -l | grep UN" 명령어를 입력하면 Uninterruptbile 상태 프로세스를 확인할 수 있어요.
흠, 그런데 "simpleperf" 프로세스가 보이네요.
crash> ps -l | grep UN
[33341014778844] [UN] PID: 16965 TASK: c3362f40 CPU: 0 COMMAND: "atd" // <<--
[ 3069103232273] [UN] PID: 8919 TASK: d4bfb9c0 CPU: 0 COMMAND: "simpleperf" // <<--
[ 727796356] [UN] PID: 123 TASK: df6e9500 CPU: 1 COMMAND: "mdss_dsi_event"
"simpleperf" 프로세스(PID: 8919)의 콜스택을 살펴보니, 뮤텍스 락을 잡고 잠들어버리고 있네요.
세부 디버깅 정보는 콜 스택 옆에 있는 주석문을 참고하세요.
-00 |context_switch(inline)
-00 |__schedule()
-01 |schedule_preempt_disabled()
-02 |spin_lock(inline)
-02 |__mutex_lock_common(inline)
-02 |__mutex_lock_slowpath(lock_count = 0xDD05A008)
-03 |current_thread_info(inline)
-03 |mutex_set_owner(inline)
-03 |mutex_lock(lock = 0xDD05A008) // <<-- mutex lock
-04 |SYSC_perf_event_open(inline) // /data/misc/perfprofd/perferr.txt 파일을 오픈
-04 |sys_perf_event_open(?, pid = 3, cpu = 0, ?, flags = 0)
-05 |ret_fast_syscall(asm)
--> |exception
-06 |syscall(asm) // <<-- userspace system calls
-07 |perf_event_open(inline)
-07 |EventFd::OpenEventFile(?, pid = 8919, cpu = -1) // <<-- android/system/extras/simpleperf/event_fd.cpp|37
-08 |EventFd::OpenEventFileForProcess(attr = (typ //<<-- android/system/extras/simpleperf/event_fd.cpp|41
-09 |operator bool(inline)
-09 |operator!=<EventFd, std::__1::default_delete<EventFd> >(inline)
-09 |IsEventTypeSupportedByKernel(inline)
-09 |IsSupportedByKernel(inline)
-09 |EventTypeFactory::FindEventTypeByName(?, ?)
-10 |SetMeasuredEventType(inline)
-10 |RecordCommandImpl::Run(this = 0xBEB08848, ?)
-11 |RecordCommand::Run(?, args = (std::__1::__vector_base<std::__1::basic_strin
-12 |main(?, ?)
-13 |__libc_init(?, ?, slingshot = 0xB6F9AB45, ?)
-14 |start(asm)
mutex_lock(lock = 0xDD05A008)에서 보이는 mutex lock 디버깅 좀 해볼께요.
뮤텍스 락을 획득하기 위해 기다리는 프로세스는 struct mutex->wait_list 리스트에 자신의 뮤텍스(Mutex) 인스턴스를 등록하고 잠들어거든요.
(struct mutex*)0xDD05A008 = 0xDD05A008 -> (
count = (counter = 0xFFFFFFFF),
wait_lock = (rlock = (raw_lock = (slock = 0x00010001, tickets = (owner = 0x1
wait_list = (
next = 0xD1611EBC -> (
next = 0xDD05A010,
prev = 0xDD05A010),
prev = 0xD1611EBC),
owner = 0xD4BFB9C0, // <<-- "simpleperf", PID: 8919 프로세스의 task descriptor
spin_mlock = 0x0)
container_of(출처: http://rousalome.egloos.com/9963702) 란 매크로를 써서 뮤텍스 락을 디버깅을 좀 더 해봤더니, "simpleperf" 란 프로세스가 뮤덱스 락을 한번 획득하고 난 다음에 또 다시 획득하려다가 잠들어 버린 디버깅 정보가 확인되네요.
wait_list.next=0xD1611EBC
(struct mutex *) container_of(0xD1611EBC,struct mutex,wait_list) = 0xD1611EB4
// snip
(struct task_struct *) owner = 0xD4BFB9C0 //<<--"simpleperf", PID: 8919 프로세스의 task descriptor
wait_list.next.next=0xDD05A010
(struct mutex *) container_of(0xDD05A010,struct mutex,wait_list) = 0xDD05A008
(atomic_t) count = ((int) counter = -1 = 0xFFFFFFFF = '....'),
//snip
(struct task_struct *) owner = 0xD4BFB9C0 // <<-- "simpleperf", PID: 8919 프로세스의 task descriptor
코드 리뷰를 해보니 정말로 mutex lock을 두 번 잡고 있네요.
어떤 분이 커널 마이그레이션을 하다가 conflict이 나서 실수로 mutex lock 코드를 추가한 것 같아요.
SYSCALL_DEFINE5(perf_event_open,
struct perf_event_attr __user *, attr_uptr,
pid_t, pid, int, cpu, int, group_fd, unsigned long, flags)
{
// .. 생략..
if (move_group) {
gctx = group_leader->ctx;
/*
* See perf_event_ctx_lock() for comments on the details
* of swizzling perf_event::ctx.
*/
mutex_lock_double(&gctx->mutex, &ctx->mutex);
perf_remove_from_context(group_leader, false);
perf_event__state_init(group_leader);
list_for_each_entry(sibling, &group_leader->sibling_list,
group_entry) {
perf_remove_from_context(sibling, false);
perf_event__state_init(sibling);
put_ctx(gctx);
}
} else {
mutex_lock(&ctx->mutex); //<<--
}
WARN_ON_ONCE(ctx->parent_ctx);
mutex_lock(&ctx->mutex); //<<-
위에 보이는 mutex_lock을 삭제하니 문제는 사라졌어요. 커널 마이그레이션 할 때 conflict나면 살 떨려서 어떻게 하죠? 조심해야 겠어요.
# Reference (ARM Processor)
# Reference: For more information on 'Linux Kernel';
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
최근 덧글