Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

0112
737
82110


[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(프로세스 관리)
4.9 프로세스 컨택스트 정보는 어떻게 저장할까?
 4.9.1 컨택스트 소개
 4.9.2 인터럽트 컨택스트 정보 확인하기
 4.9.3 Soft IRQ 컨택스트 정보 확인하기
 4.9.4 선점 스케줄링 여부 정보 저장
4.10 프로세스 디스크립터 접근 매크로 함수
 4.10.1 current_thread_info()
 4.10.2 current 매크로란
4.11 프로세스 디버깅
 4.11.1 glibc fork 함수 gdb 디버깅
 4.11.2 유저 프로그램 실행 추적 

    핑백

    덧글

    댓글 입력 영역