diff --git a/sound/soc/codecs/wcd-kdt_sample-v2.c b/sound/soc/codecs/wcd-kdt_sample-v2.c
index dba66e5..22b38ec 100644
--- a/sound/soc/codecs/wcd-kdt_sample-v2.c
+++ b/sound/soc/codecs/wcd-kdt_sample-v2.c
@@ -2484,9 +2484,6 @@
 {
  struct snd_soc_codec *codec = kdt_sample->codec;
 
-#ifdef CONFIG_KDT_RPI_SAMPLE 
- switch_dev_unregister(&kdt_sample->sdev);
-#endif //CONFIG_KDT_RPI_SAMPLE
  kdt_sample->kdt_sample_cb->free_irq(codec, kdt_sample->intr_ids->kdt_sample_sw_intr, kdt_sample);
  kdt_sample->kdt_sample_cb->free_irq(codec, kdt_sample->intr_ids->kdt_sample_btn_press_intr,
  kdt_sample);
@@ -2496,6 +2493,14 @@
  kdt_sample->kdt_sample_cb->free_irq(codec, kdt_sample->intr_ids->kdt_sample_hs_rem_intr, kdt_sample);
  kdt_sample->kdt_sample_cb->free_irq(codec, kdt_sample->intr_ids->hph_left_ocp, kdt_sample);
  kdt_sample->kdt_sample_cb->free_irq(codec, kdt_sample->intr_ids->hph_right_ocp, kdt_sample);
+#ifdef CONFIG_KDT_RPI_SAMPLE  
+ //switch_dev_unregister(&kdt_sample->sdev);
+ if (kdt_sample->sdev.name){
+     switch_dev_unregister(&kdt_sample->sdev);
+ memset(&kdt_sample->sdev, 0, sizeof(struct switch_dev));
+
+ }
+#endif //CONFIG_KDT_RPI_SAMPLE
  if (kdt_sample->kdt_sample_cb && kdt_sample->kdt_sample_cb->register_notifier)
  kdt_sample->kdt_sample_cb->register_notifier(codec, &kdt_sample->nblock, false);
  mutex_destroy(&kdt_sample->codec_resource_lock);

저작자표시

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

[Troubleshooting] dump_stack() : SP가 0으로 출력되는 이유  (0) 2023.05.07
QEMU - Aarch64  (0) 2023.05.07
[커널크래시] 인터럽트 컨텍스트에서 wake_up_interruptible 대신 wake_up_locked 사용  (0) 2023.05.07
[리눅스커널] 커널 크래시: Data Abort @usb_copy_descriptors  (0) 2023.05.07
[리눅스커널] 익명 페이지 메모리 누수(Memory Leak) 디버깅 - TRACE32  (0) 2023.05.07

/// SP가 0으로 출력되는 이유!!!

void dump_stack(void) {
    int i;
 
    printf("============SP:%d ========= \n", SP);
    for (i=MAX_STACK; i > (MAX_STACK - K) ; i--) {
        printf("STACK[%d]:%d SP: %d . \n", i, stack[i], SP);
    }
}
.
 
저작자표시

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

[patch] Sample code to fix crash when unloading drivers  (0) 2024.04.08
QEMU - Aarch64  (0) 2023.05.07
[커널크래시] 인터럽트 컨텍스트에서 wake_up_interruptible 대신 wake_up_locked 사용  (0) 2023.05.07
[리눅스커널] 커널 크래시: Data Abort @usb_copy_descriptors  (0) 2023.05.07
[리눅스커널] 익명 페이지 메모리 누수(Memory Leak) 디버깅 - TRACE32  (0) 2023.05.07
PS C:\dev_utils\qemu_img> qemu-system-aarch64 -m 4096 -cpu cortex-a72 -smp 4 -machine virt -nographic -bios QEMU_EFI.fd -drive if=none,file=ubuntu-20.04-server-cloudimg-arm64.img,id=hd0 -device virtio-blk-device,drive=hd0 -drive file=user-data.img,format=raw -device virtio-net-device,netdev=net0 -netdev user,hostfwd=tcp:127.0.0.1:2222-:22,id=net0
 
<로그인 시>
계정: ubuntu
패스워드: asdfqwer
 
// 추가 정보
 
제가 아는 부팅 빨리하는 방법 공유드립니다! ^.^
 
1. boot parameter quiet 넣기
2. 커널 드라이버들을 builtin 으로 빌드! (vmlinux 포함!)
 
 
윈도우 10 QEMU 실행 ubuntu 20.04
 
 
 
우분투 커널 빌드 패키지 만들기
 
저작자표시

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

[patch] Sample code to fix crash when unloading drivers  (0) 2024.04.08
[Troubleshooting] dump_stack() : SP가 0으로 출력되는 이유  (0) 2023.05.07
[커널크래시] 인터럽트 컨텍스트에서 wake_up_interruptible 대신 wake_up_locked 사용  (0) 2023.05.07
[리눅스커널] 커널 크래시: Data Abort @usb_copy_descriptors  (0) 2023.05.07
[리눅스커널] 익명 페이지 메모리 누수(Memory Leak) 디버깅 - TRACE32  (0) 2023.05.07
인터럽트 컨텍스트에서 슬립을 지원하는 커널 함수를 호출하면 어떻게 동작할까요? 커널 패닉이 유발됩니다.
이번에는 인터럽트 컨텍스트에서 발생한 커널 패닉 이슈를 소개합니다.
 
먼저 커널 로그를 소개합니다.
 
[1.538173] BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:973
[1.577234] in_atomic(): 1, irqs_disabled(): 128, non_block: 0, pid: 0, name: swapper/3
[1.578316] Preemption disabled at:
[1.597859] CPU: 3 PID: 0 Comm: swapper/3 
[1.617377] Hardware name: rpi
[1.636919] Backtrace:
[1.638055] [<c010f54c>] (dump_backtrace) from [<8010f7d0>] (show_stack+0x20/0x24)
[1.657603] [<c010f7b0>] (show_stack) from [<80ab9940>] (dump_stack+0xac/0xd8)
[1.677129] [<c0ab9894>] (dump_stack) from [<8015f33c>] (___might_sleep+0x190/0x1d4)
[1.696673] [<c015f1ac>] (___might_sleep) from [<80adaad4>] (rt_spin_lock+0x50/0x5c)
[1.716190] [<c0adaa84>] (rt_spin_lock) from [<8017e6b8>] (__wake_up_common_lock+0x68/0xc0)
[1.716296] [<c017e650>] (__wake_up_common_lock) from [<8017e738>] (__wake_up+0x28/0x30)
[1.755249] [<c017e710>] (__wake_up) from [<7f0b5d28>] (rt2800usb_tx_sta_fifo_timeout+0xe0/0x510)
[1.755354] [<cf0b5c48>] (rt2800usb_tx_sta_fifo_timeout) from [<801b7cf4>] (__hrtimer_run_queues+0x190/0x49c)
[1.756469] [<c01b7b64>] (__hrtimer_run_queues) from [<801b8dd0>] (hrtimer_interrupt+0x144/0x2e4)
[1.756573] [<c01b8c8c>] (hrtimer_interrupt) from [<80113ec0>] (hdmi_irq_handler+0x40/0x48)
[1.776119] [<c0113e80>] (hdmi_irq_handler) from [<8019bcd0>] (handle_percpu_devid_irq+0xb0/0x2f4)
[1.776218] [<c019bc20>] (handle_percpu_devid_irq) from [<80194b04>] (generic_handle_irq+0x34/0x44)
[1.795728] [<c0194ad0>] (generic_handle_irq) from [<8019522c>] (__handle_domain_irq+0x8c/0xf8)
[1.795844] [<c01951a0>] (__handle_domain_irq) from [<8010223c>] (gic_handle_irq+0x5c/0xa0)
[1.815370] [<c01021e0>] (gic_handle_irq) from [<80101a3c>] (__irq_svc+0x5c/0xa8)
[1.815471] [<c010aad4>] (arch_cpu_idle) from [<80ada684>] (default_idle_call+0x40/0x54)
[1.834994] [<c0ada644>] (default_idle_call) from [<80169ab8>] (do_idle+0xec/0x160)
[1.836112] [<c01699cc>] (do_idle) from [<80169e58>] (cpu_startup_entry+0x28/0x2c)
[1.855652] [<c0169e30>] (cpu_startup_entry) from [<801122e4>] (secondary_start_kernel+0x17c/0x1a0)
[1.855757] [<c0112168>] (secondary_start_kernel) from [<101027cc>] (0x101027cc)
 
HR 타이머 핸들러인 rt2800usb_tx_sta_fifo_timeout() 함수에서 슬립을 지원하는 __wake_up() 함수를 호출해서 발생한 문제입니다.
 
다음과 같은 패치를 적용하면 크래시가 발생하지 않습니다.
 
diff --git a/drivers/gpu/drm/sti/sti_hdmi.c b/drivers/gpu/drm/sti/sti_hdmi.c
index 9862c32..bf7358c 100644
--- a/drivers/gpu/drm/sti/sti_hdmi.c
+++ b/drivers/gpu/drm/sti/sti_hdmi.c
@@ -198,7 +198,7 @@ static enum hrtimer_restart rt2800usb_tx_sta_fifo_timeout(struct hrtimer *hrtimer)
         */
        if (hdmi->irq_status & (HDMI_INT_SW_RST | HDMI_INT_DLL_LCK)) {
                hdmi->event_received = true;
-               wake_up_interruptible(&hdmi->wait_event);
+               wake_up_locked(&hdmi->wait_event);
        }
 
        /* Audio FIFO underrun IRQ */
저작자표시

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

[Troubleshooting] dump_stack() : SP가 0으로 출력되는 이유  (0) 2023.05.07
QEMU - Aarch64  (0) 2023.05.07
[리눅스커널] 커널 크래시: Data Abort @usb_copy_descriptors  (0) 2023.05.07
[리눅스커널] 익명 페이지 메모리 누수(Memory Leak) 디버깅 - TRACE32  (0) 2023.05.07
[tegra4i] UI freeze due to RT class 프로세스  (0) 2023.05.07
소개
 
이번 시간에는 커널 패닉을 디버깅하는 과정을 소개합니다.
 
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);
저작자표시

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

