커널 패닉이란 말을 들어본 적이 있나요? 혹시 여러분이 임베디드 리눅스 개발자면 몇 번 쯤은 들어봤을 겁니다. 하지만, 리눅스를 자주 안 쓰거나 리눅스를 학습 용도로 쓰시는 분들에겐 단어가 낯설게 들릴수도 있죠. 
 
여러분들은 대부분 컴퓨터나 노트북을 윈도 운영체제로 쓰실 겁니다. 그런데 혹시 컴퓨터를 오래 쓰다가 블루 스크린을 본 적이 있나요? 밝은 파란색 배경 화면에 흰색으로 이상한 경고 문구가 떠있죠. 이 때 컴퓨터는 아무런 동작을 안합니다. 이런 화면을 처음 봤을 때 어땠나요? 좀 짜증나지 않았나요? 전 예전 처음 이 블루 스크린을 봤을 때 엄청 당황했었어요. 왜냐면 “전원을 다시 키면 부팅은 할까?”, “혹시 컴퓨터에 저장된 자료가 날아가는 건 아닌가”? 이런 걱정을 했죠. 정말 뭔가 컴퓨터에 큰 고장이 난 것 같았어요. 
 
이렇게 윈도 운영체제에서 뜨는 블루 스크린은 리눅스 운영 체제에서는 발생하지 않을까요? 다들 아시겠지만 윈도 운영체제에서 뜨는 블루 스크린이 리눅스에서도 있습니다. 대신 리눅스 운영체제에서는 검은색 배경에 흰색 문구를 띄웁니다. 이를 보통 커널 패닉이라고 합니다. 개발자들은 커널 크래시라고도 말하죠.
 
