#커널 크래시 디버깅 및 TroubleShooting
 
worker_pool_idr 전역 변수에 접근하면 (*(worker_pool_idr.top)).ary 각 CPU별 워커풀 인스턴스가 있다고 했죠.
  (static struct idr) worker_pool_idr = (
    (struct idr_layer *) hint = 0xFFFFFFC6307B9308,
    (struct idr_layer *) top = 0xFFFFFFC6307B9308 -> (
      (int) prefix = 0x0,
      (int) layer = 0x0,
      (struct idr_layer * [256]) ary = (
        [0x0] = 0xFFFFFFC63A30B000,  //<<--CPU0, node0
        [0x1] = 0xFFFFFFC63A30B400,  //<<--CPU0, node1 
        [0x2] = 0xFFFFFFC63A322000,  //<<--CPU1, node0
        [0x3] = 0xFFFFFFC63A322400,  //<<--CPU1, node1 
        [0x4] = 0xFFFFFFC63A339000,  //<<--CPU2, node0
        [0x5] = 0xFFFFFFC63A339400,  //<<--CPU2, node1 
        [0x6] = 0xFFFFFFC63A350000,  //<<--CPU3, node0
        [0x7] = 0xFFFFFFC63A350400,  //<<--CPU3, node1
        [0x8] = 0xFFFFFFC63A367000,
        [0x9] = 0xFFFFFFC63A367400,
        [0x0A] = 0xFFFFFFC63A37E000,
        [0x0B] = 0xFFFFFFC63A37E400,
        [0x0C] = 0xFFFFFFC63A395000
 
이 워커 풀을 하나 하나 씩 열어서 아직 실행 안된 배리어 워크가 있는 지 알아봐야 합니다.
각각 워커풀을 다 확인했는데, CPU1 워커풀에서 뭔가 특이한 디버깅 정보가 보이네요.
 
아래는 CPU1에 대한 워커풀입니다.
  (struct worker_pool *) (struct worker_pool*)0xFFFFFFC63A322000 = 0xFFFFFFC63A322000 -> (
    (spinlock_t) lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u16) owner =
    (int) cpu = 1 = 0x1,
    (int) node = 0 = 0x0,
    (int) id = 2 = 0x2,
    (unsigned int) flags = 0 = 0x0,
    (long unsigned int) watchdog_ts = 4302303488 = 0x00000001006FF100,
    (struct list_head) worklist = ((struct list_head *) next = 0xFFFFFFC63A322030, (struct list_head
    (int) nr_workers = 4 = 0x4,
    (int) nr_idle = 2 = 0x2,
    (struct list_head) idle_list = ((struct list_head *) next = 0xFFFFFFC582B43380, (struct list_hea
    (struct timer_list) idle_timer = ((struct hlist_node) entry = ((struct hlist_node *) next = 0xDE
    (struct timer_list) mayday_timer = ((struct hlist_node) entry = ((struct hlist_node *) next = 0x
    (struct hlist_head [64]) busy_hash = (
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0xFFFFFFC4DEB55880),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0x0),
      ((struct hlist_node *) first = 0xFFFFFFC5956E1E80),
      ((struct hlist_node *) first = 0x0),
//...
    (struct worker *) manager = 0x0,
    (struct mutex) attach_mutex = ((atomic_t) count = ((int) counter = 1 = 0x1), (spinlock_t) wait_l
    (struct list_head) workers = (
      (struct list_head *) next = 0xFFFFFFC4DEB558D0 -> (
        (struct list_head *) next = 0xFFFFFFC5956E1ED0 -> (
          (struct list_head *) next = 0xFFFFFFC5F3942AD0 -> (
            (struct list_head *) next = 0xFFFFFFC582B433D0,
 
struct worker_pool->workers.next 링크드 리스트와 struct worker_pool->busy_hash를 보니 
아래 주소로 등록된 워커를 살펴봐야 할 것 같습니다. 
(struct list_head) workers = (
  (struct list_head *) next = 0xFFFFFFC4DEB558D0 -> (
    (struct list_head *) next = 0xFFFFFFC5956E1ED0 -> (
v.v %h %t %d container_of(0xFFFFFFC4DEB558D0,struct worker,node)         
v.v %h %t %d container_of(0xFFFFFFC5956E1ED0,struct worker,node)   
 
배리어 워크는 struct worker->scheduled 링크드 리스트에 등록합니다. 그래서 struct worker->scheduled 멤버를 확인해야 하는데요. 아래 워크는 특이 정보가 없습니다. 왜냐면 struct worker->scheduled에 등록된 링크드 리스트가 비어 있기 때문이죠. 
  (struct worker *) container_of(0xFFFFFFC4DEB558D0,struct worker,node) = 0xFFFFFFC4DEB55880  
    (struct list_head) entry = ((struct list_head *) next = 0x0  
    (struct hlist_node) hentry = ((struct hlist_node *) next = 0x0  
    (struct work_struct *) current_work = 0xFFFFFFC6237C15A8  
    (work_func_t) current_func = 0xFFFFFF97D7172254 = pm_runtime_work,
    (struct pool_workqueue *) current_pwq = 0xFFFFFFC63A329600 
    (bool) desc_valid = FALSE,
    (struct list_head) scheduled = (
      (struct list_head *) next = 0xFFFFFFC4DEB558B0  
        (struct list_head *) next = 0xFFFFFFC4DEB558B0  
        (struct list_head *) prev = 0xFFFFFFC4DEB558B0 
      (struct list_head *) prev = 0xFFFFFFC4DEB558B0  
    (struct task_struct *) task = 0xFFFFFFC51CDC4480  
    (struct worker_pool *) pool = 0xFFFFFFC63A322000  
    (struct list_head) node = ((struct list_head *) next = 0xFFFFFFC5956E1ED0 
    (long unsigned int) last_active = 4302072889 = 0x00000001006C6C39,
    (unsigned int) flags = 0 = 0x0,
    (int) id = 0 = 0x0,
    (char [24]) desc = (0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 =
    (struct workqueue_struct *) rescue_wq = 0x0 
 
배리어 워크를 struct worker->scheduled 링크드 리스트에 등록하는 코드는 아래 흐름으로 호출되는 insert_wq_barrier 함수를 참고하세요.
 
flush_work -> start_flush_work -> insert_wq_barrier
static void insert_wq_barrier(struct pool_workqueue *pwq,
      struct wq_barrier *barr,
      struct work_struct *target, struct worker *worker)
{
struct list_head *head;
//..
if (worker)
head = worker->scheduled.next;  //<<--
else {
unsigned long *bits = work_data_bits(target);
 
head = target->entry.next;
/* there can already be other linked works, inherit and set */
linked = *bits & WORK_STRUCT_LINKED;
__set_bit(WORK_STRUCT_LINKED_BIT, bits);
}
 
이번에는 다음 워커를 살펴볼 차례입니다.
 
드디어 처리 안된 배리어 워크를 찾았습니다.
0xFFFFFFC55731E680 주소 태스크 디스크립터인 워커 쓰래드에서 처리 안된 배리어 워크가 있군요.
(struct worker *) container_of(0xFFFFFFC5956E1ED0,struct worker,node) = 0xFFFFFFC5956E1E80 
    (struct list_head) entry = ((struct list_head *) next = 0x0  
    (struct hlist_node) hentry = ((struct hlist_node *) next = 0x0  
    (struct work_struct *) current_work = 0xFFFFFFC623C0AD48 
    (work_func_t) current_func = 0xFFFFFF97D72263A8 = ufshcd_exception_event_handler,
    (struct pool_workqueue *) current_pwq = 0xFFFFFFC63A328800  
    (bool) desc_valid = FALSE,
    (struct list_head) scheduled = (
      (struct list_head *) next = 0xFFFFFFC5F4707B18  
        (struct list_head *) next = 0xFFFFFFC5956E1EB0  
          (struct list_head *) next = 0xFFFFFFC5F4707B18  
          (struct list_head *) prev = 0xFFFFFFC5F4707B18  
        (struct list_head *) prev = 0xFFFFFFC5956E1EB0  
      (struct list_head *) prev = 0xFFFFFFC5F4707B18  
    (struct task_struct *) task = 0xFFFFFFC55731E680  
    (struct worker_pool *) pool = 0xFFFFFFC63A322000  
    (struct list_head) node = ((struct list_head *) next = 0xFFFFFFC5F3942AD0  
    (long unsigned int) last_active = 4302072800 = 0x00000001006C6BE0,
    (unsigned int) flags = 0 = 0x0,
    (int) id = 1 = 0x1,
    (char [24]) desc = (0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 = 0x0, 0 =
    (struct workqueue_struct *) rescue_wq = 0x0  
 
그럼 다음 struct worker->scheduled 멤버가 가르키는 주소를 참고해서 배리어 워크의 정체를 알아볼 차례입니다...
(struct list_head) scheduled = (
  (struct list_head *) next = 0xFFFFFFC5F4707B18  
    (struct list_head *) next = 0xFFFFFFC5956E1EB0  
 
배리어 워크의 구조체는 다음과 같고, worker->scheduled.next에는 struct work_struct.entry 주소를 등록했습니다.
struct wq_barrier {
struct work_struct work;
struct completion done;
};
 
따라서 다음 명령어로 배리어 워크 정보를 확인할 수 있습니다.  
v.v %all container_of(0xFFFFFFC5F4707B18,struct work_struct,entry)
 
  (struct work_struct *) container_of(0xFFFFFFC5F4707B18,struct work_struct,entry) = 0xFFFFFFC5F4707B10 =
    (atomic_long_t) data = ((long int) counter = -248131712539 = 0xFFFFFFC63A3289E5 = '....:2..'),
    (struct list_head) entry = ((struct list_head *) next = 0xFFFFFFC5956E1EB0 
    (work_func_t) func = 0xFFFFFF97D6AC58F0 = wq_barrier_func -> )
 
또한 struct work_struct work 멤버는 struct wq_barrier 구조체의 첫 멤버 변수이므로 같은 주소로 다음과 같이 캐스팅 할 수 있습니다.  
v.v %all (struct wq_barrier*)0xFFFFFFC5F4707B10
 
struct wq_barrier *) (struct wq_barrier*)0xFFFFFFC5F4707B10 = 0xFFFFFFC5F4707B10  
 (struct work_struct) work = ((atomic_long_t) data = ((long int) counter = -248131712539 = 0xFFFFFFC63A3289E5 
 (struct completion) done = (
   (unsigned int) done = 0 = 0x0 = '....',
   (wait_queue_head_t) wait = (
     (spinlock_t) lock = ((struct raw_spinlock) rlock = 
     (struct list_head) task_list = (
       (struct list_head *) next = 0xFFFFFFC5F4707A88 
         (struct list_head *) next = 0xFFFFFFC5F4707B50  
         (struct list_head *) prev = 0xFFFFFFC5F4707B50  
       (struct list_head *) prev = 0xFFFFFFC5F4707A88  
 (struct task_struct *) task = 0xFFFFFFC541030080 
 
위에서 보이는 주소가 눈에 좀 익숙하지 않나요?
 
CPU2 워커풀 에서 배리어 워크를 기다리는 콜스택이 있었죠? 다음 디버깅 정보를 보면 웨이트 큐에 등록된 프로세스 주소가 같음을 알 수 있습니다.
(struct completion *) (struct completion *)0xFFFFFFC5F4707B30 = 0xFFFFFFC5F4707B30 -> (
    (unsigned int) done = 0x0,
    (wait_queue_head_t) wait = (
      (spinlock_t) lock = (
        (struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u16) owner = 0x1, (u16) next =
      (struct list_head) task_list = (
        (struct list_head *) next = 0xFFFFFFC5F4707A88 -> (
          (struct list_head *) next = 0xFFFFFFC5F4707B50 -> (  //<<--
 
(where: CPU2에서 배리어 워크가 수행되기를 기다리다가 슬립에 빠진 프로세스 콜스택)
-000|__switch_to(prev = 0xFFFFFFC541030080, next = 0xFFFFFFC60E561180)
-001|context_switch(inline)
-001|__schedule(?)
-002|schedule()
-003|schedule_timeout(timeout = 9223372036854775807)
-004|do_wait_for_common(inline)
-004|__wait_for_common(inline)
-004|wait_for_common(x = 0xFFFFFFC5F4707B30, timeout = 9223372036854775807, ?)
-005|wait_for_completion(x = 0xFFFFFFC5F4707B30)
-006|destroy_work_on_stack(inline)
-006|flush_work(?)
-007|ufshcd_suspend(hba = 0xFFFFFFC623C0AB70, pm_op = UFS_RUNTIME_PM)
-008|ufshcd_runtime_suspend(hba = 0xFFFFFFC623C0AB70)
-009|ufshcd_pltfrm_runtime_suspend(dev = 0xFFFFFFC62CFE6690)
-010|pm_generic_runtime_suspend(dev = 0xFFFFFFC62CFE6690)
//...
-014|pm_runtime_work(work = 0xFFFFFFC62CFE67F8)
 -015|trace_workqueue_execute_end(inline)
-015|process_one_work(worker = 0xFFFFFFC4DE83A780, work = 0xFFFFFFC62CFE67F8)
-016|__read_once_size(inline)
-016|list_empty(inline)
-016|worker_thread(__worker = 0xFFFFFFC4DE83A780)
-017|kthread(_create = 0xFFFFFFC4DA494D00)
-018|ret_from_fork(asm)
 
이제 다시 이전 디버깅 정보로 돌아가서, 
위에서 찾은 CPU1 워커풀에 등록된 워커 중 현재 처리 중인 배리어 워크가 있는 워커는 다음과 같습니다.
  (struct worker *) container_of(0xFFFFFFC5956E1ED0,struct worker,node) = 0xFFFFFFC5956E1E80  
    (struct list_head) entry = ((struct list_head *) next = 0x0  
    (struct hlist_node) hentry = ((struct hlist_node *) next = 0x0  
    (struct work_struct *) current_work = 0xFFFFFFC623C0AD48 
    (work_func_t) current_func = 0xFFFFFF97D72263A8 = ufshcd_exception_event_handler,
    (struct pool_workqueue *) current_pwq = 0xFFFFFFC63A328800  
    (bool) desc_valid = FALSE,
    (struct list_head) scheduled = (
      (struct list_head *) next = 0xFFFFFFC5F4707B18  
        (struct list_head *) next = 0xFFFFFFC5956E1EB0  
          (struct list_head *) next = 0xFFFFFFC5F4707B18  
          (struct list_head *) prev = 0xFFFFFFC5F4707B18  
        (struct list_head *) prev = 0xFFFFFFC5956E1EB0  
      (struct list_head *) prev = 0xFFFFFFC5F4707B18  
    (struct task_struct *) task = 0xFFFFFFC55731E680 //<<--
 
그럼 이 프로세스의 이름과 콜스택을 알아볼까요?
"kworker/1:1" 프로세스가 아래 콜스택으로 동작 중이었습니다.
-000|__switch_to(prev = 0xFFFFFFC55731E680, next = 0xFFFFFFC4C4B98080)
-001|context_switch(inline)
-001|__schedule(?)
-002|schedule()
-003|spin_lock_irq(inline)
-003|rpm_resume(dev = 0xFFFFFFC62CFE6690, rpmflags = 4)
-004|__pm_runtime_resume(dev = 0xFFFFFFC62CFE6690, rpmflags = 4)
-005|ufshcd_scsi_block_requests(inline)
-005|ufshcd_exception_event_handler(work = 0xFFFFFFC623C0AD48)
-006|process_one_work(worker = 0xFFFFFFC5956E1E80, work = 0xFFFFFFC623C0AD48)
-007|__read_once_size(inline)
-007|list_empty(inline)
-007|worker_thread(__worker = 0xFFFFFFC5956E1E80)
-008|kthread(_create = 0xFFFFFFC540CA7C80)
-009|ret_from_fork(asm)
 
그럼 여기까지 분석한 디버깅 정보로 이제 문제 발생 원인을 다음과 같이 좁힐 수 있습니다.
하나 하나 퍼즐을 맞히니 그림이 그려지는 것 같군요.
     CPU1                                    CPU2                                                                            
process_one_work                          process_one_work
ufshcd_exception_event_handler     pm_runtime_work     
__pm_runtime_resume                  pm_generic_runtime_suspend
  flush_work                                  ufshcd_runtime_suspend
                                                    ufshcd_suspend
                                                    flush_work
                                                    ; 배리어 워크가 처리되기를 기다림
 
1. CPU1에서 flush_work 함수 호출로 배리어 워크를 추가했는데, 뭔가 문제가 생겨서 배리어 워크 처리를 못했습니다.
2. CPU2에서는 배리어 워크가 실행 되기를 기다리고 있습니다.
3. 115초 후 워크큐 락업으로 감지되어 커널 크래시가 발생했습니다.
 
이제 문제를 유발시킨 코드를 조금 깊히 살펴볼 차례입니다.
 
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
 
저작자표시

'Core BSP 분석 > 커널 트러블슈팅' 카테고리의 다른 글

[리눅스][커널] 커널 크래시 분석은 왜 중요할까?  (0) 2023.05.07
[Linux][Kernel] 커널 크래시란  (0) 2023.05.07
[Kernel][Crash] 워크큐(workqueue) 락업(2) at [0321]  (0) 2023.05.07
[Kernel][Crash][0320] 워크큐(workqueue) 락업(1)  (0) 2023.05.07
[Kernel][Panic] panic@ttwu_do_activate (메모리 불량 보드)  (0) 2023.05.07

+ Recent posts

티스토리툴바