QEMU - Aarch64  (0) 2023.05.07
[커널크래시] 인터럽트 컨텍스트에서 wake_up_interruptible 대신 wake_up_locked 사용  (0) 2023.05.07
[리눅스커널] 익명 페이지 메모리 누수(Memory Leak) 디버깅 - TRACE32  (0) 2023.05.07
[tegra4i] UI freeze due to RT class 프로세스  (0) 2023.05.07
[리눅스커널] Crash: 비트 플립 @profile_tick()  (0) 2023.05.07
많은 리눅스 시스템 개발자들은 자신이 개발하고 있는 리눅스 커널의 버전이 주류였으면 하는 바램이 있다. 하지만 현실은 다르다. 현재 리눅스 커널의 최신 버전인 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
 
저작자표시

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

[커널크래시] 인터럽트 컨텍스트에서 wake_up_interruptible 대신 wake_up_locked 사용  (0) 2023.05.07
[리눅스커널] 커널 크래시: Data Abort @usb_copy_descriptors  (0) 2023.05.07
[tegra4i] UI freeze due to RT class 프로세스  (0) 2023.05.07
[리눅스커널] Crash: 비트 플립 @profile_tick()  (0) 2023.05.07
[리눅스] 커널 크래시: abort@test_and_set_bit  (0) 2023.05.07
커널 로그는 다음과 같습니다. 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);
+                       }
+               }
 
 
"이 포스팅이 유익하다고 생각되시면 댓글로 응원해주시면 감사하겠습니다.  
혹시 글을 읽고 궁금점이 있으면 댓글로 질문 남겨주세요. 상세한 답글 올려 드리겠습니다!"
 
