Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

8200
629
98815


[리눅스커널] 동기화 - 유저 프로세스 시스템 콜 호출 시 레이스 컨디션 9장. 커널동기화(스핀락/뮤텍스)

유저 공간에서 생성된 프로세스는 여러 개 쓰레드를 생성합니다. 이 쓰레드들이 같은 디바이스 노드에 접근해서 시스템 콜을 발생하며 커널과 통신합니다.

fork() 라는 함수를 유저 공간에서 시스템 콜로 호출하면 유저 공간에서 sys_clone()이란 함수 호출로 프로세스를 생성합니다. 유저 공간에서 open(), write() 그리고 ioctl() 이란 함수를 호출하면 이에 대응하는 시스템 콜을 호출해서 커널 공간과 통신합니다.

이번에는 시스템 콜 관련 함수에서 발생한 레이스 컨디션을 확인합니다. 
먼저 패치 코드를 소개하겠습니다.
1 diff --git a/kernel/exit.c b/kernel/exit.c
2 --- a/kernel/exit.c
3 +++ b/kernel/exit.c
4 @@ -760,10 +760,24 @@ static void check_stack_usage(void)
5 static inline void check_stack_usage(void) {}
6 #endif
8  +void trace_function_dummy_call(void)
9  +{
10 + trace_printk("[++] comm:%s, pid:%d, from(%pS) \n", 
11 + current->comm, current->pid, (void *)__builtin_return_address(0));
12 +}
13 +
14 void __noreturn do_exit(long code)
15 {
16  struct task_struct *tsk = current;
17  int group_dead;
18 +
19 + trace_printk("[+] comm: %s, pid: %d, global_func_exe_times7: %d\n", 
20 + current->comm, current->pid, global_func_exe_times);
21 +
22 + global_func_exe_times++;
23 +       trace_function_dummy_call();
24 +
25  profile_task_exit(tsk);
26  kcov_task_exit(tsk);
27 @@ -809,6 +823,13 @@ void __noreturn do_exit(long code)
28  }
29 
30  exit_signals(tsk);  /* sets PF_EXITING */
31 +
32 + trace_printk("[-] comm: %s, pid: %d, global_func_exe_times8: %d\n", 
33 + current->comm, current->pid, global_func_exe_times);
34 +
35  /*
36    * Ensure that all new tsk->pi_lock acquisitions must observe
37   * PF_EXITING. Serializes against futex.c:attach_to_pi_owner().

패치 코드는 do_exit() 이라는 함수에 작성하면 됩니다.

패치 작성하는 방법을 먼저 소개합니다. 
먼저 19~22번째 줄 코드는 do_exit() 함수 앞부분에 작성하고 32~34번째 줄 코드는 30번째 exit_signals(tsk); 코드 다음에 입력하면 됩니다.

우선 19번째 줄 코드를 함께 살펴보겠습니다. 코드 내용은 어렵지 않습니다.
19 + trace_printk("[+] comm: %s, pid: %d, global_func_exe_times7: %d\n", 
20 + current->comm, current->pid, global_func_exe_times);
21 +
22 + global_func_exe_times++;

현재 구동 중인 프로세스 이름과 pid 그리고 global_func_exe_times 전역 변수를 ftrace 로그로 출력합니다. 

22번째 줄 코드는 global_func_exe_times 이란 전역 변수를 +1만큼 증감하는 동작입니다.

다음 23번째 줄 코드에서 trace_function_dummy_call() 함수를 호출합니다.
23 +       trace_function_dummy_call();

8~9번째 줄 코드에 구현된 trace_function_dummy_call()는 디버깅 용도로 생성한 함수입니다.
8  +void trace_function_dummy_call(void)
9  +{
10 + trace_printk("[++] comm:%s, pid:%d, from(%pS) \n", 
11 + current->comm, current->pid, (void *)__builtin_return_address(0));
12 +}

이 함수는 왜 생성해서 호출할까요? 이 함수를 ftrace set filter에 지정하면 콜스택을 확인할 수 있기 때문입니다. 레이스 컨디션 발생 시 조금 더 많은 디버깅 정보를 얻을 수 있습니다.

이 패치 코드를 작성한 후 ftrace 로그를 설정해야 합니다.
그동안 ftrace 설정 방법을 많이 소개했으니 예전과 비교해 달라지는 점만 소개하겠습니다.
1 echo  trace_function_dummy_call > /sys/kernel/debug/tracing/set_ftrace_filter
2
3 echo 1 > /sys/kernel/debug/tracing/options/sym-offset

먼저 1번째 줄 코드를 보겠습니다.
set_ftrace_filter로 trace_function_dummy_call() 함수를 지정합니다.

마지막 3번째 줄 코드를 보겠습니다.
ftrace가 콜스택을 출력할 때 함수 주소 정보를 오프셋 주소를 출력(9번째 줄)합니다.
이 옵션을 키고 ftrace 로그를 받으면 다음과 같이 함수 옆에 주소 정보를 볼 수 있습니다.
 => __mmc_start_request+0x78/0x1ac  
 => mmc_start_request+0x158/0x184  
 => mmc_wait_for_req+0x94/0xfc  
 => mmc_io_rw_extended+0x258/0x2f8 
 => sdio_io_rw_ext_helper+0x14c/0x1c0  
 => sdio_readsb+0x2c/0x34 
 => brcmf_sdiod_buffrw+0x50/0xa0 [brcmfmac]  
 => brcmf_sdiod_recv_pkt+0x74/0x80 [brcmfmac] 
 => brcmf_sdiod_recv_buf+0x3c/0x88 [brcmfmac]  
 => brcmf_sdio_dataworker+0x1b68/0x2384 [brcmfmac] 
 => process_one_work+0x224/0x518 
 => worker_thread+0x60/0x5f0 
 => kthread+0x144/0x174  
 => ret_from_fork+0x14/0x28  
 
위 ftrace 로그 콜스택 중 worker_thread 함수 옆에 있는 주소 정보를 같이 확인합시다.
worker_thread+0x60/0x5f0

worker_thread() 함수 전체 크기는 0x5f0이며 worker_thread() 함수 시작 주소 기준으로 0x60에 떨어진 코드에서 process_one_work() 함수를 호출했다는 의미입니다.

먼저 레이스가 발생하지 않을 때 ftrace 로그를 먼저 보겠습니다. 레이스가 발생하지 않았을 때 패턴의 로그를 분석하는 이유는 레이스가 발생했을 때 로그 패턴과 비교하기 위해서입니다.

분석할 로그는 다음과 같습니다.
1 <...>-3106  [001] .... 1342.119405: do_exit: [+] comm: TaskSchedulerRe, pid: 3106, global_func_exe_times: 43
2 <...>-3106  [001] .... 1342.119407: trace_function_dummy_call <-do_exit
3 <...>-3106  [001] .... 1342.119423: <stack trace>
4 => get_signal+0x35c/0x69c  
5 => do_signal+0x300/0x3d4  
6 => do_work_pending+0xb4/0xcc 
7 => slow_work_pending+0xc/0x20 
8 <...>-3106  [001] ....  1342.119427: trace_function_dummy_call: [++] comm:TaskSchedulerRe, pid:3106, from(do_exit+0x890/0xc18) 
9 <...>-3106 [001] .... 1342.119431: do_exit: [-] comm: TaskSchedulerRe, pid: 3106, global_func_exe_times: 44

1번째 줄 로그는 do_exit() 함수 앞부분 코드가 실행할 때 출력합니다.
pid가 3106인 "TaskSchedulerRe" 프로세스가 종료하는 동작입니다.

이때 global_func_exe_times 전역 변수는 43입니다. 이 ftrace 로그를 출력하고 다음 코드를 실행해서 global_func_exe_times 전역 변수를 +1만큼 증감하니 44가 됩니다.
global_func_exe_times++;

2~7번째 줄 로그는 trace_function_dummy_call() 함수 콜스택입니다. 
유저 공간에 실행 중인 프로세스 간 통신을 위해 시그널을 처리하는 동작입니다. 유저 공간 생성된 프로세스는 시그널 통신으로 종료합니다.

8번째 줄 로그는 trace_function_dummy_call() 함수에서 출력하는 프로세스 정보입니다. 1번째 줄 로그와 같은 프로세스 이름과 pid를 볼 수 있습니다.

9번째 줄 로그로 do_exit() 함수 하단에 추가한 패치 코드가 실행함을 알 수 있습니다. 
global_func_exe_times 전역 변수를 +1만큼 증감했으니 44를 출력합니다.

다음 do_exit() 함수에서 6~24줄 코드까지 CPU1에서 pid가 3106인 TaskSchedulerRe 프로세스가 실행했음을 알 수 있습니다. 레이스가 발생하지 않았다고 할 수 있습니다.
1 void __noreturn do_exit(long code)
2 {
3 struct task_struct *tsk = current;
4 int group_dead;
5
6 profile_task_exit(tsk);
7 kcov_task_exit(tsk);
8
9 WARN_ON(blk_needs_flush_plug(tsk));
10
11 if (unlikely(in_interrupt()))
12 panic("Aiee, killing interrupt handler!");
13 if (unlikely(!tsk->pid))
14 panic("Attempted to kill the idle task!");
15 set_fs(USER_DS);
16 ptrace_event(PTRACE_EVENT_EXIT, code);
17 validate_creds_for_do_exit(tsk);
18 if (unlikely(tsk->flags & PF_EXITING)) {
19 pr_alert("Fixing recursive fault but reboot is needed!\n");
20 tsk->flags |= PF_EXITPIDONE;
21 set_current_state(TASK_UNINTERRUPTIBLE);
22 schedule();
23 }
24 exit_signals(tsk);  /* sets PF_EXITING */

