Gomdol Kim

rousalome.egloos.com

포토로그



[Linux-Kernel][Debug]kernel panic@mmc_wait_data_done 리눅스 커널

Debugging
"ndroid.systemui" 프로세스가 raw_spin_lock_irqsave() API 동작 중에 watchdog reset이 되었다.
-000|aee_wdt_atf_entry()
-001|prefetchw(inline)
-001|arch_spin_lock(inline)
-001|do_raw_spin_lock_flags(inline)
-001|__raw_spin_lock_irqsave(inline)
-001|raw_spin_lock_irqsave(lock = 0xDD82725C)
-002|__wake_up(q = 0xDD82725C, mode = 1, nr_exclusive = 1, key = 0x0)
-003|mmc_wait_data_done
-004|msdc_irq_data_complete(host = 0xDD827280, ?, error = 0)
-005|msdc_irq(?, dev_id = 0xDD13B9C8)
-006|static_key_count(inline)
-006|static_key_false(inline)
-006|trace_irq_handler_exit(inline)
-006|handle_irq_event_percpu(?, action = 0xDD13B9C8)
-007|handle_irq_event(desc = 0xC0F38440)
-008|cond_unmask_eoi_irq(inline)
-008|handle_fasteoi_irq(?, desc = 0xC0F38440)
-009|static_key_count(inline)
-009|static_key_false(inline)
-009|trace_irq_exit(inline)
-009|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)
-010|__raw_readl(inline)
-010|gic_handle_irq(regs = 0xDD13BFB0)
-011|__irq_usr(asm)

spinlock이 release되어 spinlock 변수가 [owner: 0x56AC, next: 0x56AD]로 업데이트되기까지 기다리고 있었다.
다른 프로세스가 spinlock을 잡고 있었는데..
(raw_spinlock_t *)0xDD82725C = 0xDD82725C -> (
  raw_lock = (
    slock = 0x56AD56AB,
       tickets = (
         owner = 0x56AB, // <<--
         next = 0x56AD))) // <<--
         
0xDD82725C spinlock 변수 주소를 누가 접근하는 지 검색해보면.
(where)
(raw_spinlock_t *)0xDD82725C
c2d01b78: dd82725c
c2d01b7c: dd82725c
c44f0994: dd82725c
dd13bd60: dd82725c // "ndroid.systemui"
dd13bd9c: dd82725c // "ndroid.systemui"
dd13bdc8: dd82725c // "ndroid.systemui"
ddbefdb8: dd82725c // <<--"mmcqd/0"
ddbefdd0: dd82725c
e0abd994: dd82725c

"mmcqd/0" 프로세스가 접근함을 알 수 있었다.
v.v % (struct thread_info*)(0xDDBEFDB8 & ~0x1fff)
  (long unsigned int) swap_in = 0 = 0x0 = '....',
  (long unsigned int) swap_out = 0 = 0x0 = '....',
  (struct task_cputime) cputime_expires = ((cputime_t) utime = 0 = 0x0 = '....', (cputime_t) stime = 0 = 0x0 = '....', (long lo
  (struct list_head [3]) cpu_timers = ([0] = ((struct list_head *) next = 0xDDB49A08 = -> ((struct list_head *) next = 0xDDB49
  (struct cred *) real_cred = 0xDDB71200 = -> ((atomic_t) usage = ((int) counter = 2 = 0x2 = '....'), (kuid_t) uid = ((uid_t)
  (struct cred *) cred = 0xDDB71200 = -> ((atomic_t) usage = ((int) counter = 2 = 0x2 = '....'), (kuid_t) uid = ((uid_t) val =
   (char [16]) comm = "mmcqd/0",

"mmcqd/0" 프로세스 콜스택은 아래와 같다.
-000|schedule()
-001|mmc_wait_for_data_req_done(inline)
-001|mmc_start_req(host = 0xC0F75D0C, areq = 0xC0F644E0, error = 0xC102CB08)
-002|mmc_blk_issue_rw_rq(mq = 0xDDB64408, rqc = 0x0)
-003|mmc_blk_issue_rq(mq = 0xDDB64408, req = 0x0)
-004|mmc_queue_thread(d = 0xDDB64408)
-005|kthread(_create = 0xDDB8BDC0)
-006|ret_from_fork(asm)
-007|ret_fast_syscall(asm)

mmc_wait_for_data_req_done 코드를 가보면, spin_lock_irqsave(&context_info->lock, flags); API를 통해 lock을 걸고 있었다.
static int mmc_wait_for_data_req_done(struct mmc_host *host,
struct mmc_request *mrq,
struct mmc_async_req *next_req)
{
    struct mmc_command *cmd;
    struct mmc_context_info *context_info = &host->context_info;
    int err;
    unsigned long flags;
    while (1) {
        wait_event_interruptible(context_info->wait,
                                               (context_info->is_done_rcv ||
                                               context_info->is_new_req));
        spin_lock_irqsave(&context_info->lock, flags);
        context_info->is_waiting_last_req = false;

조금 더 코드를 보면 Watchdog Reset이 trigger된 "ndroid.systemui" 프로세스 콜 스택에 아래 함수들이 있었다.
-003|mmc_wait_data_done
-004|msdc_irq_data_complete(host = 0xDD827280, ?, error = 0)

mmc_wait_data_done() 함수를 보면 mrq->host->context_info.is_done_rcv = true로 설정하고,
&mrq->host->context_info.wait wait queue을 깨우는 역할을 수행했다.
static void mmc_wait_data_done(struct mmc_request *mrq){
    mrq->host->context_info.is_done_rcv = true;
     wake_up_interruptible(&mrq->host->context_info.wait);
}

그런데 mmc_wait_for_data_req_done() 함수의 아래 구문은 context_info->is_done_rcv, context_info->is_new_req가 true가
될 때 까지 기다리는 코드다.
wait_event_interruptible(context_info->wait,
  (context_info->is_done_rcv ||
  context_info->is_new_req));

정리해보면, race condition으로 wake_up_interruptible(&mrq->host->context_info.wait); 함수를 통해 wait_queue에 queue된 
&mrq->host->context_info.wait으로 등록된 프로세스를 깨우기 전에 아래 구문이 풀려버려 이미 깨어버린 경우임을 짐작할 수 있다.

잠을 자고 있는 누군가를 깨우려고 손을 대려고 하는데 이미 깨버린 경우와 비슷하네.

In-depth Analysis
내 추정이 맞다면 아래 코드를 삽입하면 바로 커널 패닉이 나야 한다.
(램덤프 force_mmc_wait_data_done_crash)
static void mmc_wait_data_done(struct mmc_request mrq){*
    mrq->host->context_info.is_done_rcv = true;
    + mdelay(1);
    wake_up_interruptible(&mrq->host->context_info.wait);
}

그런데 바로 커널 패닉이 발생했다.
-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)
-001|__dabt_svc(asm)
-->|exception
-002|debug_spin_lock_before(inline)
-002|do_raw_spin_lock(lock = 0x02B4)
-003|raw_spin_lock_irqsave(lock = 0x02B4)
-004|__wake_up(q = 0x02B4, mode = 1, nr_exclusive = 1, key = 0x0)
-005|mmc_wait_data_done(mrq = 0xDC9725F8)
-006|msdc_irq_data_complete(host = 0xDC919300, ?, error = 0)
-007|msdc_irq(?, dev_id = 0x1)
-008|handle_irq_event_percpu(?, action = 0xDC91E0C0)
-009|handle_irq_event(desc = 0xC121A440)
-010|cond_unmask_eoi_irq(inline)
-010|handle_fasteoi_irq(?, desc = 0xC121A440)
-011|static_key_count(inline)
-011|static_key_false(inline)
-011|trace_irq_exit(inline)
-011|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)
-012|__raw_readl(inline)
-012|gic_handle_irq(regs = 0xCB773E10)
-013|__irq_svc(asm)
-->|exception
-014|current_thread_info(inline)
-014|check_preemption_disabled(what1 = 0xC0F115AC, what2 = 0xC0EE0B28)
-015|debug_smp_processor_id()
-016|MT_trace_preempt_on()
-017|preempt_count_sub
-018|current_thread_info(inline)
-018|preempt_count(inline)
-018|should_resched(inline)
-018|__percpu_counter_add(fbc = 0xD8AC7178, amount = 0, batch = 32)
-019|__sb_start_write(sb = 0xC0F115AC, level = -1058141400, wait = FALSE)
-020|file_start_write(inline)
-020|vfs_write(file = 0xD366C480, buf = 0xBEA83A4C, ?, pos = 0xCB773F78)
-021|SYSC_write(inline)
-021|sys_write(?, buf = -1096271284, count = 146)
-022|ret_fast_syscall(asm)

mrq->host->context_info.wait 변수를 확인해보면, 이미 mrq->host 변수가 0이다.
(struct mmc_request *)0xDC9725F8 = 0xDC9725F8 -> (
    sbc = 0xDC97262C,
    cmd = 0xDC972660,
    data = 0xDC9726C8,
    stop = 0xDC972694,
    completion = (done = 0x0, wait = (lock = (rlock = (raw_lock = (slock = 0x0,
      done = 0x0,
     host = 0x0)

어머 그런데, mmcqd/0 프로세스가 mmc_wait_for_data_req_done() 코드를 이미 수행했네?
-000|context_switch(inline)
-000|__schedule()
-001|schedule()
-002|mmc_wait_for_data_req_done(inline)
-002|mmc_start_req(host = 0xDC919000, areq = 0xDC972710, ?)
-003|mmc_blk_issue_rw_rq(mq = 0x0, rqc = 0xC64B18C0)
-004|mmc_blk_issue_rq(mq = 0xDC972494, req = 0xC64B18C0)
-005|mmc_queue_thread(d = 0xDC972494)
-006|kthread(_create = 0xDCA24E40)
-007|ret_from_fork(asm)
-008|ret_fast_syscall(asm)

@ftrace log를 좀 더 추가해보자.
diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c
index db74413..fcf6692 100644
? a/drivers/mmc/core/core.c
+++ b/drivers/mmc/core/core.c
@@ -1034,6 +1034,9 @@ out:
}
EXPORT_SYMBOL(mmc_start_bkops);
#endif
/*
mmc_wait_data_done() - done callback for data request
@mrq: done data request
@@ -1042,10 +1045,25 @@ EXPORT_SYMBOL(mmc_start_bkops);
*/
static void mmc_wait_data_done(struct mmc_request *mrq)
static void mmc_wait_data_done(struct mmc_request mrq) *{
        mrq->host->context_info.is_done_rcv = true;

+      trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));
        mdelay(1);
+      trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));
        wake_up_interruptible(&mrq->host->context_info.wait);
+      trace_printk("--msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));
 

역시나 GIC mtk-msdc(111) IRQ가 Trigger된 다음에 아래와 같이 커널 패닉이 발생하였네.
(램덤프: neo_more_crash_ftrace)
-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)
-001|__dabt_svc(asm)
-->|exception
-002|debug_spin_lock_before(inline)
-002|do_raw_spin_lock(lock = 0x02B4)
-003|raw_spin_lock_irqsave(lock = 0x02B4)
-004|__wake_up(q = 0x02B4, mode = 1, nr_exclusive = 1, key = 0x0)
-005|mmc_wait_data_done(mrq = 0xDC9235F8)
-006|msdc_irq_data_complete(host = 0xDC927300, ?, error = 0)
-007|msdc_irq(?, dev_id = 0x1)
-008|handle_irq_event_percpu(?, action = 0xDC92B180)
-009|handle_irq_event(desc = 0xC121A440)
-010|cond_unmask_eoi_irq(inline)
-010|handle_fasteoi_irq(?, desc = 0xC121A440)
-011|static_key_count(inline)
-011|static_key_false(inline)
-011|trace_irq_exit(inline)
-011|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)
-012|__raw_readl(inline)
-012|gic_handle_irq(regs = 0xC2631E20)
-013|__irq_svc(asm)
-->|exception
-014|__fget(?, mask = 16384)
-015|__fget_light(?, mask = 16384)
-016|__fdget
-017|sockfd_lookup_light(?, err = 0xC2631EC8, fput_needed = 0xC2631ECC)
-018|SYSC_recvfrom(inline)
-018|sys_recvfrom(?, ubuf = -1212542344, ?, flags = 64, addr = 0, addr_len = 0)
-019|ret_fast_syscall(asm)
 
Ftrace log 분석 좀 해보자.
커널 패닉이 일어나기 직전 상황
[1]: irq=111 name=mtk-msdc 가 Trigger됨
[2]: IRQ context에서 mmc_wait_data_done() 함수가 호출 from(msdc_irq_data_complete)
[2]~[3] 사이 mmcq0 process가 context switching 되지 않고 수행 ( InputDispatcher-1538)
[3]: mdelay(1); 이후 찍히는 ftrace log
[4]: wake_up_interruptible(&mrq->host->context_info.wait); API 호출로 mmcq0 process을 wakeup 시킴
CPU5: mmcqd/0, pid=244
sched_wakeup: comm=mmcqd/0 pid=244 prio=120 success=1 target_cpu=005 state=W
[5]: wake_up_interruptible(&mrq->host->context_info.wait); API 호출이 끝난 후 찍히는 로그(별 의미 없음)

kworker/4:0-25 [004] 149.827488: irq_handler_entry: irq=111 name=mtk-msdc // <<--[1]
kworker/4:0-25 [004] 149.827495: bprint: mmc_wait_data_done: +msdc [F: mmc_wait_data_done, L:1049]: ? ? from(msdc_irq_data_complete) // <<--[2]
InputDispatcher-1538 [005] 149.827496: sched_migrate_task: comm=m.lge.launcher3 pid=2135 prio=120 orig_cpu=6 dest_cpu=4 state=W
InputDispatcher-1538 [005] 149.827519: sched_wakeup: comm=m.lge.launcher3 pid=2135 prio=120 success=1 target_cpu=004 state=W
InputDispatcher-1538 [005] 149.827591: sched_migrate_task: comm=ndroid.systemui pid=1622 prio=120 orig_cpu=5 dest_cpu=6 state=W
InputDispatcher-1538 [005] 149.827608: sched_wakeup: comm=ndroid.systemui pid=1622 prio=120 success=1 target_cpu=006 state=W
InputDispatcher-1538 [005] 149.827675: sched_migrate_task: comm=android.ui pid=1287 prio=118 orig_cpu=4 dest_cpu=6 state=W
InputDispatcher-1538 [005] 149.827694: sched_wakeup: comm=android.ui pid=1287 prio=118 success=1 target_cpu=006 state=W
InputDispatcher-1538 [005] 149.827855: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d 
<idle>-0 [005] 149.827912: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=InputDispatcher next_pid=1538 next_prio=112 extra_prev_state=K|m|d 
InputDispatcher-1538 [005] 149.828064: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d 
<idle>-0 [005] 149.828209: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=InputDispatcher next_pid=1538 next_prio=112 extra_prev_state=K|m|d 
InputDispatcher-1538 [005] 149.828352: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d 
kworker/4:0-25 [004] 149.828497: bprint: mmc_wait_data_done: ++msdc [F: mmc_wait_data_done, L:1058]: ? ? from(msdc_irq_data_complete) // <<--[3]
kworker/4:0-25 [004] 149.828521: sched_wakeup: comm=mmcqd/0 pid=244 prio=120 success=1 target_cpu=005 state=W // <<--[4]
kworker/4:0-25 [004] 149.828525: bprint: mmc_wait_data_done: -msdc [F: mmc_wait_data_done, L:1060]: ? ? from(msdc_irq_data_complete) <<-[5]
<idle>0 [005] 149.828528: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=mmcqd/0 next_pid=244 next_prio=120 extra_prev_state=K|m|d <<-[6]
kworker/4:0-25 [004] 149.828530: irq_handler_exit: irq=111 ret=handled
 
1046 static void mmc_wait_data_done(struct mmc_request *mrq)
1047*{*
1048 mrq->host->context_info.is_done_rcv = true;
1049 trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[2]
//생략
1051 mdelay(1);
//생략
1057
1058 trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[3]
1059 wake_up_interruptible(&mrq->host->context_info.wait);
1060 trace_printk("-msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<-[5]

커널 패닉 상황
[7]: irq=111 name=mtk-msdc 가 handle 되었음
[8]: [mmcqd/0-244, CPU5]mmc_wait_for_data_req_done() 함수 내[from(mmc_blk_issue_rw_rq)] wait_event_interruptible()에서 빠져나옴.
[9][10]: [mmcqd/0-244, CPU5]mmc_wait_for_data_req_done() 함수를 빠져나옴
[11]: irq=111 name=mtk-msdc 가 Trigger됨 --> CPU4의 m.lge.launcher3-2135
[12]: [mmcqd/0-244, CPU5] 깨어난 mmcqd/0-244 프로세스 활동 시작
&mqrq->brq 변수를 0으로 밀어버림 (where: memset(brq, 0, sizeof(struct mmc_blk_request));
[13]: [m.lge.launcher3-2135 CPU4] irq=111 name=mtk-msdc IRQ로 Trigger되어 실행되어
mmc_wait_data_done() 함수 진입 
[14][15]: [mmcqd/0-244, CPU5] mmc_blk_rw_rq_prep() 함수 퇴장하려함
[16][17][18] [mmcqd/0-244, CPU5] mmc_wait_for_data_req_done() 함수 처리 후 퇴장하려함
[19]: [m.lge.launcher3-2135 CPU4] wake_up_interruptible(&mrq->host->context_info.wait);
[20] 커널 패닉
[12]번 동작에서 0으로 초기화된 &mrq->host 변수를 통해 밀린((where: memset(brq, 0, sizeof(struct mmc_blk_request)) wake_up_interruptible() API 호출
kworker/4:0-25 [004] 149.828530: irq_handler_exit: irq=111 ret=handled // <<--[7]
mmcqd/0-244 [005] 149.828536: bprint: mmc_start_req: ++mmcq [F: mmc_wait_for_data_req_done, L:1236]: ? ? from(mmc_blk_issue_rw_rq) // <<--[8]
kworker/4:0-25 [004] 149.828537: irq_handler_entry: irq=30 name=arch_timer
kworker/4:0-25 [004] 149.828546: irq_handler_exit: irq=30 ret=handled
mmcqd/0-244 [005] 149.828559: bprint: mmc_start_req: mmcq [F: mmc_wait_for_data_req_done, L:1268]: ? ? from(mmc_blk_issue_rw_rq) // <<-[9]
mmcqd/0-244 [005] 149.828561: bprint: mmc_start_req: mmcq release [F: mmc_wait_for_data_req_done, L:1270]: ? ? from(mmc_blk_issue_rw_rq) // <<--[10]
kworker/4:0-25 [004] 149.828584: workqueue_execute_end: work struct 0xcb40cae4
kworker/4:0-25 [004] 149.828630: sched_switch: prev_comm=kworker/4:0 prev_pid=25 prev_prio=120 prev_state=S ==> next_comm=m.lge.launcher3 next_pid=2135 next_prio=120 extra_prev_state=K|m|d 
m.lge.launcher3-2135 [004] 149.828660: irq_handler_entry: irq=111 name=mtk-msdc // <<--[11]
mmcqd/0-244 [005] 149.828661: bprint: mmc_blk_rw_rq_prep: ++mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1725]: ? ? from(mmc_blk_issue_rw_rq) // <<--[12]
m.lge.launcher3-2135 [004] 149.828666: bprint: mmc_wait_data_done: +msdc [F: mmc_wait_data_done, L:1049]: ? ? from(msdc_irq_data_complete) // <<--[13]
mmcqd/0-244 [005] 149.828670: bprint: mmc_blk_rw_rq_prep: -mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1905]: ? ? from(mmc_blk_issue_rw_rq) // <<-[14]
mmcqd/0-244 [005] 149.828672: bprint: mmc_blk_rw_rq_prep: mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1907]: ? ? from(mmc_blk_issue_rw_rq) // <<-[15]
mmcqd/0-244 [005] 149.828681: bprint: mmc_start_req: +mmcq [F: mmc_wait_for_data_req_done, L:1231]: ? ? from(mmc_blk_issue_rw_rq) // <<--[16]
mmcqd/0-244 [005] 149.828683: bprint: mmc_start_req: ++mmcq [F: mmc_wait_for_data_req_done, L:1236]: ? ? from(mmc_blk_issue_rw_rq) // <<--[17]
mmcqd/0-244 [005] 149.828695: bprint: mmc_start_req: -mmcq [F: mmc_wait_for_dat뗥nQ, L:0]: ? ? from(0x726f776bS) // <<--[18]
m.lge.launcher3-2135 [004] 149.829669: bprint: mmc_wait_data_done: ++msdc [F: mmc_wait_data_done, L:1058]: ? ? from(msdc_irq_data_complete) // <<--[19]
m.lge.launcher3-2135 [004] 149.829748: tracing_on: ftrace is disabled caller=oops_enter // <<?[20]

1222 static int mmc_wait_for_data_req_done(struct mmc_host *host,
1223 struct mmc_request *mrq,
1224 struct mmc_async_req *next_req)
1225*{*
1226 struct mmc_command *cmd;
1227 struct mmc_context_info *context_info = &host->context_info;
1228 int err;
1229 unsigned long flags;
1230
1231 trace_printk("+mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[16]
1232 while (1) {
1233 wait_event_interruptible(context_info->wait,
1234 (context_info->is_done_rcv ||
1235 context_info->is_new_req));
1236 trace_printk("++mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[8], [17]
1237 spin_lock_irqsave(&context_info->lock, flags);
//snip
1268 trace_printk("mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<-[9], [18]
1269 mmc_retune_release(host);
1270 trace_printk("mmcq release [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));
1271 return err;
1272 }

1701 static void mmc_blk_rw_rq_prep(struct mmc_queue_req *mqrq,
1702 struct mmc_card *card,
1703 int disable_multi,
1704 struct mmc_queue *mq)
1705*{*
1706 u32 readcmd, writecmd;
1707 struct mmc_blk_request *brq = &mqrq->brq;
//생략
1724 memset(brq, 0, sizeof(struct mmc_blk_request));
1725 trace_printk("++mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[12]
1726 brq->mrq.cmd = &brq->cmd;
//생략
1905 trace_printk("-mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); //<<-[14]
1906 mmc_queue_bounce_pre(mqrq);
1907 trace_printk("-mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));
1908 }

1046 static void mmc_wait_data_done(struct mmc_request *mrq)
1047*{*
1048 mrq->host->context_info.is_done_rcv = true;
1049 trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[13]
//생략
1051 mdelay(1);
//생략
1057
1058 trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[19]
1059 wake_up_interruptible(&mrq->host->context_info.wait);
1060 trace_printk("--msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

정리하면 wake_up_interruptible() API에 파라미터로 전달되는 &mrq->host->context_info.wait를 다른 값(mmcqd를 깨울 수 있는 wait_queue)으로 바꾸거나,
wake_up_interruptible() 호출 시 조건을 줘야 한다. 혹은 spinlock irq save로 코드 보호

솔류션
분석된 내용에 따라 아래 패치를 적용하였더니 문제가 사라졌다. 
 diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c
index c3abe34..01e4bfc 100644
--- a/drivers/mmc/core/core.c
+++ b/drivers/mmc/core/core.c
@@ -403,8 +403,13 @@ EXPORT_SYMBOL(mmc_start_bkops);
*/
static void mmc_wait_data_done(struct mmc_request *mrq)
{
+       unsigned long flags;
+       struct mmc_context_info *context_info = &mrq->host->context_info;
+
+       spin_lock_irqsave(&context_info->lock, flags);
         mrq->host->context_info.is_done_rcv = true;
         wake_up_interruptible(&mrq->host->context_info.wait);
+       spin_unlock_irqrestore(&context_info->lock, flags);
}
static void mmc_wait_done(struct mmc_request *mrq)
@@ -465,6 +470,7 @@ static int mmc_wait_for_data_req_done(struct mmc_host *host,
         struct mmc_command *cmd;
         struct mmc_context_info *context_info = &host->context_info;
         int err;
+       bool is_done_rcv = false;
         unsigned long flags;
         while (1) {
@@ -472,9 +478,10 @@ static int mmc_wait_for_data_req_done(struct mmc_host *host,
        (context_info->is_done_rcv ||
                     context_info->is_new_req));
                     spin_lock_irqsave(&context_info->lock, flags);
+          is_done_rcv = context_info->is_done_rcv;
            context_info->is_waiting_last_req = false;
            spin_unlock_irqrestore(&context_info->lock, flags);
-          if (context_info->is_done_rcv) {
+         if (is_done_rcv) {
                  context_info->is_done_rcv = false;
                  context_info->is_new_req = false;
                  cmd = mrq->cmd;

그런데, 리눅스 커뮤니티에서 이미 패치를 릴리즈했네. 
https://patchwork.kernel.org/patch/7089351/
diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c
index 347108a..db74413 100644
--- a/drivers/mmc/core/core.c
+++ b/drivers/mmc/core/core.c
@@ -1042,8 +1042,10 @@ EXPORT_SYMBOL(mmc_start_bkops);
*/
static void mmc_wait_data_done(struct mmc_request *mrq)
{
-       mrq->host->context_info.is_done_rcv = true;
-       wake_up_interruptible(&mrq->host->context_info.wait);
+      struct mmc_context_info *context_info = &mrq->host->context_info;
+
+      context_info->is_done_rcv = true;
+      wake_up_interruptible(&context_info->wait);
}


[Linux][ftrace]function/function_graph tracer 리눅스 커널

config 설정
아래와 같이 CONFIG를 설정하면 function/functin_graph Trace가 enable됩니다.
diff --git a/arch/arm/configs/pompeii_com_defconfig b/arch/arm/configs/pompeii_com_defconfig
index cb0ff09..e76a947 100644
--- a/arch/arm/configs/pompeii_com_defconfig
+++ b/arch/arm/configs/pompeii_com_defconfig
@@ -772,6 +770,9 @@ CONFIG_FREE_PAGES_RDONLY=y
 CONFIG_DEBUG_SET_MODULE_RONX=y
 CONFIG_SECURITY=y
 CONFIG_SECURITY_NETWORK=y
+CONFIG_DYNAMIC_FTRACE=y
+CONFIG_FUNCTION_TRACER=y
+CONFIG_FUNCTION_GRAPH_TRACER=y
 CONFIG_LSM_MMAP_MIN_ADDR=4096
 CONFIG_SECURITY_SELINUX=y
 CONFIG_CRYPTO_NULL=y
 
아래와 같이 설정하면 function tracer가 enable됩니다.
adb shell "echo  > d/tracing/set_event"
adb shell "sleep 1"

adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"

 adb shell "echo function > d/tracing/current_tracer"
: adb shell "echo function_graph > d/tracing/current_tracer"
adb shell "sleep 1"

: Do not trace trash logs
:adb shell "echo msm_* > d/tracing/set_ftrace_notrace"
adb shell "sleep 1"

adb shell "echo __fd_install smpboot_thread_fn process_one_work > d/tracing/set_ftrace_filter"
adb shell "sleep 1"

adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1"

function tracer를 키고 받은 ftrace log는 아래와 같은데, caller 함수를 확인할 수 있습니다.
             top-7786  [000] ...1   961.518100: __fd_install <-fd_install
             top-7786  [000] ...1   961.518416: __fd_install <-fd_install
   kworker/u16:4-341   [005] d..2   961.518468: process_one_work <-worker_thread
   kworker/u16:4-341   [005] d..2   961.518513: process_one_work <-worker_thread
             top-7786  [000] ...1   961.518646: __fd_install <-fd_install
     kworker/5:2-2599  [005] d..2   961.518785: process_one_work <-worker_thread
             top-7786  [000] ...1   961.518875: __fd_install <-fd_install
             top-7786  [000] ...1   961.519139: __fd_install <-fd_install
             top-7786  [000] ...1   961.519379: __fd_install <-fd_install
             top-7786  [000] ...1   961.519637: __fd_install <-fd_install

Function Graph Trace는 아래와 같이 설정할 수 있습니다. 한 가지 주의할 점은 set_ftrace_filter을 설정하지 않으면,
많은 로깅으로 와치독 리셋이 발생한다는 것입니다.
adb shell "echo  > d/tracing/set_event"
adb shell "sleep 1"

adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"

adb shell "echo function_graph > d/tracing/current_tracer"
adb shell "sleep 1"

: Do not trace trash logs
:adb shell "echo msm_* > d/tracing/set_ftrace_notrace"
adb shell "sleep 1"

adb shell "echo __fd_install smpboot_thread_fn process_one_work > d/tracing/set_ftrace_filter"
adb shell "sleep 1"

adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1"             

샘플 Ftrace log
 4) + 11.406 us   |  process_one_work();
 ------------------------------------------
 4)  kworker-7886  =>  pompeii_irq-8041 
 ------------------------------------------

 4)   1.198 us    |  __fd_install();
 4)   0.885 us    |  __fd_install();
 4)   1.094 us    |  __fd_install();
 4)   0.886 us    |  __fd_install();
 4)   0.937 us    |  __fd_install();
 4)   0.990 us    |  __fd_install();
 4)   0.938 us    |  __fd_install();
 4)   4.375 us    |  __fd_install();
 4)   0.938 us    |  __fd_install();
 4)   0.833 us    |  __fd_install();
 4)   0.781 us    |  __fd_install();
 4)   0.782 us    |  __fd_install();
 4)   0.781 us    |  __fd_install();
 ------------------------------------------
 5)  kworker-2599  =>  kworker-341  
 ------------------------------------------

 5) ! 884.322 us  |  process_one_work();
 4)   0.990 us    |  __fd_install();
 4)   0.729 us    |  __fd_install();
 5) + 43.229 us   |  process_one_work();
 5) ! 189.166 us  |  process_one_work();
 ------------------------------------------
 5)  kworker-341   =>  kworker-2599 
 ------------------------------------------

 5) + 10.156 us   |  process_one_work();
 4)   0.834 us    |  __fd_install();
 4)   0.729 us    |  __fd_install();
 4)   0.833 us    |  __fd_install();
 4)   0.781 us    |  __fd_install();
 4)   0.625 us    |  __fd_install();
 4)   0.886 us    |  __fd_install();
 4)   0.781 us    |  __fd_install();
 4)   0.625 us    |  __fd_install();
 4)   0.729 us    |  __fd_install();
 ------------------------------------------
 4)  msm_irq-8041  =>  logd.wr-436  
 ------------------------------------------

 4)   1.406 us    |  __fd_install();
 4)   0.729 us    |  __fd_install();
 4)   0.729 us    |  __fd_install();
 4)   0.730 us    |  __fd_install();
 ------------------------------------------

