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나면 살 떨려서 어떻게 하죠? 조심해야 겠어요.

임베디드 개발에서 T32-Trace32 장비를 많이 써서 소스 코드 디버깅을 합니다.

이번 시간에는 리눅스 커널에서 웨이크락(wake lock)을 잡는 모듈이 누구인지 파악하는 디버깅(Debugging) 방법을 소개합니다.

리눅스 커널는 wakeup_sources이란 연결 리스트를 통해 wakelock 정보를 확인할 수 있습니다.

리눅스 커널 개발자 중에 crash-utility을 잘 쓰는 분이 있습니다.

하지만 임베디드 개발에선 Trace32도 더 많이 활용하는 것 같습니다.

개발자는 다양한 툴을 써야 한 가지 툴에 종속된 노예 개발자가 되는 것을 피할 수 있습니다.

또한 각 툴의 장점을 잘 활용할 수도 있습니다.

먼저, 다음 T32 명령어를 입력해서 offsetof와 container_of 매크로를 생성합시다.

sYmbol.NEW.MACRO offsetof(type,member) ((int)(&((type*)0)->member))

sYmbol.NEW.MACRO container_of(ptr,type,member) ((type *)((char *)(ptr)-offsetof(type,member)))

리눅스 커널 소스 코드에서 구현된 그래도 매크로를 선언하는 것입니다.

#define container_of(ptr, type, member) ({ \

void *__mptr = (void *)(ptr); \

((type *)(__mptr - offsetof(type, member))); })

#define offsetof(TYPE, MEMBER) ((size_t)&((TYPE *)0)->MEMBER)

우선 wakeup_sources 변수를 봅시다.

v.v %h %t wakeup_sources

  (static struct list_head) wakeup_sources = (

    (struct list_head *) next = 0xFFFFFFC5FD92EA88 -> (

      (struct list_head *) next = 0xFFFFFFC5FD92FC88 -> (

        (struct list_head *) next = 0xFFFFFFC541226488,

        (struct list_head *) prev = 0xFFFFFFC5FD92EA88),

      (struct list_head *) prev = 0xFFFFFF97D92B4D00),

    (struct list_head *) prev = 0xFFFFFFC62D3EDB88)

wakelock을 잡은 모듈들은 wakeup_sources 이란 전역 변수에 등록돼 있습니다.

계속 struct list_head->next로 리스트들이 연결돼 있다는 사실을 파악할 수 있습니다.

이제 앞에서 생성한 container_of 매크로를 쓸 순간입니다. 다음과 같이 명령어를 입력합시다.

v.v %h %t %s  container_of(0xFFFFFFC5FD92EA88,struct wakeup_source,entry)

  (struct wakeup_source *) container_of(0xFFFFFFC5FD92EA88,struct wakeup_source,entry) = 0xFFFFFFC5FD92EA80 -> (

    (char *) name = 0xFFFFFFC55DEE3280 -> "ipc00001269_1988_HwBinder:682_1",

    (struct list_head) entry = ((struct list_head *) next = 0xFFFFFFC5FD92FC88, (struct list_head *) prev = 0xFFF

    (spinlock_t) lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u16) owner = 0x298F, (u16)

    (struct wake_irq *) wakeirq = 0x0,

    (struct timer_list) timer = ((struct hlist_node) entry = ((struct hlist_node *) next = 0x0, (struct hlist_nod

    (long unsigned int) timer_expires = 0x0,

    (ktime_t) total_time = ((s64) tv64 = 0x0),

    (ktime_t) max_time = ((s64) tv64 = 0x0),

    (ktime_t) last_time = ((s64) tv64 = 0x000040E1FC6B0DF2),

    (ktime_t) start_prevent_time = ((s64) tv64 = 0x0),

    (ktime_t) prevent_sleep_time = ((s64) tv64 = 0x0),

    (long unsigned int) event_count = 0x0,

    (long unsigned int) active_count = 0x0,

    (long unsigned int) relax_count = 0x0,

    (long unsigned int) expire_count = 0x0,

    (long unsigned int) wakeup_count = 0x0,

    (long unsigned int) pending_count = 0x0,

    (bool:1) active = FALSE,

    (bool:1) autosleep_enabled = FALSE)

위 멤버 변수 중 active 변수가 FALSE이니 "ipc00001269_1988_HwBinder:682_1"이란 wakeup source가 wakelock을 잡고 있지 않습니다.

v.v %h %t %s  container_of(0xFFFFFFC5FD92EA88,struct wakeup_source,entry)

위와 같은 명령어를 쓴 이유는, struct wakeup_source이란 구조체에 entry이란 struct list_head 타입 멤버 변수가

wakeup_sources이란 링크드 리스트 전역 변수 wakeup_sources->next로 등록됐기 때문입니다.

해당 구조체를 봅시다.

struct wakeup_source {

const char *name;

struct list_head entry;

spinlock_t lock;

struct wake_irq *wakeirq;

struct timer_list timer;

unsigned long timer_expires;

ktime_t total_time;

ktime_t max_time;

ktime_t last_time;

ktime_t start_prevent_time;

ktime_t prevent_sleep_time;

unsigned long event_count;

unsigned long active_count;

unsigned long relax_count;

unsigned long expire_count;

unsigned long wakeup_count;

bool active:1;

bool autosleep_enabled:1;

};

쉽게 설명하면 아래 방식으로 wakeup_source가 wakeup_sources 리스트에 등록합니다.

1st wakeup source 등록

wakeup_sources->next = struct wakeup_source->entry

2nd wakeup source등록

wakeup_sources->next->next = struct wakeup_source->entry

개발자분들이여, 임베디드 동네의 최강의 툴인 Trace32를 잘 활용해서 일찍 퇴근합시다.