레이스가 발생하지 않은 코드를 봤으니 레이스가 발생했을 때 ftrace 로그를 보겠습니다.
1 CompositorTileW-3064  [003] ....  1396.127136: do_exit: [+] comm: CompositorTileW, pid: 3064, global_func_exe_times: 111
2 CompositorTileW-3064  [003] ....  1396.127139: trace_function_dummy_call <-do_exit
3 GpuMemoryThread-3061  [000] ....  1396.127141: do_exit: [+] comm: GpuMemoryThread, pid: 3061, global_func_exe_times: 111
4  GpuMemoryThread-3061  [000] ....  1396.127144: trace_function_dummy_call+0x14/0x58   <-do_exit+0x890/0xc18 
5 CompositorTileW-3064  [003] ....  1396.127169: <stack trace>
6 => get_signal+0x35c/0x69c 
7 => do_signal+0x74/0x3d4 
8 => do_work_pending+0xb4/0xcc  
9 => slow_work_pending+0xc/0x20  
10 GpuMemoryThread-3061  [000] ....  1396.127170: <stack trace>
11 => get_signal+0x35c/0x69c 
12 => do_signal+0x74/0x3d4  
13 => do_work_pending+0xb4/0xcc  
14 => slow_work_pending+0xc/0x20  
15 CompositorTileW-3064  [003] ....  1396.127172: trace_function_dummy_call: [++] comm:CompositorTileW, pid:3064, from(do_exit+0x890/0xc18) 
16 GpuMemoryThread-3061  [000] ....  1396.127174: trace_function_dummy_call: [++] comm:GpuMemoryThread, pid:3061, from(do_exit+0x890/0xc18) 
17 CompositorTileW-3064  [003] ....  1396.127178: do_exit: [-] comm: CompositorTileW, pid: 3064, global_func_exe_times: 114