multi_cpu_stop를 function_graph filter로 설정하면 아래와 같은 로그를 확인할 수 있습니다.
 2) ! 1474.479 us |  multi_cpu_stop();
 4) ! 1459.688 us |  multi_cpu_stop();
 5) ! 1460.105 us |  multi_cpu_stop();
 6) ! 1446.406 us |  multi_cpu_stop();
 7) ! 1442.136 us |  multi_cpu_stop();
 5) ! 2408.698 us |  multi_cpu_stop();
 4) ! 2408.698 us |  multi_cpu_stop();
 6) ! 2405.000 us |  multi_cpu_stop();
 7) ! 2401.354 us |  multi_cpu_stop();
 2) ! 2100.209 us |  multi_cpu_stop(); 

아래와 같은 필터를 설정하면
adb shell "echo msm_cpu_pm_enter_sleep psci_enter_sleep cluster_prepare > d/tracing/set_ftrace_filter"

ftrace log 확보가 아래와 같이 가능합니다. power collapse 문제로 재현이 잘되는 시료가 확보되면 한번 테스트 해보아야 겠습니다.
 0) + 11.198 us   |  psci_enter_sleep();
 3)   0.781 us    |  cluster_prepare();
 0)               |  cluster_prepare() {
 3) + 21.875 us   |  psci_enter_sleep();
 0)               |    cluster_prepare() {
 0)   0.364 us    |      cluster_prepare();
 0)   7.292 us    |    }
 0) + 14.688 us   |  }
 0) + 11.094 us   |  psci_enter_sleep();
 3)   0.782 us    |  cluster_prepare();
 0)               |  cluster_prepare() {
 3) + 22.031 us   |  psci_enter_sleep();
 0)               |    cluster_prepare() {
 0)   0.365 us    |      cluster_prepare();
 0)   7.344 us    |    }
 0) + 14.791 us   |  }
 0) + 11.198 us   |  psci_enter_sleep();
 3)   0.834 us    |  cluster_prepare();
 0)               |  cluster_prepare() {

function_graph tracer는 설정 방법이 약간 다릅니다.
가장 많이 호출되는 함수 __fd_install와 scm_call2를 아래와 같이 설정 해보겠습니다.
adb shell "echo  > d/tracing/set_event"
adb shell "sleep 1"

adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"

adb shell "echo function_graph > d/tracing/current_tracer"
adb shell "sleep 1"

adb shell "echo  > d/tracing/set_ftrace_filter"
adb shell "sleep 1"

adb shell "echo __fd_install scm_call2  > d/tracing/set_graph_function"
adb shell "sleep 1"

adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1"

ftrace를 열어서 보면 scm_call2() 함수가 수행되는데에 23.229 us시간이 걸렸음을 알 수 있습니다.
 ------------------------------------------
 7)  Thread--2524  =>  kworker-1553 
 ------------------------------------------

 7)               |  scm_call2() {
 7)   0.260 us    |    is_scm_armv8();
 7)               |    allocate_extra_arg_buffer.part.3() {
 7)               |      kmem_cache_alloc_trace() {
 7)   0.312 us    |        __might_sleep();
 7)   0.365 us    |        preempt_count_add();
 7)   0.260 us    |        preempt_count_sub();
 7)               |        __slab_alloc.constprop.8() {
 7)               |          get_partial_node() {
 7)               |            _raw_spin_lock() {
 7)   0.313 us    |              preempt_count_add();
 7)   0.312 us    |              do_raw_spin_lock();
 7)   5.990 us    |            }
 7)   0.312 us    |            preempt_count_add();
 7)   0.312 us    |            preempt_count_sub();
 7)               |            _raw_spin_unlock() {
 7)   0.364 us    |              do_raw_spin_unlock();
 7)   0.261 us    |              preempt_count_sub();
 7)   5.937 us    |            }
 7) + 23.646 us   |          }

또 다른 흥미로운 점은 함수 콜 도중에 IRQ가 Fire되었을 때 화살표를 찍어줍니다.
 7)               |            _raw_spin_lock() {
 7)   0.365 us    |              preempt_count_add();
 7)   0.312 us    |              do_raw_spin_lock();
 7)   5.937 us    |            }
 7)   0.260 us    |            preempt_count_add();
 7)   0.313 us    |            preempt_count_sub();
 7)               |            _raw_spin_unlock() {
 7)   0.313 us    |              do_raw_spin_unlock();
 7)   0.261 us    |              preempt_count_sub();
 7)   5.937 us    |            }
 7) + 57.187 us   |          }
 7)   ==========> |
 7)               |          gic_handle_irq() {
 7)               |            handle_IPI() {
 7)   0.521 us    |              scheduler_ipi();
 7)   4.219 us    |            }
 7)   9.322 us    |          }
 7)   <========== |
 7)               |          preempt_schedule_irq() {
 7)               |            __schedule() {
 7)   0.261 us    |              preempt_count_add();
 7)               |              rcu_note_context_switch() {

__fd_install() 함수는 17.136 us 시간이 걸렸군요.
 3)               |  __fd_install() {
 3)               |    _raw_spin_lock() {
 3)   0.365 us    |      preempt_count_add();
 3)   0.364 us    |      do_raw_spin_lock();
 3)   5.937 us    |    }
 3)               |    _raw_spin_unlock() {
 3)   0.312 us    |      do_raw_spin_unlock();
 3)   0.313 us    |      preempt_count_sub();
 3)   5.730 us    |    }
 3) + 17.136 us   |  }

그럼 이제 __fd_install() 함수가 수행되는 시간을 Tracing해보겠습니다.
참고로, __fd_install() 함수는 시스템 콜을 통해 file descriptor를 설정하는 중요한 커널 API입니다.
adb shell "echo __fd_install  > d/tracing/set_ftrace_filter"
adb shell "sleep 1"

adb shell "echo __fd_install  > d/tracing/set_graph_function"
adb shell "sleep 1"

아래와 같이 __fd_install() 함수가 수행된 시간을 확인할 수 있습니다.
 ------------------------------------------
 5)    gbmd-822    => pompeii_irq-10671 
 ------------------------------------------

 5)   1.458 us    |  __fd_install();
 5)   1.146 us    |  __fd_install();
 5)   1.041 us    |  __fd_install();
 5)   0.989 us    |  __fd_install();
 5)   0.885 us    |  __fd_install();
 5)   1.041 us    |  __fd_install();
 5)   1.407 us    |  __fd_install();
 5)   0.990 us    |  __fd_install();
 5)   1.145 us    |  __fd_install();
 5)   0.886 us    |  __fd_install();
 5)   0.834 us    |  __fd_install();
 5)   0.886 us    |  __fd_install();
 5)   0.782 us    |  __fd_install();
 5)   0.834 us    |  __fd_install();
 5)   0.885 us    |  __fd_install();
 5)   0.833 us    |  __fd_install();
 5)   0.885 us    |  __fd_install();

scm_call2() 함수를 둘다 d/tracing/set_ftrace_filter d/tracing/set_graph_function 필터로 지정하면 아래와
같은 시간을 확인할 수 있습니다.
 6) + 48.854 us   |  scm_call2();
 6) + 47.136 us   |  scm_call2();
 4) + 48.489 us   |  scm_call2();
 4) + 47.292 us   |  scm_call2();
 4) + 48.177 us   |  scm_call2();
 4) + 46.771 us   |  scm_call2();
 5) + 47.708 us   |  scm_call2();
 5) + 47.239 us   |  scm_call2();
 
function/function_graph tracer의 강력한 기능 중의 하나는 ftrace event와 같이 로그를 볼 수 있다는 점입니다.
 
그럼 하나의 예제로 watchdog kick이 수행될 때의 동작을 점검해보겠습니다.
watchdog_kthread() 함수에서 watchdog kick을 하는 함수는 pet_watchdog() 인데,
ping_other_cpus() 함수 콜을 수행합니다.

static __ref int watchdog_kthread(void *arg)
{
 struct pompeii_watchdog_data *wdog_dd =
  (struct pompeii_watchdog_data *)arg;
 unsigned long delay_time = 0;
 struct sched_param param = {.sched_priority = MAX_RT_PRIO-1};

 sched_setscheduler(current, SCHED_FIFO, &param);
 while (!kthread_should_stop()) {
  while (wait_for_completion_interruptible(
   &wdog_dd->pet_complete) != 0)
   ;
  reinit_completion(&wdog_dd->pet_complete);
  if (enable) {
   delay_time = msecs_to_jiffies(wdog_dd->pet_time);
   if (wdog_dd->do_ipi_ping)
    ping_other_cpus(wdog_dd);  // <<--
   pet_watchdog(wdog_dd);
static void ping_other_cpus(struct msm_watchdog_data *wdog_dd)
{
 int cpu;
 cpumask_clear(&wdog_dd->alive_mask);
 smp_mb();
 for_each_cpu(cpu, cpu_online_mask) {
  if (!cpu_idle_pc_state[cpu])
   smp_call_function_single(cpu, keep_alive_response, // <<--
       wdog_dd, 1);
 }

아래와 같이 설정하겠습니다.
adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"

adb shell "echo  > d/tracing/set_event"
adb shell "sleep 1"

adb shell "echo 1  > d/tracing/events/sched/sched_switch/enable"
adb shell "sleep 1"

adb shell "echo function > d/tracing/current_tracer"
adb shell "sleep 1"

: Do not trace trash logs
:adb shell "echo msm_* > d/tracing/set_ftrace_notrace"
adb shell "sleep 1"

adb shell "echo smp_call_function_single > d/tracing/set_ftrace_filter"
adb shell "sleep 1"

adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1"

2분 동안 타겟을 구동시킨 다음에 ftrace log를 받아 msm_watchdog 스트링으로 검색하면 아래와 같은 ftrace log 확인이 가능합니다.
100% 재현되는 watchdog reset 이슈가 있으면 유용하게 디버깅할 수 있습니다.
           <...>-334   [007] d..3  6904.620469: sched_switch: prev_comm=cfinteractive prev_pid=334 prev_prio=0 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120
          <idle>-0     [006] d..3  6904.640143: sched_switch: prev_comm=swapper/6 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=msm_watchdog next_pid=66 next_prio=0
    msm_watchdog-66    [006] ...1  6904.640151: smp_call_function_single <-watchdog_kthread  "//<<--"
    msm_watchdog-66    [006] ...1  6904.640160: smp_call_function_single <-watchdog_kthread  "//<<--"
    msm_watchdog-66    [006] ...1  6904.640169: smp_call_function_single <-watchdog_kthread  "//<<--"
    msm_watchdog-66    [006] ...1  6904.640178: smp_call_function_single <-watchdog_kthread  "//<<--"
    msm_watchdog-66    [006] ...1  6904.640187: smp_call_function_single <-watchdog_kthread  "//<<--"
    msm_watchdog-66    [006] ...1  6904.640189: smp_call_function_single <-watchdog_kthread  "//<<--"
    msm_watchdog-66    [006] d..3  6904.640250: sched_switch: prev_comm=msm_watchdog prev_pid=66 prev_prio=0 prev_state=S ==> next_comm=kworker/u16:2 next_pid=10199 next_prio=120
           <...>-10199 [006] d..3  6904.640387: sched_switch: prev_comm=kworker/u16:2 prev_pid=10199 prev_prio=120 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120

smp_call_function_single() 함수 콜 내부 동작을 좀 더 확인하고 싶으면, 아래와 같이 설정하면 됩니다.
adb shell "echo 0 > d/tracing/tracing_on"
adb shell "sleep 1"

adb shell "echo  > d/tracing/set_event"
adb shell "sleep 1"

adb shell "echo 1  > d/tracing/events/sched/sched_switch/enable"
adb shell "sleep 1"

adb shell "echo function > d/tracing/current_tracer"
adb shell "sleep 1"

: Do not trace trash logs
:adb shell "echo msm_* > d/tracing/set_ftrace_notrace"
adb shell "sleep 1"

adb shell "echo smp_call_function_single > d/tracing/set_ftrace_filter"
adb shell "sleep 1"

adb shell "echo 1 > d/tracing/tracing_on"
adb shell "sleep 1" 

아래 로그를 해석해보겠습니다.
 6)               |  /* sched_switch: prev_comm=swapper/6 prev_pid=0 prev_prio=120 prev_state=R+ ==> next_comm=msm_watchdog next_pid=66 next_prio=0 */
 ------------------------------------------
 6)    <idle>-0    =>   msm_wat-66  
 ------------------------------------------

 6)               |  smp_call_function_single() {
 6)   0.469 us    |    preempt_count_add();
 6)               |    generic_exec_single() {
 6)               |      arch_send_call_function_single_ipi() {
 6)               |        smp_cross_call_common() {
 6)               |          gic_raise_softirq() {
 6)               |            _raw_spin_lock_irqsave() {
 6)   0.365 us    |              preempt_count_add();
 6)   0.468 us    |              do_raw_spin_lock();
 6)   8.437 us    |            }
 6)               |            _raw_spin_unlock_irqrestore() {
 6)   0.416 us    |              do_raw_spin_unlock();
 6)   0.365 us    |              preempt_count_sub();
 6)   7.083 us    |            }
 6) + 23.021 us   |          }
 6) + 26.719 us   |        }
 6) + 30.000 us   |      }
 6) + 34.375 us   |    }
 6)   0.364 us    |    preempt_count_sub();
 6) + 47.396 us   |  }  // <<-- smp_call_function_single() 수행된 시간입니다.
 6)               |  smp_call_function_single() {
 6)   0.521 us    |    preempt_count_add();
 6)               |    generic_exec_single() {
 6)               |      arch_send_call_function_single_ipi() {
 6)               |        smp_cross_call_common() {
 6)               |          gic_raise_softirq() {
 6)               |            _raw_spin_lock_irqsave() {
 6)   0.313 us    |              preempt_count_add();
 6)   0.417 us    |              do_raw_spin_lock();
 6)   7.240 us    |            }
 6)               |            _raw_spin_unlock_irqrestore() {
 6)   0.417 us    |              do_raw_spin_unlock();
 6)   0.365 us    |              preempt_count_sub();
 6)   7.083 us    |            }
 6) + 21.250 us   |          }
 6) + 24.948 us   |        }
 6) + 28.229 us   |      }
 6) ! 148.229 us  |    }
 6)   0.312 us    |    preempt_count_sub();
 6) ! 160.469 us  |  } // <<-- smp_call_function_single() 수행된 시간인데 느낌표가 있는 이유는 smp_call_function_single() 함수가 수행된 시간이 100.us 시간을 넘었기 때문입니다.
 6)               |  smp_call_function_single() {
 6)   0.416 us    |    preempt_count_add();
 6)               |    generic_exec_single() {
 6)               |      arch_send_call_function_single_ipi() {
 6)               |        smp_cross_call_common() {
 6)               |          gic_raise_softirq() {
 6)               |            _raw_spin_lock_irqsave() {
 6)   0.365 us    |              preempt_count_add();
 6)   0.365 us    |              do_raw_spin_lock();
 6)   6.927 us    |            }
 6)               |            _raw_spin_unlock_irqrestore() {
 6)   0.417 us    |              do_raw_spin_unlock();
 6)   0.312 us    |              preempt_count_sub();
 6)   6.979 us    |            }
 6) + 20.937 us   |          }
 6) + 24.322 us   |        }
 6) + 27.500 us   |      }
 6) ! 163.802 us  |    }
 6)   0.365 us    |    preempt_count_sub();
 6) ! 174.739 us  |  }
 6)               |  smp_call_function_single() {
 6)   0.469 us    |    preempt_count_add();
 6)               |    generic_exec_single() {
 6)               |      arch_send_call_function_single_ipi() {
 6)               |        smp_cross_call_common() {
 6)               |          gic_raise_softirq() {
 6)               |            _raw_spin_lock_irqsave() {
 6)   0.365 us    |              preempt_count_add();
 6)   0.417 us    |              do_raw_spin_lock();
 6)   6.979 us    |            }
 6)               |            _raw_spin_unlock_irqrestore() {
 6)   0.417 us    |              do_raw_spin_unlock();
 6)   0.312 us    |              preempt_count_sub();
 6)   6.979 us    |            }
 6) + 21.094 us   |          }
 6) + 24.479 us   |        }
 6) + 27.709 us   |      }
 6) ! 155.104 us  |    }
 6)   0.417 us    |    preempt_count_sub();
 6) ! 166.250 us  |  }
 6)               |  smp_call_function_single() {
 6)   0.469 us    |    preempt_count_add();
 6)               |    generic_exec_single() {
 6)   0.521 us    |      keep_alive_response();
 6)   4.218 us    |    }
 6)   0.365 us    |    preempt_count_sub();
 6) + 14.687 us   |  }
 6)               |  smp_call_function_single() {
 6)   0.416 us    |    preempt_count_add();
 6)               |    generic_exec_single() {
 6)               |      arch_send_call_function_single_ipi() {
 6)               |        smp_cross_call_common() {
 6)               |          gic_raise_softirq() {
 6)               |            _raw_spin_lock_irqsave() {
 6)   0.312 us    |              preempt_count_add();
 6)   0.416 us    |              do_raw_spin_lock();
 6)   7.396 us    |            }
 6)               |            _raw_spin_unlock_irqrestore() {
 6)   0.417 us    |              do_raw_spin_unlock();
 6)   0.365 us    |              preempt_count_sub();
 6)   7.031 us    |            }
 6) + 21.511 us   |          }
 6) + 25.104 us   |        }
 6) + 28.333 us   |      }
 6) ! 155.730 us  |    }
 6)   0.364 us    |    preempt_count_sub();
 6) ! 167.032 us  |  } 

