소개
 
이번 시간에는 커널 패닉을 디버깅하는 과정을 소개합니다.
 
1차 분석
 
콜스택을 TRACE32로 잡아 보니 Data abort로 커널 패닉이 발생했습니다.
 
-000|el1_da(asm)
 -->|exception
-001|usb_copy_descriptors(src = 0xFFFFFFF50D806080)
-002|configfs_composite_bind(gadget = 0xFFFFFFF4C4F16298, gdriver = 0xFFFFFFF5B2943B08)
-003|udc_bind_to_driver(udc = 0xFFFFFFF5B67BD000, driver = 0xFFFFFFF5B2943B08)
-004|usb_udc_attach_driver(name = 0xFFFFFFF57B6C3F80, driver = 0xFFFFFFF5B2943B08)
-005|schedule_work(inline)
-005|gadget_dev_desc_UDC_store(item = 0xFFFFFFF5B2943800, ?, len = 12)
-006|configfs_write_file(file = 0xFFFFFFF4D93A7F00, buf = 0x0000007F961D31D1, ?, ppos = 0xFFFFFFF5B9363EB
-007|__vfs_write(file = 0xFFFFFFF4D93A7F00, ?, ?, pos = 0xFFFFFFF5B9363EB0)
-008|vfs_write(file = 0xFFFFFFF4D93A7F00, buf = 0x0000007F961D31D1, ?, pos = 0xFFFFFFF5B9363EB0)
-009|sys_write(?, ?, ?)
-010|el0_svc_naked(asm)
 -->|exception
-011|NUX:0x7F9741D688(asm)
 ---|end of frame
 
Data Abort가 발생한 인스트럭션은 'ldrb w2,[x2]' 인데 x2는 0x736563697665642F입니다.
'0x736563697665642F'이라? 주소의 형태만 봐도 MMU가 처리할 수 없는 주소로 보입니다.
 
 ______________addr/line|code___________|label____|mnemonic________________|comment
   NSX:FFFFFF84CDC306B8|91000421                  add     x1,x1,#0x1       ; x1,x1,#1
   NSX:FFFFFF84CDC306BC|8B010EA2                  add     x2,x21,x1,lsl #0x3   ; x2,src,x1,lsl #3
   NSX:FFFFFF84CDC306C0|F85F8042                  ldur    x2,[x2,#-0x8]    ; x2,[x2,#-8]
   NSX:FFFFFF84CDC306C4|B4000082                  cbz     x2,0xFFFFFF84CDC306D4
___NSX:FFFFFF84CDC306C8|39400042__________________ldrb____w2,[x2]
 
Data Abort가 발생한 소스 코드의 위치는 어딜까요?
 
y.l.line 0xFFFFFF84CDC306C8
 
linux-next\drivers\usb\gadget\config.c|\136--136   
 
이번에는 'v.l %l %t' 명령어로 지역 변수를 어느 레지스터가 저장했는지 확인해볼까요?
 
usb_copy_descriptors(
    (register struct usb_descriptor_header * *) [X21] src = 0xFFFFFFF50D806080)
  (register unsigned int) [X19] n_desc = 0
  
x21은 0xFFFFFFF50D806080입니다.
 
0xFFFFFFF50D806080의 출처는 0xFFFFFFF5551DD800입니다.  
 
  (struct usb_function *) [-] (struct usb_function*)0xFFFFFFF5551DD800 = 0xFFFFFFF5551DD800 -> (
    (char *) [D:0xFFFFFFF5551DD800] name = 0xFFFFFF84CEF20533 -> "mtp",
    (int) [D:0xFFFFFFF5551DD808] intf_id = 0,
    (struct usb_gadget_strings * *) [D:0xFFFFFFF5551DD810] strings = 0xFFFFFF84CFEE3138,
    (struct usb_descriptor_header * *) [D:0xFFFFFFF5551DD818] fs_descriptors = 0xFFFFFFF50D806080 -> 0x1 -> (  //<<--
      (__u8) [D:0x1] bLength = 0,
      (__u8) [D:0x2] bDescriptorType = 0),
    (struct usb_descriptor_header * *) [D:0xFFFFFFF5551DD820] hs_descriptors = 0xFFFFFFF50D806280 -> 0x1 -> ( //<<--
      (__u8) [D:0x1] bLength = 0,
      (__u8) [D:0x2] bDescriptorType = 0),
    (struct usb_descriptor_header * *) [D:0xFFFFFFF5551DD828] ss_descriptors = 0xFFFFFFF50D806F00 -> 0x0 -> NULL //<<--
 
그런데 코어 덤프에서는 otg_desc[0]이 NULL입니다.
 
  (static struct usb_descriptor_header * [2]) otg_desc = (
    [0] = 0x0 =  -> NULL,
    [1] = 0x0 =  -> NULL)
 
(where)
1764static void configfs_composite_unbind(struct usb_gadget *gadget)
1765{
1766 struct usb_composite_dev *cdev;
1767 struct gadget_info *gi;
1768
1769 /* the gi->lock is hold by the caller */
1770
1771 cdev = get_gadget_data(gadget);
1772 gi = container_of(cdev, struct gadget_info, cdev);
1773
1774 kfree(otg_desc[0]);
1775 otg_desc[0] = NULL; //<<--
 
Solution Patch
 
아래와 같이 코드를 수정하면 Data Abort를 방지할 수 있습니다.
 
 
diff --git a/drivers/usb/gadget/configfs.c b/drivers/usb/gadget/configfs.c
index ec94fbb..be06b39 100644
--- a/drivers/usb/gadget/configfs.c
+++ b/drivers/usb/gadget/configfs.c
@@ -1570,7 +1570,7 @@ static int configfs_composite_bind(struct usb_gadget *gadget,
                                goto err_purge_funcs;
                        }
-                       if (f->multi_config_support) {
+                       if (f->multi_config_support && !otg_desc[0]) {
                                if (f->fs_descriptors)
                                        f->fs_descriptors =
                                                usb_copy_descriptors(f->fs_descriptors);
많은 리눅스 시스템 개발자들은 자신이 개발하고 있는 리눅스 커널의 버전이 주류였으면 하는 바램이 있다. 하지만 현실은 다르다. 현재 리눅스 커널의 최신 버전인 4.19(LTS 기준)으로 개발하고 있어도 이전 리눅스 커널 버전에서 다뤘던 자료 구조에 대해 알고 있어야 한다.
 
이번에는 커널 3.10 버전에서 struct anon_vma 구조체와 struct address_space 구조체의 관계에 대해 알아보겠다.
 
먼저 다음 TRACE32 명령어를 입력해 3번째 프레임의 페이지 디스크립터를 확인하자.
 
$(TRACE32 명령어)  v.v %d %t %h %i (struct page[0x7FFF])*mem_map
  (static struct page [32767]) (struct page[0x7FFF])*mem_map = (
    [0] = ((long unsigned int) flags = 524392 = 0x00080068, (struct address_space *) mapping = 0xF70
    [1] = ((long unsigned int) flags = 2592 = 0x0A20, (struct address_space *) mapping = 0xF6E90564,
    [2] = ((long unsigned int) flags = 524392 = 0x00080068, (struct address_space *) mapping = 0xF70
    [3] = (
      (long unsigned int) flags = 524392 = 0x00080068,
      (struct address_space *) mapping = 0xF70A6861,
      (long unsigned int) index = 468946 = 0x000727D2,
      (void *) freelist = 0x000727D2,
      (bool) pfmemalloc = -46 = 0xD2,
      (unsigned int) counters = 0 = 0x0,
 
struct address_space 타입인 mapping 필드는 0xF70A6861 이란 주소를 저장하고 있다.
 
어, 뭔가 이상하다! 왜 주소 끝 부분이 0x1로 끝날까?
 
그 이유는 익명(ANON) 페이지의 mapping 필드는 다음과 같은 규칙으로 정해지기 때문이다.
 
   * page->mapping & 0xFFFFFFFE = struct anon_vma 구조체 주소
 
그렇다면 0xF70A6860 주소를 struct anon_vma 구조체로 캐스팅을 해서 확인해볼까?
 
$(TRACE32 명령어) v.v %d %t %h %i (struct anon_vma)0xF70A6860
 
  (static struct anon_vma) (struct anon_vma)0xF70A6860 = (
    (struct anon_vma *) root = 0xF70A6860,
    (struct rw_semaphore) rwsem = (
      (__s32) activity = 0 = 0x0,
      (raw_spinlock_t) wait_lock = (
        (arch_spinlock_t) raw_lock = (
          (u32) slock = 171772477 = 0x0A3D0A3D,
          (struct __raw_tickets) tickets = (
            (u16) owner = 2621 = 0x0A3D,
            (u16) next = 2621 = 0x0A3D))),
      (struct list_head) wait_list = (
        (struct list_head *) next = 0xF70A686C,
        (struct list_head *) prev = 0xF70A686C)),
    (atomic_t) refcount = ((int) counter = 1 = 0x1),
    (struct rb_root) rb_root = ((struct rb_node *) rb_node = 0xF733FCF0))
 
필드를 보니 제대로된 값을 저장하고 있는 듯 하다.
스핀락의 티켓과 오너의 값이 같으니 말이다.
 
이번에는 메모리 릭으로 의심이 되는 mm_struct 구조체를 확인해보자.
 
$(TRACE32 명령어) v.v %i %h %t (struct mm_struct)0xF7F41880 
 
  (static struct mm_struct) (struct mm_struct)0xF7F41880 = (
    (struct vm_area_struct *) mmap = 0xF706DE70 -> (
      (long unsigned int) vm_start = 0x48400000,
      (long unsigned int) vm_end = 0xB4C00000,
      (struct vm_area_struct *) vm_next = 0xF71F34D0,
      (struct vm_area_struct *) vm_prev = 0x0,
      (struct rb_node) vm_rb = ((long unsigned int) __rb_parent_color = 0xF71F34E1, (struct rb_node
      (long unsigned int) rb_subtree_gap = 0x48400000,
      (struct mm_struct *) vm_mm = 0xF7F41880,
      (pgprot_t) vm_page_prot = 0x079F,
      (long unsigned int) vm_flags = 0x00100073,
      (union) shared = ((struct) linear = ((struct rb_node) rb = ((long unsigned int) __rb_parent_co
      (struct list_head) anon_vma_chain = ((struct list_head *) next = 0xF733FCE8, (struct list_head
      (struct anon_vma *) anon_vma = 0xF70A6860,
      (struct vm_operations_struct *) vm_ops = 0x0,
      (long unsigned int) vm_pgoff = 0x00048400,
      (struct file *) vm_file = 0x0,
      (void *) vm_private_data = 0x0),
 
anon_vma의 구조체인 anon_vma 필드가 0xF70A6860 주소를 저장하고 있다.
 
그렇다면, 다음과 같은 규칙에 따라 익명 페이지의 페이지 디스크립터 mapping 필드는 
0xF70A6861 일 것이다.  
 
   * page->mapping & 0xFFFFFFFE = struct anon_vma 구조체 주소
 
크래시 유틸리티를 사용해 0xF70A6861 주소를 누가 얼만큼 저장하는지 알아볼까?
아래는 'search 0xF70A6861' 명령어를 입력한 출력 결과이다.
 
crash> search 0xF70A6861
ce600004: f70a6861
ce60004c: f70a6861
ce600070: f70a6861
ce600124: f70a6861
ce600148: f70a6861
ce60016c: f70a6861
ce600190: f70a6861
...
 
엄청난 결과가 출력이 된다.
 
전체 페이지 디스크립터 중 0xF70A6861을 얼마나 차지하는지 확인해볼까?
 
crash> search 0xF70A6861 | wc -l
443296
 
무려 443296 개나 된다.
 
페이지 한 개당 크기가 4096이니 다음과 같은 계산식으로 익명 페이지가 1,731MB 의 메모리 공간을 차지하고 있다.
 
443296 * 4096 = 0x6C3A_0000
0x1B0E80KB(0x6C3A_0000/1024) = 1,731MB(0x1B0E80/1024)
 
 
   * 결론은 유저 공간의 메모리 릭이다!
 
참고로, 익명 페이지는 거의 유저 공간에 어떤 파일을 읽거나 쓸 때 사용한다.
 
위에서 살펴본 덤프는 아래 콜스택과 같이 메모리가 부족해 OOM Killer이 발생해 추출됐다.
 
-000|out_of_memory()
-001|__alloc_pages_may_oom(inline)
-001|__alloc_pages_slowpath(inline)
-001|__alloc_pages_nodemask()
-002|alloc_pages_node(inline)
-002|__page_cache_alloc(inline)
-002|page_cache_alloc_cold(inline)
-002|page_cache_read(inline)
-002|filemap_fault()
-003|alloc_pages_node(inline)
-003|__do_fault()
-004|handle_pte_fault()
-005|pmd_page_vaddr(inline)
-005|__handle_mm_fault(inline)
-005|handle_mm_fault()
-006|__do_page_fault(inline)
-006|do_page_fault()
-007|do_PrefetchAbort()
-008|__pabt_usr(asm)
 -->|exception
 
커널 로그는 다음과 같습니다. UI freeze 상태라 강제 커널 크래시를 유발시켜 램덤프를 추출했습니다.
 
[ 7164.614352] tegra sound_card.27: Ply shutdown, devnum 7
[ 7165.077580] ------------[ cut here ]------------
[ 7165.077807] WARNING: at /root/rpi/kernel/workqueue.c:2904 __cancel
_work_timer+0x12c/0x178()
[ 7165.087114] Modules linked in: texfat(PO)
[ 7165.092596] CPU: 3 PID: 1373 Comm: mmcqd/0 Tainted: P        W  O 3.10.44+ #1
[ 7165.101579] [<c0017344>] (unwind_backtrace+0x0/0x144) from [<c0013874>] (show_stack+0x20/0x24)
[ 7165.111750] [<c0013874>] (show_stack+0x20/0x24) from [<c0936350>] (dump_stack+0x20/0x28)
[ 7165.121489] [<c0936350>] (dump_stack+0x20/0x28) from [<c0028848>] (warn_slowpath_common+0x5c/0x7c)
[ 7165.132133] [<c0028848>] (warn_slowpath_common+0x5c/0x7c) from [<c0028894>] (warn_slowpath_null+0x2c/0x34)
[ 7165.143418] [<c0028894>] (warn_slowpath_null+0x2c/0x34) from [<c0048600>] (__cancel_work_timer+0x12c/0x178)
[ 7165.154654] [<c0048600>] (__cancel_work_timer+0x12c/0x178) from [<c0048668>] (cancel_delayed_work_sync+0x1c/0x20)
[ 7165.168097] [<c0048668>] (cancel_delayed_work_sync+0x1c/0x20) from [<c007b588>] (pm_qos_update_request+0x34/0xac)
[ 7165.178711] [<c007b588>] (pm_qos_update_request+0x34/0xac) from [<c064348c>] (sdhci_disable+0x2c/0x48)
[ 7165.189268] [<c064348c>] (sdhci_disable+0x2c/0x48) from [<c062e68c>] (mmc_release_host+0xa8/0xc0)
[ 7165.199855] [<c062e68c>] (mmc_release_host+0xa8/0xc0) from [<c0640794>] (mmc_blk_issue_rq+0x104/0x664)
[ 7165.210600] [<c0640794>] (mmc_blk_issue_rq+0x104/0x664) from [<c0641514>] (mmc_queue_thread+0xb4/0x14c)
[ 7165.221673] [<c0641514>] (mmc_queue_thread+0xb4/0x14c) from [<c004ef1c>] (kthread+0xc0/0xd0)
[ 7165.231685] [<c004ef1c>] (kthread+0xc0/0xd0) from [<c000f788>] (ret_from_fork+0x14/0x20)
[ 7165.241314] ---[ end trace b64c1dfefe8a5e9e ]---
 
 
각 cpu별 current task들의 backtrace
0 번 CPU만 key에 의한 강제 crash를 발생 시키기 위한 work thread가 돌고 있고 나머지 cpu들은 idle task였습니다.
 
PID: 21555  TASK: c3e76400  CPU: 0   COMMAND: "kworker/0:1" ? 강제 crash를 발생한 work
#0 [<c03df0c4>] (crash_kexec_odin) from [<c0931038>]
#1 [<c0931038>] (panic) from [<c0013b4c>]
#2 [<c0013b4c>] (die) from [<c0013ba8>]
#3 [<c0013ba8>] (arm_notify_die) from [<c0008370>]
#4 [<c0008370>] (do_undefinstr) from [<c000f2f0>]
 
PID: 0      TASK: d909e400  CPU: 1   COMMAND: "swapper/1"
#0 [<c00166b0>] (machine_crash_nonpanic_core) from [<c0098774>]
#1 [<c0098774>] (generic_smp_call_function_single_interrupt) from [<c00158ec>]
#2 [<c00158ec>] (handle_IPI) from [<c00086f0>]
#3 [<c00086f0>] (gic_handle_irq) from [<c000f244>]
#4 [<c000f244>] (__irq_svc) from [<c008dce4>]
 
PID: 0      TASK: d909ee00  CPU: 2   COMMAND: "swapper/2"
#0 [<c00166b0>] (machine_crash_nonpanic_core) from [<c0098774>]
#1 [<c0098774>] (generic_smp_call_function_single_interrupt) from [<c00158ec>]
#2 [<c00158ec>] (handle_IPI) from [<c00086f0>]
#3 [<c00086f0>] (gic_handle_irq) from [<c000f244>]
#4 [<c000f244>] (__irq_svc) from [<c008dce4>]
#5 [<c007e63c>] (cpu_startup_entry) from [<c092dc10>]
 
PID: 0      TASK: d92a0000  CPU: 3   COMMAND: "swapper/3"
#0 [<c00166b0>] (machine_crash_nonpanic_core) from [<c0098774>]
#1 [<c0098774>] (generic_smp_call_function_single_interrupt) from [<c00158ec>]
#2 [<c00158ec>] (handle_IPI) from [<c00086f0>]
#3 [<c00086f0>] (gic_handle_irq) from [<c000f244>]
#4 [<c000f244>] (__irq_svc) from [<c008dce4>]
 
 
task state 확인
system_server가 UNINTERRUPTIBLE 상태였습니다. 따라서, UI freeze 발생한 것으로 보입니다.
 
2611      2   3  d79d4600  UN   0.0       0      0  [jbd2/mmcblk0p29]
   2627      2   2  d82dc600  UN   0.0       0      0  [jbd2/mmcblk0p10]
   2630      2   1  d82dee00  UN   0.0       0      0  [jbd2/mmcblk0p22]
   2977      1   3  d82c0a00  UN   0.0    1092    524  rctd
   2993      1   2  d6763c00  UN   0.0    3576    776  sdcard
   3053   2981   0  d84a6e00  UN   0.0     904    432  logcat
   3066   2980   2  d7c91e00  UN   0.0    1312    876  kernel_logger
   3070   2984   0  d7f2da00  UN   0.0     900    428  logcat
   3071   2985   3  d7c91400  UN   0.0     916    440  logcat
   3072   2982   0  d75a8a00  UN   0.0     900    428  logcat
   3077   2986   3  d776b200  UN   0.1    3560   1144  tcpdump
   3127   2758   1  d66ca800  UN   5.5 1075264 112420  system_server
   3304      2   2  d6f69e00  UN   0.0       0      0  [ts_ldisc_tx_loo]
   3305      1   3  d7cbe400  UN   0.1    5568   1248  nvm_server
   3332   2758   2  d675e400  UN   5.5 1075264 112420  InputDispatcher
   3546   2758   3  d7cba800  UN   5.5 1075264 112420  Binder_5
   3556   2758   1  d6f6a800  UN   5.5 1075264 112420  watchdog
   3598   2758   0  d79f8000  UN   3.5  986664  72460  com.lge.ime
   4674      1   2  c6562800  UN   0.0   11324    576  thermalmgr
   5103      1   0  c55f0000  UN   0.0    1040    576  dhcpcd
 
 
system_server Call Stack
system_server가 file open을 하는 도중, mutex_lock을 얻기 위해, UNINTERRUPTIBLE 상태로 들어간 상태에서 schedule된 상태입니다.
 
crash> bt 3127
PID: 3127   TASK: d66ca800  CPU: 1   COMMAND: "system_server"
#0 [<c093de28>] (__schedule) from [<c093e324>]
#1 [<c093e324>] (schedule) from [<c093e6e0>]
#2 [<c093e6e0>] (schedule_preempt_disabled) from [<c093cab4>]
#3 [<c093cab4>] (mutex_lock_nested) from [<c0145ed8>]
#4 [<c0145ed8>] (do_last) from [<c0146950>]
#5 [<c0146950>] (path_openat) from [<c014707c>]
#6 [<c014707c>] (do_filp_open) from [<c01372d0>]
#7 [<c01372d0>] (do_sys_open) from [<c0137398>]
#8 [<c0137398>] (sys_open) from [<c000f6c0>]
    pc : [<400a0918>]    lr : [<400ae009>]    psr: 200f0010
    sp : be807318  ip : 6d773a44  fp : be80736c
    r10: 417ed7a0  r9 : 6d773a38  r8 : be807354
    r7 : 00000005  r6 : 00000042  r5 : 00000180  r4 : 417ed178
    r3 : be807328  r2 : 00000180  r1 : 00020042  r0 : 88d01960
    Flags: nzCv  IRQs on  FIQs on  Mode USER_32  ISA ARM
 
 
해당 mutex lock 조사
 
crash> struct mutex 0xD8F0B900
struct mutex {
  count = {
    counter = -1  // lock 걸려있음
  },
<생략>
  wait_list = {
    next = 0xd626fdb0,
    prev = 0xd626fdb0
  },
  owner = 0xc4815000,   // lock의 owner임
  name = 0x0,
  magic = 0xd8f0b900,
  dep_map = {
    key = 0xc0fa51e8 <ext4_fs_type+92>,
    class_cache = {0xc124114c <lock_classes+231200>, 0xc1241bec <lock_classes+233920>},
    name = 0xc0ce3190 "&type->i_mutex_dir_key"
  }
}
 
 
owner task의 backtrace
 
PID: 21441   TASK: c4815000  CPU: 4   COMMAND: "BatteryStats-Wr"
#0 [<c093de28>] (__schedule) from [<c093e324>]
#1 [<c093e324>] (schedule) from [<c01eb6a0>]
#2 [<c01eb6a0>] (start_this_handle) from [<c01ebb44>]
#3 [<c01ebb44>] (jbd2__journal_start) from [<c01d3810>]
#4 [<c01d3810>] (__ext4_journal_start_sb) from [<c01a66f8>]
#5 [<c01a66f8>] (__ext4_new_inode) from [<c01b5bd4>]
#6 [<c01b5bd4>] (ext4_create) from [<c0143dcc>]
#7 [<c0143dcc>] (vfs_create) from [<c01464a0>]
#8 [<c01464a0>] (do_last) from [<c0146950>]
#9 [<c0146950>] (path_openat) from [<c014707c>]
#10 [<c014707c>] (do_filp_open) from [<c01372d0>]
#11 [<c01372d0>] (do_sys_open) from [<c0137398>]
#12 [<c0137398>] (sys_open) from [<c000f6c0>]
    pc : [<400a0918>]    lr : [<400ae009>]    psr: 20070010
    sp : 7f639ad0  ip : 796fbef4  fp : 7f639b24
    r10: 87b27138  r9 : 796fbee8  r8 : 7f639b0c
    r7 : 00000005  r6 : 00000241  r5 : 00000180  r4 : 86d5cd08
    r3 : 7f639ae0  r2 : 00000180  r1 : 00020241  r0 : 80b05e48
    Flags: nzCv  IRQs on  FIQs on  Mode USER_32  ISA ARM
 
 
0xc4815000 task(PID ? 21441, BatteryStats-Wr ) 도 UNINTERRUPTIBLE 상태임
 
21441   2758   4  c4815000  UN   5.5 1075264 112420  BatteryStats-Wr
 
 
BatteryStats-Wr task가 mutex lock을 accquire한 상태에서, TASK_UNINTERRUPTIBLE로 들어갔고, 
system_server는 같은 mutex lock을 accquire하기 위해 대기중 인 상태라 UI Freeze가 발생한 것으로 보입니다.
 
static int start_this_handle(journal_t *journal, handle_t *handle) {
<생략>
              spin_lock(&transaction->t_handle_lock);
              needed = transaction->t_outstanding_credits + nblocks;
 
              if (needed > journal->j_max_transaction_buffers) {
                            DEFINE_WAIT(wait);
 
                            jbd_debug(2, "Handle %p starting new commit...\n", handle);
                            spin_unlock(&transaction->t_handle_lock);
                            prepare_to_wait(&journal->j_wait_transaction_locked, &wait, TASK_UNINTERRUPTIBLE); //--> 여기서 UN으로 들어감
                            __log_start_commit(journal, transaction->t_tid);
                            spin_unlock(&journal->j_state_lock);
                            schedule();
                            finish_wait(&journal->j_wait_transaction_locked, &wait);
                            goto repeat;
              }
}
 
 
TASK_UNINTERRUPTIBLE 상태인 다른 몇몇 task의 backtrace를 조사해 봤습니다.
 
PID: 2611   TASK: d79d4600  CPU: 3   COMMAND: "jbd2/mmcblk0p29"
#0 [<c093de28>] (__schedule) from [<c093e324>]
#1 [<c093e324>] (schedule) from [<c01ee80c>]
#2 [<c01ee80c>] (jbd2_journal_commit_transaction) from [<c01f4794>]
#3 [<c01f4794>] (kjournald2) from [<c004ef1c>]
#4 [<c004ef1c>] (kthread) from [<c000f788>]
 
 
아래의 코드에서 UNINTERRUPTIBLE로 상태로 변경 후 schedule됩니다.
 
void jbd2_journal_commit_transaction(journal_t *journal){
// snip
              while (atomic_read(&commit_transaction->t_updates)) {
                            DEFINE_WAIT(wait);
                            prepare_to_wait(&journal->j_wait_updates, &wait, TASK_UNINTERRUPTIBLE);
                            if (atomic_read(&commit_transaction->t_updates)) {
                                          spin_unlock(&commit_transaction->t_handle_lock);
                                          write_unlock(&journal->j_state_lock);
                                          schedule();
                                          write_lock(&journal->j_state_lock);
                                          spin_lock(&commit_transaction->t_handle_lock);
                            }
                            finish_wait(&journal->j_wait_updates, &wait);
              }  // snip
 
 
아래와 같이 commit_transaction->t_updates가 2입니다.
 
crash> struct transaction_s.t_updates 0xD6858D80
 t_updates = {
   counter = 2
 }
 
 
BatteryStats-Wr task가 mutex lock을 accquire한 상태에서, TASK_UNINTERRUPTIBLE로 들어갔고, system_server는 같은 mutex lock을 accquire하기 위해 대기중 인 상태라 UI Freeze가 발생한 것으로 보입니다.
 
static int start_this_handle(journal_t *journal, handle_t *handle) {
<생략>
              spin_lock(&transaction->t_handle_lock);
              needed = transaction->t_outstanding_credits + nblocks;
 
              if (needed > journal->j_max_transaction_buffers) {
                            DEFINE_WAIT(wait);
 
                            jbd_debug(2, "Handle %p starting new commit...\n", handle);
                            spin_unlock(&transaction->t_handle_lock);
                            prepare_to_wait(&journal->j_wait_transaction_locked, &wait, TASK_UNINTERRUPTIBLE); //<<-- 여기서 UN으로 들어감
                            __log_start_commit(journal, transaction->t_tid);
                            spin_unlock(&journal->j_state_lock);
                            schedule();
                            finish_wait(&journal->j_wait_transaction_locked, &wait);
                            goto repeat;
              }
}
.
 
jbd2/mmcblk0p10 task를 보면, 아래의 코드에서 UNINTERRUPTIBLE로 상태로 변경 후 schedule됐는데, io buffer가 lock상태여서, lock이 풀릴때까지 대기 상태에 있는 것입니다.
 
void jbd2_journal_commit_transaction(journal_t *journal) {
<생략>
                            jh = commit_transaction->t_iobuf_list->b_tprev;
                            bh = jh2bh(jh);
                            if (buffer_locked(bh)) {
                                          wait_on_buffer(bh);
                                          goto wait_for_iobuf;
                            }
<생략>
}
PID: 2627   TASK: d82dc600  CPU: 2   COMMAND: "jbd2/mmcblk0p10"
#0 [<c093de28>] (__schedule) from [<c093e324>]
#1 [<c093e324>] (schedule) from [<c093e3d4>]
#2 [<c093e3d4>] (io_schedule) from [<c0168084>]
#3 [<c0168084>] (sleep_on_buffer) from [<c093b784>]
#4 [<c093b784>] (__wait_on_bit) from [<c093b834>]
#5 [<c093b834>] (out_of_line_wait_on_bit) from [<c0168064>]
#6 [<c0168064>] (__wait_on_buffer) from [<c01ef218>]
#7 [<c01ef218>] (jbd2_journal_commit_transaction) from [<c01f4794>]
#8 [<c01f4794>] (kjournald2) from [<c004ef1c>]
#9 [<c004ef1c>] (kthread) from [<c000f788>]
 
 
TASK_UNINTERRUPTIBLE상태의 task중 아래와 같이 대부분의 task들이 file관련 동작중 TASK_UNINTERRUPTIBLE상태로 진입한 상태입니다.
 
PID: 2977   TASK: d82c0a00  CPU: 3   COMMAND: "rctd"
PID: 2993   TASK: d6763c00  CPU: 2   COMMAND: "sdcard"
PID: 3053   TASK: d84a6e00  CPU: 0   COMMAND: "logcat"
PID: 3070   TASK: d7f2da00  CPU: 0   COMMAND: "logcat"
PID: 3071   TASK: d7c91400  CPU: 3   COMMAND: "logcat"
PID: 3072   TASK: d75a8a00  CPU: 0   COMMAND: "logcat"
PID: 3077   TASK: d776b200  CPU: 3   COMMAND: "tcpdump"
PID: 3127   TASK: d66ca800  CPU: 1   COMMAND: "system_server"
PID: 3305   TASK: d7cbe400  CPU: 3   COMMAND: "nvm_server"
PID: 3332   TASK: d675e400  CPU: 2   COMMAND: "InputDispatcher"
PID: 3546   TASK: d7cba800  CPU: 3   COMMAND: "Binder_5"
PID: 3556   TASK: d6f6a800  CPU: 1   COMMAND: "watchdog"
PID: 5103   TASK: c55f0000  CPU: 0   COMMAND: "dhcpcd"
PID: 5165   TASK: c5008a00  CPU: 1   COMMAND: "GC"
PID: 5738   TASK: c59e3200  CPU: 2   COMMAND: "Thread-315"
PID: 8773   TASK: c5344600  CPU: 3   COMMAND: "kworker/u16:6"
PID: 21359  TASK: c4826e00  CPU: 2   COMMAND: "OMXCallbackDisp"
PID: 21413  TASK: d6e48000  CPU: 0   COMMAND: "Thread-220"
PID: 21416  TASK: c9ee0a00  CPU: 1   COMMAND: "referencesProto"
PID: 21424  TASK: d84a4600  CPU: 0   COMMAND: "Compiler"
PID: 21431  TASK: c62c1e00  CPU: 4   COMMAND: "UsageStatsServi"
PID: 21441  TASK: c4815000  CPU: 4   COMMAND: "BatteryStats-Wr"
 
 
다시 최초의 log를 리뷰하니 PID 1373, mmcqd/0 task에서 WARNING 메시지 출력합니다.
 
[ 7165.077807] WARNING: at /root/pi/kernel/workqueue.c:2904 __cancel_work_timer+0x12c/0x178()
[ 7165.087114] Modules linked in: texfat(PO)
[ 7165.092596] CPU: 3 PID: 1373 Comm: mmcqd/0 Tainted: P        W  O 3.10.44+ #1
[ 7165.101579] [<c0017344>] (unwind_backtrace+0x0/0x144) from [<c0013874>] (show_stack+0x20/0x24)
[ 7165.111750] [<c0013874>] (show_stack+0x20/0x24) from [<c0936350>] (dump_stack+0x20/0x28)
[ 7165.121489] [<c0936350>] (dump_stack+0x20/0x28) from [<c0028848>] (warn_slowpath_common+0x5c/0x7c)
[ 7165.132133] [<c0028848>] (warn_slowpath_common+0x5c/0x7c) from [<c0028894>] (warn_slowpath_null+0x2c/0x34)
[ 7165.143418] [<c0028894>] (warn_slowpath_null+0x2c/0x34) from [<c0048600>] (__cancel_work_timer+0x12c/0x178)
[ 7165.154654] [<c0048600>] (__cancel_work_timer+0x12c/0x178) from [<c0048668>] (cancel_delayed_work_sync+0x1c/0x20)
[ 7165.168097] [<c0048668>] (cancel_delayed_work_sync+0x1c/0x20) from [<c007b588>] (pm_qos_update_request+0x34/0xac)
[ 7165.178711] [<c007b588>] (pm_qos_update_request+0x34/0xac) from [<c064348c>] (sdhci_disable+0x2c/0x48)
[ 7165.189268] [<c064348c>] (sdhci_disable+0x2c/0x48) from [<c062e68c>] (mmc_release_host+0xa8/0xc0)
[ 7165.199855] [<c062e68c>] (mmc_release_host+0xa8/0xc0) from [<c0640794>] (mmc_blk_issue_rq+0x104/0x664)
[ 7165.210600] [<c0640794>] (mmc_blk_issue_rq+0x104/0x664) from [<c0641514>] (mmc_queue_thread+0xb4/0x14c)
[ 7165.221673] [<c0641514>] (mmc_queue_thread+0xb4/0x14c) from [<c004ef1c>] (kthread+0xc0/0xd0)
[ 7165.231685] [<c004ef1c>] (kthread+0xc0/0xd0) from [<c000f788>] (ret_from_fork+0x14/0x20)
 
 
 mmcqd관련 task의 backtrace 조사한 결과를 정리하면 다음과 같습니다.
 
 01 |  mmcqd/0 task의 backtrace를 보면, WARNING을 출력했던 backtrace와 동일한 backtrace를 가지고 있음을 알 수 있음.
 02 | mmcqd/0는 mmc 동작중 pm_qos를 통해 boosting을 했고, 완료 이후, pm_qos설정을 이전으로 돌리기 위한 작업을 진행하는 과정
 03 |   sdhci_disable () -> pm_qos_update_request () -> cancel_delayed_work_sync () -> __cancel_work_timer () -> schedule ()
 
PID: 1373    TASK: d7d29400  CPU: 7   COMMAND: "mmcqd/0"
#0 [<c093de28>] (__schedule) from [<c093e324>]
#1 [<c093e324>] (schedule) from [<c0048610>]
#2 [<c0048610>] (__cancel_work_timer) from [<c0048668>]
#3 [<c0048668>] (cancel_delayed_work_sync) from [<c007b588>]
#4 [<c007b588>] (pm_qos_update_request) from [<c064348c>]
#5 [<c064348c>] (sdhci_disable) from [<c062e68c>]
#6 [<c062e68c>] (mmc_release_host) from [<c0640794>]
#7 [<c0640794>] (mmc_blk_issue_rq) from [<c0641514>]
#8 [<c0641514>] (mmc_queue_thread) from [<c004ef1c>]
#9 [<c004ef1c>] (kthread) from [<c000f788>]
 
PID: 1374   TASK: d7d29e00  CPU: 0   COMMAND: "mmcqd/0boot0"
#0 [<c093de28>] (__schedule) from [<c093e324>]
#1 [<c093e324>] (schedule) from [<c0641580>]
#2 [<c0641580>] (mmc_queue_thread) from [<c004ef1c>]
#3 [<c004ef1c>] (kthread) from [<c000f788>]
 
PID: 1375   TASK: d79d6e00  CPU: 0   COMMAND: "mmcqd/0boot1"
#0 [<c093de28>] (__schedule) from [<c093e324>]
#1 [<c093e324>] (schedule) from [<c0641580>]
#2 [<c0641580>] (mmc_queue_thread) from [<c004ef1c>]
#3 [<c004ef1c>] (kthread) from [<c000f788>]
 
PID: 1376   TASK: d79d6400  CPU: 2   COMMAND: "mmcqd/0rpmb"
#0 [<c093de28>] (__schedule) from [<c093e324>]
#1 [<c093e324>] (schedule) from [<c0641580>]
#2 [<c0641580>] (mmc_queue_thread) from [<c004ef1c>]
#3 [<c004ef1c>] (kthread) from [<c000f788>]
 
PID: 1472   TASK: d8222800  CPU: 2   COMMAND: "mmcqd/1"
#0 [<c093de28>] (__schedule) from [<c093e324>]
#1 [<c093e324>] (schedule) from [<c0641580>]
#2 [<c0641580>] (mmc_queue_thread) from [<c004ef1c>]
#3 [<c004ef1c>] (kthread) from [<c000f788>]
 
 
__cancel_work_timer ()  함수에서 mmcqd  프로세스가 TASK_INERRUPTIBLE로 진입 후 schedule() 됩니다.
 
static bool __cancel_work_timer(struct work_struct *work, bool is_dwork) {
<생략>
              do {
                            ret = try_to_grab_pending(work, is_dwork, &flags);
                            if (unlikely(ret == -ENOENT)) {
                                          if (!flush_work(work)) {
                                                        if (work_is_canceling(work)) {
                                                                      set_current_state(TASK_INTERRUPTIBLE);
                                                                      schedule(); //<<--INTERRUPTIBLE로 진입후 스케쥴
                                                                      __set_current_state(TASK_RUNNING);
                                                        }
                                          }
                            }
              } while (unlikely(ret < 0));
<생략> }
 
 
최초 로그의 WARNING이 출력된 시간과 비슷(7165s) 합니다.
 
crash> struct task_struct.se 0xd7d29400
 se = {
   load = {
     weight = 1024,
     inv_weight = 4194304
   },
   run_node = {
     __rb_parent_color = 1,
     rb_right = 0x0,
     rb_left = 0x0
   },
   group_node = {
     next = 0xd7d2944c,
     prev = 0xd7d2944c
   },
   on_rq = 0,
   exec_start = 7165247678131, //<<-- 최초 로그의 WARNING이 출력된 시간과 비슷함(7165s)
 
 
task_struct.se.exec_start는 아래의 코드에서 update가 되도록 되어있습니다.
 
static void update_curr(struct cfs_rq *cfs_rq){ <생략>
              curr->exec_start = now;
<생략>
}
 
 
emmc 관련 동작을 하는 mmcqd/0 가 7165s wakeup되어 running중, TASK_INTERRUPTIBLE 상태로 schedule이 되고, 다시 wakeup되지 않습니다.
 1.  file open/read/write 및 jonrnaling 등의 동작을 시도한 task들이 전부 TASK_UNINTERRUPTIBLE상태로 들어가게 됨.
 2.  따라서, UI Freeze로 현상이 나타남.
 
 
 
다음 패치를 적용한 후 UI Freeze 현상은 사라졌습니다.
diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index e1cae9d..cb3a27b 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -2759,6 +2759,7 @@ static bool __cancel_work_timer(struct work_struct *work, bool is_dwork)
 * If someone else is canceling, wait for the same event it
                 * would be waiting for before retrying.
                 */
 
-               if (unlikely(ret == -ENOENT))
-                       flush_work(work);
+               if (unlikely(ret == -ENOENT)) {
+                       if (!flush_work(work) &&  current->policy == SCHED_FIFO && work_is_canceling(work)) {   
+                               struct sched_param old, new;
+                               new.sched_priority = 0;
+                               sched_setscheduler(current, SCHED_NORMAL, &new);
+                               schedule();
+                               sched_setscheduler(current, SCHED_FIFO, &old);
+                       }
+               }
 
 
"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.  
혹시 글을 읽고 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려 드리겠습니다!"
 
이번에는 비트 플립으로 발생한 커널 패닉 코어 덤프 분석 과정을 소개합니다.
 
다음은 T32로 커널 패닉이 발생했을 때 잡은 콜스택입니다.
01 -000|machine_restart(?)
02 -001|arch_local_irq_enable(inline)
03 -001|panic(fmt = 0xC0EF195A)
04 -002|oops_end(inline)
05 -002|die(str = 0xC017409E, ?, err = -590234666)
06 -003|do_undefinstr(regs = 0xDCD1BCA8)
07 -004|__und_svc_fault(asm)
08  -->|exception
09 -005|profile_tick(type = -590234136)
10 -006|tick_sched_timer(timer = 0xC5B5B620)
11 -007|static_key_false(inline)
12 -007|trace_hrtimer_expire_exit(inline)
13 -007|__run_hrtimer(timer = 0xC5B5B620, now = 0xDCD1BD68)
14 -008|hrtimer_interrupt(?)
15 -009|timer_handler(inline)
16 -009|arch_timer_handler_virt(?, ?)
17 -010|static_key_false(inline)
18 -010|trace_irq_handler_exit(inline)
19 -010|handle_percpu_devid_irq(irq = 20, desc = 0xE1C08F00)
20 -011|generic_handle_irq(irq = 20)
21 -012|handle_IRQ(irq = 20, ?)
22 -013|gic_handle_irq(regs = 0xC5B5B620)
23 -014|__irq_svc(asm)
24  -->|exception
25 -015|open_check_o_direct(f = 0xDB621900)
26 -016|do_last(nd = 0xDCD1BF00, path = 0xDCD1BEC0, file = 0xDB621900, ?, opened = 0xDCD1BEBC, name = 0xC02057EC)
27 -017|path_openat(dfd = -100, ?, nd = 0xDCD1BF00, op = 0xDCD1BF78, flags = 65)  // /proc/32/status
28 -018|do_filp_open(dfd = -100, pathname = 0xD44BC000, op = 0xDCD1BF78, flags = 1)
29 -019|do_sys_open(dfd = -614328064, ?, flags = 131072, ?)
 
콜스택 정보로 보아 profile_tick() 함수에서 undefined instruction 익셉션이 발생했음을 알 수 있습니다.
07 -004|__und_svc_fault(asm)
08  -->|exception
09 -005|profile_tick(type = -590234136)
10 -006|tick_sched_timer(timer = 0xC5B5B620)
 
07번 째 줄을 보면 undefined instruction 익셉션 벡터인 __und_svc_fault 레이블을 볼 수 있습니다.
 
문제를 분석하기 위해 익셉션이 발생한 0xc0174084 주소 코드를 점검했습니다.
01 0xc0174084 <profile_handoff_task+0x24>:                 ; <UNDEFINED> instruction: 0x87bfd030
 /root/pi/kernel/kernel/profile.c: 154
02  0xc0174088 <profile_munmap>:    andeq   r0, r0, r0
 /root/pi/kernel/kernel/profile.c: 155
03 0xc017408c <profile_munmap+0x4>:        ldmdahi r7!, {r3, r4, r5, r6, r8, r12, sp, lr, pc}^
 
0xc0174084 주소에 있는 어셈블리 코드를 보니 <UNDEFINED> instruction:을 확인할 수 있습니다.
 
0xc0174084 주소에서 비트 플립으로 익셉션이 발생했음을 확인할 수 있었습니다.
우선 콜스택부터 점검을 해보면, "kswapd0" 프로세스에서 slab cache를 scanning 하는 도중 커널 크래시가 발생하였음을 알 수 있습니다. 메모리가 부족한 상태로 보입니다. ("kswapd0" 프로세스는 page memory가 부족할 때 실행됩니다.)
-000|do_DataAbort(addr = 3244789312, fsr = 3245415784, regs = 0xC1678E40)
-001|__dabt_svc(asm)
 -->|exception
-002|test_and_set_bit(asm)  // <<**** kernel panic
-003|bit_spin_lock(inline)
-003|hlist_bl_lock(inline)
-003|mb_cache_shrink_scan(?, ?)
-004|shrink_slab_node(shrinkctl = 0xED1C9F08, shrinker = 0xC1721FF0, ?, ?)
-005|shrink_slab(shrinkctl = 0xED1C9F08, nr_pages_scanned = 871, lru_pages = 392
-006|kswapd_shrink_zone(inline)
-006|balance_pgdat(inline)
-006|kswapd(p = 0xC1830580)
-007|kthread(_create = 0xED18ED80)
-008|ret_from_fork(asm)
-009|ret_fast_syscall(asm)
 
커널 패닉이 발생한 주소는 0xC037B07C인데, r12가 0x2이라서 "strneb r1,[r12] " 명령어 실행 도중 data abort가 trigger되었습니다.
   NSR:C037B078|E211C003  _test_and_set_bit:      ands    r12,r1,#0x3      ; r12,r1,#3
___NSR:C037B07C|15CC1000                          strneb  r1,[r12]   <<-- kernel panic
 
그럼 r12가 왜 0x2가 되었는지. 그리고 어떤 데이터 structure였는지 코드 리뷰를 해보면,
bit_spin_lock() 함수에서 _test_and_set_bit() 함수 호출 시 r9(0xE9C25A4E)에서 r1으로 copy를 하고,
______addr/line|code_____|label__________________|mnemonic________________|comment
   NSR:C0256018|E3A00000                          mov     r0,#0x0          ; r0,#0
   NSR:C025601C|E1A01009                          cpy     r1,r9
   NSR:C0256020|EB049414                          bl      0xC037B078       ; _test_and_set_bit
 
_test_and_set_bit() 함수 첫 instruction에서 "ands r12,r1,#0x3" 동작으로 r12가 0x2가 되었습니다.
   NSR:C037B078|E211C003  _test_and_set_bit:      ands    r12,r1,#0x3      ; r12,r1,#3  // <<-- r1: 0xE9C25A4E
___NSR:C037B07C|15CC1000                          strneb  r1,[r12]   <<-- kernel panic
 
그럼, bit_spin_lock() 함수에서 _test_and_set_bit() 함수 호출 시 쓰이는 r9의 출처는 어디 일까요?
@C0255FF8 주소에서 "ldr r9,r4,#0x34" 인스트럭션으로 r9가 0xE9C25A4E로 업데이트됩니다.
   NSR:C0255FF8|E5949034                          ldr     r9,[r4,#0x34]
   NSR:C0255FFC|E3C3303F                          bic     r3,r3,#0x3F      ; r3,r3,#63
   NSR:C0256000|E5932004                          ldr     r2,[r3,#0x4]
   NSR:C0256004|E2822001                          add     r2,r2,#0x1       ; r2,r2,#1
   NSR:C0256008|E5832004                          str     r2,[r3,#0x4]
   NSR:C025600C|E1A0300D                          cpy     r3,r13
   NSR:C0256010|E3C35D7F                          bic     r5,r3,#0x1FC0    ; r5,r3,#8128
   NSR:C0256014|E3C5A03F                          bic     r10,r5,#0x3F     ; r10,r5,#63
   NSR:C0256018|E3A00000                          mov     r0,#0x0          ; r0,#0
   NSR:C025601C|E1A01009                          cpy     r1,r9
   NSR:C0256020|EB049414                          bl      0xC037B078       ; _test_and_set_bit
 
아래 offset 명령어로 R4: 0xDAC71BC0 = struct mb_cache_entry 임을 알 수 있습니다.
 
offsetof(struct mb_cache_entry,e_block_hash_p) = 0x34
 
  (struct mb_cache_entry*)0xDAC71BC0 // <<-- R4
    e_lru_list = (next = 0xDAC71BC0, prev = 0xDAC71BC0),
    e_cache = 0xE698B000,
    e_used = 0x0,
    e_queued = 0x0,
    e_refcnt = (counter = 0x0),
    e_bdev = 0xEDC4CC00,
    e_block = 0x8313,
    e_block_list = (next = 0x0, pprev = 0xE9C25A4C),
    e_index = (o_list = (next = 0x0, pprev = 0xE9C26808), o_key = 0x396FB86C),
    e_block_hash_p = 0xE9C25A4E // <<--R9
      first = 0xDAC7 -> (
        next = 0x0,  // <<--?
        pprev = 0x0)), // <<--?
    e_index_hash_p = 0xE9C26808)
 
그런데 논리적으로 문제가 될만한 디버깅 정보는 찾기 어렵습니다.
 
#커널 크래시 디버깅 및 TroubleShooting
 
커널 크래시 분석을 잘하는 게 왜 중요할까요? 너무 당연한 질문인가요? 사실 세상에 너무 당연한 질문은 없습니다. 어쩌면 너무 당연한 질문에 답하려고 고민하다가 많은 걸 깨닫는 경우가 많은 것 같습니다.
 
여러분이 리눅스 드라이버를 개발하거나 새로운 리눅스 커널 버전을 포팅했다고 가정하겠습니다. 그런데 안타깝게도 부팅 도중 아래와 같은 로그를 출력하는 커널 크래시가 100% 발생하고 있습니다. 어떻게 분석해야 할지 몰라 하루 꼬박 밤을 새웠습니다. 참 이럴 때 난감하죠. 
[ 0.986578] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(0,0)
[ 0.986589] CPU: 0 PID: 1 Comm: swapper Not tainted 3.18.20 #1
[ 0.986610] [<c0013260>] (unwind_backtrace) from [<c0011440>] (show_stack+0x10/0x14)
[ 0.986624] [<c0011440>] (show_stack) from [<c05a68b4>] (panic+0xf0/0x2dc)
[ 0.986640] [<c05a68b4>] (panic) from [<c083c164>] (mount_block_root+0x26c/0x2b0)
[ 0.986655] [<c083c164>] (mount_block_root) from [<c083c37c>] (prepare_namespace+0x88/0x1ac)
[ 0.986668] [<c083c37c>] (prepare_namespace) from [<c083bdac>] (kernel_init_freeable+0x16c/0x1b0)
[ 0.986681] [<c083bdac>] (kernel_init_freeable) from [<c05a5d6c>] (kernel_init+0x8/0xe0)
[ 0.986693] [<c05a5d6c>] (kernel_init) from [<c000dda0>] (ret_from_fork+0x14/0x34)
[ 1.982696] Rebooting in 5 seconds..
 
그런데 어떤 동료가 산신령 같이 나타나서 같이 분석을 시작합니다. 이것은 rootfs 파일 시스템 마운트를 못해서 발생한 문제라고 하네요. 그리고 꼼꼼히 로그를 같이 보면서 파티션 마운트가 제대로 됐는지 부트 디바이스가 제대로 동작하는지 점검 후 문제가 해결됐습니다. 그러면 여러분 기분은 어떨까요? (아 조금 어려운 용어 “파티션 마운트”, “부트 디바이스”, “rootfs”가 보이죠? 이번 장 마지막에 친절히 설명했으니 참고하세요.)
 
그 동료에게 참 고맙게 생각하겠죠. 흠, 그런데 전 약간 다릅니다. 물론 이 동료에게 감사 표현을 할 것이 분명하죠. 이런 문제를 해결 못한 저를 엄청 자책할 겁니다. 앞으로 비슷한 커널 크래시가 나오면 바로 해결할 수 있도록 열심히 준비하면서 말이죠. 
 
 
일단 이 동료는 커널 크래시 문제를 해결했습니다. 다시 반복하자면 어떤 문제를 해결했죠. 임베디드 리눅스 개발자에게 문제 해결 능력은 가장 중요한 실무 역량입니다. 모든 회사가 애타게 찾는 개발자는 문제 해결 능력이 있는 개발자입니다. 문제 해결 능력이 있는 개발자를 당연히 실력 있다고 봐야 겠죠. 그런데 문제 해결을 하기 위한 첫걸음은 문제를 정확히 분석하는 능력입니다. 대부분 로그를 분석하는 과정에 답이 있는 경우가 많거든요. 실력 있는 개발자가 되기 위해서 커널 크래시 분석 능력이 키우는 게 중요합니다. 
 
리눅스 커뮤니티
그런데 가끔 바로 문제 해결을 못 할 때도 있습니다. 예를 들어 리눅스 버전을 새롭게 업그레이드했는데 커널 크래시가 발생할 경우죠. 콜스택 모두 우리 눈에 낯선 함수입니다. 이 경우 어떻게 해야 할까요? 
 
이럴 때 너무 자신을 자책하지 마세요. 리눅스 커널은 수 많은 서브 시스템으로 이루어져 있어 소스를 볼 수 있는 범위가 넓습니다. 그래서 모든 커널 코드를 잘 알기 힘듭니다. 그래서 리눅스 커널에는 분야별로 전문적으로 코드 리뷰를 하는 메인테이너가 있습니다. 우선 아래와 같은 정보를 포함해서 정밀히 분석해야 합니다. 
- 크래시가 발생한 정확한 코드 위치와 그 이유 
- 프로세스 이름 
- 인터럽트 컨택스트 여부 
- ftrace log 상세 분석 
 
이렇게 정밀하게 분석을 한 다음 리눅스 커뮤니티에 업로드를 하면 되죠. 리눅스 커널 메일링 리스트에 공유하면 좋습니다. 리눅스 커널은 강력한 커뮤니티가 큰 강점이라고 알려져 있죠. 그런데, 커널 로그만 복사해서 버그를 알리면 제대로 도움을 받을 수 있을까요? 프로세스 이름, 정확히 크래시가 난 코드와 함수 위치, 문제가 발생한 재현 경로를 자세히 올려야 도움을 받을 가능성이 높습니다. 그래서 커널 크래시 분석 능력이 중요합니다. 
 
효율적인 업무 진행
가끔 주말 동안 스트레스 테스트를 디바이스에 돌릴 경우가 있습니다. 안드로이드에서 몽키 테스트라고 하죠. 실제 유저가 디바이스를 사용하듯이 테스트 시나리오를 만들어 신뢰성 테스트를 하는 것입니다. 그런데 보드 20대 중에 10대가 커널 크래시를 맞으면 이 때 어떤 방식으로 일을 하는 게 효율적일까요? 10개의 코어 덤프를 리눅스 커널 커뮤니티나 벅질라 이슈에 올려야 할까요? 10개의 코어 덤프를 올리는 일도 보통 오래 시간이 걸리는 일이 아니죠. 10개의 코어 덤프를 크래시 유틸리티로 자세히 분석하면 커널 크래시의 원인은 2~3개로 좁혀지는 경우가 많습니다.
 
커널 크래시가 발생하는 패턴을 생각해 볼 필요가 있습니다. 우리는 보통 문제가 발생한 코드에서 바로 커널 크래시가 발생할 것이라 예상할 때가 있어요. 정말 문제 코드에서 딱 크래시가 발생하면 얼마나 좋을까요? 사실 그렇지 않습니다. 원인은 하나 인데 다양한 로그로 커널 크래시가 발생할 수 있습니다. 가장 대표적인 예가 슬랩 메모리를 누군가 깨 먹는 경우입니다. 아니면 특정 디바이스에서만 커널 크래시가 발생하는 경우도 있습니다. 갑자기 다양한 커널 로그로 랜덤하게 크래시가 발생하면 정말 죽을 맛이죠. 이럴 때 정밀하게 커널 크래시 디버깅을 하면 그 범인을 잡을 수 있습니다.
 
프로젝트 마감에 큰 걸림돌
프로젝트 마감이 내일인데 커널 크래시가 발생하면 여러분들은 기분은 어떨까요? 제품 출시에 걸림돌이 되는 가장 큰 이슈는 커널 크래시입니다. 사소한 버그는 첫 제품 출시 후 잡자고 고객사를 설득할 수 있습니다. 그런데 커널 크래시를 고객사에게 출시 후에 잡겠다고 협의를 할 수 있을까요? 실현 불가능한 현실이죠. 이렇게 프로젝트 막바지에 가끔 임베디드 리눅스 개발자들은 이 문제를 해결하기 전에 집에 못 가는 짜증나는 경험이 생각 날 겁니다.
 
저 같은 경우엔 예전에 어느 매니저님께서 담요와 베개를 갖고 제 옆에 오셨던 악몽이 되살아 나는군요. 이렇게 말씀하시면서요. “이 문제 해결하기 전까지 집에 못가.” 물론 그 당시 열심히 크래시 디버깅을 해서 문제의 원인을 잡아 집에 들어는 갔습니다.
 
커널 크래시 디버깅을 통한 학습
커널 디버깅을 하면 할수록 리눅스 커널과 디바이스 실력이 빨리 향상됩니다. 커널 크래시 디버깅을 잘하면 리눅스 커널 개발 능력이 업그레이드 되기 때문입니다. 리눅스 커뮤니티나 주위 고수들 중에 커널 크래시 디버깅을 잘 못하는 개발자를 본 적이 없습니다.
 
가끔은 커널 크래시 디버깅을 잘하는 개발자를 폄하하는 분도 만난 적이 있습니다. “커널 디버깅 툴(crash utility, Trace32, ftrace)을 잘 쓸 뿐이다.”라고 말이죠. 맞습니다. 리눅스 커널 고수들 정말 디버깅 툴 잘 씁니다. 그런데 리눅스 커널에 대한 깊은 이해와 커널 자료구조에 익숙하지 않고 절대 커널 크래시 디버깅을 능숙하게 할 수 없습니다.
 
#커널 크래시 디버깅 및 TroubleShooting
 
 
 
# Reference: For more information on 'Linux Kernel';
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 1
 
디버깅을 통해 배우는 리눅스 커널의 구조와 원리. 2
 
 
 
커널 패닉이란 말을 들어본 적이 있나요? 혹시 여러분이 임베디드 리눅스 개발자면 몇 번 쯤은 들어봤을 겁니다. 하지만, 리눅스를 자주 안 쓰거나 리눅스를 학습 용도로 쓰시는 분들에겐 단어가 낯설게 들릴수도 있죠. 
 
여러분들은 대부분 컴퓨터나 노트북을 윈도 운영체제로 쓰실 겁니다. 그런데 혹시 컴퓨터를 오래 쓰다가 블루 스크린을 본 적이 있나요? 밝은 파란색 배경 화면에 흰색으로 이상한 경고 문구가 떠있죠. 이 때 컴퓨터는 아무런 동작을 안합니다. 이런 화면을 처음 봤을 때 어땠나요? 좀 짜증나지 않았나요? 전 예전 처음 이 블루 스크린을 봤을 때 엄청 당황했었어요. 왜냐면 “전원을 다시 키면 부팅은 할까?”, “혹시 컴퓨터에 저장된 자료가 날아가는 건 아닌가”? 이런 걱정을 했죠. 정말 뭔가 컴퓨터에 큰 고장이 난 것 같았어요. 
 
이렇게 윈도 운영체제에서 뜨는 블루 스크린은 리눅스 운영 체제에서는 발생하지 않을까요? 다들 아시겠지만 윈도 운영체제에서 뜨는 블루 스크린이 리눅스에서도 있습니다. 대신 리눅스 운영체제에서는 검은색 배경에 흰색 문구를 띄웁니다. 이를 보통 커널 패닉이라고 합니다. 개발자들은 커널 크래시라고도 말하죠.
 
그럼 커널 크래시는 왜 발생할까요? 그 이유에 대해서 찬찬히 살펴볼게요.  혹시 소프트웨어 공학에서 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
 
 

+ Recent posts