Arm Linux Kernel Hacks

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

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

락업이 된 상태에서 디바이스를 받아 강제로 코어 덤프를 뜬 다음에 콜 트레이스를 봤는데요.

아래 콜 스택이 확인되었어요. 프로세스 이름은 "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나면 살 떨려서 어떻게 하죠? 조심해야 겠어요.