그럼 커널 크래시는 왜 발생할까요? 그 이유에 대해서 찬찬히 살펴볼게요.  혹시 소프트웨어 공학에서 ASSERT란 단어 들어 보신적 있나요? 이해를 돕기 위해서 간단한 코드를 소개 할게요. 아래 코드를 눈 여겨 보면 param이란 포인터가 NULL이 아니면 void 타입의 파라미터를 task란 지역 변수로 캐스팅합니다. 그런데 param이란 포인터가 NULL이면 ASSERT를 유발하죠.
void proc_func_ptr(void *param)
{
       struct task_struct *task;
if (!param) 
ASSERT(1);
    else
task = (struct task_struct*)param;
 
리눅스 커널에서는 ASSERT 대신 BUG() 혹은 panic() 란 함수를 씁니다. 보통 소프트웨어적으로 심각한 오류 상태라 더 이상 실행할 수 없다고 판단 할 때 호출 합니다. 그럼 만약 param 이란 포인터가 널일 때 아래 if 구문이 없으면 어떻게 동작할까요? 이후 구문에서 Data Abort로 익셉션이 발생 할 겁니다.
void proc_func_ptr(void *param)
{
        struct task_struct *task;
if (!param) 
BUG();
    else
task = (struct task_struct*)param;
 
그럼 비슷한 유형의 리눅스 커널 코드를 잠깐볼까요? 아래 함수를 보면 BUG_ON()이란 함수가 보이죠.
[drivers/clk/tegra/clk-tegra20.c]
1 static unsigned long tegra20_clk_measure_input_freq(void)
2 {
3 u32 osc_ctrl = readl_relaxed(clk_base + OSC_CTRL);
4 u32 auto_clk_control = osc_ctrl & OSC_CTRL_OSC_FREQ_MASK;
5 u32 pll_ref_div = osc_ctrl & OSC_CTRL_PLL_REF_DIV_MASK;
6 unsigned long input_freq;
7
8 switch (auto_clk_control) {
9 case OSC_CTRL_OSC_FREQ_12MHZ:
10 BUG_ON(pll_ref_div != OSC_CTRL_PLL_REF_DIV_1);
11 input_freq = 12000000;
12 break;
13 case OSC_CTRL_OSC_FREQ_13MHZ:
14 BUG_ON(pll_ref_div != OSC_CTRL_PLL_REF_DIV_1);
15 input_freq = 13000000;
16 break;
// .. 생략 ..
17 default:
18 pr_err("Unexpected clock autodetect value %d",
19        auto_clk_control);
20 BUG();
21 return 0;
22 }
 
위 코드는 nVidia Tegra SoC에서 클락을 제어하는 코드인데요. 
10번과 14번째 줄 코드를 보면 pll_ref_div != OSC_CTRL_PLL_REF_DIV_1, pll_ref_div != OSC_CTRL_PLL_REF_DIV_1 조건이 보이죠? 만약 pll_ref_div !=OSC_CTRL_PLL_REF_DIV_1 조건을 만족하면 결과는 1이기 때문에 BUG_ON(1)이 호출되고 결국 BUG()함수가 수행되어 커널 크래시를 발생합니다. 이 코드를 해석하면 이 조건이 시스템이 치명적인 결함이 생길 위험이 크다고 판단하는 것입니다.
 
또한 8번 줄의 auto_clk_control 값이 switch~case문에서 정의된 case에서 처리안되고 default가 수행되면 커널 패닉을 유발시킵니다. 이 조건도 시스템을 더 이상 구동시킬 수 없는 상태로 보고 있습니다.
 
자, 그럼 다음 코드를 같이 살펴볼까요?
[init/do_mounts.c]
1 void __init mount_block_root(char *name, int flags)
2 {
// .. 생략..
3 printk_all_partitions();
4 #ifdef CONFIG_DEBUG_BLOCK_EXT_DEVT
5 printk("DEBUG_BLOCK_EXT_DEVT is enabled, you need to specify "
6        "explicit textual name for \"root=\" boot option.\n");
7 #endif
8 panic("VFS: Unable to mount root fs on %s", b);
 
8번 줄의 panic이란 함수가 보이죠? 부팅 도중 root 파일 시스템을 마운트를 못했을 때 panic() 함수를 호출해서 커널 패닉을 유발합니다. 그럼 왜 커널 크래시를 유발할까요? root 파일 시스템이 마운트 안되면 시스템 부팅 과정에서 계속 에러가 발생할 겁니다. root 파일 시스템이 마운트 안된 사실을 모르고 계속 시스템 에러를 잡는 삽질을 할 가능성이 높죠.  그래서 커널 크래시를 유발하고 우선 root 파일 시스템 마운트를 하라고 알려주는 겁니다. 참고로  root 파일 시스템을 통해 시스템 기본 설정에 연관된 init rc파일들을 읽습니다. 
 
 
이렇게 리눅스 커널 코드를 살펴보면 이런 panic과 BUG 코드가 지뢰 밭처럼 깔려 있는데요. 이런 코드를 추가한 이유는 뭘까요? 왜 강제로 커널 크래시를 유발해서 짜증나게 할까요? 이 이유에 대해서 조금 더 살펴볼께요.
 
"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.  
그리고 혹시 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려드리겠습니다!"
 
#커널 크래시 디버깅 및 TroubleShooting
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
 
#커널 크래시 디버깅 및 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
 
 
 
#커널 크래시 디버깅 및 TroubleShooting
 
자 여기까지 커널 크래시가 발행한 원인까지 확인했습니다.
그럼 CPU2에 워커풀에서 등록된 워커쓰레드를 살펴봐야 겠습니다.
 
워커쓰레드들은 워커 풀에 등록할 때 struct worker_pool.workers 멤버 링크드 리스트로 등록합니다.
1  (struct worker_pool *) (struct worker_pool*)0xFFFFFFC63A339000 = 0xFFFFFFC63A339000 -> (
2    (spinlock_t) lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u16) owner =
3    (int) cpu = 2,
4    (int) node = 0,
5    (int) id = 4,
6    (unsigned int) flags = 1,
// ....
7    (struct mutex) attach_mutex = ((atomic_t) count = ((int) counter = 1), (spinlock_t) wait_lock =
8    (struct list_head) workers = (
9      (struct list_head *) next = 0xFFFFFFC4DE83A7D0 -> (
10        (struct list_head *) next = 0xFFFFFFC50C460CD0 -> (
11          (struct list_head *) next = 0xFFFFFFC4E26A30D0 -> (
12            (struct list_head *) next = 0xFFFFFFC63A339300 -> (
13              (struct list_head *) next = 0xFFFFFFC4DE83A7D0,
 
자 위에서 7번째부터 13번째까지 링크트 리스트로 연결된 주소가 보이죠?
struct worker_pool.workers.next에 등록된 리스트 주소는 해당 워크의 struct worker.node 와 같습니다.
struct worker {
/* on idle list while idle, on busy hash table while busy */
union {
struct list_head entry; /* L: while idle */
struct hlist_node hentry; /* L: while busy */
};
 
struct work_struct *current_work; /* L: work being processed */
// ..
 
struct task_struct *task; /* I: worker task */
struct worker_pool *pool; /* I: the associated pool */
/* L: for rescuers */
struct list_head node; /* A: anchored at pool->workers */
 
container_of 매크로를 써서 이 자료구조의 상관 관계를 다음과 같이 표시할 수 있습니다.
container_of(struct worker_pool.workers.next, struct worker, node)
 
참고로, Trace32로 다음과 같이 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)))
 
이 명령어를 활용해서 워커풀에 등록된 워커 쓰레드 정보를 확인할께요. 다음 자료 구조 주소를 참고하고요.
9      (struct list_head *) next = 0xFFFFFFC4DE83A7D0 -> (
10        (struct list_head *) next = 0xFFFFFFC50C460CD0 -> (
11          (struct list_head *) next = 0xFFFFFFC4E26A30D0 -> (
12            (struct list_head *) next = 0xFFFFFFC63A339300 -> (
13              (struct list_head *) next = 0xFFFFFFC4DE83A7D0,
 
9줄에 있는 주소부터 확인할게요. 
v.v %t %h %d %s container_of(0xFFFFFFC4DE83A7D0,struct worker,node)
1  (struct worker *) container_of(0xFFFFFFC4DE83A7D0,struct worker,node) = 0xFFFFF
2    (struct list_head) entry = ((struct list_head *) next = 0x0 = , (struct list_
3    (struct hlist_node) hentry = ((struct hlist_node *) next = 0x0 = , (struct hl
4    (struct work_struct *) current_work = 0xFFFFFFC62CFE67F8 = __efistub__end+0x2
5    (work_func_t) current_func = 0xFFFFFF97D7172254 = pm_runtime_work,
6    (struct pool_workqueue *) current_pwq = 0xFFFFFFC63A340600 = __efistub__end+0
7    (bool) desc_valid = FALSE,
8    (struct list_head) scheduled = ((struct list_head *) next = 0xFFFFFFC4DE83A7B
9    (struct task_struct *) task = 0xFFFFFFC541030080  
10    (struct worker_pool *) pool = 0xFFFFFFC63A339000 
11    (struct list_head) node = ((struct list_head *)  
12    (long unsigned int) last_active = 4302072797 = 0x00000001006C6BDD,
13    (unsigned int) flags = 0 = 0x0,
14    (int) id = 2 = 0x2,
15    (char [24]) desc = "",
16    (struct workqueue_struct *) rescue_wq = 0x0 = )
 
가장 중요한 정보부터 확인하면 해당 워커 쓰레드의 태스크 디스크립터는 0xFFFFFFC541030080이고, 
가장 마지막에 실행된 시간은 last_active은 4302072797입니다. 이 값은 jiffies 이겠죠. 
9    (struct task_struct *) task = 0xFFFFFFC541030080 
12    (long unsigned int) last_active = 4302072797 = 0x00000001006C6BDD,
 
태스크 디스크립터는 0xFFFFFFC541030080 정보로 이 프로세스 이름과 콜스택을 알아볼까요? 
  (struct task_struct *) (struct task_struct*)0xFFFFFFC541030080 = 0xFFFFFFC541030080 -> (
    (struct thread_info) thread_info = ((long unsigned int) flags = 0, (mm_segment_t) addr_limit = 1
    (long int) state = 2,
    (void *) stack = 0xFFFFFFC5F4704000,
    (atomic_t) usage = ((int) counter = 2),
//...
    (char [16]) comm = "kworker/2:2",
    (struct nameidata *) nameidata = 0x0,
 
"kworker/2:2" 프로세스 콜스택은 다음과 같군요. 
-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)
-011|__rpm_callback(inline)
-011|rpm_callback(cb = 0xFFFFFF97D716DCE0, dev = 0xFFFFFFC62CFE6690)
-012|rpm_suspend(dev = 0xFFFFFFC62CFE6690, rpmflags = 10)
-013|rpm_idle(dev = 0xFFFFFFC62CFE6690, rpmflags = 2)
-014|spin_unlock_irq(inline)
-014|pm_runtime_work(work = 0xFFFFFFC62CFE67F8)
-015|__read_once_size(inline)
-015|static_key_count(inline)
-015|static_key_false(inline)
-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)
 
위 콜스택을 보면 process_one_work -> pm_runtime_work 흐름으로 워크가 실행된 후 
디바이스 드라이버에 등록된 suspend 콜백 함수를 호출합니다. 이후 flush_work 함수를 호출합니다. 
1 bool flush_work(struct work_struct *work)
2 {
3 struct wq_barrier barr;
4
5 lock_map_acquire(&work->lockdep_map);
6 lock_map_release(&work->lockdep_map);
7
8 if (start_flush_work(work, &barr)) {
9 wait_for_completion(&barr.done);
10 destroy_work_on_stack(&barr.work);
11 return true;
 
그런데 세번째 줄 코드에 다음과 같은 변수 선언문을 볼 수 있습니다. 이 코드는 뭘 의미할까요? 
3 struct wq_barrier barr;
 
이 구조체를 배리어 워크라고 합니다. 현재 워크(struct work_struct)가 워커 쓰레드에서 실행 중일 때,
flush_work 함수를 호출하면 지금 처리 중인 워크 실행을 마무리 할 수 있습니다. 참고하시고요.
 
이번에는 가장 중요한 코드 중 하나인 8번과 9번 줄 코드입니다. 
8 if (start_flush_work(work, &barr)) {
9 wait_for_completion(&barr.done);
 
해당 코드인 flush_work 함수를 9번줄 코드에서 wait_for_completion(&barr.done) 함수를 호출합니다. 
이 함수를 호출하면 complete(&barr.done) 가 실행될 때 까지 기다립니다.
static void wq_barrier_func(struct work_struct *work)
{
struct wq_barrier *barr = container_of(work, struct wq_barrier, work);
complete(&barr->done);
}
 
달리 설명드리면 배리어 워크가 워커 쓰레드에서 실행될 때 까지 기다리는 루틴입니다.
워크큐에서 상당히 많이 쓰는 배리어 워크는 다음 시간에 다룰 예정이니 기다려 주세요.
 
그럼 위 콜스택에서 &barr.done 정체가 뭔지 볼까요? 
-005|wait_for_completion(x = 0xFFFFFFC5F4707B30)
 
wait_for_completion 함수 선언부를 보면 해당 파라미터 x = 0xFFFFFFC5F4707B30 구조체는 struct completion입니다. 그래서 이 구조체로 디버깅 정보를 확인하면 다음과 같습니다. 
  (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 -> (
            (struct list_head *) next = 0xFFFFFFC5F4707A88,
 
struct completion->wait.task_list에 2개의 링크드 리스트가 보이는군요.
여기에 등록된 링크드 리스트는 struct __wait_queue.task_list에 등록된 링크드 리스트와 같습니다.
그래서 container_of(struct completion->wait.task_list.next,struct __wait_queue, task_list) 조건을 만족합니다.
(where)
struct __wait_queue {
unsigned int flags;
void *private;
wait_queue_func_t func;
struct list_head task_list;
};
 
typedef struct __wait_queue wait_queue_t;
 
이 조건에 따라 다음 명령어를 입력하겠습니다.
v.v %all container_of(0xFFFFFFC5F4707A88,struct __wait_queue,task_list)
v.v %all container_of(0xFFFFFFC5F4707B50,struct __wait_queue,task_list)
 
다음 정보를 태스크 디스크립터가 0xFFFFFFC541030080인 프로세스가 종료되기를 기다리고 있습니다.
v.v %h %t container_of(0xFFFFFFC5F4707A88,struct __wait_queue,task_list) 
 
  (struct __wait_queue *) container_of(0xFFFFFFC5F4707A88,struct __wait_queue,task_list) = 0xFFFFFFC
    (unsigned int) flags = 1 = 0x1 = '....',
    (void *) private = 0xFFFFFFC541030080  
    (wait_queue_func_t) func = 0xFFFFFF97D6AE571C = default_wake_function -> ,
    (struct list_head) task_list = ((struct list_head *) next = 0xFFFFFFC5F4707B50 
 
0xFFFFFFC541030080 태스크 디스크립터는 "kworker/2:2" 프로세스 것이고요. 문제는 다음 wait queue에 등록된 인스턴스 입니다. 0xFFFFFFC5F4707B50 주소를 눈여겨 보세요.
  (struct __wait_queue *) container_of(0xFFFFFFC5F4707B50,struct __wait_queue,task_list) = 0xFFFFFFC
    (unsigned int) flags = 65537 = 0x00010001 
    (void *) private = 0xFFFFFFC6FFFFFFFF  
    (wait_queue_func_t) func = 0xFFFFFFFFFFFFFFFF  
    (struct list_head) task_list = ((struct list_head *) next = 0xFFFFFFC5F4707A88 
 
확인해보니 안타깝게도 쓰레기 값이군요. 
(where)
  (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 -> (  //<<--
 
여기까지 디버깅 정보를 종합하면 8번 줄에 이미 wait_queue에 등록된 프로세스 때문에 0xFFFFFFC5F4707A88에 해당하는 wait queue가 처리되지 못하고 있습니다. 
1  (struct completion *) (struct completion *)0xFFFFFFC5F4707B30 = 0xFFFFFFC5F4707B30 -> (
2    (unsigned int) done = 0x0,
3    (wait_queue_head_t) wait = (
4      (spinlock_t) lock = (
5        (struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u16) owner = 0x1, (u16) next =
6      (struct list_head) task_list = (
7        (struct list_head *) next = 0xFFFFFFC5F4707A88 -> (
8          (struct list_head *) next = 0xFFFFFFC5F4707B50 -> (
 
여기까지 모은 디버깅 정보를 정리하면 다른 CPU 워커 풀에 있는 배리어 워크가 실행되지 않았습니다.
그래서 CPU2의 워커 풀이 Stuck 되어 워크큐 락업으로 감지된 거죠.
-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)
-011|__rpm_callback(inline)
-011|rpm_callback(cb = 0xFFFFFF97D716DCE0, dev = 0xFFFFFFC62CFE6690)
-012|rpm_suspend(dev = 0xFFFFFFC62CFE6690, rpmflags = 10)
-013|rpm_idle(dev = 0xFFFFFFC62CFE6690, rpmflags = 2)
-014|spin_unlock_irq(inline)
-014|pm_runtime_work(work = 0xFFFFFFC62CFE67F8)
-015|__read_once_size(inline)
-015|static_key_count(inline)
-015|static_key_false(inline)
-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)
 
이번에는 다른 워커 풀에서 Pending된 배리어 워크를 찾아야 합니다.
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
 
 
 
#커널 크래시 디버깅 및 TroubleShooting
 

커널 크래시가 발생했습니다. 우선 커널 크래시 발생 직전 커널 로그부터 천천히 볼까요?

1 [73669.590105 / 12-01 13:26:44.379][0] BUG: workqueue lockup - pool cpus=2 node=0 flags=0x1 nice=0 stuck for 115s!
2 [73669.592865 / 12-01 13:26:44.379][2] kernel BUG at home001/austindh.kim/src/kernel/workqueue.c:5381!
3 [73669.592905 / 12-01 13:26:44.379][2] Internal error: Oops - BUG: 0 [#1] PREEMPT SMP
4 [73669.592922 / 12-01 13:26:44.379][0] Modules linked in: texfat(PO) snd_soc_sdm845 
5 [73669.593061 / 12-01 13:26:44.379][2] CPU: 2 PID: 1416 Comm: lowi-server Tainted: P        W  O    4.9.60+ #1
6 [73669.593080 / 12-01 13:26:44.379][2] Hardware name: Qualcomm Technologies, Inc. SDM845 V2 MTP (DT)
7 [73669.593094 / 12-01 13:26:44.379][2] task: ffffffc5e9db5580 task.stack: ffffffc5e9d60000
8 [73669.593132 / 12-01 13:26:44.379][2] PC is at wq_watchdog_timer_fn+0x188/0x18c
9 [73669.593145 / 12-01 13:26:44.379][2] LR is at wq_watchdog_timer_fn+0x188/0x18c
 
첫 번째 줄 로그는 매우 중요한 정보를 담고 있는데요. workerpool(CPU2, node=0)에 등록된 워커 쓰레드가 115초 동안 실행되지 않았다고 알려줍니다.
workpool은 struct *worker_pool이란 자료 구조이며 각 CPU마다 node 2개를 갖고 있습니다. 
BUG: workqueue lockup - pool cpus=2 node=0 flags=0x1 nice=0 stuck for 115s!
 
이번에는 2번째와 8번째 줄 로그입니다.
2 [73669.592865 / 12-01 13:26:44.379][2] kernel BUG at home001/src/kernel/workqueue.c:5381!
8 [73669.593132 / 12-01 13:26:44.379][2] PC is at wq_watchdog_timer_fn+0x188/0x18c
 
이제 BUG가 실행된 코드를 분석해야 할 시간입니다. 왜냐면 정확히 커널 크래시가 발생한 원인을 알기 위해서죠.
 
그럼 wq_watchdog_timer_fn 함수를 분석해볼까요? 
분석하기 전에 커널 크래시 발생 전 아주 유익한 힌트를 이미 커널 로그가 말해 줬습니다. 
CPU2에 해당 워커풀에서 타임 아웃이 발생했다는 점입니다. 이 점을 유념하면서 함수 리뷰를 해야 겠습니다.
1 static void wq_watchdog_timer_fn(unsigned long data)
2 {
3 unsigned long thresh = READ_ONCE(wq_watchdog_thresh) * HZ;
4 bool lockup_detected = false;
5 struct worker_pool *pool;
6 int pi;
7
8 if (!thresh)
9 return;
10
11 rcu_read_lock();
12
13 for_each_pool(pool, pi) {
14 unsigned long pool_ts, touched, ts;
15
16 if (list_empty(&pool->worklist))
17 continue;
18
19 /* get the latest of pool and touched timestamps */
20 pool_ts = READ_ONCE(pool->watchdog_ts);
21 touched = READ_ONCE(wq_watchdog_touched);
22
23 if (time_after(pool_ts, touched))
24 ts = pool_ts;
25 else
26 ts = touched;
27
28 if (pool->cpu >= 0) {
29 unsigned long cpu_touched =
30 READ_ONCE(per_cpu(wq_watchdog_touched_cpu,
31   pool->cpu));
32 if (time_after(cpu_touched, ts))
33 ts = cpu_touched;
34 }
35
36 /* did we stall? */
37 if (time_after(jiffies, ts + thresh)) {
38 lockup_detected = true;
39 pr_emerg("BUG: workqueue lockup - pool");
40 pr_cont_pool_info(pool);
41 pr_cont(" stuck for %us!\n",
42 jiffies_to_msecs(jiffies - pool_ts) / 1000);
43 }
44 }
45
46 rcu_read_unlock();
47
48 if (lockup_detected) {
49 show_workqueue_state();
50 BUG();
51 }
 
13번째와 14번째 줄 코드부터 봐야 겠습니다. for_each_pool는 각 워커풀 갯수만큼 접근하는 for loop입니다.
13 for_each_pool(pool, pi) {
14 unsigned long pool_ts, touched, ts;
 
커널 로그에서 CPU2에 워커풀에 문제가 있다고 했으니 CPU2에 해당하는 워커풀을 봐야 겠습니다.
그럼 코어 덤프에서 CPU2에 해당하는 워커풀은 어떻게 가져올까요?
 
for_each_pool 매크로를 보면 worker_pool_idr이란 IDR변수에서 워커풀을 가져옴을 알 수 있습니다.
#define for_each_pool(pool, pi) \
idr_for_each_entry(&worker_pool_idr, pool, pi) \
if (({ assert_rcu_or_pool_mutex(); false; })) { } \
else
 
worker_pool_idr 전역 변수에 접근하면 (*(worker_pool_idr.top)).ary[4]에 CPU2에 대한 워커풀 인스턴스가 있네요.
  (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,
        [0x7] = 0xFFFFFFC63A350400,
        [0x8] = 0xFFFFFFC63A367000,
        [0x9] = 0xFFFFFFC63A367400,
        [0x0A] = 0xFFFFFFC63A37E000,
        [0x0B] = 0xFFFFFFC63A37E400,
        [0x0C] = 0xFFFFFFC63A395000,
 
0xFFFFFFC63A339000 주소를 (struct worker_pool *) 구조체로 캐스팅하니 다음과 같은 멤버 변수를 볼 수 있습니다.
1  (struct worker_pool *) (struct worker_pool*)0xFFFFFFC63A339000 = 0xFFFFFFC63A339000 -> (
2    (spinlock_t) lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u16) owner =
3    (int) cpu = 2 = 0x2,
4    (int) node = 0 = 0x0,
5    (int) id = 4 = 0x4,
6    (unsigned int) flags = 1 = 0x1,
7    (long unsigned int) watchdog_ts = 4302292746 = 0x00000001006FC70A,  //<<--
8    (struct list_head) worklist = (
9      (struct list_head *) next = 0xFFFFFFC62B7DB6E8,
10      (struct list_head *) prev = 0xFFFFFF97D9308360),
11    (int) nr_workers = 3 = 0x3,
12    (int) nr_idle = 0 = 0x0,
13    (struct list_head) idle_list = ((struct list_head *) next = 0xFFFFFFC63A339048, (struct list_hea
14    (struct timer_list) idle_timer = ((struct hlist_node) entry = ((struct hlist_node *) next = 0xDE
15    (struct timer_list) mayday_timer = ((struct hlist_node) entry = ((struct hlist_node *) next = 0x
16    (struct hlist_head [64]) busy_hash = ([0] = ((struct hlist_node *) first = 0x0), [1] = ((struct
17    (struct worker *) manager = 0xFFFFFFC50C460C80,
18    (struct mutex) attach_mutex = ((atomic_t) count = ((int) counter = 1 = 0x1), (spinlock_t) wait_l
19    (struct list_head) workers = (
20      (struct list_head *) next = 0xFFFFFFC4DE83A7D0,
21      (struct list_head *) prev = 0xFFFFFFC4E26A30D0),
22    (struct completion *) detach_completion = 0x0,
 
위에서 3번째, 4번째 그리고 6번째 멤버를 보면 cpu2에 대한 워커풀에 node가 0이고 flags가 1이란 점을 알 수 있습니다. 
3    (int) cpu = 2 = 0x2,
4    (int) node = 0 = 0x0,
6    (unsigned int) flags = 1 = 0x1,
 
커널 크래시 발생 전 로그와 일치하죠.
BUG: workqueue lockup - pool cpus=2 node=0 flags=0x1 nice=0 stuck for 115s!
 
다음은 워크큐 락업을 감지하는 37번째부터 42번째 코드를 봐야 할 차례입니다.
이 부분이 커널 크래시가 발생한 이유를 말해주는 핵심 코드라 봐야 합니다.
37 if (time_after(jiffies, ts + thresh)) {
38 lockup_detected = true;
39 pr_emerg("BUG: workqueue lockup - pool");
40 pr_cont_pool_info(pool);
41 pr_cont(" stuck for %us!\n",
42 jiffies_to_msecs(jiffies - pool_ts) / 1000);
43 }
 
그런데 코드에서 시간을 처리하는 코드가 눈이 띄는데요. 이를 분석하려면 우선 이 시스템이 구동되고 있는 조건에 대해서 잠시 살펴봐야 하는데요.
1. HZ
HZ은 CONFIG_HZ이 100이므로 100입니다. HZ이 100이란 의미는 1초에 jiffies가 100번 씩 증분된다고 봐야겠죠.
 
2. jiffies
이 시스템은 ARM64 아키텍처입니다. 그래서 jiffies 값은 전처리 파일로 보면 jiffies_64로 대응합니다..
 
이제 커널 코드와 디버깅 정보를 함께 볼 시간입니다..
37 if (time_after(jiffies, ts + thresh)) {
 
time_after이란 매크로가 등장했는데요. 함수 이름만 봐도 주눅이 드는 것 같군요.
리눅스 커널의 아주 난해한 time을 처리하는 함수로 보이지만, 아주 간단한 매크로입니다.
 
time_after은 다음 조건을 만족하면 true를 리턴하는 함수입니다.
jiffies > (ts + thresh)
 
그럼 jiffies 값을 알아 봐야 겠습니다. jiffies_64 변수를 확인하니 4302304310이군요. 
jiffies_64 = 4302304310
 
그럼 (ts + thresh)이 결괏값이 jiffies 4302304310 값 보다 작았군요. 그래야 if문 내 코드가 실행되어
다음 커널 로그를 출력할 수 있잖아요.
BUG: workqueue lockup - pool cpus=2 node=0 flags=0x1 nice=0 stuck for 115s!
 
그럼 ts값을 알아봐야 겠습니다. 다음 코드를 잠깐 보면 ts는 pool->watchdog_ts 멤버 변수 값이란 걸 알 수 있습니다. 
20 pool_ts = READ_ONCE(pool->watchdog_ts);
21 touched = READ_ONCE(wq_watchdog_touched);
22
23 if (time_after(pool_ts, touched))
24 ts = pool_ts;
25 else
26 ts = touched;
 
watchdog_ts는 struct worker_pool 구조체의 멤버 중 하나입니다. 
그럼 잠깐 이 변수의 의미를 알아볼게요.
 
디바이스 드라이버에서 워크(strut work_struct)을 큐잉할 때와 워커 쓰레드가 실행되어
워크가 실행될 때 struct worker_pool.watchdog_ts 멤버에 그 당시 시간 정보인 jiffies값을 저장합니다. 워커풀이 가장 마지막에 실행된 시간 정보를 담고 있다고 봐야죠. 
해당 함수는 __queue_work와 worker_thread이니 시간되면 코드를 한번 열어보세요.
 
그럼 코어 덤프에서 해당 멤버 변수를 확인하니 4302292746입니다. 
  (struct worker_pool *) (struct worker_pool*)0xFFFFFFC63A339000 = 0xFFFFFFC63A339000 -> (
    (spinlock_t) lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u16) owner =
    (int) cpu = 2,
    (int) node = 0,
    (int) id = 4,
    (unsigned int) flags = 1,
    (long unsigned int) watchdog_ts = 4302292746,
    (struct list_head) worklist = ((struct list_head *) next = 0xFFFFFFC62B7DB6E8, (struct list_head
 
여기까지 다음 37번째 줄 코드에서 jiffies와 ts 값을 확인했으니, thresh 변수를 알아볼 차례입니다.
37 if (time_after(jiffies, ts + thresh)) {
38 lockup_detected = true; 
 
thresh 변수는 지역 변수로 선언됐는데, 다음 3번째 줄 코드와 같이 선언됐습니다.
3 unsigned long thresh = READ_ONCE(wq_watchdog_thresh) * HZ;
4 bool lockup_detected = false;
 
확인해보니 코어 덤프에서는 wq_watchdog_thresh이 60입니다. 
wq_watchdog_thresh = 60
 
그럼 다음 계산식으로 thresh는 6000이라는 걸 알 수 있습니다.
6000 = 60 * 100 = wq_watchdog_thresh * HZ
 
여기서 wq_watchdog_thresh * HZ 코드가 뭘 의미하는지 생각해볼까요?
HZ이 100이면 1초에 jiffies가 100번 증분된다고 알고 있습니다. 그런데 여기에 60을 곱하고 있어요.
 
thresh는 1분 동안의 jiffies 값이라고 할 수 있습니다. 
허벌라게 어렵죠? 이렇게 커널 크래시를 제대로 분석하려면 리눅스 커널 전반에 대해 깊히 알아야 합니다.      
 
이제 이제까지 진행했던 커널 함수 코드 리뷰로 돌아갈께요.
37 if (time_after(jiffies, ts + thresh)) {
38 lockup_detected = true;
39 pr_emerg("BUG: workqueue lockup - pool");
40 pr_cont_pool_info(pool);
41 pr_cont(" stuck for %us!\n",
42 jiffies_to_msecs(jiffies - pool_ts) / 1000);
43 }
 
그럼 그 동안 모은 디버깅 정보로 jiffies > (ts + thresh) 조건을 만족하는군요. 그래서 if문이 실행된 것 겠죠.
4302304310(jiffies) > 4302298746(ts + thresh = 4302292746 + 6000)
 
(where: 디버깅 정보)
jiffies = 4302304310
ts = 4302292746 = struct worker_pool.watchdog_ts
thresh = 6000 = 60 * 100 = wq_watchdog_thresh * HZ
 
다음 코드를 볼게요. "stuck for %us!"란 에러 메시지를 커널 로그로 출력합니다.
41 pr_cont(" stuck for %us!\n",
42 jiffies_to_msecs(jiffies - pool_ts) / 1000);
 
그 동안 반복했던 아래 커널 로그에 대응합니다. 115s 동안 stuck됐다는 군요.
workqueue lockup - pool cpus=2 node=0 flags=0x1 nice=0 stuck for 115s!   
 
그럼 115초가 어떻게 계산됐는지 알아볼게요. 115초는 아래 jiffies_to_msecs 함수를 실행해서 얻은 결괏값인데요.
41 pr_cont(" stuck for %us!\n",
42 jiffies_to_msecs(jiffies - pool_ts) / 1000);
 
jiffies_to_msecs 함수는 jiffies값을 밀리초로 변환합니다. 여기서 jiffies, pool_ts값은 다음과 같죠.
jiffies = 4302304310
pool_ts = 4302292746
 
이 값을 밀리초 단위로 계산하면 어떤 값일까요? 결과는 다음과 같습니다.
jiffies(밀리초) = 73370140
pool_ts(밀리초) = 73254500
 
밀리초로 변환한 값을 (jiffies - pool_ts) 식으로 계산하니 정말 115초가 나오는군요.
115640 = 73370140 - 73254500 = jiffies(밀리초) - pool_ts(밀리초)
 
그럼 여기까지 모든 디버깅 정보를 모아 이 문제가 왜 발생했는지 정리해볼게요.
아래는 워크(struct work_struct)을 처리하는 과정입니다.
 
1. 워크(&host->work, struct work_struct 타입)을 해당 워크큐에 큐잉합니다.
2. schedule_work -> queue_work -> queue_work_on -> __queue_work 순서 함수 호출
3. schedule_work() 함수가 실행된 CPU번호에 대한 워커풀을 찾아서, pool->watchdog_ts에 jiffies을 업데이트
   즉, __queue_work 함수를 통해 해당 워커풀에 접근했을 때 시간 정보를 저장
   이후 pool->worklist에 &host->work을 등록함 
4. 워커풀에 등록된 워커 쓰레드를 깨움
5. 워커 쓰레드가 깨어나 실행할 때 worker_thread 함수에서 pool->watchdog_ts에 jiffies 즉 시간 정보 업데이트
6. 등록된 워크(pool->worklist)를 실행 
7. wq_watchdog_timer_fn 함수에서 워크 큐 락업을 감지하여 커널 크래시를 유발합니다.
  즉, 위 schedule_work -> queue_work -> queue_work_on 함수 흐름으로 워크를 등록했는데, 
  해당 워커 쓰레드가 1분 동안 실행되지 않았는지 점검한다는 의미죠. 즉 4/5/6 번 동작에 문제가 있어 제대로 실행안된 것입니다.
  자 여기서, thresh가 1분을 의미한다고 했죠? 60초 동안 워커풀이 실행됐는지 점검하는 thresh hold라고 봐야 합니다.
 
sdmmc_request 코드를 예를 들까요?  워크를 큐잉할 때 schedule_work 란 함수를 호출합니다. schedule() 함수에 전달하는 &host->work 변수의 구조체는 struct work_struct임을 기억하세요. 
static void sdmmc_request(struct mmc_host *mmc, struct mmc_request *mrq)
{
struct realtek_pci_sdmmc *host = mmc_priv(mmc);
struct mmc_data *data = mrq->data;
 
mutex_lock(&host->host_mutex);
host->mrq = mrq;
mutex_unlock(&host->host_mutex);
 
if (sd_rw_cmd(mrq->cmd) || sdio_extblock_cmd(mrq->cmd, data))
host->using_cookie = sd_pre_dma_transfer(host, data, false);
 
schedule_work(&host->work);
}
 
여기까지 1차로 워크큐 락업으로 커널 크래시가 발생한 원인을 알아 봤습니다. 그럼 다음 시간에는 조금 더 구체적으로 왜 커널 크래시가 발생했는지 분석을 해야 겠죠? 다음 세미나 시간을 기대해주세요.
 
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
#커널 크래시 디버깅 및 TroubleShooting
CPU: 3 PID: 435 Comm: kworker/u17:2 프로세스에서 dm-verity를 처리하는 워크 함수 verity_prefetch_io 서브 루틴에서 커널 데이터 어보트가 발생했습니다.
-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)
-001|__dabt_svc(asm)
 -->|exception
-002|ttwu_activate(inline)
-002|ttwu_do_activate.constprop.52(rq = 0xEB95AB80, p = 0xFFFFF69B)
-003|ttwu_queue(inline)
-003|try_to_wake_up(p = 0xEB95AB80, ?, wake_flags = -237815936)
-004|arch_spin_unlock(inline)
-004|__mutex_unlock_common_slowpath(inline)
-004|__mutex_unlock_slowpath(lock_count = 0xEB5BCB40)
-005|dm_bufio_prefetch(c = 0xEB5BCB40, block = 903261, ?)
-006|verity_prefetch_io(work = 0xF1D33780)
-007|static_key_count(inline)
-007|static_key_false(inline)
-007|trace_workqueue_execute_end(inline)
-007|process_one_work(worker = 0xEB063500, work = 0xD36AF980)
-008|worker_thread(__worker = 0xF1D33780)
-009|kthread(_create = 0xEB06EEC0)
-010|ret_from_fork(asm)
-011|ret_fast_syscall(asm)
 
dm_bufio_prefetch 코드에서 mutex_unlock하는 동작 중 struct mutex.wait_list에 등록된 프로세스를 깨우는 동작이었습니다.
해당 mutex는 아래 변수이며, struct mutex.wait_list에 가장 먼저 등록한 struct mutex.wait_list.next 프로세스를 깨웁니다.
  (struct mutex *) (struct mutex*)0xEB5BCB40 = 0xEB5BCB40 = __key+0x295D6EA4 -> (
    (atomic_t) count = ((int) counter = 1 = 0x1 = '....'),
    (spinlock_t) wait_lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u32) slo
    (struct list_head) wait_list = (
      (struct list_head *) next = 0xE9F91D78  //<<--
        (struct list_head *) next = 0xE90ADD78
          (struct list_head *) next = 0xEAFFFE08
            (struct list_head *) next = 0xE5FD5E18
              (struct list_head *) next = 0xE90F7D78
 
struct mutex.wait_list.next 프로세스의 정체는 struct task_struct 가 0xEB95AB80 인 "kworker/u17:4" 프로세스입니다.
v.v %t %h %s container_of(0xE9F91D78,struct mutex,wait_list)
  (struct mutex *) container_of(0xE9F91D78,struct mutex,wait_list) = 0xE9F91D64 -> (
    (atomic_t) count = ((int) counter = 0xEB5BCB54),
    (spinlock_t) wait_lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u32) slo
    (struct list_head) wait_list = ((struct list_head *) next = 0xE90ADD78, (struct list_head *) pre
    (struct task_struct *) owner = 0xEB95AB80 -> ( //<<--
      (long int) state = 0x0100,
      (void *) stack = 0xE9F90000,
      (atomic_t) usage = ((int) counter = 0x2),
// .. 생략 ..
      (struct cred *) cred = 0xEB063C00,
      (char [16]) comm = "kworker/u17:4",
 
"kworker/u17:4" 프로세스의 콜스택을 보면 역시 뮤텍스락을 얻기 위해 휴면에 진입한 상태였습니다.
v.f /task 0xEB95AB80 
 
-000|context_switch(inline)
-000|__schedule()
-001|schedule_preempt_disabled()
-002|__mutex_lock_common(inline)
-002|__mutex_lock_slowpath(lock_count = 0xEB5BCB40)
-003|current_thread_info(inline)
-003|mutex_set_owner(inline)
-003|mutex_lock(lock = 0xEB5BCB40)
-004|new_read(c = 0xEB5BCB40, block = 903235, nf = NF_READ, bp = 0xE9F91E1C)
-005|dm_bufio_read(?, ?, ?)
-006|verity_verify_level(v = 0xEB140400, io = 0xE9ED5A00, ?, ?, skip_unverified = FALSE, want_digest = 0x
-007|verity_hash_for_block(v = 0xEB140400, io = 0xE9ED5A00, block = 847125, digest = 0xE9ED5B10, is_zero
-008|verity_verify_io(inline)
-008|verity_work(w = 0x0)
-009|static_key_count(inline)
-009|static_key_false(inline)
-009|trace_workqueue_execute_end(inline)
-009|process_one_work(worker = 0xEB1F2A80, work = 0xE9ED5A38)
-010|worker_thread(__worker = 0x0)
-011|kthread(_create = 0xEB7D7E00)
-012|ret_from_fork(asm)
-013|ret_fast_syscall(asm)
 
다음 5줄 어셈블리 코드에서 데이터 어보트가 발생했는데, 이유는 R4가 0xFFFFF69B란 값을 담고 있었기 때문입니다.
MMU가 0xFFFFF69B란 가상 메모리를 처리하지 못해 ARM이 데이터 어보트를 유발한 것입니다.
1______addr/line|code_____|label____|mnemonic________________|comment
2   NSR:C014E914|158034D0            strne   r3,[r0,#0x4D0]
3   NSR:C014E918|EBFFFECB            bl      0xC014E44C       ; activate_task
4   NSR:C014E91C|E3A03001            mov     r3,#0x1          ; r3,#1
5___NSR:C014E920|E584302C____________str_____r3,[r4,#0x2C]
 
그럼 "str_____r3,r4,#0x2C" 이 어셈블리 코드의 정체는 뭘까요? struct task_struct 자료구조에서 on_rq에 멤버에 접근하는 코드입니다.
  (int) offsetof(struct task_struct,on_rq) = 44 = 0x2C = '...,'
 
이렇게 암흑의 어셈블리 코드 세상에서 벗어나 C 코드로 이동해보면 아래 4785 줄 에서 데이터 어보트가 발생했음을 알 수 있습니다.
4782static inline void ttwu_activate(struct rq *rq, struct task_struct *p, int en_flags)
4783{
4784 activate_task(rq, p, en_flags);
4785 p->on_rq = TASK_ON_RQ_QUEUED;
4786
4787 /* if a worker is waking up, notify workqueue */
4788 if (p->flags & PF_WQ_WORKER)
4789 wq_worker_waking_up(p, cpu_of(rq));
4790}
 
ttwu_activate 함수를 눈 여겨 보면 두 번째 파라미터가 struct task_struct *p이고 이 파라미터가 0xFFFFF69B란 주소를 담고 있는게 문제입니다.
다음 5줄 어셈블리 코드에서 데이터 어보트가 발생했는데, 이유는 R4가 0xFFFFF69B란 값을 담고 있었기 때문입니다.
MMU가 0xFFFFF69B란 가상 메모리를 처리하지 못해 ARM이 데이터 어보트를 유발한 것입니다.
1______addr/line|code_____|label____|mnemonic________________|comment
2   NSR:C014E914|158034D0            strne   r3,[r0,#0x4D0]
3   NSR:C014E918|EBFFFECB            bl      0xC014E44C       ; activate_task
4   NSR:C014E91C|E3A03001            mov     r3,#0x1          ; r3,#1
5___NSR:C014E920|E584302C____________str_____r3,[r4,#0x2C]
 
그럼 ttwu_activate 함수는 어느 함수가 호출했을까요?
 
코드를 조금 살펴보면 아래 4981줄에서 호출했음을 알 수 있습니다.
두번 째 파라미터로 전달하고 있으니 어셈블리 코드로 보면 R1으로 전달하겠죠.
4968static void ttwu_queue(struct task_struct *p, int cpu)
4969{
4970 struct rq *rq = cpu_rq(cpu);
4971
4972#if defined(CONFIG_SMP)
4973 if (sched_feat(TTWU_QUEUE) && !cpus_share_cache(smp_processor_id(), cpu)) {
4974 sched_clock_cpu(cpu); /* sync clocks x-cpu */
4975 ttwu_queue_remote(p, cpu);
4976 return;
4977 }
4978#endif
4979
4980 raw_spin_lock(&rq->lock);
4981 ttwu_do_activate(rq, p, 0);  //<<--
4982 raw_spin_unlock(&rq->lock);
4983}
 
예상했다 싶히, R10에서 R1으로 struct task_struct *p 값을 전달하네요. 
그럼 Trace32 프로그램에서는 R10이 0xEB95AB80 주소를 담고 있습니다.
1   NSR:C015597C|E1A00008            cpy     r0,r8
2   NSR:C0155980|EB3ADE16            bl      0xC100D1E0       ; _raw_spin_lock
3   NSR:C0155984|E1A00008            cpy     r0,r8
4   NSR:C0155988|E1A0100A            cpy     r1,r10           ; r1,p
5   NSR:C015598C|EBFFE3D7            bl      0xC014E8F0       ; ttwu_do_activate.constprop.52
 
0xEB95AB80 주소를 struct task_struct 구조체로 캐스팅해볼까요?
아래 명령어로 확인해보니 정말 태스크 디스크립터는 정상 멤버 값들을 담고 있군요.
  (struct task_struct*)0xEB95AB80 = 0xEB95AB80 -> (
    state = 256 = 0x0100,
    stack = 0xE9F90000,
    usage = (counter = 2 = 0x2),
    flags = 69238880 = 0x04208060,
// .. 생략..
    real_cred = 0xEB063C00,
    cred = 0xEB063C00,
    comm = "kworker/u17:4",
    link_count = 0 = 0x0,
 
아까 뮤텍스락 디버깅을 했었죠? 그 때 정보를 되살려 보면
0xEB95AB80 struct task_struct 구조체 주소는 뮤텍스락 wait_list.next에 등록된 프로세스의 태스크 디스크립터입니다.
v.v %t %h %s container_of(0xE9F91D78,struct mutex,wait_list)
  (struct mutex *) container_of(0xE9F91D78,struct mutex,wait_list) = 0xE9F91D64 -> (
    (atomic_t) count = ((int) counter = 0xEB5BCB54),
    (spinlock_t) wait_lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) raw_lock = ((u32) slo
    (struct list_head) wait_list = ((struct list_head *) next = 0xE90ADD78, (struct list_head *) pre
    (struct task_struct *) owner = 0xEB95AB80 -> ( //<<--
      (long int) state = 0x0100,
      (void *) stack = 0xE9F90000,
 
다시 원래 했던 디버깅 흐름으로 돌아와서.
그럼 두 번째 파라미터 전달했던 struct task_struct *p에 해당하는 0xEB95AB80 주소가 0xFFFFF69B 주소로 왜 갑자기 바뀌었을까요?
 
아래 5번 째 줄 코드에서 ttwu_do_activate 함수를 호출하기 직전 스택 주소는 0xEAD9DDE0이고.
1   NSR:C015597C|E1A00008            cpy     r0,r8
2   NSR:C0155980|EB3ADE16            bl      0xC100D1E0       ; _raw_spin_lock
3   NSR:C0155984|E1A00008            cpy     r0,r8
4   NSR:C0155988|E1A0100A            cpy     r1,r10           ; r1,p
5   NSR:C015598C|EBFFE3D7            bl      0xC014E8F0       ; ttwu_do_activate.constprop.52
 
ttwu_do_activate 함수의 어셈블리 코드를 보면 아래와 같이 r4, r5, r11, r14을 스택에 푸쉬합니다.
NSR:C014E8F0|E92D4830  ttwu_do_activate.constprop.52:  push    {r4-r5,r11,r14}
 
아래 스택 주소 0xEAD9DDE0 근처 메모리 덤프를 보면 7번, 8번, 9번 줄의 메모리 덤프와 같이 스택에 레지스터 값을 저장합니다. 그런데 5번 째 줄을 보면 R10이 0x0입니다. 원래 0xEB95AB80 이어야 하는데요.
1   NSD:EAD9DDC4| FF FF FF FF  0xFFFFFFFF         \\vmlinux\mdss_mdp_pipe\mdss_mdp_pipe_assign\__out
2   NSD:EAD9DDC8| 51 00 00 00  0x51               \\vmlinux\sch_mqprio\__exitcall_mqprio_module_exit+0x1
3   NSD:EAD9DDCC| 1C E9 14 C0  0xC014E91C         \\vmlinux\sched/core\ttwu_do_activate.constprop.52+0x2C
4   NSD:EAD9DDD0| 07 00 00 00  0x7                \\vmlinux\aesbs-glue\__exitcall_aesbs_mod_exit+0x3
5   NSD:EAD9DDD4| 00 00 00 00  0x0                // <<-- R10
6   NSD:EAD9DDD8| 3C DE D9 EA  0xEAD9DE3C   // <<-- R11
7   NSD:EAD9DDDC| 90 59 15 C0 0xC0155990 \\vmlinux\sched/core\try_to_wake_up+0x394 //<<-- R14
8   NSD:EAD9DDE0| 40 2B A8 5F  0x5FA82B40
 
결국 아래 코드에서 스택 푸쉬를 이상하게 해서 발생한 문제로 보입니다.
NSR:C014E8F0|E92D4830  ttwu_do_activate.constprop.52:  push    {r4-r5,r11,r14}
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
#커널 크래시 디버깅 및 TroubleShooting
 
커널 패닉 시 아래 콜 스택이 남아 있습니다.
[39136682.663247]  <IRQ>  [<ffffffff816351f1>] dump_stack+0x19/0x1b
[39136682.663626]  [<ffffffff8162ea6c>] panic+0xd8/0x1e7
[39136682.663988]  [<ffffffff8158bd35>] ? tcp_v4_rcv+0x635/0x9f0
[39136682.664361]  [<ffffffff8107b00b>] __stack_chk_fail+0x1b/0x20
[39136682.664743]  [<ffffffff8158bd35>] tcp_v4_rcv+0x635/0x9f0
[39136682.665131]  [<ffffffff8163d0ed>] common_interrupt+0x6d/0x6d
[39136682.665529]  <EOI>  [<ffffffff81645a2b>] ? sysret_audit+0x17/0x21
 
위 콜 스택을 보면 여러가지 의문이 생기는데요.
1> tcp_v4_rcv이 인터럽트 핸들러로 호출되는 것 처럼 보이는데, 다른 인터럽트 핸들러도 위와 같은 콜 스택이 확인되나요?
    다른 인터럽트 핸들러가 호출될 때와 다른 콜스택이면 스택 Corruption을 의심할 수 있습니다.
    
2> 커널 패닉이 발생했을 때 RSP 즉 스택 주소(00002aaec5008b98)가 이상합니다. 
커널 프로세스의 스택 주소는 struct task_struct->stack -- (struct task_struct->stack)+0x4000 사이이어야 합니다.
crash> bt
PID: 168037 TASK: ffff880494923980 CPU: 26 COMMAND: "app01"
#0 [ffff88046f3a3db8] machine_kexec at ffffffff81051beb
#1 [ffff88046f3a3e18] crash_kexec at ffffffff810f2542
#2 [ffff88046f3a3ee8] panic at ffffffff8162ea73
#3 [ffff88046f3a3f68] __stack_chk_fail at ffffffff8107b00b
#4 [ffff88046f3a3f78] tcp_v4_rcv at ffffffff8158bd35
--- <IRQ stack> ---
#5 [ffff880217dbbf58] ret_from_intr at ffffffff8163d0ed
RIP: 00002aae21629848 RSP: 00002aaec5008b98 RFLAGS: 00000202
RAX: 00002aaf8c0394c0 RBX: ffffffff81645a2b RCX: 0000000000038400
RDX: 0000000000038180 RSI: 00002aaf68157390 RDI: 00002aaf8c0716c0
RBP: 00002aaec5009180 R8: 00002aaf8c0718b0 R9: 0000000000000000
R10: 0000000000000002 R11: 00002aae21657160 R12: 0000000000000000
R13: 00002aaec500a700 R14: 00002aaec500a9c0 R15: 0000000000000000
ORIG_RAX: ffffffffffffffca CS: 0033 SS: 002b
 
아래 명령어로 스택 주소를 확인해보세요.
struct task_struct.stack ffff880494923980
 
예)
crash64> struct task_struct.stack ffffffc001580e40
  stack = 0xffffffc001574000 <init_thread_union>
 
3> 만약 2>에서 언급된 것과 같이 스택이 꺠져 있다면, 아래 방법으로 tcp_v4_rcv 함수 내에서 호출되는 함수 전 후로 로그를 확인해도 좋을 것 같습니다. 
 
4> 커널 Makefile을 보면 -fstack-protector 옵션이 켜져 있을 때 스택 카나리 코드가 추가됩니다. 아래 옵션을 한 번 끄고 어떤 동작을 하는 지 점검해도 좋을 것 같습니다.
 ifdef CONFIG_CC_STACKPROTECTOR_REGULAR
   stackp-flag := -fstack-protector
   ifeq ($(call cc-option, $(stackp-flag)),)
     $(warning Cannot use CONFIG_CC_STACKPROTECTOR_REGULAR: \
              -fstack-protector not supported by compiler)
   endif
 else
 ifdef CONFIG_CC_STACKPROTECTOR_STRONG
   stackp-flag := -fstack-protector-strong
   ifeq ($(call cc-option, $(stackp-flag)),)
     $(warning Cannot use CONFIG_CC_STACKPROTECTOR_STRONG: \
               -fstack-protector-strong not supported by compiler)
   endif
 else
   # Force off for distro compilers that enable stack protector by default.
   stackp-flag := $(call cc-option, -fno-stack-protector)
 
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
#커널 크래시 디버깅 및 TroubleShooting
 
CPU3에서 실행 중인 "Binder:15701_2" 프로세스가 데이터 어보트로 커널 크래시가 발생했습니다.
커널 로그가 데이터 어보트 발생 시 어떤 동작을 했는지 레지스터 정보와 함께 알려주네요. 
[69350.929482] <26>Unable to handle kernel paging request at virtual address 11ad4e80
[69350.929511] <26>pgd = d57f0000
[69350.929527] <22>[11ad4e80] *pgd=00000000
[69350.929548] <6>Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[69350.929563] <c2>Modules linked in: texfat(PO)
[69350.929590] <c6>CPU: 5 PID: 15728 Comm: Binder:15701_2 Tainted: P        W  O   3.18.71-ge77ee2f-00001-g0988851 #1
[69350.929608] <c6>task: d2fb2b80 ti: ce4f8000 task.ti: ce4f8000
[69350.929635] <c2>PC is at cpuacct_charge+0x30/0x58
[69350.929653] <c2>LR is at cpuacct_charge+0x1c/0x58
[69350.929671] <c2>pc : [<c01709a4>]    lr : [<c0170990>]    psr: 20070193
                   sp : ce4f9cb8  ip : 03bd1201  fp : ce4f9d9c
[69350.929695] <c2>r10: d2fb2b80  r9 : 000068cc  r8 : 00000005
[69350.929711] <c2>r7 : 00000000  r6 : 0016a175  r5 : e6188290  r4 : d2fb2b80
[69350.929727] <c2>r3 : e17bbe80  r2 : 30319000  r1 : e97bbe80  r0 : c1a0e538
[69350.929744] <c2>Flags: nzCv  IRQs off  FIQs on  Mode SVC_32  ISA ARM  Segment none
[69350.929760] <c2>Control: 10c0383d  Table: 957f006a  DAC: 00000051
[69350.929776] <6>Process Binder:15701_2 (pid: 15728, stack limit = 0xce4f8210)
 
크래시 유틸리티 프로그램으로 콜스택을 잡아 봤습니다. 아래와 같이 이쁘게 콜스택이 출력되네요.
함수 흐름을 살펴보면 IRQ가 Trigger된 후 current_thread_info의 preempt_count가 0이라 스케쥴링이 되었습니다.
svc_preempt -> preempt_schedule_irq -> __schedule
crash> bt -I C01709A4 -S  CE4F9CB8 d2fb2b80
PID: 15728  TASK: d2fb2b80  CPU: 5   COMMAND: "Binder:15701_2"
bt: WARNING:  stack address:0xce4f9da8, program counter:0xc0ff4658
 #0 [<c01709a4>] (cpuacct_charge) from [<c01592a8>]
 #1 [<c01592a8>] (update_curr) from [<c015c00c>]
 #2 [<c015c00c>] (put_prev_entity) from [<c015c61c>]
 #3 [<c015c61c>] (put_prev_task_fair) from [<c0167a14>]
 #4 [<c0167a14>] (pick_next_task_rt) from [<c0ff4364>]
 #5 [<c0ff4364>] (__schedule) from [<c0ff4e2c>]
 #6 [<c0ff4e2c>] (preempt_schedule_irq) from [<c0ff97d8>]
 #7 [<c0ff97d8>] (svc_preempt) from [<c039b9dc>]
 #8 [<c039b9e0>] (blk_flush_plug_list) from [<c039bd88>]
 #9 [<c039bd88>] (blk_finish_plug) from [<c02d3c44>]
#10 [<c02d3c44>] (ext4_writepages) from [<c01f0218>]
#11 [<c01f0218>] (__filemap_fdatawrite_range) from [<c01f0318>]
#12 [<c01f0318>] (filemap_write_and_wait_range) from [<c02caa4c>]
#13 [<c02caa4c>] (ext4_sync_file) from [<c0267980>]
#14 [<c0267980>] (vfs_fsync) from [<c0267a68>]
#15 [<c0267a68>] (do_fsync) from [<c0106a00>]
    pc : [<b1d5a520>]    lr : [<b0cb491b>]    psr: 80070010
    sp : a51a5cc0  ip : 00000000  fp : 00000000
    r10: 00000006  r9 : b001e400  r8 : 00000200
    r7 : 00000094  r6 : 00000000  r5 : 00000000  r4 : b001e5b8
    r3 : 00000000  r2 : b0cb4905  r1 : 00000002  r0 : 00000033
    Flags: Nzcv  IRQs on  FIQs on  Mode USER_32  ISA ARM
 
Trace32로 콜스택을 잡으면 더 직관적으로 디버깅 정보를 표현해줍니다.
__irq_svc 심볼이 콜스택에 보이는데요. 이는 IRQ가 Trigger될 시 프로그램 카운터가 이동하는 함수입니다.
__irq_svc -> svc_preempt -> preempt_schedule_irq -> __schedule
-000|cpuacct_charge()
-001|account_group_exec_runtime(inline)
-001|update_curr()
-002|check_spread(inline)
-002|put_prev_entity()
-003|put_prev_task_fair()
-004|pick_next_task_rt(inline)
-004|pick_next_task_rt()
-005|pick_next_task(inline)
-005|__schedule()
-006|arch_local_irq_disable(inline)
-006|preempt_schedule_irq()
-007|svc_preempt(asm)
-008|__irq_svc(asm)
 -->|exception
-009|blk_flush_plug_list()
-010|current_thread_info(inline)
-010|blk_finish_plug()
-011|ext4_writepages()
-012|__filemap_fdatawrite_range()
-013|filemap_write_and_wait_range()
-014|ext4_sync_file()
-015|vfs_fsync()
-016|fdput(inline)
-016|do_fsync()
-017|ret_fast_syscall(asm)
 
이제 커널 패닉이 왜 발생했는지 점검해봐야 겠습니다.
C01709A4 주소에서 커널 패닉이 일어났는데, 이 당시 r3은 e17bbe80  r2는 30319000입니다.
"ldrd    r4,r5,[r3,+r2]" 명령어는 r3에서 r2를 더한 주소의 메모리 덤프를 8바이트 만큼 r4, r5에 로딩합니다.
그런데, r2와 r3를 더하면 결과는 111AD4E80 인데, MMU에서 11AD4E80 주소를 물리 주소로 변환하지 못합니다.
NSR:C01709A0|E5913060                       ldr     r3,[r1,#0x60]    ; _________p1,[r1,#96]
NSR:C01709A4|E18340D2                      ldrd    r4,r5,[r3,+r2]  //<<-- 커널 패닉
 
그래서 커널 메시지가 아래 로그를 토해내는 것이죠.
[69350.929482] <26>Unable to handle kernel paging request at virtual address 11ad4e80
[69350.929511] <26>pgd = d57f0000
 
그럼, R3나 R2값이 잘못됐다고 볼 수 있고 이 레지스터들이 어떻게 실행됐는지 추적해봐야 합니다.
커널 소스를 열어서 보면, 커널 패닉이 발생한 코드는 아래 cpuacct_charge() 함수 247 라인 per_cpu_ptr(ca->cpuusage, cpu); 임을 알 수 있어요.
235void cpuacct_charge(struct task_struct *tsk, u64 cputime)
236{
237 struct cpuacct *ca;
238 int cpu;
239
240 cpu = task_cpu(tsk);
241
242 rcu_read_lock();
243
244 ca = task_ca(tsk);
245
246 while (true) {
247 u64 *cpuusage = per_cpu_ptr(ca->cpuusage, cpu);  //<<--
248 *cpuusage += cputime;
 
그럼 R2나 R3가 per-cpu offset 정보를 담고 있다고 봐야 하는데요.
__per_cpu_offset 변수를 보면 다섯 번째 per-cpu 오프셋이 0x30319000 이군요.
커널 패닉 발생 시 r2: 30319000은 정상 값이라고 봐야 겠습니다.
crash> p __per_cpu_offset
__per_cpu_offset = $3 =
 {0x302dd000, 0x302e9000, 0x302f5000, 0x30301000, 0x3030d000, 0x30319000, 0x30325000, 0x30331000}
NSR:C0170974|E92D4DF0  cpuacct_charge:      push    {r4-r8,r10-r11,r14}
NSR:C0170978|E1A07003                       cpy     r7,r3
NSR:C017097C|E5903004                       ldr     r3,[r0,#0x4]
NSR:C0170980|E1A04000                       cpy     r4,r0            ; r4,tsk
NSR:C0170984|E1A06002                       cpy     r6,r2
NSR:C0170988|E5938014                       ldr     r8,[r3,#0x14]
NSR:C017098C|EB004241                       bl      0xC0181298       ; __rcu_read_lock
NSR:C0170990|E594367C                       ldr     r3,[r4,#0x67C]  //<<--[1]
NSR:C0170994|E59F002C                       ldr     r0,0xC01709C8
NSR:C0170998|E593102C                       ldr     r1,[r3,#0x2C] //<<--[2]
NSR:C017099C|E7902108                       ldr     r2,[r0,+r8,lsl #0x2]
NSR:C01709A0|E5913060                       ldr     r3,[r1,#0x60]    ; _________p1,[r1,#96] //<<--[3]
NSR:C01709A4|E18340D2                      ldrd    r4,r5,[r3,+r2]  //<<--[4]
 
이제 R3가 e17bbe80으로 어떻게 업데이트 됐는지 추적해봐야 겠습니다. 위 어셈블리 코드를 분석 시작할께요.
[1]: R4: 0xD2FB2B80는 task descriptor 포인터를 가르키고 있는데, 0x67C 오프셋에 위치한 메모리 덤프 로딩을 실행합니다.
크래시 유틸리티 프로그램으로 확인하면 task_struct.cgroups 멤버에 접근하네요.
crash> struct -o task_struct.cgroups
struct task_struct {
  [0x67c] struct css_set *cgroups;
}
 
R3 = 0xDFB18800 = *D2FB31FC= *(0xD2FB2B80 + 0x67C) = *(R4 + 0x67C)
crash> struct task_struct.cgroups 0xD2FB2B80
  cgroups = 0xdfb18800
 
[2]: R1 = 0xE97BBE80 = *(0xDFB1882C) = *(0xDFB18800 + 0x2C) = *(R3 + 0x2C)
crash> rd 0xDFB1882C
dfb1882c:  e97bbe80  
 
[3]: R3 = 0xCECCA980 = *0xE97BBEE0  *(0xE97BBE80 + 0x60)  = *(R1 + 0x60)
crash> rd 0xE97BBEE0
e97bbee0:  cecca980 
 
[4]: 커널 패닉 발생 시 R3이 0xCECCA980값이 아니라 0xE17BBE80입니다.
#커널 패닉 시 메시지
[69350.929711] <c2>r7 : 00000000  r6 : 0016a175  r5 : e6188290  r4 : d2fb2b80
[69350.929727] <c2>r3 : e17bbe80  r2 : 30319000  r1 : e97bbe80  r0 : c1a0e538
 
다른 관점으로 cgroups 자료 구조를 분석해보면,
커널 패닉 시 cgroups 정보와 init_css_set 정보 확인 후 0xe97bbe80 메모리 덤프가 0xc1a1f480값 일 것 같은데요.
crash> struct css_set.subsys  0xdfb18800
  subsys = {0xc1bf2d58 <root_task_group>, 0xe97bbe80, 0xf15e5000, 0xf15e5080}
  
crash> struct css_set.subsys  0xc1a21a84
  subsys = {0xc1bf2d58 <root_task_group>, 0xc1a1f480 <root_cpuacct>, 0xf15e5000, 0xf15e5080}
  
crash> p &init_css_set
$4 = (struct css_set *) 0xc1a21a84 <init_css_set>
 
크래시 덤프 분석을 정리하면 아래와 2가지 이유 중 하나로 데이터 어보트가 생겼다고 추정할 수 있습니다.
1. @C01709A0 메모리 주소의 "ldr     r3,[r1,#0x60]" 명령어 오동작
2. struct css_set.subsys 멤버가 잘못된 주소를 가르키고 있음(0xc1a1f480 -> 0xe97bbe80)
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
 
 
#커널 크래시 디버깅 및 TroubleShooting
 
아래 커널 로그와 함께 시스템이 커널 패닉으로 돌아가셨어요.
irq_affinity_notify+0x4c 란 함수에서 data abort가 난 것을 확인할 수 있어요.
[287229.435076] <c6>mmc0: mmc_start_bkops: raw_bkops_status=0x2, from_exception=1
[287230.328287] <c6>mmc0: mmc_start_bkops: Starting bkops
[287231.319886] <26>Unable to handle kernel NULL pointer dereference at virtual address 000000fc
[287231.319920] <26>pgd = c0004000
[287231.319936] <22>[000000fc] *pgd=00000000
[287231.319957] <6>Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[287231.319974] <c2>Modules linked in: core_ctl(PO)
[287231.320000] <c6>CPU: 2 PID: 13 Comm: kworker/1:0 Tainted: P        W  O 3.10.49-gca5eb64 #1
[287231.320028] <c2>Workqueue: events irq_affinity_notify
[287231.320046] <c6>task: e0063fc0 ti: e01f2000 task.ti: e01f2000
[287231.320065] <c2>PC is at irq_affinity_notify+0x4c/0xf8
[287231.320083] <c2>LR is at pm_qos_update_target+0x20c/0x240
[287231.320102] <c2>pc : [<c006c194>]    lr : [<c0068ce0>]    psr: 00000013
 
코어 덤프를 올려서 왜 커널 패닉이 발생했는지 조금 더 살펴볼까요?
우선 crash-utility 프로그램으로 콜스택을 살펴보면 c006c194란 프로그램 카운터에서 data abort가 발생했음을 알 수 있어요.
crash> bt -I C0008400 -S E01F3DF0 0xE0063FC0
PID: 13     TASK: e0063fc0  CPU: 2   COMMAND: "kworker/1:0"
 #0 [<c0008400>] (do_DataAbort) from [<c000d958>]
    pc : [<c006c194>]    lr : [<c0068ce0>]    psr: 00000013
    sp : e01f3ee0  ip : 00000004  fp : 00000000
    r10: 00000000  r9 : c4826700  r8 : e0009a24
    r7 : c0069124  r6 : e01f3ee4  r5 : 000000f8  r4 : ded06564
    r3 : 00000100  r2 : e01f3e98  r1 : 60000013  r0 : 00000000
    Flags: nzcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM
 #1 [<c000d958>] (__dabt_svc) from [<c0068ce0>]
 #2 [<c006c194>] (irq_affinity_notify) from [<c004248c>]
 #3 [<c004248c>] (process_one_work) from [<c004320c>]
 #4 [<c004320c>] (worker_thread) from [<c0047b10>]
 #5 [<c0047b10>] (kthread) from [<c000de98>]
 
그럼 어떤 흐름으로 data abort가 일어났는지, 어셈블 코드 레벨로 디버깅을 좀 해보려고 해요.
이제 시작해볼까요?
 
1]:  R7= *desc, (코드): struct irq_desc *desc = container_of(work, struct irq_desc, affinity_work);
[2]:  파라미터 struct work_struct *work를 r4에 저장
[3]: R8 = 0xE0009A24 =  irq_desc.affinity_notify값, where: offsetof(struct irq_desc,affinity_notify) = 0x64
[4]: irq_desc.affinity_notify 주소를 가져오는데 where r5는 0xE0009A24이어야 하죠
[5]: r3 = 0x100, r8 = 0xE0009A24
[6]: list_for_each_entry() loop에 진입하면 안됨
[7]: "ldr     r3, [r5, #4]" instruction의 base 주소 r5가 0xf8라서 Data Abort 발생
  커널 로그(Unable to handle kernel NULL pointer dereference at virtual address 000000fc)에서 똑같은 정보를 확인할 수 있어요.
0xc006c148 <irq_affinity_notify>:       push    {r0, r1, r4, r5, r6, r7, r8, lr}
0xc006c14c <irq_affinity_notify+0x4>:   subs    r7, r0, #108    ; 0x6c  //<<--[1]
0xc006c150 <irq_affinity_notify+0x8>:   mov     r4, r0            //<<--[2]
0xc006c154 <irq_affinity_notify+0xc>:   beq     0xc006c234 <irq_affinity_notify+236>
0xc006c158 <irq_affinity_notify+0x10>:  add     r5, r7, #88     ; 0x58
0xc006c15c <irq_affinity_notify+0x14>:  add     r6, sp, #8
0xc006c160 <irq_affinity_notify+0x18>:  add     r8, r7, #100    ; 0x64 //<<--[3]
0xc006c164 <irq_affinity_notify+0x1c>:  mov     r0, r5
0xc006c168 <irq_affinity_notify+0x20>:  bl      0xc0a34ca0 <_raw_spin_lock_irqsave>
0xc006c16c <irq_affinity_notify+0x24>:  ldr     r3, [r4, #-72]  ; 0x48
0xc006c170 <irq_affinity_notify+0x28>:  str     r3, [r6, #-4]!
0xc006c174 <irq_affinity_notify+0x2c>:  mov     r1, r0
0xc006c178 <irq_affinity_notify+0x30>:  mov     r0, r5
0xc006c17c <irq_affinity_notify+0x34>:  bl      0xc0a35028 <_raw_spin_unlock_irqrestore>
0xc006c180 <irq_affinity_notify+0x38>:  ldr     r5, [r4, #-8] //<<--[4]
0xc006c184 <irq_affinity_notify+0x3c>:  sub     r5, r5, #8
0xc006c188 <irq_affinity_notify+0x40>:  add     r3, r5, #8
0xc006c18c <irq_affinity_notify+0x44>:  cmp     r3, r8 //<<--[5]
0xc006c190 <irq_affinity_notify+0x48>:  beq     0xc006c234 <irq_affinity_notify+236> //<<--[6]
0xc006c194 <irq_affinity_notify+0x4c>:  ldr     r3, [r5, #4]  //<<--[7]
 
해당 C 코드는 아래와 같은데요. 참 신기하죠. &desc->affinity_notify가 NULL인데, 
list_for_each_entry(notify, &desc->affinity_notify, list) 를 뚫고 들어가 실행을 한거란 말이죠.
static void irq_affinity_notify(struct work_struct *work)
{
struct irq_desc *desc =
container_of(work, struct irq_desc, affinity_work);
cpumask_var_t cpumask;
unsigned long flags;
struct irq_affinity_notify *notify;
// .. snip..
list_for_each_entry(notify, &desc->affinity_notify, list) {  //<<--
if (!kref_get_unless_zero(&notify->kref))
continue;
notify->notify(notify, cpumask);
kref_put(&notify->kref, notify->release);
}
mutex_unlock(&desc->notify_lock);
 
free_cpumask_var(cpumask);
}
 
(To Be continue)
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
 
#커널 크래시 디버깅 및 TroubleShooting
 
USB와 TTY Driver 관련한 커널 패닉 디버깅 정보를 좀 공유하고자 해요.
 
아래 Signature로 커널 패닉이 발생했는데요. __irq_usr -> gic_handle_irq 코드 흐름으로 보아 유저 공간에서 실행 중인 프로세스로 IRQ가 Trigger되었다는 정보를 확인할 수 있어요.
바꾸어 말하면 아래 콜스택은 IRQ Context라고 할 수 있죠. 문제가 발생한 보드는 Mediatek MT6755랍니다.
[<c001df40>] do_page_fault+0x338/0x3f8 
[<c0008544>] do_DataAbort+0x38/0x98 
[<c0015058>] __dabt_svc+0x38/0x60 
[<c031a5a0>] tty_wakeup+0xc/0x64 
[<c06f82ec>] gs_start_io+0x94/0xf4 
[<c06f8698>] gserial_connect+0xe0/0x180
[<c06f7578>] acm_set_alt+0x88/0x1a8 
[<c06f3c5c>] composite_setup+0xd34/0x1520 
[<c070d154>] android_setup+0x1f4/0x1fc 
[<c03fc6e8>] forward_to_driver+0x64/0x100 
[<c03fd418>] musb_g_ep0_irq+0x7d8/0x1c18 
[<c03fb094>] musb_interrupt+0x94/0xc78 
[<c04024f0>] generic_interrupt+0xc34/0x1218 
[<c009b020>] handle_irq_event_percpu+0xe0/0x2e4
[<c009b268>] handle_irq_event+0x44/0x64
[<c009df54>] handle_fasteoi_irq+0xe8/0x1a4 
[<c009a7dc>] __handle_domain_irq+0x104/0x264 
[<c0008668>] gic_handle_irq+0x2c/0x64 
[<c00153a8>] __irq_usr+0x48/0x60
 
비슷한 시기에 nVidia Tegra4i SoC에서 아래 커널 로그와 함께 크래시가 발생했어요.
Tegra4i에서 정의한 OTG IRQ를 처리하는 함수만 다르지 처리되는 함수 흐름은 똑같네요.
[71653.259161 08-15 11:27:39.779] android_work: did not send uevent (0 0   (null))
[71653.290526 08-15 11:27:39.811] android_work: sent uevent USB_STATE=CONNECTED
[71653.292844 08-15 11:27:39.813] android_work: sent uevent USB_STATE=DISCONNECTED
[71653.365187 08-15 11:27:39.885] android_usb gadget: high speed config #1: android
[71653.365758 08-15 11:27:39.885] Unable to handle kernel NULL pointer dereference at virtual address 000000a8
[71653.365775 08-15 11:27:39.885] pgd = c0004000
[71653.365785 08-15 11:27:39.885] [000000a8] *pgd=00000000
[71653.365805 08-15 11:27:39.885] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[71653.365841 08-15 11:27:39.885] Modules linked in: bcmdhd(O)
[71653.365864 08-15 11:27:39.885] CPU: 0    Tainted: G           O  (3.4.65-g000d394 #1)
[71653.365891 08-15 11:27:39.885] PC is at tty_wakeup+0x14/0x80
[71653.365910 08-15 11:27:39.885] LR is at gs_start_io+0x90/0xe8
[71653.365922 08-15 11:27:39.885] pc : [<c03b2fe8>]    lr : [<c04a2520>]    psr: 20030193
[71653.365928 08-15 11:27:39.885] sp : d2b2db10  ip : d2b2db28  fp : d2b2db24
[71653.365944 08-15 11:27:39.885] r10: e29ba318  r9 : e29ba324  r8 : 00000000
[71653.365955 08-15 11:27:39.885] r7 : e29ba2f4  r6 : e16290a8  r5 : e29ba2e8  r4 : e29ba2c0
[71653.365967 08-15 11:27:39.885] r3 : 0000000a  r2 : 00000000  r1 : 60030193  r0 : 00000000
[71653.365984 08-15 11:27:39.885] Flags: nzCv  IRQs off  FIQs on  Mode SVC_32  ISA ARM  Segment kernel
[71653.365996 08-15 11:27:39.885] Control: 10c5387d  Table: 8567c04a  DAC: 00000015
// ... 생략...
[71653.369827 08-15 11:27:39.885] [<c03b2fe8>] (tty_wakeup+0x14/0x80) from [<c04a2520>] (gs_start_io+0x90/0xe8)
[71653.369848 08-15 11:27:39.885] [<c04a2520>] (gs_start_io+0x90/0xe8) from [<c04a2f24>] (gserial_connect+0xdc/0x164)
[71653.369865 08-15 11:27:39.885] [<c04a2f24>] (gserial_connect+0xdc/0x164) from [<c04a3440>] (acm_set_alt+0x90/0x1ac)
[71653.369883 08-15 11:27:39.885] [<c04a3440>] (acm_set_alt+0x90/0x1ac) from [<c04995b4>] (composite_setup+0x244/0xf80)
[71653.369899 08-15 11:27:39.885] [<c04995b4>] (composite_setup+0x244/0xf80) from [<c049a3b0>] (android_setup+0xc0/0x154)
[71653.369921 08-15 11:27:39.885] [<c049a3b0>] (android_setup+0xc0/0x154) from [<c0487d44>] (tegra_udc_irq+0xbd4/0x11d0)
[71653.369944 08-15 11:27:39.885] [<c0487d44>] (tegra_udc_irq+0xbd4/0x11d0) from [<c00e64a8>] (handle_irq_event_percpu+0x88/0x2ec)
[71653.369962 08-15 11:27:39.885] [<c00e64a8>] (handle_irq_event_percpu+0x88/0x2ec) from [<c00e6758>] (handle_irq_event+0x4c/0x6c)
[71653.369980 08-15 11:27:39.885] [<c00e6758>] (handle_irq_event+0x4c/0x6c) from [<c00e96ec>] (handle_fasteoi_irq+0xcc/0x174)
[71653.369998 08-15 11:27:39.885] [<c00e96ec>] (handle_fasteoi_irq+0xcc/0x174) from [<c00e5c28>] (generic_handle_irq+0x3c/0x50)
[71653.370022 08-15 11:27:39.885] [<c00e5c28>] (generic_handle_irq+0x3c/0x50) from [<c000f9c4>] (handle_IRQ+0x5c/0xbc)
[71653.370040 08-15 11:27:39.885] [<c000f9c4>] (handle_IRQ+0x5c/0xbc) from [<c0008504>] (gic_handle_irq+0x34/0x68)
[71653.370057 08-15 11:27:39.885] [<c0008504>] (gic_handle_irq+0x34/0x68) from [<c000ec00>] (__irq_svc+0x40/0x70)
[71653.370070 08-15 11:27:39.885] Exception stack(0xd2b2dd80 to 0xd2b2ddc8)
 
이번에는 모바일계의 맞형 퀄컴님의 MSM8917 보드에서 똑같이 크래시가 발생했어요.
커널 로그는 아래와 같은데 똑같이 tty_wakeup() 함수에서 NULL pointer dereference로 크래시가 발생했네요.
[   51.610867 / 01-01 11:22:44.521][1] cfg80211: Invalid regulatory domain detected:
[   52.471153 / 01-01 11:22:45.381][0] Unable to handle kernel NULL pointer dereference at virtual address 000001cc
[   52.471172 / 01-01 11:22:45.381][0] pgd = d04f4000
[   52.471183 / 01-01 11:22:45.381][0] [000001cc] *pgd=00000000
[   52.471198 / 01-01 11:22:45.381][0] Internal error: Oops: 5 [#1] PREEMPT SMP ARM
[   52.471209 / 01-01 11:22:45.381][0] Modules linked in: texfat(PO)
[   52.471228 / 01-01 11:22:45.381][0] CPU: 0 PID: 1026 Comm: rild Tainted: P        W  O   3.18.31-gadfe554 #1
[   52.471240 / 01-01 11:22:45.381][0] task: e8ffb3c0 ti: d076e000 task.ti: d076e000
[   52.471260 / 01-01 11:22:45.381][0] PC is at tty_wakeup+0x8/0x58
[   52.471275 / 01-01 11:22:45.381][0] LR is at gs_start_io+0xb8/0xfc
[   52.471288 / 01-01 11:22:45.381][0] pc : [<c04f534c>]    lr : [<c06f364c>]    psr: 20000193
[   52.471288 / 01-01 11:22:45.381][0] sp : d076fd70  ip : 0000000b  fp : ec6ebc80
[   52.471305 / 01-01 11:22:45.381][0] r10: e97b5d84  r9 : e97b5d90  r8 : 00000000
[   52.471316 / 01-01 11:22:45.381][0] r7 : c42a63b0  r6 : e97b5d58  r5 : e97b5d64  r4 : 00000000
[   52.471328 / 01-01 11:22:45.381][0] r3 : e885e400  r2 : 00000000  r1 : 00320031  r0 : 00000000
//..
[   52.471712 / 01-01 11:22:45.381][0] [<c04f534c>] (tty_wakeup) from [<c06f364c>] (gs_start_io+0xb8/0xfc)
[   52.471729 / 01-01 11:22:45.381][0] [<c06f364c>] (gs_start_io) from [<c06f37d4>] (gserial_connect+0x144/0x1b0)
[   52.471745 / 01-01 11:22:45.381][0] [<c06f37d4>] (gserial_connect) from [<c06f22ec>] (acm_set_alt+0x1e8/0x248)
[   52.471760 / 01-01 11:22:45.381][0] [<c06f22ec>] (acm_set_alt) from [<c06efa1c>] (composite_setup+0x1448/0x159c)
[   52.471778 / 01-01 11:22:45.381][0] [<c06efa1c>] (composite_setup) from [<c0725390>] (android_setup+0x124/0x1ac)
[   52.471796 / 01-01 11:22:45.381][0] [<c0725390>] (android_setup) from [<c074967c>] (msm_udc_irq+0xd78/0xfb0)
[   52.471813 / 01-01 11:22:45.381][0] [<c074967c>] (msm_udc_irq) from [<c016f7e4>] (handle_irq_event_percpu+0xb4/0x2ac)
[   52.471829 / 01-01 11:22:45.381][0] [<c016f7e4>] (handle_irq_event_percpu) from [<c016fa18>] (handle_irq_event+0x3c/0x5c)
[   52.471845 / 01-01 11:22:45.381][0] [<c016fa18>] (handle_irq_event) from [<c01727b8>] (handle_fasteoi_irq+0xb0/0x128)
[   52.471863 / 01-01 11:22:45.381][0] [<c01727b8>] (handle_fasteoi_irq) from [<c016ef6c>] (generic_handle_irq+0x20/0x30)
[   52.471880 / 01-01 11:22:45.381][0] [<c016ef6c>] (generic_handle_irq) from [<c016f230>] (__handle_domain_irq+0x7c/0xa0)
[   52.471897 / 01-01 11:22:45.381][0] [<c016f230>] (__handle_domain_irq) from [<c01005c4>] (gic_handle_irq+0x48/0x78)
[   52.471916 / 01-01 11:22:45.381][0] [<c01005c4>] (gic_handle_irq) from [<c0f3a004>] (__irq_usr+0x44/0x60)
 
3개의 다른 SoC에서 다른 콜스택으로 호출되어 결국 똑같은 함수에서 Data Abort가 발생한 게 신기하죠?
 
이제 덤프를 분석해야 할 시간이에요.
 
커널 패닉이 일어난 코드를 열여서 확인해보니, 
tty_wakeup() 함수로 전달되는 파라미터 struct tty_struct *tty 가 NULL이라 데이터 Abort가 발생한 것처럼 보이는데요.
void tty_wakeup(struct tty_struct *tty)
{
    struct tty_ldisc *ld;
    if (test_bit(TTY_DO_WRITE_WAKEUP, &tty->flags)) { // <<-- kernel panic
        ld = tty_ldisc_ref(tty);
 
struct tty_struct *tty 파라미터를 어떤 함수가 호출하는지 점검할 필요가 있어 보여요.
그럼 tty_wakeup() 함수를 어느 함수가 호출했는지 찾아가 보면, gs_start_io() 함수에서 port->port.tty 파라미터를 전달하고 있군요. port->port.tty 변수가 NULL인 것이 문제죠.
(struct gs_port *)0xE97B5C00 = 0xE97B5C00 -> (
    port = (
      buf = (head = 0xE97B5C40, work = (data = (counter = 0xFFFFFFE0), entry = (
      tty = 0x0,  // <<--
      itty = 0x0,
      ops = 0x0,
      lock = (rlock = (raw_lock = (slock = 0x0, tickets = (owner = 0x0, next = 0
      blocked_open = 0x0,
 
해당 코드는 아래와 같아요.      
static int gs_start_io(struct gs_port *port)
{
// .. skip ..
        /* unblock any pending writes into our circular buffer */
         if (started) {
                 tty_wakeup(port->port.tty);  //<<--
         } else {
                 gs_free_requests(ep, head, &port->read_allocated);
                 gs_free_requests(port->port_usb->in, &port->write_pool,
                         &port->write_allocated);
                 status = -EIO;
         }
 
그런데 커널 패닉이 일어나기 전 커널 로그를 아주 자세히 관찰해보면, 아래 커널 로그를 확인할 수가 있어요.
gs_close() 함수가 호출되었다는 정보를 확인할 수 있는데요.
[ 6285.082083 / 06-01 11:43:40.318] -(4)[981:mdl_sock_host]gs_close: ttyGS1 (d3681900,d7e1ca80) ...
 
커널 로그에 위 로그에 매핑되는 코드를 찾아가 보면 gs_close() 함수를 확인할 수 있어요.
이 함수에서 port->port.tty 변수를 NULL로 설정하는군요.
static void gs_close(struct tty_struct *tty, struct file *file)
{
struct gs_port *port = tty->driver_data;
struct gserial *gser;
// ..skip..
if (gser == NULL)
gs_buf_free(&port->port_write_buf);
else
gs_buf_clear(&port->port_write_buf);
 
tty->driver_data = NULL;
port->port.tty = NULL; //<<--
 
정리하면, USB단에서 USB OTG IRQ가 떠서 RX 패킷을 받아서 tty layer로 넘겨주려고 tty port를 wakeup 하는 동작에서 tty port가 close 되었군요.
아래 조건으로 race condition이 발생했음을 알 수 있어요.
CPU0                                         CPU1
-gs_close
  port->port.tty = NULL 설정
                                             IRQ Trigger
                                             gs_start_io+0x94/0xf4
                                               tty_wakeup+0xc/0x64
                                                  커널 패닉
 
그럼 아래 패치를 적용해서 평소 어떤 흐름으로, gs_close() 함수가 호출되는지 확인해볼까요?
diff --git a/drivers/usb/gadget/function/u_serial.c b/drivers/usb/gadget/function/u_serial.c
index d0b519d..d5cc9f1 100644
--- a/drivers/usb/gadget/function/u_serial.c
+++ b/drivers/usb/gadget/function/u_serial.c
@@ -789,6 +789,10 @@ static int gs_start_io(struct gs_port *port)
 
        if (!port->port_usb)
                return -EIO;
+
+       show_stack(NULL, NULL);
+       printk("[+][flash][%s][%s,%d]: caller: (%pS)\n", current->comm, __func__,__LINE__,  (void *)__builtin_return_address(0));
+
        /* unblock any pending writes into our circular buffer */
        if (started) {
@@ -982,6 +986,9 @@ static void gs_close(struct tty_struct *tty, struct file *file)
        tty->driver_data = NULL;
        port->port.tty = NULL;
 
+       show_stack(NULL, NULL);
+       printk("[+][flash][%s][%s,%d]: caller: (%pS)\n", current->comm, __func__,__LINE__,  (void *)__builtin_return_address(0));
+
        port->openclose = false;
 
        pr_debug("gs_close: ttyGS%d (%pK,%pK) done!\n",
 
아래와 같은 커널 로그를 확인할 수 있어요. 
tty driver를 등록한 프로세스가 종료될 때 tty_release -> gs_close 순서로 함수가 호출되고 있네요.
<6>[  172.692835 / 01-06 19:00:22.975][5] [<c0016f78>] (unwind_backtrace) from [<c0013720>] (show_stack+0x20/0x24)
<6>[  172.692877 / 01-06 19:00:22.975][5] [<c0013720>] (show_stack) from [<c067a3b8>] (gs_close+0x1c8/0x258)
<6>[  172.692910 / 01-06 19:00:22.975][5] [<c067a3b8>] (gs_close) from [<c045d16c>] (tty_release+0x148/0x4cc)
<6>[  172.692941 / 01-06 19:00:22.975][5] [<c045d16c>] (tty_release) from [<c015b708>] (__fput+0x104/0x1e4)
<6>[  172.692969 / 01-06 19:00:22.975][5] [<c015b708>] (__fput) from [<c015b85c>] (____fput+0x18/0x1c)
<6>[  172.693004 / 01-06 19:00:22.975][5] [<c015b85c>] (____fput) from [<c0049240>] (task_work_run+0xc4/0xf0)
<6>[  172.693038 / 01-06 19:00:22.975][5] [<c0049240>] (task_work_run) from [<c0012f40>] (do_work_pending+0xb8/0xd0)
<6>[  172.693069 / 01-06 19:00:22.975][5] [<c0012f40>] (do_work_pending) from [<c000f320>] (work_pending+0xc/0x20)
<6>[  172.693092 / 01-06 19:00:22.975][5] [+][flash][atd][gs_close,990]: caller: (tty_release+0x148/0x4cc)
 
그럼 어떻게 예외 처리 코드를 추가하면 좋을까요?
아래와 같은 패치 코드를 작성하여 예외처리 루틴을 추가했더니 이 현상은 사라졌어요. port->port.tty이 null 포인터가 아닐 때만 tty_wakeup(port->port.tty); 함수를 호출하는거죠.
diff --git a/drivers/usb/gadget/function/u_serial.c b/drivers/usb/gadget/function/u_serial.c
index 2610e22..4c28a25 100644
--- a/drivers/usb/gadget/function/u_serial.c
+++ b/drivers/usb/gadget/function/u_serial.c
@@ -790,7 +790,11 @@ static int gs_start_io(struct gs_port *port)
        if (!port->port_usb)
                return -EIO;
        /* unblock any pending writes into our circular buffer */
-        if (started) {
+       if (started && port->port.tty) {
                tty_wakeup(port->port.tty);
        } else {
                gs_free_requests(ep, head, &port->read_allocated);
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
#커널 크래시 디버깅 및 TroubleShooting
예전 MTK SoC에서 일어났던 Watchdog Reset 이슈인데요. 디버깅 정보를 조금 공유하고자 해요.
 
CPU1에서 수행 중인 "migration/1" process에서 watchdog reset이 발생하여 시스템이 리셋된 흔적을 확인할 수 있어요.
-000|do_undefinstr()
-001|__und_svc_fault(asm)
 -->|exception
-002|aee_wdt_atf_info()
-003|aee_wdt_atf_entry()
-004|debug_smp_processor_id()
-005|cpu_stopper_thread()
-006|smpboot_thread_fn()
-007|kthread()
-008|ret_from_fork(asm)
-009|ret_fast_syscall(asm)
 
MTK SoC에서는 각 CPU가 Hotplug 동작 전 후에서 Watchdog Kick 여부를 파악하는데요.
cpus_kick_bit 변수는 hotplugin을 수행 요청을 한 CPU의 비트마스크이고, kick_bit은 hotplugin 동작 완료 시 notifier call이 수행된 CPU 비트 필드를 보여줘요.
11110011  (where) cpus_kick_bit = 0xF3
00000000  (where)kick_bit = 0x0
 
그럼 위 정보로 보아, CPU0/1/4/5/6/7에서 무엇인가 Stuck이 되어 Watchdog Kick을 못했다고 추정할 수 있어요.
각 CPU의 콜스택을 점검해보니 CPU4에서 "kworker/4:3" 프로세스가 아래 콜스택으로 구동 중임을 알 수 있어요.
-000|__ipv6_dev_ac_inc()
-001|addrconf_join_anycast()
-002|__ipv6_ifa_notify()
-003|local_bh_enable(inline)
-003|rcu_read_unlock_bh(inline)
-003|ipv6_ifa_notify()
-004|addrconf_dad_begin(inline)
-004|addrconf_dad_work()
-005|static_key_count(inline)
-005|static_key_false(inline)
-005|trace_workqueue_execute_end(inline)
-005|process_one_work()
-006|list_empty(inline)
-006|worker_thread()
-007|kthread()
-008|ret_from_fork(asm)
-009|ret_fast_syscall(asm)
 
그럼 ftrace log로 실제 각 CPU별로 어떤 동작을 수행 중이었는 지 살펴보도록 할께요.
우선 CPU4에서 어떤 동작이 있었는지 살펴보면, "kworker/4:3-10711" 프로세스가 addrconf_dad_work work를 수행 중인 로그가 확인되요.
그런데, workqueue_execute_end 0xd8c3cb7c란 로그가 안 보이는 것으로 보아 위에 제가 잡은 콜스택 정보와 일치하는 정보이군요. 
   addrconf_dad_work -> ipv6_ifa_notify -> __ipv6_ifa_notify -> addrconf_join_anycast
 
그리고 마지막 ftrace로그의 타임 스탬프는 1595.644768로 확인되거든요. CPU4가 22초 동안 preemption되지 않고 stuck되었다는 정보를 확인할 수 있죠. 
kworker/4:3-10711 [004]  1573.162047: workqueue_execute_start: work struct 0xd8c3cb7c: function addrconf_dad_work
kworker/4:3-10711 [004]  1573.162099: sched_migrate_task:   comm=dnsmasq pid=11779 prio=120 orig_cpu=5 dest_cpu=6 state=W
kworker/4:3-10711 [004]  1573.162114: sched_wakeup:         comm=dnsmasq pid=11779 prio=120 success=1 target_cpu=006 state=W
kworker/4:3-10711 [004]  1573.162128: sched_wakeup:         comm=vpnclientd pid=2786 prio=120 success=1 target_cpu=004 state=W
kworker/4:3-10711 [004]  1573.162136: sched_migrate_task:   comm=netd pid=1145 prio=120 orig_cpu=5 dest_cpu=4 state=W
kworker/4:3-10711 [004]  1573.162140: sched_wakeup:         comm=netd pid=1145 prio=120 success=1 target_cpu=004 state=W
kworker/4:3-10711 [004]  1573.164771: irq_handler_entry:    irq=30 name=arch_timer
kworker/4:3-10711 [004]  1573.164795: irq_handler_exit:     irq=30 ret=handled
kworker/4:3-10711 [004]  1573.170639: irq_handler_entry:    irq=216 name=ovl0 
kworker/4:3-10711 [004]  1573.170651: irq_handler_exit:     irq=216 ret=handled
kworker/4:3-10711 [004]  1573.170771: irq_handler_entry:    irq=218 name=rdma0 
kworker/4:3-10711 [004]  1573.170789: sched_wakeup:         comm=VSyncThread_0 pid=455 prio=112 success=1 target_cpu=006 state=W
kworker/4:3-10711 [004]  1573.170792: irq_handler_exit:     irq=218 ret=handled
kworker/4:3-10711 [004]  1573.174770: irq_handler_entry:    irq=30 name=arch_timer
kworker/4:3-10711 [004]  1573.174786: irq_handler_exit:     irq=30 ret=handled
kworker/4:3-10711 [004]  1573.175936: irq_handler_entry:    irq=209 name=mutex 
kworker/4:3-10711 [004]  1573.175944: irq_handler_exit:     irq=209 ret=handled
kworker/4:3-10711 [004]  1573.176141: irq_handler_entry:    irq=270 name=AHB_SLAVE_HIF
kworker/4:3-10711 [004]  1573.176150: sched_wakeup:         comm=tx_thread pid=11483 prio=120 success=1 target_cpu=006 state=W
kworker/4:3-10711 [004]  1573.176152: irq_handler_exit:     irq=270 ret=handled
// 생략
migration/1-11    [001]  1595.638701: irq_handler_entry:    irq=232 name=ovl1_2l 
migration/1-11    [001]  1595.638704: irq_handler_exit:     irq=232 ret=handled
migration/1-11    [001]  1595.644768: irq_handler_entry:    irq=30 name=arch_timer
// end of ftrace log
 
이제 더 watchdog reset의 원인을 더 좁히기 위해, 디버깅 정보를 좀 더 뒤져봐야 하는데요.
Uninterruptible 상태 프로세스 정보를 확인해볼께요. 보통 크래시 코어 덤프가 나오면 습관적으로 점검을 하곤 하거든요.
 
그런데 아래와 같이 평소에 보이지 않는 프로세스들이 보이네요.
crash> ps -l | grep UN
[1573221067182] [UN]  PID: 1043   TASK: d8959000  CPU: 5   COMMAND: "android.io"
[1573169741644] [UN]  PID: 273    TASK: dd903600  CPU: 5   COMMAND: "bat_update_thre"
[1573164748105] [UN]  PID: 6531   TASK: c748a000  CPU: 5   COMMAND: "DnsConfigServic"
[1573163602413] [UN]  PID: 4299   TASK: c1a8e600  CPU: 6   COMMAND: "DnsConfigServic"
[1573160763720] [UN]  PID: 25     TASK: de900600  CPU: 4   COMMAND: "kworker/4:0"
[1573134929413] [UN]  PID: 166    TASK: ddca8600  CPU: 4   COMMAND: "disp_idlemgr"
[1572444794180] [UN]  PID: 172    TASK: dea1d000  CPU: 4   COMMAND: "disp_check"
[1571706203179] [UN]  PID: 221    TASK: ddfc2600  CPU: 0   COMMAND: "touch_boost"
[  67489120544] [UN]  PID: 279    TASK: ddb81000  CPU: 5   COMMAND: "reclaim_task"
[  61815993377] [UN]  PID: 5447   TASK: c7464000  CPU: 5   COMMAND: "secwidevinemdw_"
[   5302444704] [UN]  PID: 483    TASK: da78d600  CPU: 4   COMMAND: "rpmb_Dci"
[   1263689925] [UN]  PID: 281    TASK: ddb83000  CPU: 1   COMMAND: "reset_task"
[    695977770] [UN]  PID: 168    TASK: de3d3000  CPU: 4   COMMAND: "decouple_trigge"
[    680735924] [UN]  PID: 165    TASK: ddc76000  CPU: 4   COMMAND: "ddp_irq_log_kth"
 
PID: 1043   TASK: d8959000  CPU: 5   COMMAND: "android.io" 프로세스 콜스택을 보니,
mutex lock을 획득하지 못해서 __schedule() 함수 호출로 sleep에 들어가네요.
-000|context_switch(inline)
-000|__schedule()
-001|schedule()
-002|schedule_preempt_disabled()
-003|spin_lock(inline)
-003|__mutex_lock_common(inline)
-003|__mutex_lock_slowpath(lock_count = 0xC0FBFB94)
-004|__mutex_fastpath_lock(inline)
-004|mutex_lock(lock = 0x0)
-005|rtnl_lock()
-006|devinet_ioctl(net = 0xC0FBEC40, ?, arg = 0x9BE1A20C)
-007|inet_ioctl(?, ?, ?)
-008|sock_do_ioctl(inline)
-008|sock_ioctl(?, cmd = 35093, ?)
-009|vfs_ioctl(inline)
-009|do_vfs_ioctl(filp = 0x0, ?, ?, ?)
-010|SYSC_ioctl(inline)
-010|sys_ioctl(fd = 267, cmd = 35093, arg = -1679711732)
-011|ret_fast_syscall(asm)
 
TASK: c748a000  CPU: 5   COMMAND: "DnsConfigServic" 프로세스도 마찬가지군요.
-000|context_switch(inline)
-000|__schedule()
-001|schedule()
-002|schedule_preempt_disabled()
-003|spin_lock(inline)
-003|__mutex_lock_common(inline)
-003|__mutex_lock_slowpath(lock_count = 0xC0FBFB94)
-004|__mutex_fastpath_lock(inline)
-004|mutex_lock(lock = 0x0)
-005|rtnl_lock()
-006|wireless_process_ioctl(inline)
-006|wext_ioctl_dispatch(inline)
-006|wext_handle_ioctl(net = 0xC0FBEC40, ifr = 0xC4EC5EA8, cmd = 35585, arg = 0x
-007|dev_ioctl(net = 0xC0FBEC40, cmd = 35585, arg = 0x9B73A4B4)
-008|sock_do_ioctl(inline)
-008|sock_ioctl(?, cmd = 35585, ?)
-009|vfs_ioctl(inline)
-009|do_vfs_ioctl(filp = 0x0, ?, ?, ?)
-010|SYSC_ioctl(inline)
-010|sys_ioctl(fd = 19, cmd = 35585, arg = -1686920012)
-011|ret_fast_syscall(asm)
 
위 두 프로세스에서 rtnl_lock() 함수 수행 후 __schedule() 함수 실행 중인 공통점을 확인할 수 있네요.
rtnl_lock() 함수 코드 리뷰 좀 해볼까요? rtnl_lock() 함수 body를 보니, rtnl_mutex란 mutex 변수로 락을 걸고 있음을 알 수 있어요.
void rtnl_lock(void)
{
mutex_lock(&rtnl_mutex);
// .. 생략..
 
rtnl_mutex 변수를 확인해보니 mutex lock owner가 "kworker/4:3"임을 알수 있어요.
mutex deadlock현상은 결국 문제의 원인이 아니라 결과임을 할 수 있어요. 
  (static struct mutex) rtnl_mutex = (
    (atomic_t) count = ((int) counter = 0xFFFFFFFD),
    (spinlock_t) wait_lock = ((struct raw_spinlock) rlock = ((arch_spinlock_t) r
    (struct list_head) wait_list = (
      (struct list_head *) next = 0xD91E5E04 -> (
        (struct list_head *) next = 0xC4EC5E04 -> (
          (struct list_head *) next = 0xD92E3E14 -> (
            (struct list_head *) next = 0xC0FBFB9C -> (
              (struct list_head *) next = 0xD91E5E04,
              (struct list_head *) prev = 0xD92E3E14),
            (struct list_head *) prev = 0xC4EC5E04),
          (struct list_head *) prev = 0xD91E5E04),
        (struct list_head *) prev = 0xC0FBFB9C),
      (struct list_head *) prev = 0xD92E3E14),
    (struct task_struct *) owner = 0xDA073600 -> (
      (long int) state = 0x0,
      (void *) stack = 0xC5728000,
 // ..생략..
      (struct cred *) cred = 0xD8FBD600,
      (char [16]) comm = "kworker/4:3",
      (int) link_count = 0x0,
 
그 이유는 "kworker/4:3" 프로세스가 rtnl_mutex 이란 mutex을 잠그고 __ipv6_dev_ac_inc() 함수에서 spinning으로 돌고 있었기 때문에, 다른 프로세스들이 rtnl_mutex란 mutex을 획득하지 못하는 상황이거든요.
-000|__ipv6_dev_ac_inc()
-001|addrconf_join_anycast()
-002|__ipv6_ifa_notify()
-003|local_bh_enable(inline)
-003|rcu_read_unlock_bh(inline)
-003|ipv6_ifa_notify()
-004|addrconf_dad_begin(inline)
-004|addrconf_dad_work()
-005|static_key_count(inline)
-005|static_key_false(inline)
-005|trace_workqueue_execute_end(inline)
-005|process_one_work()
-006|list_empty(inline)
-006|worker_thread()
-007|kthread()
-008|ret_from_fork(asm)
-009|ret_fast_syscall(asm)     
 
그럼 "kworker/4:3" 프로세스가 rtnl_mutex란 mutex를 언제 거냐구요? 위 콜스택 정보를 참고하면 addrconf_dad_work 함수에서 rtnl_lock() 함수 호출로 rtnl_mutex란 mutex를 잠그고 있어요.
static void addrconf_dad_work(struct work_struct *w)
{
struct inet6_ifaddr *ifp = container_of(to_delayed_work(w),
struct inet6_ifaddr,
dad_work);
struct inet6_dev *idev = ifp->idev;
struct in6_addr mcaddr;
 
enum {
DAD_PROCESS,
DAD_BEGIN,
DAD_ABORT,
} action = DAD_PROCESS;
 
rtnl_lock();
 
그럼 __ipv6_dev_ac_inc() 함수로 되돌아갈 시간이네요.
__ipv6_dev_ac_inc() 함수를 리뷰해보면, 아래 for loop에서 함수가 계속 무한루프를 돌고 있었는데요.
int __ipv6_dev_ac_inc(struct inet6_dev *idev, const struct in6_addr *addr)
{
struct ifacaddr6 *aca;
struct rt6_info *rt;
int err;
// .. skip..
 
for (aca = idev->ac_list; aca; aca = aca->aca_next) {
if (ipv6_addr_equal(&aca->aca_addr, addr)) {
aca->aca_users++;
err = 0;
goto out;
}
}
 
idev->ac_list 변수가 어떤 값을 갖고 있는 지 점검을 해보았어요. 
확인해보니 참 황당하게도 이 값이 0x0이네요.
  (struct inet6_dev *) (struct inet6_dev *)0xC2000400 = 0xC2000400 -> (
    (struct net_device *) dev = 0xDA5CA800,
    (struct list_head) addr_list = ((struct list_head *) next = 0xD8C3CBC0, (str
// .. skip ..
    (struct ifacaddr6 *) ac_list = 0x0,
 
kworker/4:3-10711란 프로세스가 __ipv6_dev_ac_inc() 함수 내 for loop를 돌면서 idev->ac_list 리스트를 iteration하는 동안에, 다른 모듈이 race condition으로 __ipv6_dev_ac_inc() 함수에 진입하여 idev->ac_list에 access한 것으로 보이네요.
 
아래와 같은 디버깅 패치를 작성해서 race condition이 발생하는지 점검하고 있었는데.
diff --git a/net/ipv6/anycast.c b/net/ipv6/anycast.c
index baf2742..44b28c0 100644
--- a/net/ipv6/anycast.c
+++ b/net/ipv6/anycast.c
@@ -257,6 +257,7 @@ int __ipv6_dev_ac_inc(struct inet6_dev *idev, const struct in6_addr *addr)
        }
 
        for (aca = idev->ac_list; aca; aca = aca->aca_next) {
+               trace_printk("%p caller: %pS\n", idev->ac_list, (void *)__builtin_return_address(0));
                if (ipv6_addr_equal(&aca->aca_addr, addr)) {
                        aca->aca_users++;
                        err = 0;
 
네트워크 드라이버를 보는 분이 잽싸게 리눅스 커뮤니티에서 ipv6_ifa_notify() 함수가 race condition을 유발시킬 수 있다는 정보를 캐치하셨어요. 아래 패치 적용 후 문제가 재현되지 않았어요.
 
ipv6_ifa_notify() may need to acquire idev->lock, for example
when calling __ipv6_dev_ac_inc() from addrconf_join_anycast()
in __ipv6_ifa_notify().
So caller must release idev->lock before calling ipv6_ifa_notify() to
avoid a deadlock.
Fix a checkpatch warning present in the same area to make checkpatch
happy.
 
#패치 코드
diff --git a/net/ipv6/addrconf.c b/net/ipv6/addrconf.c
index 3d9afb7..7b92c50 100644
--- a/net/ipv6/addrconf.c
+++ b/net/ipv6/addrconf.c
@@ -2227,10 +2227,12 @@ static void manage_tempaddrs(struct inet6_dev *idev,
                        ift->flags &= ~IFA_F_DEPRECATED;
 
                spin_unlock(&ift->lock);
-               if (!(flags&IFA_F_TENTATIVE))
-                       ipv6_ifa_notify(0, ift);
-       }
-
+  if (!(flags&IFA_F_TENTATIVE)) {
+      read_unlock_bh(&idev->lock);
+      ipv6_ifa_notify(0, ift);
+      read_lock_bh(&idev->lock);
+    }
+ }
        if ((create || list_empty(&idev->tempaddr_list)) &&
            idev->cnf.use_tempaddr > 0) {
                /* When a new public address is created as described
@@ -3340,7 +3342,9 @@ static void addrconf_dad_begin(struct inet6_ifaddr *ifp)
                        /* Because optimistic nodes can use this address,
                         * notify listeners. If DAD fails, RTM_DELADDR is sent.
                         */
-                       ipv6_ifa_notify(RTM_NEWADDR, ifp);
+    read_unlock_bh(&idev->lock);
+    ipv6_ifa_notify(RTM_NEWADDR, ifp);
+    read_lock_bh(&idev->lock);
                }
        }
 
"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.  
그리고 혹시 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려드리겠습니다!"
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
 
 

+ Recent posts