[Linux][Debug][T32] macro offsetof/container_of 리눅스 커널

Overview
When debugging ramdump with stability issues, I have been spending most of time casting various data structure as belows.
v.v %s (struct task_struct*)0xC1917FCC
For this matter, I made several macros to minimize the debugging time.
The definition of the macro is below.
sYmbol.NEW.MACRO offsetof(type,member) ((int)(&((type*)0)->member))
sYmbol.NEW.MACRO container_of(ptr,type,member) ((type *)((char *)(ptr)-offsetof(type,member)))

offsetof(type,member)
When analyzing assembly code, I have to know the offset of certain element, assembly code is generated based upon offset value of data structure.
[1]: offset: struct kgsl_context.device is calculated as 0x1C
v.v % offsetof(struct kgsl_context,device)
  (int) offsetof(struct kgsl_context,device) = 28 = 0x1C = '....'
[assemble code]
NSR:C0500F68|E594501C                                  ldr     r5,[r4,#0x1C]

[2]: offset: struct adreno_context.rb
v.v % offsetof(struct adreno_context,rb)
  (int) offsetof(struct adreno_context,rb) = 768 = 0x0300 = '....'
[assemble code]
NSR:C0501054|E5943300                                  ldr     r3,[r4,#0x300]

Code segment for this example
449void adreno_drawctxt_detach(struct kgsl_context *context)
450{
451 struct kgsl_device *device;
452 struct adreno_device *adreno_dev;
453 struct adreno_context *drawctxt;
454 struct adreno_ringbuffer *rb;
455 int ret, count, i;
456 struct kgsl_cmdbatch *list[ADRENO_CONTEXT_CMDQUEUE_SIZE];
//snip
460
461 device = context->device;  // <<--[1]
462 adreno_dev = ADRENO_DEVICE(device);
463 drawctxt = ADRENO_CONTEXT(context);
 464 rb = drawctxt->rb; // <<--[2]
465

container_of(ptr,type,member)
(Example1)
In order to find out the total element of "struct task_struct" as per "struct task_struct.tasks.next",
I have to manipulate the T32 many times. For this, let me introduce the container_of(ptr,type,member) macro
v.v %h container_of(0xEE458238,struct task_struct,tasks)
  container_of(0xEE458238,struct task_struct,tasks) = 0xEE458000 -> (
    state = 0x1,
    stack = 0xEE44A000,
//snip
    cputime_expires = (utime = 0x0, stime = 0x0, sum_exec_runtime = 0x0),
    cpu_timers = ((next = 0xEE458380, prev = 0xEE458380), (next = 0xEE458388, pr
    real_cred = 0xE2494D00,
    cred = 0xE2494D00,
    comm = "init",

(where)
  [D:0xC16141E8] init_task = (
    [D:0xC16141E8] state = 0x0,
    [D:0xC16141EC] stack = 0xC1600000,
//snip
    [D:0xC161441C] rcu_blocked_node = 0x0,
    [D:0xC1614420] tasks = (
      [D:0xC1614420] next = 0xEE458238,  // <<--
      [D:0xC1614424] prev = 0xC288B938),
    [D:0xC1614428] pushable_tasks = ([D:0xC1614428] prio = 0x8C, [D:0xC161442C] prio_list = ([D:0xC161442C] next = 0x
//snip
    [D:0xC1614584] cred = 0xC1619D18,
    [D:0xC1614588] comm = "swapper/0",
    [D:0xC1614598] link_count = 0x0,
    [D:0xC161459C] total_link_count = 0x0,

v.v %h %s container_of(0xDB63FE68,struct mutex,wait_list)
  container_of(0xDB63FE68,struct mutex,wait_list) = 0xDB63FE54 -> (
    count = (counter = 0xC0C0A56C),
    wait_lock = (rlock = (raw_lock = (slock = 0xC16A057C, tickets = (owner = 0x057C, next = 0xC16A)), magic = 0xC0C08C70, o
    wait_list = (next = 0xDAC43DB8, prev = 0xC15DBC40),
    owner = 0xE0396E00,
    name = 0xDB63FE68 -> ".=..@.].",
    magic = 0xFFFFFFFF)

  container_of(0xDAC43DB8,struct mutex,wait_list) = 0xDAC43DA4 -> (
    count = (counter = 0xC0C0A56C),
    wait_lock = (rlock = (raw_lock = (slock = 0xC16A057C, tickets = (owner = 0x0
    wait_list = (next = 0xDAC55E68, prev = 0xDB63FE68),
    owner = 0xDD5C5D80,
    name = 0xDAC43DB8 -> "h^..h.c..]\..=..``v.,.].",
    magic = 0xDB766060)

(where)  binder_main_lock = (
    count = (counter = 0xFFFFFFFF),
    wait_lock = (rlock = (raw_lock = (slock = 0xF1CCF1CC, tickets = (owner = 0xF
    wait_list = (
      next = 0xDB63FE68 // <<--
        next = 0xDAC43DB8 // <<--
          next = 0xDAC55E68 -> (
            next = 0xC15DBC40 -> (
              next = 0xDB63FE68,

container_of_double_vcast(ptr,type,member,new_member,cast_type)
Definition
sYmbol.NEW.MACRO container_double_vcast(ptr,type,member,new_member,cast_type) ((cast_type *)(*(type *)((char *)(ptr)-offsetof(type,member)+offsetof(type,new_member))))
(Example1: PHONEMODEL-1958)
container_of_double_vcast(0xDAC43DB8,struct mutex,wait_list,owner,struct task_struct)
  container_of_double_vcast(0xDAC43DB8,struct mutex,wait_list,owner,struct task_struct) = 0xDD5C5D80 -> (
    state = 0x2,
    stack = 0xDAC42000,
    usage = (counter = 0x2),
    flags = 0x00400040,
    ptrace = 0x0,
    wake_entry = (next = 0x0),
    on_cpu = 0x0,
    on_rq = 0x0,
    prio = 0x78,
    static_prio = 0x78,

(where)
  binder_main_lock = (  // <<-- type: struct mutex
    count = (counter = 0xFFFFFFFF),
    wait_lock = (rlock = (raw_lock = (slock = 0xF1CCF1CC, tickets = (owner = 0xF
    wait_list // <<-- member
      next = 0xDB63FE68 
        next = 0xDAC43DB8 // <<--  ptr
          next = 0xDAC55E68 -> (
            next = 0xC15DBC40 -> (
              next = 0xDB63FE68,
              prev = 0xDAC55E68),
            prev = 0xDAC43DB8),
          prev = 0xDB63FE68),
        prev = 0xC15DBC40),
      prev = 0xDAC55E68),
    owner = 0xD9E6A100,  // <<-- new_member, cast_type: struct task_struct
    name = 0x0,
    magic = 0xC15DBC2C)

container_down_vcast(ptr,type,member,cast)
Definition
sYmbol.NEW.MACRO container_down_vcast(ptr,type,member,cast) ((cast *)(*(type *)((char *)(ptr)+offsetof(type,member))))

v.v % container_down_vcast(0xC15DBC2C,struct mutex,owner,struct task_struct)
v.v % container_down_vcast(0xC15DBC2C,struct mutex,owner,struct task_struct)
  container_down_vcast(0xC15DBC2C,struct mutex,owner,struct task_struct) = 0xD9E6A100 -> (
    state = 1,
    stack = 0xD9ECC000,
    usage = (counter = 2),
//snip
    min_flt = 304,
    maj_flt = 0,
    cputime_expires = (utime = 0, stime = 0, sum_exec_runtime = 0),
    cpu_timers = ((next = 0xD9E6A448, prev = 0xD9E6A448), (next = 0xD9E6A450, prev = 0xD9E6A450), (next = 0xD9E6A45
    real_cred = 0xDEEF1900,
    cred = 0xDEEF1900,
    comm = "Binder_4",
    link_count = 0,

(where)
  [D:0xC15DBC2C] binder_main_lock = (  // <<-- ptr: 0xC15DBC2C, type: struct mutex
    [D:0xC15DBC2C] count = ([D:0xC15DBC2C] counter = -1),
    [D:0xC15DBC30] wait_lock = ([D:0xC15DBC30] rlock = ([D:0xC15DBC30] raw_lock
    [D:0xC15DBC40] wait_list = ([D:0xC15DBC40] next = 0xDB63FE68, [D:0xC15DBC44]
    [D:0xC15DBC48] owner = 0xD9E6A100,  // <<--member, cast: struct task_struct
    [D:0xC15DBC4C] name = 0x0,
    [D:0xC15DBC50] magic = 0xC15DBC2C)

threadoffset(ptr)
Definition
sYmbol.NEW.MACRO threadoffset(ptr) ((ptr ~0x1fff))
sYmbol.NEW.MACRO thread_of(ptr) ((struct thread_info *)((int *)threadoffset(ptr)))
When kernel crash occurs, the kernel dumps below logs
[ 1894.897301] Internal error: Oops - BUG: 0 [#1] PREEMPT SMP ARM
[ 1894.897314] Modules linked in: texfat(PO)
[ 1894.897333] CPU: 2 PID: 4324 Comm: Binder_4 Tainted: P        W  O 3.10.49-g184f2e4 #1
[ 1894.897347] task: d9e6a100 ti: d9ecc000 task.ti: d9ecc000
[ 1894.897362] PC is at __list_add+0x9c/0xd0
[ 1894.897376] LR is at __list_add+0x58/0xd0
[ 1894.897390] pc : [<c032e9e8>]    lr : [<c032e9a4>]    psr: 000f0093
[ 1894.897390] sp : d9ecdd90  ip : 00000000  fp : dc08da00
[ 1894.897409] r10: d9ecc000  r9 : c16a39ec  r8 : d9e6a100
[ 1894.897422] r7 : 00000000  r6 : d9ecddb8  r5 : c15dbc40  r4 : c0004860
[ 1894.897435] r3 : 00000000  r2 : 00001201  r1 : c16a28a8  r0 : 00000000
[ 1894.897450] Flags: nzcv  IRQs off  FIQs on  Mode SVC_32  ISA ARM  Segment user
[ 1894.897464] Control: 10c0383d  Table: 9e06006a  DAC: 00000015
[ 1894.897476] Process Binder_4 (pid: 4324, stack limit = 0xd9ecc238)
[ 1894.897489] Stack: (0xd9ecdd90 to 0xd9ece000)
[ 1894.897504] dd80:                                     00000000 c0004860 c15dbc40 c15dbc2c
[ 1894.897522] dda0: 600f0013 d9ecc030 c15dbc30 c0c08bcc d9ecdddc c15dbc40 d9ecddb8 d9ecddb8
[ 1894.897540] ddc0: 11111111 d9ecddb8 600f0013 c15dbc2c de364e00 b786a844 d9ecc038 c1660598
[ 1894.897557] dde0: 00000000 d9ecc000 dc08da00 c0c08e70 ddf0f000 c072d020 ded48000 c018b544
[ 1894.897574] de00: 00000000 800f0193 00000028 dd041600 c8002ab0 b781ee04 00000000 db0d1c00
[ 1894.897591] de20: c8002ad0 00000000 00000000 b786a840 b786a940 ddf0f01c d9ecdee0 d9ecc000

With any stack address, the (struct thread_info*) can be casted with the single command.
v.v %all thread_of(0xd9ecdd90)
  (struct thread_info *) thread_of(0xd9ecdd90) = 0xD9ECC000 = __bss_stop+0x1855F
    (long unsigned int) flags = 0 = 0x0 = '....',
    (int) preempt_count = 3 = 0x3 = '....',
    (mm_segment_t) addr_limit = 3204448256 = 0xBF000000 = '....',
    (struct task_struct *) task = 0xD9E6A100 = __bss_stop+0x184FD964 -> ((long i
    (struct exec_domain *) exec_domain = 0xC1579CDC = default_exec_domain -> ((c
    (__u32) cpu = 2 = 0x2 = '....',
    (__u32) cpu_domain = 21 = 0x15 = '....',
    (struct cpu_context_save) cpu_context = ((__u32) r4 = 3740230976 = 0xDEEF654
    (__u32) syscall = 0 = 0x0 = '....',
    (__u8 [16]) used_cp = "",
    (long unsigned int [2]) tp_value = ([0] = 3001371000 = 0xB2E54978 = '..Ix',
    (union fp_state) fpstate = ((struct fp_hard_struct) hard = ((unsigned int [3
    (union vfp_state) vfpstate = ((struct vfp_hard_struct) hard = ((__u64 [32])
    (struct restart_block) restart_block = ((long int (*)()) fn = 0xC0131A64 = d

v.v %all thread_of(0xd9ecddc0)
  (struct thread_info *) thread_of(0xd9ecddc0) = 0xD9ECC000 = __bss_stop+0x1855F
    (long unsigned int) flags = 0 = 0x0 = '....',
    (int) preempt_count = 3 = 0x3 = '....',
    (mm_segment_t) addr_limit = 3204448256 = 0xBF000000 = '....',
    (struct task_struct *) task = 0xD9E6A100 = __bss_stop+0x184FD964 -> ((long i
    (struct exec_domain *) exec_domain = 0xC1579CDC = default_exec_domain -> ((c
    (__u32) cpu = 2 = 0x2 = '....',
    (__u32) cpu_domain = 21 = 0x15 = '....',
    (struct cpu_context_save) cpu_context = ((__u32) r4 = 3740230976 = 0xDEEF654
    (__u32) syscall = 0 = 0x0 = '....',
    (__u8 [16]) used_cp = "",
    (long unsigned int [2]) tp_value = ([0] = 3001371000 = 0xB2E54978 = '..Ix',
    (union fp_state) fpstate = ((struct fp_hard_struct) hard = ((unsigned int [3
    (union vfp_state) vfpstate = ((struct vfp_hard_struct) hard = ((__u64 [32])
    (struct restart_block) restart_block = ((long int (*)()) fn = 0xC0131A64 = d


[Linux][Debug][CrashTools] New command "ps -e" 리눅스 커널


Why I added new features to crash tool?

Sometimes, some linux kernel in another platform are missing struct task_struct.sched_info.last_arrival element. For this matter, it is hard to know how the processes are executed at the time of order.

The "ps -e" command allows for listing the process at the time of order based on execution launching time.

crash> ps -e

ps: exec_start - task_struct.se.exec_start will be displayed at the time of order

   2123      1   4  e2d8ca40  IN   0.2   33324   7556  Aat_key_press

     36      2   4  eb5d9440  IN   0.0       0      0  [ksoftirqd/4]

   2118      1   4  e203c380  UN   0.2   33324   7556  func_keypress

    904      1   4  d0f04380  IN   0.1   57988   3148  thermal-engine

   1783      1   4  e59e9b00  UN   0.3   50144  13760  wireless_cmdmgr

   1250      1   4  e6eaaf40  UN   0.0   14724   1668  mtsd

    347      2   4  c4f9e540  UN   0.0       0      0  [mmc-cmdqd/0]

    713      2   4  ccdee540  IN   0.0       0      0  [kworker/u16:9]

   1701   1677   4  e58f86c0  UN   0.0    3944   1672  kernel_logger

    342      2   4  c4f98000  IN   0.0       0      0  [cfinteractive]

>   545      1   7  e91bc380  RU   0.4  127608  15532  Binder:482_2

   1793      1   5  e58fbcc0  IN   0.1   19544   2832  MSensorControl

>  1901      1   5  e4bf6540  RU   0.1   64628   5348  TouchLocation

    544      1   5  e91baf40  IN   0.4  127608  15532  DispSync

    616      1   5  e92d2880  IN   0.4  127608  15532  EventThread

   1878      1   5  e4ba3cc0  IN   0.1   82996   5608  SensorEventAckR


As sanity-test, it proves that output of "ps -e" command is the same as that of "ps -l" command.

crash> ps -l

[303201734830] [IN]  PID: 2123   TASK: e2d8ca40  CPU: 4   COMMAND: "Aat_key_press"

[303200690976] [IN]  PID: 36     TASK: eb5d9440  CPU: 4   COMMAND: "ksoftirqd/4"

[303163325351] [UN]  PID: 2118   TASK: e203c380  CPU: 4   COMMAND: "func_keypress"

[303160294830] [IN]  PID: 904    TASK: d0f04380  CPU: 4   COMMAND: "thermal-engine"

[303113625611] [UN]  PID: 1783   TASK: e59e9b00  CPU: 4   COMMAND: "wireless_cmdmgr"

[303113595247] [UN]  PID: 1250   TASK: e6eaaf40  CPU: 4   COMMAND: "mtsd"

[303113557955] [UN]  PID: 347    TASK: c4f9e540  CPU: 4   COMMAND: "mmc-cmdqd/0"

[303113325299] [IN]  PID: 713    TASK: ccdee540  CPU: 4   COMMAND: "kworker/u16:9"

[303112047955] [UN]  PID: 1701   TASK: e58f86c0  CPU: 4   COMMAND: "kernel_logger"

[303111794049] [IN]  PID: 342    TASK: c4f98000  CPU: 4   COMMAND: "cfinteractive"

[303090714882] [RU]  PID: 1901   TASK: e4bf6540  CPU: 5   COMMAND: "TouchLocation"

[303090673424] [IN]  PID: 1793   TASK: e58fbcc0  CPU: 5   COMMAND: "MSensorControl"

[303084315090] [IN]  PID: 544    TASK: e91baf40  CPU: 5   COMMAND: "DispSync"

[303084262278] [IN]  PID: 616    TASK: e92d2880  CPU: 5   COMMAND: "EventThread"

[303083165715] [IN]  PID: 1878   TASK: e4ba3cc0  CPU: 5   COMMAND: "SensorEventAckR"


As for this project, "ps -l" does not work as below.

crash> ps -l

ps: last-run timestamps do not exist in this kernel

Usage:

  ps [-k|-u|-G] [-s] [-p|-c|-t|-[l|m][-C cpu]|-a|-g|-r|-S]

     [pid | task | command] ...

Enter "help ps" for details.


crash> ps -e

crash> ps -e

ps: exec_start - task_struct.se.exec_start will be displayed at the time of order

> 31114      2   3  c2385280  RU   0.0       0      0  [kworker/u8:0]

> 21723      2   0  eb33bc80  RU   0.0       0      0  [kworker/u8:3]

  20759      1   1  d243b700  IN   0.0   42688   1536  atd

> 29684      1   2  c1c31080  RU   0.0       0      0  thread-pool-0

  31741      2   0  c2888580  IN   0.0       0      0  [kworker/0:0]

  32030      2   0  cd6c5d80  IN   0.0       0      0  [kworker/u8:2]

    757      1   1  dccfb700  IN   0.0   50520   1248  thermal-engine

    701      1   1  e4624d00  IN   0.0   10848    904  gbmd

  30403      2   3  e6decd00  IN   0.0       0      0  [kworker/3:2]

     10      2   0  ee45b180  IN   0.0       0      0  [rcuop/0]

      7      2   0  ee45a100  IN   0.0       0      0  [rcu_preempt]

    700      1   0  e4623180  IN   0.0   10848    904  gbmd

    699      1   0  e4623c80  IN   0.0   10848    904  gbmd

  32291      1   0  e6dee300  IN   0.4   70608  14952  cameraserver

    446      1   0  e9de3700  IN   0.0    4868    952  servicemanager

  23230      2   1  e6e41080  IN   0.0       0      0  [kworker/1:2]

    293      2   0  c3e47380  UN   0.0       0      0  [mmc-cmdqd/0]

    289      2   0  c3e45d80  IN   0.0       0      0  [irq/148-7824900]


Patches to add new feature listing the process at the time of order based upon "((struct task_struct).se.exec_start"

diff --git a/defs.h b/defs.h

index a1746cc..c5d26ea 100644

--- a/defs.h

+++ b/defs.h

@@ -952,6 +952,9 @@ struct vaddr_range {


 #define MAX_MACHDEP_ARGS 5  /* for --machdep/-m machine-specific args */


 struct machdep_table {

  ulong flags;

  ulong kvbase;

@@ -1719,6 +1722,11 @@ struct offset_table {                    /* stash of commonly-used offsets */

  long vcpu_struct_rq;

  long task_struct_sched_info;

  long sched_info_last_arrival;

+ long task_struct_sched_entity;

+ long se_exec_start;

+

  long page_objects;

  long kmem_cache_oo;

  long char_device_struct_cdev;

@@ -4426,9 +4434,18 @@ extern long _ZOMBIE_;

 #define PS_BY_REGEX    (0x8000)

 #define PS_NO_HEADER  (0x10000)

 #define PS_MSECS      (0x20000)

+#if 1

+#define PS_EXEC_START    (0x40000)

+#define PS_SUMMARY    (0x80000)

+#else

 #define PS_SUMMARY    (0x40000)

+#endif


+#if 1

+#define PS_EXCLUSIVE (PS_TGID_LIST|PS_ARGV_ENVP|PS_TIMES|PS_CHILD_LIST|PS_PPID_LIST|PS_LAST_RUN|PS_EXEC_START|PS_RLIMIT|PS_MSECS|PS_SUMMARY)

+#else

 #define PS_EXCLUSIVE (PS_TGID_LIST|PS_ARGV_ENVP|PS_TIMES|PS_CHILD_LIST|PS_PPID_LIST|PS_LAST_RUN|PS_RLIMIT|PS_MSECS|PS_SUMMARY)

+#endif


 #define MAX_PS_ARGS    (100)   /* maximum command-line specific requests */


@@ -5102,6 +5119,9 @@ ulong task_state(ulong);

 ulong task_mm(ulong, int);

 ulong task_tgid(ulong);

 ulonglong task_last_run(ulong);

+#ifdef LGE_BSP_KERNEL_SE_EXEC_START_SHOW

+ulonglong task_exec_start(ulong);

+#endif

 ulong vaddr_in_task_struct(ulong);

 int comm_exists(char *);

 struct task_context *task_to_context(ulong);

diff --git a/filesys.c b/filesys.c

index 9b59998..68452f5 100644

--- a/filesys.c

+++ b/filesys.c

@@ -3671,7 +3671,7 @@ get_live_memory_source(void)

   sprintf(modname1, "%s.o", pc->memory_module);

                 sprintf(modname2, "%s.ko", pc->memory_module);

          while (fgets(buf, BUFSIZE, pipe)) {

-   if (strstr(buf, "invalid option") &&

+   if (strstr(buf, "invalid option: filesys.c 3674") &&

        (uname(&utsname) == 0)) {

     sprintf(buf,

         "/lib/modules/%s/kernel/drivers/char/%s",

diff --git a/main.c b/main.c

index 821bb4e..3985448 100644

--- a/main.c

+++ b/main.c

@@ -408,7 +408,7 @@ main(int argc, char **argv)

    break;


   default:

-   error(INFO, "invalid option: %s\n",

+   error(INFO, "main.c @411, invalid option: %s\n",

     argv[optind-1]);

    program_usage(SHORT_FORM);

   }

diff --git a/memory.c b/memory.c

index 216038d..0b97477 100644

--- a/memory.c

+++ b/memory.c

@@ -1756,9 +1756,11 @@ cmd_wr(void)

  long size;

  struct syment *sp;


+// Guillermo would like to update memory content. 11/22/2016

+#if 0

  if (DUMPFILE())

   error(FATAL, "not allowed on dumpfiles\n");

-

+#endif

  memtype = 0;

  buf = NULL;

  addr = 0;

diff --git a/symbols.c b/symbols.c

index a8d3563..6d80834 100644

--- a/symbols.c

+++ b/symbols.c

@@ -8497,6 +8497,11 @@ dump_offset_table(char *spec, ulong makestruct)

                 OFFSET(sched_rt_entity_run_list));

  fprintf(fp, "       sched_info_last_arrival: %ld\n",

                 OFFSET(sched_info_last_arrival));

+ error(INFO, "dump_offset_table: Initializing task_struct.se.exec_start\n");

+ fprintf(fp, "       se_exec_start: %ld\n",

+                OFFSET(se_exec_start));

         fprintf(fp, "       task_struct_thread_info: %ld\n",

                 OFFSET(task_struct_thread_info));

         fprintf(fp, "           task_struct_nsproxy: %ld\n",

@@ -12518,7 +12523,7 @@ OFFSET_verify(long offset, char *func, char *file, int line, char *item)

  if (offset < 0) {

   void *retaddr[NUMBER_STACKFRAMES] = { 0 };

   SAVE_RETURN_ADDRESS(retaddr);

-  sprintf(errmsg, "invalid structure member offset: %s",

+  sprintf(errmsg, "Guillermo: invalid structure member offset: %s",

    item);

   datatype_error(retaddr, errmsg, func, file, line);

  }

diff --git a/task.c b/task.c

index b857cf6..ee3ac45 100644

--- a/task.c

+++ b/task.c

@@ -268,6 +268,23 @@ task_init(void)

          strcpy(buf, "alias last ps -l");

          alias_init(buf);

  }

+

+ MEMBER_OFFSET_INIT(task_struct_sched_entity, "task_struct", "se");

+ error(INFO, "Guillermo: Initializing task_struct.se.exec_start\n");

+ if (VALID_MEMBER(task_struct_sched_entity)) {

+  STRUCT_SIZE_INIT(sched_entity, "sched_entity");

+  MEMBER_OFFSET_INIT(se_exec_start, "sched_entity", "exec_start");

+  char buf[BUFSIZE];

+         strcpy(buf, "alias last ps -e");

+

+  alias_init(buf);

+  if (VALID_MEMBER(se_exec_start)) {

+   error(INFO, "Guillermo:VALID task_struct.se.exec_start\n");

+  }

+ }

+

  MEMBER_OFFSET_INIT(pid_link_pid, "pid_link", "pid");

  MEMBER_OFFSET_INIT(pid_hash_chain, "pid", "hash_chain");


@@ -2471,6 +2488,35 @@ sort_by_pid(const void *arg1, const void *arg2)

                         t1->pid == t2->pid ? 0 : 1);

 }


+static int

+sort_by_exec_start(const void *arg1, const void *arg2)

+{

+ ulong task_last_run_stamp(ulong);

+ struct task_context *t1, *t2;

+ ulonglong lr1, lr2;

+

+ t1 = (struct task_context *)arg1;

+ t2 = (struct task_context *)arg2;

+

+ lr1 = task_exec_start(t1->task);

+ lr2 = task_exec_start(t2->task);

+

+        return (lr2 < lr1 ? -1 :

+  lr2 == lr1 ? 0 : 1);

+}

+

+static void

+sort_context_array_by_exec_start(void)

+{

+        ulong curtask;

+

+ curtask = CURRENT_TASK();

+ qsort((void *)tt->context_array, (size_t)tt->running_tasks,

+  sizeof(struct task_context), sort_by_exec_start);

+ set_context(curtask, NO_PID);

+}


 static int

 sort_by_last_run(const void *arg1, const void *arg2)

@@ -2897,8 +2943,11 @@ cmd_ps(void)

  BZERO(&psinfo, sizeof(struct psinfo));

  cpuspec = NULL;

  flag = 0;

-

+#if 1

+ while ((c = getopt(argcnt, args, "SgstcpkuGlemarC:")) != EOF) {

+#else

         while ((c = getopt(argcnt, args, "SgstcpkuGlmarC:")) != EOF) {

+#endif

                 switch(c)

   {

   case 'k':

@@ -2978,7 +3027,18 @@ cmd_ps(void)

    check_ps_exclusive(flag, PS_LAST_RUN);

    flag |= PS_LAST_RUN;

    break;

-

+  case 'e':

+   if (INVALID_MEMBER(se_exec_start)) {

+    error(INFO,

+                            "exec_start timestamps do not exist in this kernel\n");

+    argerrs++;

+    break;

+   }

+   check_ps_exclusive(flag, PS_EXEC_START);

+   flag |= PS_EXEC_START;

+   break;

   case 's':

    flag |= PS_KSTACKP;

    break;

@@ -3010,6 +3070,12 @@ cmd_ps(void)


  if (flag & (PS_LAST_RUN|PS_MSECS))

   sort_context_array_by_last_run();

+ else if (flag & PS_EXEC_START) {

+  error(INFO, "exec_start - task_struct.se.exec_start will be displayed at the time of order\n");

+  sort_context_array_by_exec_start();

+ }

  else if (psinfo.cpus) {

   error(INFO, "-C option is only applicable with -l and -m\n");

   goto bailout;

@@ -5299,6 +5365,26 @@ task_tgid(ulong task)

         return (ulong)tgid;

 }


+ulonglong

+task_exec_start(ulong task)

+{

+        ulong exec_start;

+ ulonglong timestamp;

+

+ timestamp = 0;

+        fill_task_struct(task);

+

+ if (VALID_MEMBER(se_exec_start)) {

+  timestamp = tt->last_task_read ?  ULONGLONG(tt->task_struct +

+   OFFSET(task_struct_sched_entity) +

+   OFFSET(se_exec_start)) : 0;

+ }

+

+        return timestamp;

+}

+

 ulonglong

 task_last_run(ulong task)

 {



[Linux][ARM] char buf[32]; vs char buf[32]={0}; 리눅스 커널

Quite interesting patch was released under the following url.
https://source.codeaurora.org/quic/la/kernel/msm-3.18/commit/?h=rel/msm-3.18&id=a0039b1e721b7b3ee1cbe7f7f9d44d451ac74543

The detailed patch is to initialize the stack array with a different way as below.
usb : dwc3: Initialize kernel stack variables properly
If kernel stack variables are not initialized properly,
there is a chance of kernel information disclosure.
So, initialize kernel stack variables with null characters.

-rw-r--r-- drivers/usb/dwc3/debugfs.c 10 
1 files changed, 4 insertions, 6 deletions
diff --git a/drivers/usb/dwc3/debugfs.c b/drivers/usb/dwc3/debugfs.c
index ce7cd96..fb252ec 100644
--- a/drivers/usb/dwc3/debugfs.c
+++ b/drivers/usb/dwc3/debugfs.c
@@ -402,7 +402,7 @@ static ssize_t dwc3_mode_write(struct file *file,
struct dwc3 *dwc = s->private;
unsigned long flags;
u32 mode = 0;
- char buf[32];
+ char buf[32] = {0};

if (copy_from_user(&buf, ubuf, min_t(size_t, sizeof(buf) - 1, count)))
return -EFAULT;
@@ -482,7 +482,7 @@ static ssize_t dwc3_testmode_write(struct file *file,
struct dwc3 *dwc = s->private;
unsigned long flags;
u32 testmode = 0;
- char buf[32];
+ char buf[32] = {0};

if (copy_from_user(&buf, ubuf, min_t(size_t, sizeof(buf) - 1, count)))
return -EFAULT;
@@ -589,7 +589,7 @@ static ssize_t dwc3_link_state_write(struct file *file,
struct dwc3 *dwc = s->private;
unsigned long flags;
enum dwc3_link_state state = 0;
- char buf[32];
+ char buf[32] = {0};

if (copy_from_user(&buf, ubuf, min_t(size_t, sizeof(buf) - 1, count)))
return -EFAULT;
@@ -630,12 +630,10 @@ static ssize_t dwc3_store_ep_num(struct file *file, const char __user *ubuf,
{
struct seq_file *s = file->private_data;
struct dwc3 *dwc = s->private;
- char kbuf[10];
+ char kbuf[10] = {0};
unsigned int num, dir, temp;
unsigned long flags;

- memset(kbuf, 0, 10);
-
if (copy_from_user(kbuf, ubuf, count > 10 ? 10 : count))
return -EFAULT;

In order to find out how the assemble code is updated after compling the patch-set, let me walk through more within dwc3_mode_write() .
The interesting debug information inside updated assemble code after "char buf[32] = {0};" is declared is that memset is appended by ARM-GCC compiler
[1]: R1 is updated as 0x0.
[2]: R2 is updated as 32 in decimal format.
[3]: R0 is belonging to stack memory area.
[4]: Call to memset is made.
memset(R0: buf, R1: 0x0, R2: 32)

[After]
static ssize_t dwc3_mode_write(struct file *file,
const char __user *ubuf, size_t count, loff_t *ppos)
{
c0629d9c: e1a0c00d mov ip, sp
c0629da0: e92ddbf0 push {r4, r5, r6, r7, r8, r9, fp, ip, lr, pc}
c0629da4: e24cb004 sub fp, ip, #4
c0629da8: e24dd028 sub sp, sp, #40 ; 0x28
c0629dac: e52de004 push {lr} ; (str lr, [sp, #-4]!)
c0629db0: ebe7958c bl c000f3e8 <__gnu_mcount_nc>
c0629db4: e59f7130 ldr r7, [pc, #304] ; c0629eec <dwc3_mode_write+0x150>
c0629db8: e1a04001 mov r4, r1
c0629dbc: e1a05002 mov r5, r2
c0629dc0: e3a01000 mov r1, #0 //<<--[1]
c0629dc4: e3a02020 mov r2, #32 //<<--[2]
c0629dc8: e5973000 ldr r3, [r7]
c0629dcc: e50b3028 str r3, [fp, #-40] ; 0xffffffd8
c0629dd0: e59030bc ldr r3, [r0, #188] ; 0xbc
c0629dd4: e24b0048 sub r0, fp, #72 ; 0x48 //<<--[3]
c0629dd8: e5936060 ldr r6, [r3, #96] ; 0x60 
c0629ddc: ebf2ec6f bl c02e4fa0 <memset> //<<--[4] 
c0629de0: e1a0200d mov r2, sp 
c0629de4: e3c21d7f bic r1, r2, #8128 ; 0x1fc0

[Before]
[1]: Assemble code before the patch is applied, the stack memory location mapped to buf[32] is saved into R0 without initilization. 
static ssize_t dwc3_mode_write(struct file *file,
const char __user *ubuf, size_t count, loff_t *ppos)
{
c0629d9c: e1a0c00d mov ip, sp
c0629da0: e92ddbf0 push {r4, r5, r6, r7, r8, r9, fp, ip, lr, pc}
c0629da4: e24cb004 sub fp, ip, #4
c0629da8: e24dd028 sub sp, sp, #40 ; 0x28
c0629dac: e52de004 push {lr} ; (str lr, [sp, #-4]!)
c0629db0: ebe7958c bl c000f3e8 <__gnu_mcount_nc>
c0629db4: e1a05002 mov r5, r2
//.. skip ,,
c0629dfc: 1a000005 bne c0629e18 <dwc3_mode_write+0x7c>
c0629e00: e24b0048 sub r0, fp, #72 ; 0x48 //<<--[1]
c0629e04: e1a02003 mov r2, r3
c0629e08: ebf2e301 bl c02e2a14 <__copy_from_user>
c0629e0c: e3500000 cmp r0, #0

Let me make it a rule to initialize the stack array like char kbuf[10] = {0}; instead of char kbuf[10];


temp Workqueue

.

Workqueue(2) - kernel workqueue 종류 Workqueue

system_wq
보통 ISR 핸들러 및 notifier call에서 주로 쓰는 workqueue이며, 멀티 코어 환경에서 동작한다. 
crash> workqueue_struct.name,flags 0xed40cc00 -p
  name = "events\
  flags = 0
 
system_wq = $1 = (struct workqueue_struct *) 0xed40cc00 
system_wq workqueue를 접근하는 API는 아래와 같다. 
static inline bool schedule_work_on(int cpu, struct work_struct *work)
{
             return queue_work_on(cpu, system_wq, work);
}
static inline bool schedule_work(struct work_struct *work)
{
             return queue_work(system_wq, work);
}
 
static inline bool schedule_delayed_work_on(int cpu, struct delayed_work *dwork,
                                                                       unsigned long delay)
{
             return queue_delayed_work_on(cpu, system_wq, dwork, delay);
}
static inline bool schedule_delayed_work(struct delayed_work *dwork,
                                                                    unsigned long delay)
{
             return queue_delayed_work(system_wq, dwork, delay);
}

 


system_highpri_wq
가장 높은 nice 우선 순위 -20 워커들이 워크를 처리한다. 
보통 CPU Hotplug 동작으로 CPU off되기 직전 worker pool에서 돌던 work를 workqueue_cpu_down_callback() 함수에서 이 system_highpri_wq queue한다.  

crash> workqueue_struct.flags,name 0xed40ccc0 –p

  flags = 0x10  //<<-- WQ_HIGHPRI

  name = "events_highpri\000\000\000\000\000\000\000\000\000"

 

crash> p system_highpri_wq

system_highpri_wq = $30 = (struct workqueue_struct *) 0xed40ccc0


아래 코드 주석문을 잘 이해하자. 

static int workqueue_cpu_down_callback(struct notifier_block *nfb,...)

{

// ... skip ...

             switch (action & ~CPU_TASKS_FROZEN) {

             case CPU_DOWN_PREPARE:

                           /* unbinding per-cpu workers should happen on the local CPU */

                           INIT_WORK_ONSTACK(&unbind_work, wq_unbind_fn);

                           queue_work_on(cpu, system_highpri_wq, &unbind_work);


system_unbound_wq
특정 cpu로 등록되어 호출되지 않고, 동일한 액션으로 2개 이상 동시 처리하지 않는 성격의 작업에 사용한다.
한 번에 하나씩만 처리되므로 요청한 작업은 즉각 동작한다. 주의: max_active 제한까지 스레드 수가 커질 수 있음 
crash> p system_unbound_wq
system_unbound_wq = $2 = (struct workqueue_struct *) 0xed40a300
crash> workqueue_struct.name,flags 0xed40a300 -p
  name = "events_unbound\000\000\000\000\000\000\000\000\000"
  flags = 2  // WQ_UNBOUND


system_freezable_wq
system_wq과 유사하게 동작하는데, suspend되는 경우 freeze 가능한 작업로 쓴다.
작업 중 suspend 요청이 오면 다른 워크큐는 마저 다 처리하지만 이 워크큐는 그대로 freeze하고 복구(resume)한 후에 동작을 계속한다. suspend/resume 시 정확한 synchronize 동작을 위해 쓰인다.
system_freezable_wq = $3 = (struct workqueue_struct *) 0xed40ce40
crash> workqueue_struct.name,flags  0xed40ce40 -p
  name = "events_freezable\000\000\000\000\000\000\000"
  flags = 4 // WQ_FREEZABLE

system_power_efficient_wq
절전 목적으로 성능을 약간 희생하여도 되는 작업에 사용한다.
crash> p system_power_efficient_wq
system_power_efficient_wq = $4 = (struct workqueue_struct *) 0xed40cf00
 
crash> workqueue_struct.name,flags  0xed40cf00 -p
  name = "events_power_efficient\000"
  flags = 0x80  // WQ_POWER_EFFICIENT = 1 << 7,

Workqueue(1) - 기본 설정 Flags Workqueue

[1]: WQ_UNBOUND
worker를 per-cpu로 등록하지 않고(pool workqueue 생성 안함) 현재 CPU로 work를 할당한다.

[2]: WQ_FREEZABLE
Power Consumption을 위해 suspend로 진입할 때 시스템 절전을 위해 suspend 상태로 빠지는 경우 플러싱을 한다.
이 때 기존 워크들이 다 처리되고 새로운 워크들을 등록하지 않고 suspend에 진입한다.

[3]: WQ_MEM_RECLAIM
메모리 부족으로 Page Reclaim에도 수행되는 동안에도 반드시 동작해야 할 경우 쓰인다.
idle 워커가 부족하여 새로운 워커를 할당 받아 동작해야 하는 경우 메모리 부족으로 인해 새로운 워커를 할당받지 못하는
 비상 상황에서 쓰기 위해 이 플래그가 사용되어 만들어둔 rescue 워커(함수: rescuer_thread)로 워크 실행을 의뢰한다.
(example): 등록  

static int ext4_fill_super(...)

{

           EXT4_SB(sb)->rsv_conversion_wq =

                      alloc_workqueue("ext4-rsv-conversion", WQ_MEM_RECLAIM | WQ_UNBOUND, 1); 

 

(example): rescuer_thread 등록 

           if (flags & WQ_MEM_RECLAIM) {

//snip

                      rescuer->rescue_wq = wq;

                      rescuer->task = kthread_create(rescuer_thread, rescuer, "%s", wq->name);

 

[4]: WQ_HIGH_PRI

각 workqueue의 worker_pool, 즉 struct worker_pool *cpu_pools[1]에 등록하여 다른 워크보다 더 빠른 우선 순위를 갖고 처리할 수 있게 한다.


[5]: WQ_CPU_INTENSIVE

워크들이 진입한 순서대로 빠르게 처리하는 WQ_HIGH_PRI와 달리 순서와 상관없이 빠르게 처리한다.

unbound 워크큐에 적합한 필드이다.


[6]: WQ_SYSFS

sysfs 인터페이스를 제공한다. 이 때 __WQ_ORDERED 필드와 ORing으로 등록하면 sysfs 등록이 안된다. 

crash> p &wq_subsys

$12 = (struct bus_type *) 0xc1817860 <wq_subsys>

crash> bus_type  0xc1817860

struct bus_type {

  name = 0xc14eac58 "workqueue",

  dev_name = 0x0,

//... skip...

  dev_groups = 0xc1817940 <wq_sysfs_groups>,;

 


[7]: WQ_POWER_EFFICIENT

절전 옵션에 따라 성능을 희생해도 되는 작업을 위해 사용된다.

CONFIG_WQ_POWER_EFFICIENT_DEFAULT 커널 옵션을 사용하거나 “power_efficient” 모듈 파라메터를 설정하는 경우 절전을 위해 언바운드 큐로 동작한다.


[8]: __WQ_ORDERED

WQ_HIGH_PRI 필드와 함께 쓰면 nice -20 값으로 우선순위가 설정[*1]된다.

워크풀에서 하나의 워커만 처리하도록 제한하여 워크의 FIFO 처리 순서를 보장한다.


소스 코드 

enum {

           WQ_UNBOUND             = 1 << 1, /* not bound to any cpu */  //<<--[1]

           WQ_FREEZABLE             = 1  << 2, /* freeze during suspend */ //<<--[2]

           WQ_MEM_RECLAIM                   = 1 << 3, /* may be used for memory reclaim */ //<<--[3]

           WQ_HIGHPRI                 = 1 << 4, /* high priority */ //<<--[4]

           WQ_CPU_INTENSIVE       = 1 << 5, /* cpu intensive workqueue */ //<<--[5]

           WQ_SYSFS                    = 1 << 6, /* visible in sysfs, see wq_sysfs_register() */ //<<--[6]

           WQ_POWER_EFFICIENT    = 1 << 7,

 

           __WQ_DRAINING            = 1 << 16, /* internal: workqueue is draining */

           __WQ_ORDERED             = 1 << 17, /* internal: workqueue is ordered */

 

           WQ_MAX_ACTIVE                      = 512,     /* I like 512, better ideas? */

           WQ_MAX_UNBOUND_PER_CPU     = 4,        /* 4 * #cpus for unbound wq */

           WQ_DFL_ACTIVE            = WQ_MAX_ACTIVE / 2,

};

 


[Appendix]

[*1] 

crash> struct workqueue_attrs ordered_wq_attrs 2

struct workqueue_attrs {

  nice = 0xed422780, // 0x0

  cpumask = {{

      bits = {0xed422800}

    }},

  no_numa = 0x40

}

struct workqueue_attrs {

  nice = 0xed4227c0, // -20, 0xffffffec

  cpumask = {{

      bits = {0x0}

    }},

  no_numa = 0x0

}

(where)

crash> int 0xed422780

ed422780:  00000000                              ....

crash> int 0xed4227c0

ed4227c0:  ffffffec                              ....

 




공포의 여자 SW개발자 칼럼

이번에는 공포의 여자 SW개발자 대해 이야기를 해보고자 한다.

10여년 동안 많은 개발자들과 함께 일을 했는데 대부분 좋은 기억으로 남아 있다. 난 개발자들을 좋아한다. 개발자들은 체질적으로 성실하고 스스로에게 자부심이 있으며 열심히 노력한 사람이 성공해야 한다고 생각하는 고지식한 DNA의 소유자들이기 때문이다. 뭐 세상은 그렇게 돌아가진 않지만 말이다. 하지만, 안타깝게도 나에게 여자 SW 개발자들에 대해선 좋은 기억은 없는 것 같다.

난 여자개발자들과 함께 할 일이 생기면 겁부터 난다. 아주 위축이 된다. 특히 고참 여자개발자들을 만나면 더 주눅들게 된다. 왜냐면 일하기 아주 힘들기 때문이다. 책임전가의 달인, 전문가들이기 때문이다. 말이 참 많다. 자기가 할일이 아니라는, 내 문제가 아니라는, 도와줘야 한다는, 그래서 안된다는, 어쩔 수 없다는.

지금 난 여자개발자들은 무턱대고 비난하고 있는 것 같지만, 왜 내가 이런 소리를 하는 지 들어보면 조금이나마 나의 궤변(?)이 이해가 될 것이라고 본다.  

1. 여자 개발자들은 우선 힘들고 어려운 일을 하려고 하지 않는다.
여러 개발 부서를 살펴보면 가끔 편한 부서들이 눈에 띈다. 개발자들이 가장 선호하는 부서는 개발 일정의 쇠사슬과 관리자들의 채찍질에서 벗어나 시간을 충분히 갖고 품질 관리를 하거나 모듈개선 작업을 하는 곳이다. 그런데, 보통 대부분의 개발 부서는 여자개발자의 비율이 20%를 넘지 않는데 이렇게 널널하다고 달려져있는 부서는 여자개발자의 비율이 70%를 넘는다고 들었다. 사내 인트라 넷으로 확인해 보았는데 역시나 여자 개발자들의 수가 압도하고 있음을 알 수 있었다. 나도 모르게 웃음이 나왔다. 그 이유가 궁금해서 편한 부서에 일하고 있는 동료들에게 직접 물어봤다. 대답을 들었는데 여자 개발자들이 계속 편한 부서로 지원을 하기 때문이라는 것이다. 나한테 이 사실을 알려줬던 그 동료는 그나마 성실히 일을 하는 스타일로 알려져 있는데 이상하게도 여자개발자들에게 심한 악감정을 품고있었다. 여자개발자들은 이렇게 편한 부서에서 쉬운 일을 하는데도 그마저 그 일을 서로 안하려고 떠넘기려고 하기 때문이라고는 것이었다. 음, 이런 세상도 있구나라는 생각이 들었다.

2. 여자 개발자는 어려운 이슈가 나오면 다른 개발자에게 의존을 하거나 다른 동료 뒤에 아예 숨어버리는 경향이 많다.
내가 쓴 위 문장은 잘못된 문장이라 부연 설명을 할 필요가 있다. 우선 먼저 어려운 이슈가 없는 쉬운 모듈을 담당하려고 하기 때문에 여자개발자들은 어려운 이슈를 만나지 않는다. 그런 상황에서 나오는 이슈들을 스스로 어려운 이슈라고 생각한다. 이렇게 어려운 이슈(?)가 나오면 여지 없이 동료 개발자들에게 찾아가서 물어보고 도움을 요청한다. 주위에서 조금이라도 실력이 있는 개발자가 눈에 띄면 껌딱지 같이 달라붙어 귀동냥을 하며 앵벌이하듯이 받아 먹으려고 하는 것이다. 아예 못하겠다고 이슈를 던지는 경우도 많다. 수동적이며 굴종적인 태도로 일을 하는 것이다.

그러면 왜 이렇게 스스로 노예같이 굴종적으로 일을 할까? 난 그 이유를 학교에 있는 친구들한테서 들을 수 있었다.가끔 난 대학 교수가 된 친구들과 술을 한잔 할 때가 있다. 자연히 학생들에 대한 이야기를 하다 보면 컴퓨터 공학과 전자공학과 등등 공대계열 학과의 여학생들의 학업 태도에 대한 에피소드를 들을 수 있다. 교수들은 여자공대생들이 프로젝트나 과제를 할 때 남자 복학생들에게 거의 100% 묻어간다고 말했다. 그런면서 여학생들의 수동적인 학습 태도에 대한 개탄의 넋두리를 늘어 놓았다. "이래서는 안된다. 어쩌구". 여자 개발자들은 그 때부터 다른 사람한테 묻어가는 것이 버릇이 되어 회사에서도 자연스럽게 다른 사람들에게 의존하면서 일을 하는 게 아닌 가 싶다. 

3. 기본적으로 개발자로써 역량이 현저히 떨어진다.
뭐 당연한 결과일지도 모르겠다. 어렵지 않고 쉬운 일만 찾아 다니니 단순한 일만 하게 되므로 개발 능력이 늘지 않는 것은 당연한 것이다. 개발자들은 업무를 하다가 대화나 질문을 통해 대략 서로의 실력을 가늠을 하곤 한다. 그런데 여자개발자들은 정말 황당한 쓰레기 질문을 할 때가 많다. "시스템 콜은 어떻게 하면 걸 수 있어요? 와이 파이 콜하고의 차이점은 뭐에요? 커널 크래시란 말을 하면, 네, 어디던 충돌은 일어나게 마련이죠." 그래서 난 여자개발자들이 질문을 하면 간단하게 대답을 해주면서 회피할 때가 많다. 제대로 그들의 질문에 대답을 해주려면 최소한 1시간 정도 걸리기 때문이다. 이렇게 된 이유는 그들이 공부를 안하기 때문이기도 하지만, 끈기있게 문제를 분석하면서 집중하는 능력이 떨어지기 때문이다. 개발자의 가장 중요한 태도인데 말이다.

저번에 인사부서에서 연말에 2명 정도의 개발자를 짜를 계획이라고 통보를 해왔다. 물론 회사 실적이 좋지 않을 경우이지만 말이다. 그래서 내 팀장은 매우 많은 고민을 했다. 누구를 명단에 올릴까? 팀장은 조용히 나에게 다가와서 물어봤다. 난 팀내에서 동료에게 끊임없이 의존하면서 역량이 좋아질 기미가 전혀 보이지 않고 계속 편안히 먹고 놀려는 사람을 짤라야 한다고 말씀 드렸다. 내 팀장은 내 말에 전적으로 동의하면서 그 명단을 결정했다.

안타깝게도 그 명단에 남자 개발자는 볼 수 없었다.

in_interrupt 매크로 리눅스 커널

커널이나 드라이버 코드 리뷰를 하는 도중에 preempt_add, preempt_sub 그리고 in_interrupt 함수를 자주 마주칩니다. 이 함수들의 사용 예와 구현부에 대해서 좀 더 짚어 보도록 하겠습니다.

in_interrupt 매크로의 역할을 간단히 말하면, 현재 실행 중인 코드가 process context 혹은 interrupt context 상에서 돌고 있는 지 알려줍니다. process context 혹은 interrupt context의 개념은 여러 리눅스 커널 교재에서 마르고 닳도록 설명하고 있는데요, 아래 스택 트레이스를 보면 간단히 파악할 수 있습니다.


__irq_svc(asm) -- unwind_backtrace() 사이에 보이는 함수(붉은색으로 마킹)들은 irq context에서 실행되는 함수들, start_kernel() --arch_cpu_idle() 구간에 보이는 함수들은 process context에서 구동이 된다고 보시면 됩니다.

[https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable.git/commit/?id=bbe097f092b0d13e9736bd2794d0ab24547d0e5d]


WARNING: CPU: 0 PID: 0 at include/linux/usb/gadget.h:405
ecm_do_notify+0x188/0x1a0
Modules linked in:
CPU: 0 PID: 0 Comm: swapper Not tainted 4.7.0+ #15
Hardware name: Atmel SAMA5
[<c010ccfc>] (unwind_backtrace) from [<c010a7ec>] (show_stack+0x10/0x14)
[<c010a7ec>] (show_stack) from [<c0115c10>] (__warn+0xe4/0xfc)
[<c0115c10>] (__warn) from [<c0115cd8>] (warn_slowpath_null+0x20/0x28)
[<c0115cd8>] (warn_slowpath_null) from [<c04377ac>] (ecm_do_notify+0x188/0x1a0)
[<c04377ac>] (ecm_do_notify) from [<c04379a4>] (ecm_set_alt+0x74/0x1ac)
[<c04379a4>] (ecm_set_alt) from [<c042f74c>] (composite_setup+0xfc0/0x19f8)
[<c042f74c>] (composite_setup) from [<c04356e8>] (usba_udc_irq+0x8f4/0xd9c)
[<c04356e8>] (usba_udc_irq) from [<c013ec9c>] (handle_irq_event_percpu+0x9c/0x158)
[<c013ec9c>] (handle_irq_event_percpu) from [<c013ed80>] (handle_irq_event+0x28/0x3c)
[<c013ed80>] (handle_irq_event) from [<c01416d4>] (handle_fasteoi_irq+0xa0/0x168)
[<c01416d4>] (handle_fasteoi_irq) from [<c013e3f8>] (generic_handle_irq+0x24/0x34)
[<c013e3f8>] (generic_handle_irq) from [<c013e640>] (__handle_domain_irq+0x54/0xa8)
[<c013e640>] (__handle_domain_irq) from [<c010b214>] (__irq_svc+0x54/0x70)
[<c010b214>] (__irq_svc) from [<c0107eb0>] (arch_cpu_idle+0x38/0x3c)
[<c0107eb0>] (arch_cpu_idle) from [<c0137300>] (cpu_startup_entry+0x9c/0xdc)
[<c0137300>] (cpu_startup_entry) from [<c0900c40>] (start_kernel+0x354/0x360)
[<c0900c40>] (start_kernel) from [<20008078>] (0x20008078)
---[ end trace e7cf9dcebf4815a6 ]---J6

 

in_interrupt 함수는 언제 쓰면 좋을까요? 샘플 패치를 하나 만들어 보았는데요. 
__rh_alloc() 함수가 Interrupt Context 즉 IRQ가 Trigger되어 호출이 될 경우, GFP_ATOMIC: atomic operation만으로 메모리 할당을 시도하고, 반대 Process Context인 경우 메모리 할당 실패 시 Sleep되어 성공할 때 까지 반복하는 GFP_KERNEL 옵션으로 메모리 할당를 수행하는 패치입니다.

diff --git a/drivers/md/dm-region-hash.c b/drivers/md/dm-region-hash.c
index b929fd5..1325a8a 100644
--- a/drivers/md/dm-region-hash.c
+++ b/drivers/md/dm-region-hash.c
@@ -289,7 +289,12 @@ static struct dm_region *__rh_alloc(struct dm_region_hash *rh, region_t region)
 {
        struct dm_region *reg, *nreg;

-       nreg = mempool_alloc(rh->region_pool, GFP_ATOMIC);
+       gfp_t gfp_flag = GFP_KERNEL;
+       if (in_interrupt()) {
+               gfp_flag = GFP_ATOMIC;
+       }
+       nreg = mempool_alloc(flush_entry_pool, gfp_flag);
+
        if (unlikely(!nreg))
                nreg = kmalloc(sizeof(*nreg), GFP_NOIO | __GFP_NOFAIL);

 

이와 비슷한 개념으로 생성한 다른 패치도 있네요.[https://patchwork.kernel.org/patch/3623051/]

diff --git a/drivers/gpu/drm/ast/ast_fb.c b/drivers/gpu/drm/ast/ast_fb.c
index 66ecc16..d56d2bf 100644
--- a/drivers/gpu/drm/ast/ast_fb.c
+++ b/drivers/gpu/drm/ast/ast_fb.c
@@ -64,7 +64,7 @@  static void ast_dirty_update(struct ast_fbdev *afbdev,
   * then the BO is being moved and we should
   * store up the damage until later.
   */
- if (!in_interrupt())
+ if (!drm_can_sleep())
   ret = ast_bo_reserve(bo, true);
  if (ret) {
   if (ret != -EBUSY)

 

in_interrupt 매크로 구현부를 확인해보면, 실제 irq_count() 매크로를 호출하는데 preempt_count() 매크로로 리턴되는 값과 HARDIRQ_MASK | SOFTIRQ_MASK 마스크와 Oring Operation을 수행합니다.

#define in_interrupt()  (irq_count())
   
#define irq_count() (preempt_count() & (HARDIRQ_MASK | SOFTIRQ_MASK \
     | NMI_MASK))  

SOFTIRQ_MASK: 0xff00,  SOFTIRQ_OFFSET: 0x100 
HARDIRQ_MASK: 0xf0000, HARDIRQ_OFFSET: 0x10000

 

그럼, preempt_count의 정체는 뭐냐? 코드를 좀 더 살펴보면, 현재 구동 중인 함수 내에서 확인되는 스택 주소를 통해
스택 top address를 얻어 온 후 (struct thread_info *) 구조체의 preempt_count 멤버에서 얻어오는 값입니다.

static __always_inline int preempt_count(void)
{
 return current_thread_info()->preempt_count;
}

[kernel/msm-3.18/arch/arm/include/asm/thread_info.h]
static inline struct thread_info *current_thread_info(void)
{
 register unsigned long sp asm ("sp");
 return (struct thread_info *)(sp & ~(THREAD_SIZE - 1));  // 0x1FFF = THREAD_SIZE - 1
}

 

예를 들어 위에서 언급된 콜스택의 경우, 아래 계산식으로 preempt_count() 값을 얻어올 수 있습니다.
preempt_count이 0x00010002이군요.

  (struct thread_info*)(0xE359B908 & ~0x1fff) = 0xE359A000 -> (
    flags = 0x2,
    preempt_count = 0x00010002, // HARDIRQ_OFFSET
    addr_limit = 0xBF000000,
    task = 0xD0B5EA40,  //<<-- task descriptor
    exec_domain = 0xC1A1AF1C,
    cpu = 0x0,
    cpu_domain = 0x15,

(where)
ecm_do_notify() 함수가 호출되었을 시의 Stack address: 0xE359B908  

 

그럼, struct thread_info.preempt_count 멤버에 HARDIRQ_OFFSET 비트를 어느 함수에서 설정할까요?
아래 함수 흐름에서 __irq_enter 매크로에서 HARDIRQ_OFFSET 비트를 설정하고 있음을 알 수 있습니다.

__irq_svc 
-gic_handle_irq
--__handle_domain_irq
---irq_enter
----__irq_enter
int __handle_domain_irq(struct irq_domain *domain, unsigned int hwirq,
   bool lookup, struct pt_regs *regs)
{
 struct pt_regs *old_regs = set_irq_regs(regs);
 unsigned int irq = hwirq;
 int ret = 0;

 irq_enter();  //<<--

//skip
 if (unlikely(!irq || irq >= nr_irqs)) {
  ack_bad_irq(irq);
  ret = -EINVAL;
 } else {
  generic_handle_irq(irq); //<<-- ISR 호출
 }

 irq_exit();  //<<--
 set_irq_regs(old_regs);
 return ret;
}
void irq_enter(void)
{
 rcu_irq_enter();
 if (is_idle_task(current) && !in_interrupt()) {
  /*
   * Prevent raise_softirq from needlessly waking up ksoftirqd
   * here, as softirq will be serviced on return from interrupt.
   */
  local_bh_disable();
  tick_irq_enter();
  _local_bh_enable();
 }

 __irq_enter(); //<<--
}
#define __irq_enter()     \
 do {      \
  account_irq_enter_time(current); \
  preempt_count_add(HARDIRQ_OFFSET); \ //<<--
  trace_hardirq_enter();   \
 } while (0)

 

struct thread_info.preempt_count 멤버에서 HARDIRQ_OFFSET bit는 아래 코드 흐름에서 Clear됩니다.

__handle_domain_irq
(irq 처리 완료)
-irq_exit
--__irq_exit
#define __irq_exit()     \
 do {      \
  trace_hardirq_exit();   \
  account_irq_exit_time(current);  \
  preempt_count_sub(HARDIRQ_OFFSET); \
 } while (0)

/*


[Kernel]panic @__wake_up 리눅스 커널

Debugging

"ndroid.systemui" 프로세스가 raw_spin_lock_irqsave() API 동작 중에 aee_wdt_atf_entry() Trigger

-000|aee_wdt_atf_entry()
-001|prefetchw(inline)
-001|arch_spin_lock(inline)
-001|do_raw_spin_lock_flags(inline)
-001|__raw_spin_lock_irqsave(inline)
-001|raw_spin_lock_irqsave(lock = 0xDD82725C)
-002|__wake_up(q = 0xDD82725C, mode = 1, nr_exclusive = 1, key = 0x0)
-003|mmc_wait_data_done
-004|msdc_irq_data_complete(host = 0xDD827280, ?, error = 0)
-005|msdc_irq(?, dev_id = 0xDD13B9C8)
-006|static_key_count(inline)
-006|static_key_false(inline)
-006|trace_irq_handler_exit(inline)
-006|handle_irq_event_percpu(?, action = 0xDD13B9C8)
-007|handle_irq_event(desc = 0xC0F38440)
-008|cond_unmask_eoi_irq(inline)
-008|handle_fasteoi_irq(?, desc = 0xC0F38440)
-009|static_key_count(inline)
-009|static_key_false(inline)
-009|trace_irq_exit(inline)
-009|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)
-010|__raw_readl(inline)
-010|gic_handle_irq(regs = 0xDD13BFB0)
-011|__irq_usr(asm)


@ spinlock이 release되어 spinlock 변수가 [owner: 0x56AC, next: 0x56AD]로 업데이트되기까지 기다림.

(raw_spinlock_t *)0xDD82725C = 0xDD82725C -> (
raw_lock = (
slock = 0x56AD56AB,
tickets = (
owner = 0x56AB, // <<--
next = 0x56AD))) // <<--

@ 0xDD82725C spinlock 변수 주소를 누가 접근하는 지 검색해보면.

(where)
(raw_spinlock_t *)0xDD82725C
c2d01b78: dd82725c
c2d01b7c: dd82725c
c44f0994: dd82725c
dd13bd60: dd82725c // "ndroid.systemui"
dd13bd9c: dd82725c // "ndroid.systemui"
dd13bdc8: dd82725c // "ndroid.systemui"
ddbefdb8: dd82725c // <<--"mmcqd/0"
ddbefdd0: dd82725c
e0abd994: dd82725c


"mmcqd/0" 프로세스가 접근함을 알 수 있음

v.v % (struct thread_info*)(0xDDBEFDB8 & ~0x1fff)
(long unsigned int) swap_in = 0 = 0x0 = '....',
(long unsigned int) swap_out = 0 = 0x0 = '....',
(struct task_cputime) cputime_expires = ((cputime_t) utime = 0 = 0x0 = '....', (cputime_t) stime = 0 = 0x0 = '....', (long lo
(struct list_head [3]) cpu_timers = ([0] = ((struct list_head *) next = 0xDDB49A08 = -> ((struct list_head *) next = 0xDDB49
(struct cred *) real_cred = 0xDDB71200 = -> ((atomic_t) usage = ((int) counter = 2 = 0x2 = '....'), (kuid_t) uid = ((uid_t)
(struct cred *) cred = 0xDDB71200 = -> ((atomic_t) usage = ((int) counter = 2 = 0x2 = '....'), (kuid_t) uid = ((uid_t) val =
(char [16]) comm = "mmcqd/0",


@ "mmcqd/0" 프로세스 콜스택

-000|schedule()
-001|mmc_wait_for_data_req_done(inline)
-001|mmc_start_req(host = 0xC0F75D0C, areq = 0xC0F644E0, error = 0xC102CB08)
-002|mmc_blk_issue_rw_rq(mq = 0xDDB64408, rqc = 0x0)
-003|mmc_blk_issue_rq(mq = 0xDDB64408, req = 0x0)
-004|mmc_queue_thread(d = 0xDDB64408)
-005|kthread(_create = 0xDDB8BDC0)
-006|ret_from_fork(asm)
-007|ret_fast_syscall(asm)


@ 코드를 가보면, spin_lock_irqsave(&context_info->lock, flags); API를 통해 lock을 걸고 있음

static int mmc_wait_for_data_req_done(struct mmc_host *host,
struct mmc_request *mrq,
struct mmc_async_req *next_req)
{
    struct mmc_command *cmd;
    struct mmc_context_info *context_info = &host->context_info;
    int err;
    unsigned long flags;
    while (1) {
        wait_event_interruptible(context_info->wait,
                                               (context_info->is_done_rcv ||
                                               context_info->is_new_req));
        spin_lock_irqsave(&context_info->lock, flags);
        context_info->is_waiting_last_req = false;


@ Watchdog Reset이 trigger된 "ndroid.systemui" 프로세스 콜 스택에 아래 함수들이 있었음

-003|mmc_wait_data_done
-004|msdc_irq_data_complete(host = 0xDD827280, ?, error = 0)


@ mmc_wait_data_done() 함수를 보면 mrq->host->context_info.is_done_rcv = true로 설정하고,
&mrq->host->context_info.wait wait queue을 깨우는 역할을 수행

static void mmc_wait_data_done(struct mmc_request *mrq){

    mrq->host->context_info.is_done_rcv = true;

     wake_up_interruptible(&mrq->host->context_info.wait);

}


그런데 mmc_wait_for_data_req_done() 함수의 아래 구문은 context_info->is_done_rcv, context_info->is_new_req가 true가
될 때 까지 기다리는 코드다.

wait_event_interruptible(context_info->wait,
(context_info->is_done_rcv ||
context_info->is_new_req));


정리해보면, race condition으로 wake_up_interruptible(&mrq->host->context_info.wait); 함수를 통해 wait_queue에 queue된 
&mrq->host->context_info.wait으로 등록된 프로세스를 깨우기 전에 아래 구문이 풀려버려 이미 깨어버린 경우임을 짐작.


잠을 자고 있는 누군가를 깨우려고 손을 대려고 하는데 이미 깨버린 경우와 비슷하네.

In-depth Analysis

내 추정이 맞다면 아래 코드를 삽입하면 바로 커널 패닉이 나야 한다.

(램덤프 force_mmc_wait_data_done_crash)

static void mmc_wait_data_done(struct mmc_request mrq){*
mrq->host->context_info.is_done_rcv = true;
+ mdelay(1);
wake_up_interruptible(&mrq->host->context_info.wait);
}


그런데 바로 커널 패닉이 발생했다.

-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)
-001|__dabt_svc(asm)
-->|exception
-002|debug_spin_lock_before(inline)
-002|do_raw_spin_lock(lock = 0x02B4)
-003|raw_spin_lock_irqsave(lock = 0x02B4)
-004|__wake_up(q = 0x02B4, mode = 1, nr_exclusive = 1, key = 0x0)
-005|mmc_wait_data_done(mrq = 0xDC9725F8)
-006|msdc_irq_data_complete(host = 0xDC919300, ?, error = 0)
-007|msdc_irq(?, dev_id = 0x1)
-008|handle_irq_event_percpu(?, action = 0xDC91E0C0)
-009|handle_irq_event(desc = 0xC121A440)
-010|cond_unmask_eoi_irq(inline)
-010|handle_fasteoi_irq(?, desc = 0xC121A440)
-011|static_key_count(inline)
-011|static_key_false(inline)
-011|trace_irq_exit(inline)
-011|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)
-012|__raw_readl(inline)
-012|gic_handle_irq(regs = 0xCB773E10)
-013|__irq_svc(asm)
-->|exception
-014|current_thread_info(inline)
-014|check_preemption_disabled(what1 = 0xC0F115AC, what2 = 0xC0EE0B28)
-015|debug_smp_processor_id()
-016|MT_trace_preempt_on()
-017|preempt_count_sub
-018|current_thread_info(inline)
-018|preempt_count(inline)
-018|should_resched(inline)
-018|__percpu_counter_add(fbc = 0xD8AC7178, amount = 0, batch = 32)
-019|__sb_start_write(sb = 0xC0F115AC, level = -1058141400, wait = FALSE)
-020|file_start_write(inline)
-020|vfs_write(file = 0xD366C480, buf = 0xBEA83A4C, ?, pos = 0xCB773F78)
-021|SYSC_write(inline)
-021|sys_write(?, buf = -1096271284, count = 146)
-022|ret_fast_syscall(asm)

@mrq->host->context_info.wait 변수를 확인해보면, 이미 mrq->host 변수가 0이다.

(struct mmc_request *)0xDC9725F8 = 0xDC9725F8 -> (
    sbc = 0xDC97262C,
    cmd = 0xDC972660,
    data = 0xDC9726C8,
    stop = 0xDC972694,
    completion = (done = 0x0, wait = (lock = (rlock = (raw_lock = (slock = 0x0,
      done = 0x0,
     host = 0x0)

@어머 그런데, mmcqd/0 프로세스가 mmc_wait_for_data_req_done() 코드를 이미 수행했네?

-000|context_switch(inline)
-000|__schedule()
-001|schedule()
-002|mmc_wait_for_data_req_done(inline)
-002|mmc_start_req(host = 0xDC919000, areq = 0xDC972710, ?)
-003|mmc_blk_issue_rw_rq(mq = 0x0, rqc = 0xC64B18C0)
-004|mmc_blk_issue_rq(mq = 0xDC972494, req = 0xC64B18C0)
-005|mmc_queue_thread(d = 0xDC972494)
-006|kthread(_create = 0xDCA24E40)
-007|ret_from_fork(asm)
-008|ret_fast_syscall(asm)


@ftrace log를 좀 더 추가해보자.

diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c
index db74413..fcf6692 100644
? a/drivers/mmc/core/core.c
+++ b/drivers/mmc/core/core.c
@@ -1034,6 +1034,9 @@ out:
}
EXPORT_SYMBOL(mmc_start_bkops);
#endif
/*
mmc_wait_data_done() - done callback for data request
@mrq: done data request
@@ -1042,10 +1045,25 @@ EXPORT_SYMBOL(mmc_start_bkops);
*/
static void mmc_wait_data_done(struct mmc_request *mrq)
static void mmc_wait_data_done(struct mmc_request mrq) *{
        mrq->host->context_info.is_done_rcv = true;


+      trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));
        mdelay(1);
+      trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));
        wake_up_interruptible(&mrq->host->context_info.wait);
+      trace_printk("--msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));

 


@ 역시나 GIC mtk-msdc(111) IRQ가 Trigger된 다음에 아래와 같이 커널 패닉이 발생함

(램덤프: neo_more_crash_ftrace)

-000|do_DataAbort(addr = 0, fsr = 0, regs = 0x0)
-001|__dabt_svc(asm)
-->|exception
-002|debug_spin_lock_before(inline)
-002|do_raw_spin_lock(lock = 0x02B4)
-003|raw_spin_lock_irqsave(lock = 0x02B4)
-004|__wake_up(q = 0x02B4, mode = 1, nr_exclusive = 1, key = 0x0)
-005|mmc_wait_data_done(mrq = 0xDC9235F8)
-006|msdc_irq_data_complete(host = 0xDC927300, ?, error = 0)
-007|msdc_irq(?, dev_id = 0x1)
-008|handle_irq_event_percpu(?, action = 0xDC92B180)
-009|handle_irq_event(desc = 0xC121A440)
-010|cond_unmask_eoi_irq(inline)
-010|handle_fasteoi_irq(?, desc = 0xC121A440)
-011|static_key_count(inline)
-011|static_key_false(inline)
-011|trace_irq_exit(inline)
-011|__handle_domain_irq(domain = 0xDE806000, hwirq = 111, lookup = TRUE, ?)
-012|__raw_readl(inline)
-012|gic_handle_irq(regs = 0xC2631E20)
-013|__irq_svc(asm)
-->|exception
-014|__fget(?, mask = 16384)
-015|__fget_light(?, mask = 16384)
-016|__fdget
-017|sockfd_lookup_light(?, err = 0xC2631EC8, fput_needed = 0xC2631ECC)
-018|SYSC_recvfrom(inline)
-018|sys_recvfrom(?, ubuf = -1212542344, ?, flags = 64, addr = 0, addr_len = 0)
-019|ret_fast_syscall(asm)

 

@ Ftrace log 분석
커널 패닉이 일어나기 직전 상황

[1]: irq=111 name=mtk-msdc 가 Trigger됨
[2]: IRQ context에서 mmc_wait_data_done() 함수가 호출 from(msdc_irq_data_complete)
[2]~[3] 사이 mmcq0 process가 context switching 되지 않고 수행 ( InputDispatcher-1538)
[3]: mdelay(1); 이후 찍히는 ftrace log
[4]: wake_up_interruptible(&mrq->host->context_info.wait); API 호출로 mmcq0 process을 wakeup 시킴
CPU5: mmcqd/0, pid=244
sched_wakeup: comm=mmcqd/0 pid=244 prio=120 success=1 target_cpu=005 state=W
[5]: wake_up_interruptible(&mrq->host->context_info.wait); API 호출이 끝난 후 찍히는 로그(별 의미 없음)


kworker/4:0-25 [004] 149.827488: irq_handler_entry: irq=111 name=mtk-msdc // <<--[1]
kworker/4:0-25 [004] 149.827495: bprint: mmc_wait_data_done: +msdc [F: mmc_wait_data_done, L:1049]: ? ? from(msdc_irq_data_complete) // <<--[2]
InputDispatcher-1538 [005] 149.827496: sched_migrate_task: comm=m.lge.launcher3 pid=2135 prio=120 orig_cpu=6 dest_cpu=4 state=W
InputDispatcher-1538 [005] 149.827519: sched_wakeup: comm=m.lge.launcher3 pid=2135 prio=120 success=1 target_cpu=004 state=W
InputDispatcher-1538 [005] 149.827591: sched_migrate_task: comm=ndroid.systemui pid=1622 prio=120 orig_cpu=5 dest_cpu=6 state=W
InputDispatcher-1538 [005] 149.827608: sched_wakeup: comm=ndroid.systemui pid=1622 prio=120 success=1 target_cpu=006 state=W
InputDispatcher-1538 [005] 149.827675: sched_migrate_task: comm=android.ui pid=1287 prio=118 orig_cpu=4 dest_cpu=6 state=W
InputDispatcher-1538 [005] 149.827694: sched_wakeup: comm=android.ui pid=1287 prio=118 success=1 target_cpu=006 state=W
InputDispatcher-1538 [005] 149.827855: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d 
<idle>-0 [005] 149.827912: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=InputDispatcher next_pid=1538 next_prio=112 extra_prev_state=K|m|d 
InputDispatcher-1538 [005] 149.828064: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d 
<idle>-0 [005] 149.828209: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=InputDispatcher next_pid=1538 next_prio=112 extra_prev_state=K|m|d 
InputDispatcher-1538 [005] 149.828352: sched_switch: prev_comm=InputDispatcher prev_pid=1538 prev_prio=112 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 extra_prev_state=K|m|d 
kworker/4:0-25 [004] 149.828497: bprint: mmc_wait_data_done: ++msdc [F: mmc_wait_data_done, L:1058]: ? ? from(msdc_irq_data_complete) // <<--[3]
kworker/4:0-25 [004] 149.828521: sched_wakeup: comm=mmcqd/0 pid=244 prio=120 success=1 target_cpu=005 state=W // <<--[4]
kworker/4:0-25 [004] 149.828525: bprint: mmc_wait_data_done: -msdc [F: mmc_wait_data_done, L:1060]: ? ? from(msdc_irq_data_complete) <<-[5]
<idle>0 [005] 149.828528: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=mmcqd/0 next_pid=244 next_prio=120 extra_prev_state=K|m|d <<-[6]
kworker/4:0-25 [004] 149.828530: irq_handler_exit: irq=111 ret=handled

 

1046 static void mmc_wait_data_done(struct mmc_request *mrq)
1047*{*
1048 mrq->host->context_info.is_done_rcv = true;
1049 trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[2]
//생략
1051 mdelay(1);
//생략
1057
1058 trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[3]
1059 wake_up_interruptible(&mrq->host->context_info.wait);
1060 trace_printk("-msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<-[5]


커널 패닉 상황
[7]: irq=111 name=mtk-msdc 가 handle 되었음
[8]: [mmcqd/0-244, CPU5]mmc_wait_for_data_req_done() 함수 내[from(mmc_blk_issue_rw_rq)] wait_event_interruptible()에서 빠져나옴.
[9][10]: [mmcqd/0-244, CPU5]mmc_wait_for_data_req_done() 함수를 빠져나옴
[11]: irq=111 name=mtk-msdc 가 Trigger됨 --> CPU4의 m.lge.launcher3-2135
[12]: [mmcqd/0-244, CPU5] 깨어난 mmcqd/0-244 프로세스 활동 시작
&mqrq->brq 변수를 0으로 밀어버림 (where: memset(brq, 0, sizeof(struct mmc_blk_request));
[13]: [m.lge.launcher3-2135 CPU4] irq=111 name=mtk-msdc IRQ로 Trigger되어 실행되어
mmc_wait_data_done() 함수 진입 
[14][15]: [mmcqd/0-244, CPU5] mmc_blk_rw_rq_prep() 함수 퇴장하려함
[16][17][18] [mmcqd/0-244, CPU5] mmc_wait_for_data_req_done() 함수 처리 후 퇴장하려함
[19]: [m.lge.launcher3-2135 CPU4] wake_up_interruptible(&mrq->host->context_info.wait);
[20] 커널 패닉
[12]번 동작에서 0으로 초기화된 &mrq->host 변수를 통해 밀린((where: memset(brq, 0, sizeof(struct mmc_blk_request)) wake_up_interruptible() API 호출

kworker/4:0-25 [004] 149.828530: irq_handler_exit: irq=111 ret=handled // <<--[7]
mmcqd/0-244 [005] 149.828536: bprint: mmc_start_req: ++mmcq [F: mmc_wait_for_data_req_done, L:1236]: ? ? from(mmc_blk_issue_rw_rq) // <<--[8]
kworker/4:0-25 [004] 149.828537: irq_handler_entry: irq=30 name=arch_timer
kworker/4:0-25 [004] 149.828546: irq_handler_exit: irq=30 ret=handled
mmcqd/0-244 [005] 149.828559: bprint: mmc_start_req: mmcq [F: mmc_wait_for_data_req_done, L:1268]: ? ? from(mmc_blk_issue_rw_rq) // <<-[9]
mmcqd/0-244 [005] 149.828561: bprint: mmc_start_req: mmcq release [F: mmc_wait_for_data_req_done, L:1270]: ? ? from(mmc_blk_issue_rw_rq) // <<--[10]
kworker/4:0-25 [004] 149.828584: workqueue_execute_end: work struct 0xcb40cae4
kworker/4:0-25 [004] 149.828630: sched_switch: prev_comm=kworker/4:0 prev_pid=25 prev_prio=120 prev_state=S ==> next_comm=m.lge.launcher3 next_pid=2135 next_prio=120 extra_prev_state=K|m|d 
m.lge.launcher3-2135 [004] 149.828660: irq_handler_entry: irq=111 name=mtk-msdc // <<--[11]
mmcqd/0-244 [005] 149.828661: bprint: mmc_blk_rw_rq_prep: ++mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1725]: ? ? from(mmc_blk_issue_rw_rq) // <<--[12]
m.lge.launcher3-2135 [004] 149.828666: bprint: mmc_wait_data_done: +msdc [F: mmc_wait_data_done, L:1049]: ? ? from(msdc_irq_data_complete) // <<--[13]
mmcqd/0-244 [005] 149.828670: bprint: mmc_blk_rw_rq_prep: -mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1905]: ? ? from(mmc_blk_issue_rw_rq) // <<-[14]
mmcqd/0-244 [005] 149.828672: bprint: mmc_blk_rw_rq_prep: mmc_blk_rw_rq_prep [F: mmc_blk_rw_rq_prep, L:1907]: ? ? from(mmc_blk_issue_rw_rq) // <<-[15]
mmcqd/0-244 [005] 149.828681: bprint: mmc_start_req: +mmcq [F: mmc_wait_for_data_req_done, L:1231]: ? ? from(mmc_blk_issue_rw_rq) // <<--[16]
mmcqd/0-244 [005] 149.828683: bprint: mmc_start_req: ++mmcq [F: mmc_wait_for_data_req_done, L:1236]: ? ? from(mmc_blk_issue_rw_rq) // <<--[17]
mmcqd/0-244 [005] 149.828695: bprint: mmc_start_req: -mmcq [F: mmc_wait_for_dat뗥nQ, L:0]: ? ? from(0x726f776bS) // <<--[18]
m.lge.launcher3-2135 [004] 149.829669: bprint: mmc_wait_data_done: ++msdc [F: mmc_wait_data_done, L:1058]: ? ? from(msdc_irq_data_complete) // <<--[19]
m.lge.launcher3-2135 [004] 149.829748: tracing_on: ftrace is disabled caller=oops_enter // <<–[20]


1222 static int mmc_wait_for_data_req_done(struct mmc_host *host,
1223 struct mmc_request *mrq,
1224 struct mmc_async_req *next_req)
1225*{*
1226 struct mmc_command *cmd;
1227 struct mmc_context_info *context_info = &host->context_info;
1228 int err;
1229 unsigned long flags;
1230
1231 trace_printk("+mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[16]
1232 while (1) {
1233 wait_event_interruptible(context_info->wait,
1234 (context_info->is_done_rcv ||
1235 context_info->is_new_req));
1236 trace_printk("++mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[8], [17]
1237 spin_lock_irqsave(&context_info->lock, flags);
//snip
1268 trace_printk("mmcq [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<-[9], [18]
1269 mmc_retune_release(host);
1270 trace_printk("mmcq release [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));
1271 return err;
1272 }


1701 static void mmc_blk_rw_rq_prep(struct mmc_queue_req *mqrq,
1702 struct mmc_card *card,
1703 int disable_multi,
1704 struct mmc_queue *mq)
1705*{*
1706 u32 readcmd, writecmd;
1707 struct mmc_blk_request *brq = &mqrq->brq;
//생략
1724 memset(brq, 0, sizeof(struct mmc_blk_request));
1725 trace_printk("++mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[12]
1726 brq->mrq.cmd = &brq->cmd;
//생략
1905 trace_printk("-mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); //<<-[14]
1906 mmc_queue_bounce_pre(mqrq);
1907 trace_printk("-mmc_blk_rw_rq_prep [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));
1908 }


1046 static void mmc_wait_data_done(struct mmc_request *mrq)
1047*{*
1048 mrq->host->context_info.is_done_rcv = true;
1049 trace_printk("+msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[13]
//생략
1051 mdelay(1);
//생략
1057
1058 trace_printk("++msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0)); // <<--[19]
1059 wake_up_interruptible(&mrq->host->context_info.wait);
1060 trace_printk("--msdc [F: %s, L:%d]: ? ? from(%pS)\n", _func,LINE, (void *)_builtin_return_address(0));


정리하면 wake_up_interruptible() API에 파라미터로 전달되는 &mrq->host->context_info.wait를 다른 값(mmcqd를 깨울 수 있는 wait_queue)으로 바꾸거나,
wake_up_interruptible() 호출 시 조건을 줘야 한다. 혹은 spinlock irq save로 코드 보호


솔류션
가능 패치 1건: mrq->host->context_info.is_done_rcv; wake_up_interruptible(&mrq->host->context_info.wait); 처리 도중 MSDC irq가
trigger되었으므로 아래아 같이 spinlock irq save로 보호

diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c
index 347108a..21b7307 100644
? a/drivers/mmc/core/core.c
+++ b/drivers/mmc/core/core.c
@@ -1042,8 +1042,10 @@ EXPORT_SYMBOL(mmc_start_bkops);
*/
static void mmc_wait_data_done(struct mmc_request *mrq)
{*
+    spin_lock_irqsave(&context_info->lock, flags);
     mrq->host->context_info.is_done_rcv = true;
     wake_up_interruptible(&mrq->host->context_info.wait);
+   spin_unlock_irqrestore(&context_info->lock, flags);
}


가능 패치 2건: wake_up_interruptible() 호출 시 조건을 줌. 패치가 허접해 보임.

diff --git a/drivers/mmc/core/core.c b/drivers/mmc/core/core.c
index 347108a..ea832709 100644
? a/drivers/mmc/core/core.c
+++ b/drivers/mmc/core/core.c
@@ -1043,7 +1043,8 @@ EXPORT_SYMBOL(mmc_start_bkops);
static void mmc_wait_data_done(struct mmc_request *mrq)
{
    mrq->host->context_info.is_done_rcv = true;
    wake_up_interruptible(&mrq->host->context_info.wait);
+  if (mrq->host)
+       wake_up_interruptible(&mrq->host->context_info.wait);
}



역사전쟁/어둠은, 결코 새벽을 이기지 못한다 칼럼

저- 참람했던 유신시절에 적용되었던 ‘국정교과서’가 다시 부활된단다.
벌써부터 으시시한 한기가 몰려온다! 이건 ‘유신’ 회귀(回歸)의 신호탄인가??
문제의 핵심은 근,현대사 100년이다. 극단적인 이념갈등과 국론분열이 불 보듯이 뻔-한데도,
정부가 지금 시점에서 이를 강행하고자 하는 진짜 속내는 무엇일까??

17C 위대한 사회학자 ‘THOMAS HOBBES‘는, "과거에 대한 인식에서 미래가 결정된다"고 하였다.
집권세력은 과거에 대한 인식을 바꿔서 자기네들이 원하는 미래를 작위적으로 만들고자 한다.
그래서 ‘역사왜곡’이 절실해진다. 지금 우리가 촛불을 켜들고서 우리 역사를 지켜야 하는 것은.
우리의 미래는 과거에 대한 인식에서 만들어지기 때문이다.

로마의 황제 철학자 ‘마르쿠스 아우렐리우스’는,
“어제 일어난 것은 오늘 일어나고, 또 내일에도 일어날 수 있다.”고 하였다.
로마제국이 전성기를 지나, 쇠퇴국면으로 기울어질 때의 역사해석이다.

1,2차 대전의 참담한 폐해로 사회전반에 비관주의가 팽배되었던 시절에, 역사학자
'아놀드 토인비'는 “역사는 계속 반복한다.”고 주장하여, 많은 역사가들의 지지를 얻게 된다.
우리나라에서도 이런 '역사 순환론’은, 6.25전쟁, 유신독재, 5.18...등
현대사의 어두웠던 시절에 큰 공감을 불러일으킨다.

19세기 1백년 동안에 오랜 평화와 더불어 산업 자본주의와 제국주의 경제번영이 계속되면서,
사람들은 강한 자신감과 낙관론에 젖어들기 시작한다.

“역사는 자유를 향하여 끊임없이 진보한다.”는 헤겔의 '역사발전론'이 ‘플라톤’ 이후 서양 철학
사의 새로운 산맥을 형성한다. 이런 직선적인 진보 역사관은 그 후 참혹한 1,2차 세계대전을
겪으면서 많은 상처를 입고, 한때는 '역사 순환론'에 다소 밀리기까지도 한다.

1919년의 대공황으로 ‘자유주의 자본주의’ 경제는 무너지고, ‘수정 자본주의’로의 대전환이
미국 등 자유주의 국가에서도 대세를 이룬다. 2차 대전의 경제적 폐해로부터 벗어나게 되는
1970년대부터는, 다시 예전 자유주의 경제가 ‘신자유주의’라는 이름으로 목청을 높이게 된다.

인류사에서도 이런 평화와 번영은 다시 자신감과 낙관론을 되찾게 하고,
그래서 '신자유주의'와 더불어 다시 '진보 사관'이 힘을 얻게 된다.

한치 앞이 보이지 않고 칠흑같은 어둠에 에워싸여 있었던 우리 현대사의 지난 시절들!
6.25전쟁과 혼란 속에서, 유신의 독재 속에서, 또 5.18의 절망 속에서, 그리고 또, 또....
그러한 때들에 ‘역사 발전론’이란, 한낱 이상주의자들의 한물간 잠꼬대처럼 들리기도 하였다.
그러나 반역자, 노태우 대통령에 의하여 민주화가 기사회생되어지고,
YS 대통령에 의하여 하나회의 별들이 가을 오동잎처럼 우수수~ 떨어지고,
DJ와 바보 대통령에 의하여 참 민주주의가 꽃을 피우게 되었을 때에,
우리는 비로써 ‘희망’을 보았단다.

그래서 역사의 물결이란, 장강(長江)의 물결처럼 굽이, 굽이 흘러 종국에는
바다로 흘러갈 뿐만 아니라, 때로는 저- 거센 황하의 물줄기가 되어 모든 것을 휩쓸며
곧바로 앞으로,거침없이 나아가기도 한다는 자연의 이치를 새삼 깨닫게 되었다.

이젠, 역사의 '발전'이란 때로는 정체되기도 하고, 회귀되기도 하고, 혹은 일탈되기도 하지만,
그래도 “저- 높은 곳을 향하여 끊임없이 나아 간다”는, 칸트와 헤겔의 ‘구원사상’은
21C 인류사회의 영원한 ‘횃불’이 되었다.

개인 인생사와 마찬가지로 한 국가의 역사에서도, 어둡고 쇠퇴적인 단계에서는
역사란 옛 과거로 회귀하려는 ‘반복 경향성’을 가진다. 그러나 힘차게 역동하는 단계에서는,
역사는 직선적으로 새로운 미래를 향하여 힘차게 헤쳐 나아가려는 '전진 방향성'을 가진다.

그리고 이러한 보수와 진보의 물결이 뒤섞이고 아우러지면서,
우리 인류역사는 정+반=합, 변증법적 발전과정을 거치게 되는 것 같다.

우리 현대사의 여러 사건들이, 주마등처럼 스쳐간다~
해방의 광명과 그 후 좌, 우의 극한대결, 그리고 6.25전쟁과 집단테러!

4.19혁명과 5.16쿠데타, 유신정변, 10.26사건과 서울의 봄!
해방후 교육받은 신군부의 등장과 민주화의 거센 물결, 세계화의 쓰나미,
DJ 와 바보의 집권 그리고 Little PARK의 집권....

집권세력은 역사를 왜곡하여 친일과 독재를 미화하고 쿠데타와 유신독재를 정당화하고자 한다.
저들은 새마을 운동의 시계바늘을 되돌려서, 역사의 불행한 회귀, 반복현상을 재현하고자 한다.
시간여행 영화 ‘BACK TO THE FUTURE’처럼,
시대정신에 어울리지 않는 황당한 미래까지도 추구하려는 듯하다.

이러다가 혹시, 우리 역사는 다시 반복되어 과거 이씨 왕조나 군사독재 시절과 같이
기회주의자들이 득실대고 백성들은 지극히 무기력하여야만 하였던,
그 암울의 시대로 정녕 다시 또 돌아가는 것은 아닐까?

그래서 이 땅의 역사는 또다시, 19C 영국의 시인 ‘T. S. ELIET’ 이 그토록 울부짖었던,
“절망과 분노의 버려진 나라” ( The Waste Land )로 다시 회귀되어지는 것은 아닐까?
아니다!!! 역사의 반복(反復)과 반동(反動)은, 오르지 ‘反역사’일 뿐이다.
 

지금 우리의 현대 역사는, 오랜 유년기와 정체기를 거쳐서 청년기를 향하여 가고 있다.
지금은 과거와 달리 역사의 ‘힘’이 여기저기서 펄뜩, 펄뜩거리고 있다.
도처에서 강한 역동성이 아주 선명하게 돋보이고 있다.

또 세계사에서도 ‘진보’ (PROGRESS)의 역사는 이제까지의 특정 지역이나, 한정 시대라는
제한된 범주를 벗어나서, 보다 일반적이고 보편적이며 또 지속적인 현상으로 바꿔지고 있다!

그러하기 때문에 난, 우리역사에서 어떤 일탈, 회귀행위가 설령 생긴다 할지라도
21세기 시대정신에 의하여 결코 길게는 허용될 수 없다고 굳게 믿는다.
어둠은 결코 새벽을 이기지 못하는 법이다!!

우리 오랜 인류사가 그러하였듯이, 순천(順天) 자는 흥하고 역천(逆天) 자는 망한다!!
이렇게 도도하게 흘러오는 저- 힘찬 21C 역사의 물결을 거슬러 올라갈 자, 뉘란 말인가??
그것이 오늘날 우리 한국사와 세계사의 분명한 ‘미래’이다!!
 
20C 사회혁명에서 가장 중요한 변화는, 대중교육의 확대에 의한 이성(理性)의 증대이다.
21C 우리의 이성은 개별성과 다양성을 압살하는 '획일성'의 역사교과서를 거부한다!

우리의 미래는 국가관리자들이 임의적으로 획정하는 것이 아니라,
우리들 자신이 역사와의 자유로운 대화를 통하여 직접 선택하는 것이기 때문이다.
박정(朴定)은 결코 역사(歷史)를 이기지 못한다!!

http://lge.lglifecare.com/Pages/Common/ShopDefault.aspx


마크 로스코 특별전 예술의 전당(05/30/2015) 에세이

마크 로스코 특별전(05/30/2015)
마크 로스코 특별전이 열린 예술의 전당에 다녀왔다. 러시아 출신 미국 미술가이다. 초현실주의란 작품 기법의 선구자로 세계에서 인정받는 대가다. 입장권 가격도 세계 정상권이었다. 그런데 말년이 좋지 않았던 것 같다. 자살을 했다.

63빌딩 페인트 공들이 ‘나도 작품 활동을 하고 있네?’란 생각이 들 정도로 두 세가지 색상 물감을 엄청난 크기의 캔버스에 떡칠한 작품이 대부분이었다. 솔직히 처음 바로 그의 작품을 보자마자 다른 사람들도 이런 생각이 들었을 것 같다. 개나 소나 다 화가가 될 수 있을 것이란 자조 섞인 웃음도 지을 법했다. 작품관에서 많은 사람들은 고상한 척하면서 진지하게 ‘떡칠 페인트 공 작품’을 똥 눌 때 스마트폰 보는 것처럼 봤다. 나도 그런 척 했다.

작품 옆에 적혀 있는 작가의 철학자인 척 하는 엄숙한 문구가 내 눈에 들어왔다. 뭔 소리인지 전혀 이해할 수 없었다. 미술가이면 미술가답게 간단히 작품을 설명하는 요약 글을 남기면 될 것이지, 자신이 무슨 니체나 되는 것처럼 근엄한 척하며 뇌까리는 게 뭔지. 이 화가가 쓴 글귀들은 ‘편견없이 어떤 잣대를 들이대지 말고 그냥 순수하게 내 작품을 감상해달라는’ 메세지였다. 그렇게 쓰면 되는데 사람들이 이해하기 어려운 암구호같은 애매한 문장으로 자신이 참 현학적인 미술가라고 관람객들을 착각에 빠지게 만들려는 의도로 보였다.

마지막 작품은 시뻘건 페인트를 떡칠한 건데 자살하기 전에 만들었다고 한다. 그래서 제일 유명한 듯하다.

이 화가가 어떤 삶을 대략 살았는지 알아보려고 연도표를 살펴봤다. 그 전에 난 러시아 출신 미술가라 그 당시 소련 스탈린 공포 정치로 미국으로 도망 와서 작품활동을 한 줄 알았다. 그런데 미국에서 배부르게 도련님같이 편하게 성장했었다. 교수 자리도 한 자리 해 먹었던 경력이 눈에 들어왔다. 도대체 어떤 이유로 자살을 했는지 평범한 서민의 눈으로 이해가 가지 않았다.

작품 전시관 분위기는 엄숙하게 구상했다. 그레고리안 성가가 바닥에 깔리며 내 귀에 썰물같이 밀려왔다. 왜 이런 음악을 틀었는지 모르겠다. 미술 작품은 그냥 미술 작품인데. 작품에 어떤 의미를 부여하려는 의도를 간파할 수 있었다.

각각 작품들은 매우 수준이 높아 관람객들의 심미안을 자극하는 색체의 다이나믹을 느낄 수 있었다. 두 보색을 경계로 단색 내 섬세한 명함과 색체 변화를 감지할 수 있었다. 이게 작품에 대한 나의 감상평이다.
그림은 아는 만큼 보인다는 말이 있다. 이 말이 내게 가장 잘 들어 맞는 말 같다. 이 대머리 작가에 대해 아는 게 없으니 보이는 것도 없을 뿐이다. 무엇보다 미술 작품을 감상한 적이 거의 없기 때문일 것이다. 그가 어떤 삶을 살았는지 좀 살펴보고 내 기억 속에 사라져가는 작품을 꺼내서 퍼즐을 맞추어봐야겠다.


[T32] Cortex A53: 프로세스 별 Call Stack 복원하는 방법 리눅스 커널

커널 디버깅을 하다 보면 T32 simulator를 많이 쓰게 된다. 디버깅 과정에서 콜 스택을 보고 싶을 경우가 많다.
이번에 ARM Cortex A53 Call Stack 복원 방법을 정리하도록 하자.

T32 시뮬레이터의 가장 큰 장점은 각 프로세스 별로 Call Stack을 이쁘게 볼 수 있다는 점이다.
그런데 current process는 Call Stack을 제대로 볼 수 없다. 그 이유는 실행 도중 프로세스이기 때문에 Context(Register)정보를 Task Descriptor에
제대로 저장을 할 수 없기 때문이다.

magic___________|command_________|state_____|uid___|pid___|spaceid|tty_|flags___|cpu|
FFFFFFC001624860|swapper/0       |running   |    0.|    0.| 0000  | 0  |00200000| 0.|
FFFFFFC00E690000|init            |sleeping  |    0.|    1.| 0001  | 0  |40400100| 3.|
FFFFFFC00E690AC0|kthreadd        |sleeping  |    0.|    2.| 0000  | 0  |00208040| 1.|
<생략>
FFFFFFC072900AC0|migration/7     |current(7)|    0.|   28.| 0000  | 0  |04208040| 7.|
FFFFFFC072901580|ksoftirqd/7     |sleeping  |    0.|   29.| 0000  | 0  |04208040| 7.|
FFFFFFC072902B00|kworker/7:0H    |sleeping  |    0.|   31.| 0000  | 0  |04208060| 7.|
FFFFFFC0729035C0|khelper         |sleeping  |    0.|   32.| 0000  | 0  |04208060| 4.|
FFFFFFC072904080|netns           |sleeping  |    0.|   33.| 0000  | 0  |04208060| 4.|
FFFFFFC072904B40|perf            |sleeping  |    0.|   34.| 0000  | 0  |04208060| 4.|


"
migration/7" 이놈 프로세스를 선택 후 우클릭을 해서 Call Stack을 보면 아래 화면과 같이 흐름이 깨져 나온다.
-000|__switch_to()
-001|degrade_zero_ticks(asm)
 ---|end of frame

그럼 이제 좀 시작해 볼까.
"
migration/7" 이놈 프로세스의 Task Descriptor를 보자. 아래 stack 주소가 보인다.
  (struct task_struct)*0xFFFFFFC072900AC0 = (
    state = 0,
    stack = 0xFFFFFFC07290C000,
    usage = (counter = 3),
    flags = 69238848,
    ptrace = 0,
    wake_entry = (next = 0x0),
    on_cpu = 1,

아래 명령어로 스택 Base 주소로 접근하자. 64비트 ARM CortexA53 아키텍처의 스택 사이즈는 0x4000이다.
(참고로 ARM32 비트 아키텍처에서는 d.v %y.l [주소] 입력해야 함)
d.v %y.q 0xFFFFFFC07290C000+0x4000
________________address|_data____________________|value_____________|symbol
   NSD:FFFFFFC07290BD78| A4 2A 29 00 C0 FF FF FF  0xFFFFFFC000292AA4 \\vmlinux\watchdog\__touch_watchdog+0x1C
   NSD:FFFFFFC07290BD80| 90 BD 90 72 C0 FF FF FF  0xFFFFFFC07290BD90
   NSD:FFFFFFC07290BD88| 6C 0B 25 00 C0 FF FF FF  0xFFFFFFC000250B6C \\vmlinux\sched/clock\sched_clock_cpu+0x1C
   NSD:FFFFFFC07290BD90| A0 BD 90 72 C0 FF FF FF  0xFFFFFFC07290BDA0
   NSD:FFFFFFC07290BD98| 98 0B 25 00 C0 FF FF FF  0xFFFFFFC000250B98 \\vmlinux\sched/clock\local_clock+0x10
   NSD:FFFFFFC07290BDA0| B0 BD 90 72 C0 FF FF FF  0xFFFFFFC07290BDB0
   NSD:FFFFFFC07290BDA8| A4 2A 29 00 C0 FF FF FF  0xFFFFFFC000292AA4 \\vmlinux\watchdog\__touch_watchdog+0x1C
   NSD:FFFFFFC07290BDB0| E0 BD 90 72 C0 FF FF FF  0xFFFFFFC07290BDE0
   NSD:FFFFFFC07290BDB8| BC 3D 24 00 C0 FF FF FF  0xFFFFFFC000243DBC \\vmlinux\smpboot\smpboot_thread_fn+0x118
   NSD:FFFFFFC07290BDC0| C0 DE 8B 72 C0 FF FF FF  0xFFFFFFC0728BDEC0
   NSD:FFFFFFC07290BDC8| 00 80 90 72 C0 FF FF FF  0xFFFFFFC072908000
   NSD:FFFFFFC07290BDD0| E0 BD 90 72 C0 FF FF FF  0xFFFFFFC07290BDE0
   NSD:FFFFFFC07290BDD8| 50 3E 24 00 C0 FF FF FF  0xFFFFFFC000243E50 \\vmlinux\smpboot\smpboot_thread_fn+0x1AC
   NSD:FFFFFFC07290BDE0| 30 BE 90 72 C0 FF FF FF  0xFFFFFFC07290BE30
   NSD:FFFFFFC07290BDE8| 40 D3 23 00 C0 FF FF FF  0xFFFFFFC00023D340 \\vmlinux\kthread\kthread+0xB0
   NSD:FFFFFFC07290BDF0| 70 BC 69 0E C0 FF FF FF  0xFFFFFFC00E69BC70
   NSD:FFFFFFC07290BDF8| 38 78 7F 01 C0 FF FF FF  0xFFFFFFC0017F7838 \\vmlinux\kthread\kthread_create_lock
   NSD:FFFFFFC07290BE00| 93 07 17 01 C0 FF FF FF  0xFFFFFFC001170793 \\vmlinux\Global\kallsyms_token_index+0x4A93
   NSD:FFFFFFC07290BE08| C0 DE 8B 72 C0 FF FF FF  0xFFFFFFC0728BDEC0
   NSD:FFFFFFC07290BE10| A4 3C 24 00 C0 FF FF FF  0xFFFFFFC000243CA4 \\vmlinux\smpboot\smpboot_thread_fn
   NSD:FFFFFFC07290BE18| 00 00 00 00 00 00 00 00  0x0
   NSD:FFFFFFC07290BE20| 00 00 00 00 00 00 00 00  0x0
   NSD:FFFFFFC07290BE28| 24 D3 23 00 C0 FF FF FF  0xFFFFFFC00023D324 \\vmlinux\kthread\kthread+0x94


위 스택 덤프에서 볼드체로 되어 있는 부분을 참고하자. 함수를 호출한 주소가 위치해있는 주소이다.
ARM CortexA53은 정말 함수 흐름을 잘 확인할 수 있 Calling Convention인 것 같다. (Cortex A7은 좀 거시기 하지.)
그럼 가장 많은 정보를 볼 수 있는 Call Stack을 복원하기 위해 Stack을 0xFFFFFFC072E07D90, Program Counter를 0xFFFFFFC00023D로 지정해보자.

________________address|_data____________________|value_____________|symbol
   NSD:FFFFFFC07290BD78| A4 2A 29 00 C0 FF FF FF  0xFFFFFFC000292AA4 \\vmlinux\watchdog\__touch_watchdog+0x1C
   NSD:FFFFFFC07290BD80| 90 BD 90 72 C0 FF FF FF  0xFFFFFFC07290BD90
   NSD:FFFFFFC07290BD88| 6C 0B 25 00 C0 FF FF FF  0xFFFFFFC000250B6C \\vmlinux\sched/clock\sched_clock_cpu+0x1C
   NSD:FFFFFFC07290BD90| A0 BD 90 72 C0 FF FF FF  0xFFFFFFC07290BDA0
   NSD:FFFFFFC07290BD98| 98 0B 25 00 C0 FF FF FF  0xFFFFFFC000250B98 \\vmlinux\sched/clock\local_clock+0x10
   NSD:FFFFFFC07290BDA0| B0 BD 90 72 C0 FF FF FF  0xFFFFFFC07290BDB0


아래 명령어를 사용하자.
r.s sp 0xFFFFFFC07290BD90
r.s pc 0xFFFFFFC000250B6C

이후 v.f 명령어를 입력하여 콜 스택을 보면 아래와 같이 이쁘게 복원이 된다.
-000|sched_clock_cpu(cpu = ?)
-001|local_clock()
-002|get_timestamp(inline)
-002|__touch_watchdog()
-003|smpboot_thread_fn(data = 0xFFFFFFC0728BDEC0)
-004|smpboot_thread_fn(data = 0xFFFFFFC07290BE30)
-005|test_bit(inline)
-005|kthread(_create = 0x0)
 ---|end of frame

좋은 글 칼럼

예전에 비해 지금은 누구나 글을 미디어로 올릴 수 있는 시대다. 20년 전만 해도 글을 볼펜으로 종이에 썼는데 지금은 대부분 컴퓨터로 글을 올린다. 인터넷에 수 많은 자료들이 널려 있다. 더 많은 정보를 무제한으로 얻을 수 있는 환경이다.

하지만 예전에 비해 깊은 사색을 통해서 다른 사람의 마음을 울리는 글은 많이 올라오지 않고 있다. 대신 대중의 말초신경을 자극하는 글들이 미디어를 뒤덮고 있다. 이젠 글은 많지만 좋은 글을 보는 안목이 중요한 때이다. 글을 쓰는 환경이 바뀌어도 좋은 글을 쓰는 가장 중요한 조건은 꾸준한 독서와 깊은 사색을 통한 자신의 성찰인 것 같다.


NUMA

NUMA[누마]멀티프로세싱 시스템에서 지역적으로는 메모리를 공유하며, 성능을 향상시키고, 시스템 확장성이 있도록 마이크로프로세서 클러스터를 구성하기 위한 방법이다. NUMA는 SMP 시스템에서 사용된다. SMP 시스템은 서로 밀접하게 결합되어, 모든 것을 공유하는 시스템으로서, 다중 프로세서들이 하나의 단일 운영체계 하에서 공통의 버스를 통해 각자의 메모리를 액세스한다. 보통, SMP의 한계는 마이크로프로세서가 추가됨에 따라, 공유 버스나 데이터 경로가 과중한 부하가 생기게 되어, 성능에 병목현상이 일어나는데 있다. NUMA는 몇 개의 마이크로프로세서들 간에 중간 단계의 공유메모리를 추가함으로써, 모든 데이터 액세스가 주버스 상에서 움직이지 않아도 되도록 한다.

NUMA는 하나의 상자 속에 있는 클러스터로 생각할 수 있다. 클러스터는 대체로 마더보드 상의 하나의 공유 메모리 (L3 캐시라고도 부른다)로 향하는 로컬버스에, 서로 연결된 네 개의 마이크로프로세서들로 구성된다. 이 유니트는 모든 클러스터들을 서로 연결하는 공용 버스 내에서 SMP를 구성하기 위하여 비슷한 유니트에 추가될 수 있다. 이러한 시스템은 대체로 16~256개의 마이크로프로세서를 가지고 있다. SMP 시스템에서 실행되는 응용프로그램에게는, 모든 개별 프로세서 메모리들이 하나의 단일 메모리인 것처럼 비쳐진다.

프로세서가 어떤 메모리 주소에 있는 데이터를 찾을 때, 그것은 마이크로프로세서 그 자체에 붙어 있는 L1 캐시를 먼저 찾은 다음, 근처에 있는 다소 큰 L2 캐시 을 찾는다. 그 다음에는 다른 마이크로프로세서 인근에 있는 원격 메모리의 데이터를 찾기 전에, NUMA 구성에 의해 제공되는 제3의 캐시를 찾는다. NUMA에게는, 이러한 클러스터들 각각이 서로 연결된 네트웍 내에 있는 하나의 노드들 처럼 비쳐진다. NUMA는 모든 노드들 상에 있는 데이터를 계층 체계로 유지한다.


NUMA SMP 시스템의 클러스터들 사이에 있는 버스에서는 SCI (scalable coherent interface) 기술을 사용하여 데이터가 움직인다. SCI는 다중 클러스터의 노드에 걸쳐 캐시 일관성이라고 불리는 것과 대등하다.

SMP와 NUMA 시스템은 대체로 공통의 데이터베이스 상에 집단적으로 작업하는 많은 수의 프로세서들에게, 작업 처리를 분담시킬 수 있는 데이터 마이닝의사결정 시스템 등과 같은 분야에 사용된다. 시퀀트, 데이터제너럴, NCR 등이 NUMA SMP 시스템을 생산하는 회사들이다.

-------------

불균일 기억 장치 접근(Non-Uniform Memory Access, NUMA)는 멀티프로세서 시스템에서 사용되고 있는 컴퓨터 메모리 설계 방법중의 하나로, 메모리에 접근하는 시간이 메모리와 프로세서간의 상대적인 위치에 따라 달라진다. NUMA구조에서 프로세서는 자기의 로컬 메모리에 접근할 때가 원격 메모리에 접근할 때보다 더 빠르다. 원격 메모리는 다른 프로세서에 연결되어 있는 메모리를 말하고 로컬 메모리는 자기 프로세서에 연결되어 있는 메모리를 말한다.

NUMA 아키텍처는 이론적으로 SMP아키텍처로부터 확장된 개념이다. Burroughs large systems에 의해서 첫 상용화되었으며 이후 유니시스, Convex Computer(이후 휴렛 패커드), 실리콘 그래픽스, Sequent Computer Systems, Data General 그리고 DEC에서 상품화되었다. 이러한 회사들이 개발해 놓은 기술들은 유닉스 계열 운영 체제에 도입되었으며 일부는 윈도 NT에도 도입되었다.

기본 개념

NUMA 시스템의 한예. 프로세서들은 버스나 크로스바로 연결되어 있음을 주목하세요. 각각의 프로세서들은 그 위치에 따라 메모리에 접근하는 우선순위가 다름을 보여준다.

현대의 CPU는 주 메모리보다 훨씬 빠르게 동작한다. 그렇지만 컴퓨터 초기에는 CPU는 일반적으로 메모리보다 천천히 동작을 했다. 1960년대에 첫 슈퍼컴퓨터와 고속 컴퓨터가 개발되면서 역전이 되었다. 그 이후, 계속해서 데이터를 더 많이 사용해야 하는 CPU는 메모리에서 데이터를 다 가지고 올 때까지 기다려야 했다. 1980년대와 1990년대에 개발된 많은 슈퍼컴퓨터는 빠르게 메모리에 접근하는 방법을 제공했고 이것으로 대용량 데이터 집합에 대한 처리를 그 어떤 다른 시스템들보다 빠르게 할 수 있었다.

메모리에 접근하는 경우의 수를 줄이는 것이 현대 컴퓨터에서 성능을 높이는 한 방법이다. 예를 들면, 고속의 캐시 메모리를 지속적으로 증가시키는 것과 캐시 미스를 줄이기 위한 뛰어난 알고리즘을 사용하는 것이다. 그렇지만 운영체제 크기의 비약적인 증가와 그 위에서 돌아가는 애플리케이션 크기의 증가는 캐시를 통한 성능 향상을 압도하게 된다. 특히나 다중 프로세서 시스템에서는 이 문제가 더 심각하다. 하나의 프로세서만이 메모리에 접근할 수 있기 때문에 많은 다른 프로세서들은 기다려야만 하기 때문이다.

NUMA는 각각의 프로세서에 독립적인 별도의 메모리를 제공함으로써 이러한 문제를 해결하려 한다. 이렇게 하면 여러 프로세서들이 동일 메모리 주소에 접근하려 할때 성능 충돌을 피할 수 있다. 서버와 애플리케이션에서 아주 일반적인 펼쳐진 데이터를 처리하는 문제의 경우에, NUMA는 하나의 공유 메모리의 경우 대비 대략적으로 프로세서의 수나 아니면 메모리 뱅크수 만큼 성능을 향상시킬 수 있다. 그렇지만 하나 이상의 프로세서가 동일 데이터를 필요로 하는 경우에 NUMA시스템은 메모리 뱅크들 사이로 데이터를 이동시켜야 하는 경우가 발생한다. 이러한 동작은 NUMA의 성능을 떨어뜨리는 요인이다. 따라서 전반적인 성능은 주어진 시간에 동작하고 있는 일의 특성에 달려있다. 어떻게 프로세스가 원격 메모리 대신 로컬 메모리를 사용하게 하느냐가 프로그램의 최적화에 대한 문제이다.

캐시 일관성 NUMA (ccNUMA)

거의 모든 CPU 아키텍처는 CPU캐시라고 알려진 적은 양의 매우 빠른 비공유 메모리를 사용한다. NUMA환경에서 공유 메모리의 캐시 일관성을 유지시키는 것은 상당히 어려운 작업이다. 비록 캐시 일관성을 제공하지 않는 NUMA아키텍처는 설계와 제작이 용이하지만 현재의 폰 노이만 구조 프로그래밍 모델에서는 프로그래밍을 하기가 매우 어렵다. 따라서 현재 시장에 판매되고 있는 모든 NUMA 컴퓨터들은 캐시 일관성을 제공한다. 이것을 ccNUMA(cache-coherent NUMA)라고 분류한다.

인텔은 2007년 후반에 x86아이테니엄 서버에서 네할렘 마이크로아키텍처 기반 프로세서와 투킬라 프로세서에서부터 NUMA 아키텍처를 적용했다.[1] 프로세서들간의 연결은 인텔 퀵패스 인터커넥트(QPI)를 통하여 이루어진다.[2]

NUMA 대 클러스터 컴퓨팅

어떤사람들은 NUMA를 매우 가깝게 연결된 컴퓨터 클러스터이라고 본다. 클러스터 아키텍처에 가상 메모리 페이징을 도입하면 NUMA가 아닌 하드웨어에서 순전히 소프트웨어적으로 구현이 가능하다. 그렇지만 노드간의 레이턴시(대기시간,Latency)는 하드웨어 기반의 NUMA보다 수십배 이상 느리다.


-----------------

Microsoft Microsoft SQL Server는 NUMA(Non-Uniform Memory Access)를 인식하며 특수한 구성 없이 NUMA 하드웨어에서 원활하게 작동합니다. 클럭 속도와 프로세서 수가 증가할수록 이러한 추가 처리 능력을 사용하는 데 필요한 메모리 대기 시간을 줄이기가 더 어려워집니다. 이러한 문제를 피하기 위해 하드웨어 공급업체에서는 대용량의 L3 캐시를 제공하지만 이는 제한적인 해결책입니다. NUMA 아키텍처는 이 문제에 대한 포괄적인 해결책을 제공합니다. SQL Server는 응용 프로그램을 변경할 필요 없이 NUMA 기반 컴퓨터를 활용하도록 디자인되었습니다.

작은 프로세서 집합에 사용되는 시스템 버스를 여러 개 구성하는 것이 일반적인 하드웨어 추세입니다. 각 프로세서 그룹에는 자체 메모리가 있으며 자체 I/O 채널이 있는 경우도 있습니다. 그러나 각 CPU는 일관된 방법으로 다른 그룹과 연결된 메모리에 액세스합니다. 각 그룹을 NUMA 노드라고 합니다. NUMA 노드 내의 CPU 수는 하드웨어 공급업체에 따라 다릅니다. 다른 NUMA 노드와 연결된 메모리보다 로컬 메모리를 액세스하는 것이 더 빠릅니다. 이러한 이유로 Non-Uniform Memory Access, 즉 NUMA 아키텍처라고 명명되었습니다.

NUMA 하드웨어에서는 일부 메모리 영역이 실제로 나머지 영역과 다른 버스에 있습니다. NUMA는 로컬 메모리와 외부 메모리를 사용하므로 다른 영역에 비해 일부 메모리 영역에 액세스하는 시간이 오래 걸립니다. 로컬 메모리외부 메모리라는 용어는 대개 현재 실행 중인 스레드에 대한 참조에 사용됩니다. 로컬 메모리는 현재 스레드를 실행 중인 CPU와 같은 노드에 있는 메모리입니다. 스레드가 현재 실행 중인 노드에 속하지 않는 메모리는 외부 메모리입니다. 외부 메모리를 원격 메모리라고도 합니다. 로컬 메모리 액세스 비용에 대한 외부 메모리 액세스 비용의 비율을 NUMA 비율이라고 합니다. NUMA 비율이 1이면 이는 SMP(대칭 다중 처리)입니다. 비율이 높을수록 다른 노드의 메모리에 액세스하는 데 더 많은 비용이 소요됩니다. SQL Server 2000 SP3 이전 버전을 포함하여 NUMA를 인식하지 않는 Windows 응용 프로그램은 경우에 따라 NUMA 하드웨어에서 제대로 작동하지 않습니다.

NUMA의 주된 이점은 확장성입니다. NUMA 아키텍처는 SMP 아키텍처의 확장성 제한을 극복하기 위해 고안되었습니다. SMP를 사용하면 모든 메모리 액세스가 같은 공유 메모리 버스에 게시됩니다. CPU 수가 비교적 적을 때는 문제가 없지만 공유 메모리 버스 액세스를 위해 수십 개나 수백 개의 CPU가 경쟁할 경우에는 이 기능이 제대로 작동하지 않습니다. NUMA는 특정 메모리 버스의 CPU 개수를 제한하고 고속 연결로 여러 개의 노드를 연결하여 이러한 병목 현상을 완화합니다.

4개의 프로세서가 있는 NUMA 노드

NUMA는 특별한 하드웨어(하드웨어 NUMA)를 통해 또는 SQL Server 메모리(소프트 NUMA)를 구성하여 메모리를 CPU에 대응시킬 수 있습니다. 시작 중에 SQL Server는 기본 운영 체제 및 하드웨어 구성이나 소프트 NUMA 설정에 따라 구성됩니다. 하드웨어 NUMA 및 소프트 NUMA 둘 다에 대해, NUMA 구성에서 SQL Server 시작 시 각 노드에 대한 다중 모드 구성 메시지와 CPU 마스크가 SQL Server 로그에 기록됩니다.

하드웨어 NUMA

하드웨어 NUMA가 구성된 컴퓨터에는 작은 프로세서 집합에 사용되는 시스템 버스가 여러 개 있습니다. 각 프로세서 그룹에는 자체 메모리가 있으며 자체 I/O 채널이 있는 경우도 있지만 각 CPU는 일관된 방법으로 다른 그룹과 연결된 메모리에 액세스할 수 있습니다. 각 그룹을 NUMA 노드라고 합니다. NUMA 노드 내의 CPU 수는 하드웨어 공급업체에 따라 다릅니다. 컴퓨터의 하드웨어 NUMA 지원 여부는 해당 하드웨어 제조업체로 문의하십시오.

하드웨어 NUMA가 있는 경우 NUMA 대신 인터리브 메모리를 사용하도록 구성할 수 있습니다. 그러면 Windows와 SQL Server에서 NUMA로 인식되지 않습니다. 다음 쿼리를 실행하여 SQL Server에서 사용 가능한 메모리 노드의 개수를 확인할 수 있습니다.

SELECT DISTINCT memory_node_idFROM sys.dm_os_memory_clerks

SQL Server에서 하나의 메모리 노드(노드 0)만 반환되면 하드웨어 NUMA가 없거나 해당 하드웨어가 인터리브(비-NUMA)로 구성되어 있는 것입니다. 하드웨어 NUMA가 잘못 구성되었다고 판단되는 경우 하드웨어 공급업체에 NUMA를 설정하도록 요청하십시오. SQL Server는 하드웨어 NUMA에 4개 이하의 CPU가 있고 CPU가 하나뿐인 노드가 하나 이상 있는 경우 NUMA 구성을 무시합니다.

소프트 NUMA

SQL Server에서는 CPU를 소프트 NUMA라는 노드로 그룹화할 수 있습니다. 일반적으로 많은 CPU가 있으며 하드웨어 NUMA가 없는 경우 소프트 NUMA를 구성하지만 소프트 NUMA를 사용하여 하드웨어 NUMA 노드를 더 작은 그룹으로 세분화할 수도 있습니다. SQL Server 스케줄러와 SQL Server 네트워크 인터페이스(SNI)만 소프트 NUMA를 인식합니다. 메모리 노드는 하드웨어 NUMA를 기반으로 생성되므로 소프트 NUMA의 영향을 받지 않습니다. 예를 들어 SMP 컴퓨터에 8개의 CPU가 있으며 각각 두 개의 CPU를 가진 소프트 NUMA 노드 4개를 만들면 메모리 노드 하나에서 4개의 NUMA 노드를 모두 처리합니다. 소프트 NUMA는 메모리에서 CPU로의 선호도를 제공하지 않습니다.

소프트 NUMA는 많은 CPU가 있고 하드웨어 NUMA가 없는 컴퓨터에서 I/O 및 지연 기록기 병목을 완화시키는 이점이 있습니다. 각 NUMA 노드에 대해 I/O 스레드와 지연 기록기 스레드가 각각 하나씩 있습니다. 데이터베이스 사용량에 따라 이러한 단일 스레드는 심각한 성능 병목이 될 수 있습니다. 4개의 소프트 NUMA 노드를 구성하면 I/O 스레드와 지연 기록기 스레드가 각각 4개가 되므로 성능이 향상됩니다.

여러 하드웨어 NUMA 노드의 CPU를 포함하는 소프트 NUMA를 만들 수는 없습니다. 예를 들어 하드웨어에 8개의 CPU(0..7)가 있고 하드웨어 NUMA 노드가 두 개(0-3 및 4-7)이면 CPU(0,1)과 CPU(2,3)을 결합하여 소프트 NUMA를 만들 수 있습니다. CPU(1, 5)를 사용하여 소프트 NUMA를 만들 수는 없지만 CPU 선호도를 사용하여 SQL Server 인스턴스의 선호도를 여러 NUMA 노드의 CPU로 설정할 수 있습니다. 따라서 앞서 설명한 예에서 SQL Server에 CPU 0-3이 사용되는 경우 I/O 스레드와 지연 기록기 스레드가 각각 하나씩 있습니다. 또한 SQL Server에 CPU 1, 2, 5, 6이 사용되는 경우 두 개의 NUMA 노드에 액세스하게 되며 I/O 스레드와 지연 기록기 스레드가 각각 두 개씩 있습니다.


공무원 연금 개혁 투쟁 칼럼

공무원 연금으로 참 말이 많다. 공무원들은 사상 최대의 인원이 운집하여 데모를 하면서 정부의 연금개혁에 대해 격렬하게 항의를 하고 있다.

공무원 연금 개혁을 하는 이유는 간단하다. 지금 이 상태로 공무원연금을 두면 30년 후에 재정이 바닥이 나서 공무원들에게 연금을 줄 수 없게 되고 이 돈들은 결국 국민의 세금으로 충당해야 한다는 것이다.


공무원 노조들도 이러한 현실에 대한 인식을 같이 해야 하며 공무원연금 개혁에 대한 대안을 제시를 해야 한다. 무조건 투쟁은 국민들에게 집단 이기주의로 비추어 질 수도 있다.


더 큰 문제는 정부에게 있다. 공무원연금 개혁의 당사자인 공무원노조와 어떠한 소통도 없이 불도저같이 정부안을 일방적으로 밀어붙히려고만 하고 있다. 개혁안을 만들고 일방적인 통보만 할 뿐이다. 참 비민주적인 처사라고 할 수 있다.

어떤 정책이든 갈등이 생길 수 밖에 없는데 서로 아이디어를 짜 맞추면서 충돌이나 갈등을 최소화하는 과정에서 현실적인 대안이 나오기를 바란다.  


의지는 고통과 욕구 불만 인문

의지는 결핍에서 생겨나며 고통에서 생겨난다. 원망의 충족은 고통을 중단시킬 수 없다. 그러나 하나의 원망의 충족은 열의 고통의 현실을 배제한다. 갈망은 길고 요구는 무한하지만 만족은 짧다. 욕구의 충족은 새로운 욕구를 지어낼 뿐이다. 충족된 욕구도 허상이요, 새로운 욕구도 허상이다. 거지에게 구제품을 주면 오늘은 살아가지만 내일의 불행은 가중된다. 모든 의지의 근거는 요구며 결핍이며 고통이다.

의지에 대한 글은 쇼펜하우어가 한 말인데 참 나의 가슴 속을 울리는 명언으로 들린다.
정말 맞는 소리다. 어떤 고통도 없고 욕구 불만도 없는 사람에게 과연 의지란 강한 감성이 생길 수는 없을 것이다.

예술가들도 금전적인 상황이 안 좋을 경우나 예술계에서 인정을 받지 못할 때 즉 욕구 불만으로 가득차 있을 때 위대한 작품을 탄생시키곤 했다. 음악가를 예를 들자면 파산 직전의 상황에서 생활비를 벌기 위해 작곡한 모짜르트 협주곡 20번, 러시아 혁명을 지켜보면서 현실에 대한 절규로 작곡한 프로코피에트 피아노 협주곡 1번, 망명 생활 중에 아름다운 조국의 모습을 그리면서 작곡한 라흐마니노프 협주곡 2번 등등.

하지만 어린 시절, 학창 시절 내내 아무런 어려움 없이 왕자같이 커온 부자집 도련님들에게 강한 의지가 있을 것이라고 기대하기는 힘들다. 대신 조금만 어려운 시간을 겪게 되어도 쓰러지는 유약한 인간이 될 가능성이 있다.

내 생각에 직장에서 지금 내가 하고 있는 일이 너무 잘 풀리고 제대로 인정받는 순간이 오게 되면 나 자신을 뒤돌아보면서 겸허히 생각을 많이 해 봐야겠다. 나도 모르게 나의 능력을 뛰어 넘어 세상을 바꾸려는 나의 강한 의지가 줄어들게 될 수 밖에 없는 순간이 될 수 있기 때문이다.

중요한 건 욕구가 충족되지 않는 고통의 순간이 다가오면 손가락을 이 세상으로 돌리지 말고 나 자신을 되돌아보아야 한다는 것이다. 이 모든 욕구 불만은 나 자신으로 비롯되는 것이다. 내가 능력이 없던가 준비가 부족하던가 이런 식으로 말이다. 아니면 내 마음을 고쳐먹건가. 아무리 이 세상에 대해 하소연을 하거나 비판을 해도 되돌아오는 것은 공허한 나의 메아림이다.


건강한 늙은이가 있는가? 칼럼

우리는 성인을 생각할 때 보통 혈기가 피둥피둥한 젊은이, 어린이의 모습을 떠올리지 않는다. 성인의 모습은 어느 때고 늘 “늙은이”의 모습으로 떠오른다. 수염이 덥수룩한 할아버지! 산신령도 혈기왕성한 젊은 산신령은 없고, 홍길동이 찾아간 도사도 반드시 꼬불꼬불한 지팡이에 하이얀 수염이 땅끝까지 내려와야 한다.

늙음은 믿음이다. 즉 젊은이가 제 아무리 성인의 모든 가능성을 집약하고, 행동과 실천으로 구현하고 있다 해도 그러한 실천의 역사성의 신뢰가 부족하기 때문에 성인의 타이틀까지는 얻을 수가 없다. 앞으로 장차 무슨 실수를 어떻게 저지를 지 모르기 때문이다. 늙음만이 궁극적으로 인간세에 믿음을 주는 가치의 원천이라고 암묵적으로 한국인들은 생각한 것이다.

나의 부모님 세대들에게 삶의 중요한 가치는 “멋있는 늙은이”가 되는 것인데 나에게 있어서도 잘 늙기 위해서 젊음이라는 에너지를 끊임없이 조합해 나가는 과정이 중요하다는 메시지로 들린다.

성인에 대한 우리의 일상적이 이미지를 검토해보면 반드시 “늙음”과 병론되어야 할 속성이 하나 있는데 그것은 건강이다. 다시 말해서 성인은 반드시 건강해야 하는 것을 필요충분조건으로 가지고 있다. 건강하지 못한 자는 성인이 될 수 없다.

여기서 우리는 성인에 대한 최종적 결론을 내릴 수 있게 된다. 성인이란 “건강한 늙은이”, 그 이상 이하도 아닌 것이다. 인간세의 소리를 항상 잘 들어온 사람, 그 이상의 아무 것도 아니다.

그런데 최근에 정치판에 등장하는 “늙은이”들 중에 건강한 늙은이가 한 명도 없다. 유신헌법을 만들어 총통제 세상을 만들기 위해 젊음을 바치고 권력의 달콤한 꿀 단지를 평생 찾아 다닌 늙은이, 소련을 언급하며 일본 식민 지배가 정당하다는 식민사관의 정신병에 걸려 있는 79세의 늙은이들. 신체적으로 건강해 보일지는 모르겠지만, 정신 건강에 상당히 문제가 있는 늙은이들이다.

내가 마음 속 깊이 존경하고 싶고 나의 삶의 건강한 모범으로써 따르고 싶은 모델과는 너무나도 거리가 있는 상황이라는 것이 안타깝다.

1 2 3 4 5 6 7