Linux Kernel(4.14) Hacks

rousalome.egloos.com

포토로그 Kernel Crash




[Linux][Kernel]뮤텍스 데드락(Mutex Deadlock) 락업(lockup) - "simpleperf" 디버깅 [Crash]Troubleshooting!!

#커널 크래시 디버깅 및 TroubleShooting

특정 시점부터 갑자기 디바이스가 락업되는 현상이 리포트가 되었거든요. 엄청 락업된 디바이스가 쏟아 졌었는데요.

이번 시간에는 그 때 어떻게 디버깅을 해서 문제를 해결했는지 업데이트하고자 해요.


락업이 된 상태에서 디바이스를 받아 강제로 코어 덤프를 뜬 다음에 콜 트레이스를 봤는데요.
아래 콜 스택이 확인되었어요. 프로세스 이름은 "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 시스템 콜


Reference(워크큐)
워크큐(Workqueue) Overview


핑백

덧글

댓글 입력 영역