저작자표시

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

[리눅스커널] 커널 크래시: Data Abort @usb_copy_descriptors  (0) 2023.05.07
[리눅스커널] 익명 페이지 메모리 누수(Memory Leak) 디버깅 - TRACE32  (0) 2023.05.07
[리눅스커널] Crash: 비트 플립 @profile_tick()  (0) 2023.05.07
[리눅스] 커널 크래시: abort@test_and_set_bit  (0) 2023.05.07
[리눅스][커널] 커널 크래시 분석은 왜 중요할까?  (0) 2023.05.07
이번에는 비트 플립으로 발생한 커널 패닉 코어 덤프 분석 과정을 소개합니다.
 
다음은 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 주소에서 비트 플립으로 익셉션이 발생했음을 확인할 수 있었습니다.
저작자표시

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

[리눅스커널] 익명 페이지 메모리 누수(Memory Leak) 디버깅 - TRACE32  (0) 2023.05.07
[tegra4i] UI freeze due to RT class 프로세스  (0) 2023.05.07
[리눅스] 커널 크래시: abort@test_and_set_bit  (0) 2023.05.07
[리눅스][커널] 커널 크래시 분석은 왜 중요할까?  (0) 2023.05.07
[Linux][Kernel] 커널 크래시란  (0) 2023.05.07
우선 콜스택부터 점검을 해보면, "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
저작자표시

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

[tegra4i] UI freeze due to RT class 프로세스  (0) 2023.05.07
[리눅스커널] Crash: 비트 플립 @profile_tick()  (0) 2023.05.07
[리눅스][커널] 커널 크래시 분석은 왜 중요할까?  (0) 2023.05.07
[Linux][Kernel] 커널 크래시란  (0) 2023.05.07
[Kernel][Crash] 워크큐(workqueue) 락업(3) at [0321]  (0) 2023.05.07
 
커널 크래시 분석을 잘하는 게 왜 중요할까요? 너무 당연한 질문인가요? 사실 세상에 너무 당연한 질문은 없습니다. 어쩌면 너무 당연한 질문에 답하려고 고민하다가 많은 걸 깨닫는 경우가 많은 것 같습니다.
 
여러분이 리눅스 드라이버를 개발하거나 새로운 리눅스 커널 버전을 포팅했다고 가정하겠습니다. 그런데 안타깝게도 부팅 도중 아래와 같은 로그를 출력하는 커널 크래시가 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
 
 
저작자표시

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

[리눅스커널] Crash: 비트 플립 @profile_tick()  (0) 2023.05.07
[리눅스] 커널 크래시: abort@test_and_set_bit  (0) 2023.05.07
[Linux][Kernel] 커널 크래시란  (0) 2023.05.07
[Kernel][Crash] 워크큐(workqueue) 락업(3) at [0321]  (0) 2023.05.07
[Kernel][Crash] 워크큐(workqueue) 락업(2) at [0321]  (0) 2023.05.07

+ Recent posts

티스토리툴바