1번째 줄 로그를 보면 global_func_exe_times 값이 111입니다. 이 ftrace 로그는 다음 코드 6번째 줄 코드가 실행됐을 때 출력합니다.
1 void __noreturn do_exit(long code)
2 {
struct task_struct *tsk = current;
int group_dead;
5 +
6 + trace_printk("[+] comm: %s, pid: %d, global_func_exe_times: %d\n", 
7 + current->comm, current->pid, global_func_exe_times);
8 +
9 + global_func_exe_times++;
10 +       trace_function_dummy_call();

위 do_exit() 함수 6번째 줄 코드를 실행하면 바로 9번째 줄 코드를 실행해서 global_func_exe_times 전역 변수를 +1만큼 증감합니다. 그 결과는 당연히 112라고 예상할 수 있습니다. 여기서 의문이 생깁니다.

CPU3에서 실행 중인 CompositorTileW-3064 프로세스가 global_func_exe_times 전역 변수를 111로 출력하고 바로 +1만큼 증감했는데, CPU0에서 구동 중인 GpuMemoryThread-3061 프로세스는 global_func_exe_times 값을 111로 출력한다. 뭔가 이상하지 않나?

맞습니다. 3번째 줄 ftrace 로그를 보면 뭔가 이상합니다.
3 GpuMemoryThread-3061 [000] ....  1396.127141: do_exit: [+] comm: GpuMemoryThread, pid: 3061, global_func_exe_times: 111

CPU0에서 구동 중인 Pid가 3061인 GpuMemoryThread 프로세스가 실행할 때 global_func_exe_times 전역 변수는 112이어야 합니다. CPU0에서 구동 중인 CompositorTileW 프로세스가 global_func_exe_times 전역변수를 +1만큼 증감했기 때문입니다. 여기서 다시 의문이 생깁니다.

Pid가 3061인 GpuMemoryThread 프로세스가 global_func_exe_times 값을 111로 출력하는 이유는 뭘까?

CPU3에서 실행 중인 CompositorTileW 프로세스(pid: 3064)가 global_func_exe_times 값을 111을 출력하고 +1을 증감하려는 사이 CPU0에서 구동 중인 GpuMemoryThread 프로세스가 do_exit() 함수에 접근해서 global_func_exe_times 전역 변수를 출력했기 때문입니다.

CPU3에서 구동 중인 CompositorTileW 프로세스(pid: 3064)와 CPU0에서 돌던 GpuMemoryThread(pid: 3061) 프로세스가 거의 동시에 do_exit() 함수 6~24번째 줄 코드에 접근한 겁니다.

do_exit() 함수에 여러 프로세스가 접근한 두 개 CPU 실행 흐름을 그림으로 표현하면 다음과 같습니다.  

시간 순서대로 CPU3와 CPU0가 실행한 순서를 알아봅시다.
 
[1] 실행 - CPU3
1396.127136초에 CPU3에서 구동 중인 CompositorTileW-3064 프로세스가 6번째 줄 코드를 실행합니다. global_func_exe_times 전역변수를 111로 출력합니다. 이후 8번째 줄 코드를 실행해서 global_func_exe_times 전역 변수를 +1만큼 증감할 겁니다.

[2] 실행 - CPU0
1396.127141초에 CPU0에서 구동 중인 GpuMemoryThread-3061 프로세스가 6번째 줄 코드 실행으로 global_func_exe_times 전역변수를 111로 출력합니다. CPU3에서 6번째 줄 코드를 실행하고 8번째 줄 코드를 실행하기 직전에 6번째 줄 코드를 실행한 겁니다.
 
[3] 실행 - CPU3
정확한 타임스탬프를 예측하기 어려우나 CPU3에서 global_func_exe_times 전역 변수를 +1만큼 증감했습니다.

[4] - CPU0
마찬가지입니다. CPU0에서 global_func_exe_times 전역 변수를 +1만큼 증감했습니다.

이번에는 CPU3에서 돌던 CompositorTileW-3064 프로세스의 함수 실행 흐름과 CPU0에서 구동 중인 GpuMemoryThread-3061 프로세스 콜스택을 봅시다.
5 CompositorTileW-3064  [003] ....  1396.127169: <stack trace>
6 => get_signal+0x35c/0x69c 
7 => do_signal+0x74/0x3d4 
8 => do_work_pending+0xb4/0xcc  
9 => slow_work_pending+0xc/0x20  
10 GpuMemoryThread-3061  [000] ....  1396.127170: <stack trace>
11 => get_signal+0x35c/0x69c 
12 => do_signal+0x74/0x3d4  
13 => do_work_pending+0xb4/0xcc  
14 => slow_work_pending+0xc/0x20 
조금 더 알아보기
유저 공간에서 프로세스가 동작 중에 인터럽트가 발생하면 __irq_usr이란 인터럽트 벡터를 실행합니다.
1  NSR:80789280|__irq_usr:  sub     r13,r13,#0x48    ; r13,r13,#72
2  NSR:80789284|            stmib   r13,{r1-r12}
3  NSR:80789288|     mrc     p15,0x0,r7,c1,c0,0x0   ; p15,0,r7,c1,c0,0 (system control)
4  NSR:8078928C|            ldr     r8,0x80789160
5  NSR:80789290|            ldm     r0,{r3-r5}
6  NSR:80789294|            add     r0,r13,#0x3C     ; r0,r13,#60
7  NSR:80789298|            mvn     r6,#0x0          ; r6,#0
8  NSR:8078929C|            str     r3,[r13]
9  NSR:807892A0|            ldr     r8,[r8]
10 NSR:807892A4|            stm     r0,{r4-r6}
11 NSR:807892A8|            stmdb   r0,{r13-r14}^
12 NSR:807892AC|            teq     r8,r7
13 NSR:807892B0|     mcrne   p15,0x0,r8,c1,c0,0x0   ; p15,0,r8,c1,c0,0 (system control)
14 NSR:807892B4|            mov     r11,#0x0         ; r11,#0
15 NSR:807892B8|            bl      0x801E9E1C       ; trace_hardirqs_off
16 NSR:807892BC|            ldr     r1,0x807892DC
17 NSR:807892C0|            cpy     r0,r13
18 NSR:807892C4|            adr     r14,0x807892CC
19 NSR:807892C8|            ldr     pc,[r1]
20 NSR:807892CC|            lsr     r9,r13,#0x0D
21 NSR:807892D0|            lsl     r9,r9,#0x0D
22 NSR:807892D4|            mov     r8,#0x0          ; r8,#0
23 NSR:807892D8|            b       0x80107E6C       ; ret_to_user_from_irq

19번째 코드에서 인터럽트를 처리하는 함수들을 호출한 다음 ret_to_user_from_irq() 함수를 호출합니다. ret_to_user_from_irq() 함수에서 slow_work_pending() 함수를 호출하는데 slow_work_pending() 함수에서 유저 공간에서 설정한 시그널 처리를 해야 할 상태인지 점검합니다.
NSR:80107E6C|ret_to_user_from_irq:   ldr     r2,[r9,#0x8]
NSR:80107E70|                        cmp     r2,#0x7F000000   ; r2,#2130706432
NSR:80107E74|                        blne    0x8010B5FC       ; addr_limit_check_failed
NSR:80107E78|                        ldr     r1,[r9]
NSR:80107E7C|                        tst     r1,#0x0F         ; r1,#15
NSR:80107E80|                        bne     0x80107E48       ; slow_work_pending

동작 순서를 정리하면 다음과 같습니다.
유저 공간 프로세스 실행 중 -> 인터럽트 발생 -> _irq_usr()이란 인터럽트 벡터 실행 -> 인터럽트 핸들러 실행 종료 -> 유저 공간에서 요청한 시그널 처리

콜스택이 동일합니다. 두 개의 프로세스를 종료하는 시그널을 전달받아 동시에 프로세스를 종료하는 상황입니다.

여기까지 코드를 분석했는데 몇 가지 의문점이 생기니 다시 Q&A 시간을 갖겠습니다.

실제 리눅스 커널 함수인 do_exit()에서는 이 코드 구간에 스핀락이나 뮤텍스를 써서 Critical Section을 보호하지 않는다. 그 이유는 무엇일까?

프로세스가 동시에 같은 함수에 접근할 때마다 반드시 락을 걸 필요는 없습니다. 대신 프로세스를 식별할 수 있는 유일한 디스크립터만 있으면 됩니다.

CPU3에서 돌던 CompositorTileW-3064 프로세스와 CPU0에서 구동 중인 GpuMemoryThread-3061은 각자 태스크 디스크립터(struct task_struct)가 있습니다. 
1 void __noreturn do_exit(long code)
2 {
3 struct task_struct *tsk = current;
4 int group_dead;
5
6 profile_task_exit(tsk);
7 kcov_task_exit(tsk);

do_exit() 함수를 잠깐 보면 3번째 줄에서 스택 주소에 접근해서 현재 실행 중인 프로세스 정보를 담고 있는 태스크 디스크립터에 접근합니다. 이 태스크 디스크립터로 프로세스를 종료하는 동작을 실행하는 겁니다.

CPU3에서 실행 중인 CompositorTileW 프로세스(pid: 3064)와 CPU0에서 구동 중인 GpuMemoryThread 프로세스는 각각 태스크 디스크립터를 갖고 있습니다.

따라서 동시에 같은 함수를 수행 중이라고 해도 각각 프로세스를 관리하는 태스크 디스크립터로 코드를 실행하면 구지 락을 걸 필요가 없습니다.

프로세스를 관리할 수 있는 유일한 메모리 혹은 자료구조는 무엇일까?

프로세스는 각자 서로 다른 스택 공간에서 실행합니다. CompositorTileW-3064와 GpuMemoryThread-3061 프로세스는 각각 서로 다른 스택 공간에서 코드를 실행합니다.

프로세스끼리 각자 실행 중인 스택 공간을 공유할 수 없습니다. 각자 독립적인 실행 공간입니다. 전역 변수를 지역 변수에 저장하고 지역 변수에서 쓰기나 읽기를 하는 코드로 레이스를 방지할 수도 있습니다. 지역 변수는 프로세스 각자 실행 중인 스택 메모리 공간을 할당해 씁니다.

그래서 레이스를 방지하기 위해 전역 변수값이나 공용 메모리값을 프로세스별로 유일하게 접근하는 스택 공간에 저장해서 처리하는 기법도 적용합니다.

커널 동기화 기법을 익힐 때 가장 중요한 점은 프로세스가 어떻게 실행하는지와 프로세스를 처리하는 자료구조를 알고 있어야 합니다.

다음에 커널 프로세스가 동작할 때 발생하는 레이스 컨디션에 대해서 확인하겠습니다.


"혹시 궁금한 점이 있으면 댓글로 질문 남겨주세요. 아는 한 성실히 답변 올려드리겠습니다!" 

Thanks,
Austin Kim(austindh.kim@gmail.com)

#Reference(커널 동기화)
커널 동기화 기본 개념 소개
레이스 발생 동작 확인
커널 동기화 기법 소개
스핀락
뮤텍스란
커널 동기화 디버깅



    핑백

    덧글

    댓글 입력 영역