Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

181162
807
85249


[리눅스커널] 동기화 - 커널 프로세스 레이스 컨디션 9장. 커널 동기화 소개

이번에 커널 공간에서만 실행하는 커널 쓰레드에서 발생하는 Race를 확인합니다. 커널 쓰레드 중 많이 알려진 워커 쓰레드를 예를 듭시다.

이를 위해 다음 패치 코드를 적용할 필요가 있습니다.
1 diff --git a/kernel/workqueue.c b/kernel/workqueue.c
2 --- a/kernel/workqueue.c
3 +++ b/kernel/workqueue.c
4 @@ -2187,6 +2187,12 @@ static void process_scheduled_works(struct worker *worker)
5  *
6  * Return: 0
7  */
8  +
9  +static unsigned int global_func_exe_times = 0;
10 +
11 +extern void trace_function_dummy_call(void);
12 +
13 static int worker_thread(void *__worker)
14 {
15  struct worker *worker = __worker;
16 @@ -2195,6 +2201,15 @@ static int worker_thread(void *__worker)
17  /* tell the scheduler that this is a workqueue worker */
18  worker->task->flags |= PF_WQ_WORKER;
19 woke_up:
20 + trace_printk("[+] comm: %s, pid: %d, global_w_func_exe_times: %d from(%pS) \n", 
21 + current->comm, current->pid, global_func_exe_times, (void *)__builtin_return_address(0));
22 +
23 + global_func_exe_times++;
24 +
25 + trace_function_dummy_call();
26 +
27  spin_lock_irq(&pool->lock);
28 
29  /* am I supposed to die? */
30 @@ -2255,6 +2270,11 @@ static int worker_thread(void *__worker)
31  } while (keep_working(pool));
32 
33  worker_set_flags(worker, WORKER_PREP);
34 +
35 + trace_printk("[-] comm: %s, pid: %d, global_w_func_exe_times: %d from(%pS) \n", 
36 + current->comm, current->pid, global_func_exe_times, (void *)__builtin_return_address(0));
37 +
38 sleep:
39  /*
40   * pool->lock is held and there's no work to process and no need to

원래 worker_thread() 함수 구현부는 다음과 같습니다.
1 static int worker_thread(void *__worker)
2 {
3 struct worker *worker = __worker;
4 struct worker_pool *pool = worker->pool;
5
6 /* tell the scheduler that this is a workqueue worker */
7 worker->task->flags |= PF_WQ_WORKER;
8 woke_up:
9 spin_lock_irq(&pool->lock);

위 커널 오리지널 8~9번째 줄 코드 사이에 +로 표시된 코드(20~26번째 줄 패치 코드)를 입력합니다.

이번에는 패치 코드에서 34~37번째 구간 작성 방법을 알아 봅시다. 
1 static int worker_thread(void *__worker)
2 {
...
3 } else {
4 move_linked_works(work, &worker->scheduled, NULL);
5 process_scheduled_works(worker);
6 }
7 } while (keep_working(pool));
8
9 worker_set_flags(worker, WORKER_PREP);
10 sleep:


위 커널 오리지널 코드 9~10번째 줄 코드 사이에 다음 코드를 입력하면 됩니다.
34 +
35 + trace_printk("[-] comm: %s, pid: %d, global_w_func_exe_times: %d from(%pS) \n", 
36 + current->comm, current->pid, global_func_exe_times, (void *)__builtin_return_address(0));

이 패치를 적용한 다음 커널 빌드 후 라즈베리파이에 설치하고 리부팅을 합시다. 패치 코드 내용은 이전 절에 다룬 내용과 같으니 생략합니다.

ftrace 로그를 설정 방법은 이전에 소개된 내용과 같습니다. trace_function_dummy_call() 함수에 set_filter를 겁시다. Race가 발생하는 ftrace 로그를 분석하기 전에 Race가 발생하지 않을 때 ftrace 로그를 봅시다.
1 kworker/3:1-3162  [003] ....  2048.385285: worker_thread: [+] comm: kworker/3:1, pid: 3162, global_func_exe_times: 34594 from(kthread+0x144/0x174) 
2 kworker/3:1-3162  [003] ....  2048.385287: trace_function_dummy_call: [++] comm:kworker/3:1, pid:3162, from(worker_thread+0x36c/0x6cc) 
3 kworker/3:1-3162  [003] ....  2048.385289: workqueue_execute_start: work struct ba383c8c: function lru_add_drain_per_cpu
4 kworker/3:1-3162  [003] ....  2048.385293: workqueue_execute_end: work struct ba383c8c
5 kworker/3:1-3162  [003] d...  2048.385296: worker_thread: [-] comm: kworker/3:1, pid: 3162, global_func_exe_times: 34595 from(kthread+0x144/0x174) 
첫 번째 줄 로그를 보면 global_func_exe_times이란 전역 변수가 34594임을 알 수 있습니다. pid가 3162인 kworker/3:1이란 프로세스가 실행 중입니다.

3~4번째 줄 로그는 worker_thread() 함수에서 호출한 process_one_work() 함수에서 출력하는 워크 실행 정보입니다. 워크 핸들러가 lru_add_drain_per_cpu() 함수입니다.
이전에 워크큐에 대한 글을 읽었으면 이해할 수 있는 ftrace 로그입니다.

이번에는 5번째 줄 로그를 봅시다. global_func_exe_times이란 전역 변수를 +1만큼 증감했으니 34595가 됩니다.
패치 코드 구간에 한 개의 CPU3에서 kworker/3:1 프로세스만 실행했습니다.

이번에 Race가 발생하는 로그를 봅시다.
1  kworker/3:1-3162  [003] ....  2048.406656: worker_thread: [+] comm: kworker/3:1, pid: 3162, global_func_exe_times: 34602 from(kthread+0x144/0x174) 
2 kworker/1:2-1376  [001] ....  2048.406660: worker_thread: [+] comm: kworker/1:2, pid: 1376, global_w_func_exe_times: 34602 from(kthread+0x144/0x174) 
3 kworker/3:1-3162  [003] ....  2048.406661: trace_function_dummy_call+0x0/0x58 <8067196c>: [++] comm:kworker/3:1, pid:3162, from(worker_thread+0x36c/0x6cc) 
4 kworker/1:2-1376  [001] ....  2048.406663: trace_function_dummy_call+0x0/0x58 <8067196c>: [++] comm:kworker/1:2, pid:1376, from(worker_thread+0x36c/0x6cc) 
5 kworker/1:2-1376  [001] ....  2048.406668: workqueue_execute_start: work struct ba361b18: function drain_local_pages_wq
6 kworker/3:1-3162  [003] ....  2048.406668: workqueue_execute_start: work struct ba383b18: function drain_local_pages_wq
7 kworker/3:1-3162  [003] ....  2048.406688: workqueue_execute_end: work struct ba383b18
8 kworker/3:1-3162  [003] d...  2048.406692: worker_thread+0x370/0x6cc <80138730>: [-] comm: kworker/3:1, pid: 3162, global_w_func_exe_times: 34604 from(kthread+0x144/0x174) 
9  kworker/1:2-1376  [001] ....  2048.406720: workqueue_execute_end: work struct ba361b18
10 kworker/1:2-1376  [001] ....  2048.406726: workqueue_execute_start: work struct 958a5ab4: function wq_barrier_func
11 kworker/1:2-1376  [001] ....  2048.406730: workqueue_execute_end: work struct 958a5ab4
12 kworker/1:2-1376  [001] d...  2048.406732: worker_thread+0x370/0x6cc <80138730>: [-] comm: kworker/1:2, pid: 1376, global_w_func_exe_times: 34604 from(kthread+0x144/0x174)

첫 번째 줄 로그를 보겠습니다.
2048.406656초에 CPU3에서 구동 중인 kworker/3:1 프로세스가 실행해서 global_func_exe_times이란 전역 변숫값인 34602를 출력합니다.

2번째 줄 로그를 분석할 차례입니다.
2048.406660초에 CPU0에서 구동 중인 kworker/1:2 프로세스가 global_func_exe_times이란 전역 변수를 출력하는데 값은 34602입니다.

패치 코드를 보면 20번 줄 ftrace 메시지를 출력하고 바로 global_func_exe_times 전역 변수를 +1만큼 증감합니다.
20 + trace_printk("[+] comm: %s, pid: %d, global_func_exe_times: %d from(%pS) \n", 
21 + current->comm, current->pid, global_func_exe_times, (void *)__builtin_return_address(0));
22 +
23 + global_func_exe_times++;

CPU3에서 20번째 줄 코드를 실행한 후 23번째 줄 코드와 같이 global_func_exe_times 전역 변수를 +1만큼 증감하기 직전 CPU0에서 돌던 kworker/1:2 프로세스가 20번 코드를 실행한 겁니다.

다음 3번째 줄 로그입니다.
3 kworker/3:1-3162  [003] ....  2048.406661: trace_function_dummy_call: [++] comm:kworker/3:1, pid:3162, from(worker_thread+0x36c/0x6cc) 

CPU3 kworker/3:1 프로세스가 2048.406661초에 trace_function_dummy_call() 함수를 실행합니다.

4번째 줄 로그를 보겠습니다.
4 kworker/1:2-1376  [001] ....  2048.406663: trace_function_dummy_call: [++] comm:kworker/1:2, pid:1376, from(worker_thread+0x36c/0x6cc) 

CPU1에서 2048.406663초에 trace_function_dummy_call() 함수를 실행합니다.
3 kworker/3:1-3162  [003] ....  2048.406661: trace_function_dummy_call: [++] comm:kworker/3:1, pid:3162, from(worker_thread+0x36c/0x6cc) 

CPU3에서 2048.406661초에 trace_function_dummy_call() 함수를 실행합니다. 두 개의 CPU가 번갈아 가면서 함수를 지그재그로 실행하고 있습니다.

5~6번째 줄 로그를 보겠습니다.
5 kworker/1:2-1376  [001] ....  2048.406668: workqueue_execute_start: work struct ba361b18: function drain_local_pages_wq
6 kworker/3:1-3162  [003] ....  2048.406668: workqueue_execute_start: work struct ba383b18: function drain_local_pages_wq
7 kworker/3:1-3162  [003] ....  2048.406688: workqueue_execute_end: work struct ba383b18
8 kworker/3:1-3162  [003] d...  2048.406692: worker_thread: [-] comm: kworker/3:1, pid: 3162, global_func_exe_times: 34604 from(kthread+0x144/0x174) 
9  kworker/1:2-1376  [001] ....  2048.406720: workqueue_execute_end: work struct ba361b18
CPU1에서 구동 중인 kworker/1:2 프로세스와 CPU3에서 실행 중인 kworker/3:1 프로세스가 2048.406668이란 시각에 동시에 ba361b18주소에 있는 워크를 실행합니다.

7~8번째 줄 로그를 보면 CPU3에서 ba361b18이란 워크 실행을 마치고 global_func_exe_times 전역 변수를 34604으로 출력합니다.

CPU3 입장에서 global_func_exe_times 변수를 +1만큼 증감하기 전 값은 34602였습니다.
1  kworker/3:1-3162  [003] ....  2048.406656: worker_thread: [+] comm: kworker/3:1, pid: 3162, global_func_exe_times: 34602 from(kthread+0x144/0x174) 

이번에 입력한 패치 코드는 커널 공간에서 수행 중인 프로세스가 겪는 Race를 확인하기 위해 입력한 겁니다.
다음 함수를 커널 동기화 관점으로 분석해 봅시다.
1 static int worker_thread(void *__worker)
2 {
3 struct worker *worker = __worker;
4 struct worker_pool *pool = worker->pool;
5
6 worker->task->flags |= PF_WQ_WORKER;
7 woke_up:
8 spin_lock_irq(&pool->lock);
9
10 /* am I supposed to die? */
11 if (unlikely(worker->flags & WORKER_DIE)) {
12 spin_unlock_irq(&pool->lock);
13 WARN_ON_ONCE(!list_empty(&worker->entry));
14 worker->task->flags &= ~PF_WQ_WORKER;
15
16 set_task_comm(worker->task, "kworker/dying");
17 ida_simple_remove(&pool->worker_ida, worker->id);
18 worker_detach_from_pool(worker, pool);
19 kfree(worker);
20 return 0;
21 }
22
23 worker_leave_idle(worker);

8번째 줄 코드에서 spin_lock_irq(&pool->lock); 함수를 호출해서 스핀락을 걸고 있습니다.
워커 쓰레드에서 워크를 실행할 때 워커 풀에 등록된 워크를 실행하기 때문에 위와 같이 워커풀에 있는 락을 걸어준 겁니다.

 코드 분석 전에 worker_thread() 함수는 워커 쓰레드가 실행하면 구동하는 핸들 함수이라는 점을 상기합시다. 즉 여러 워커 쓰레드가 이 함수에서 동시에 실행할 수 있다는 이야기입니다. 

코드를 분석하니 여러 가지 의문이 생깁니다. 다시 Q&A 시간입니다.

이전에 프로세스만의 유일한 메모리나 자료구조를 활용하면 락을 걸 필요가 없다고 했다. 위 코드에서 관련 자료구조는 무엇일까?

반복하지만 worker_thread() 함수는 워커 쓰레드만 실행하는 쓰레드 핸들 함수입니다. 
1 static int worker_thread(void *__worker)
2 {
3 struct worker *worker = __worker;

커널 쓰레드는 쓰레드를 처리할 수 있는 매개변수(디스크립터)를 첫 번째 인자로 전달합니다.
void 포인터 형태인 __worker 인자는 3번째 줄 코드와 같이 struct worker 구조체로 캐스팅됩니다.

이 __worker 인자가 워커 쓰레드를 식별하는 주소를 담고 있습니다.
워커 쓰레드를 표현하는 자료구조는 struct worker인데 worker_thread() 함수에서 전달하는 __worker 인자로 유일한 주소를 전달한다는 겁니다.

kworker/1:2-1376와 kworker/3:1-3162 프로세스는 유일한 struct worker 구조체 주소로 처리한다는 겁니다.

그래서 다음 11~23번째 줄 코드에서 worker 포인터 변수로 워커 쓰레드를 종료하는 동작을 실행합니다.
11 if (unlikely(worker->flags & WORKER_DIE)) {
12
13 WARN_ON_ONCE(!list_empty(&worker->entry));
14 worker->task->flags &= ~PF_WQ_WORKER;
15
16 set_task_comm(worker->task, "kworker/dying");
17 ida_simple_remove(&pool->worker_ida, worker->id);
18 worker_detach_from_pool(worker, pool);
19 kfree(worker);
20 return 0;
21 }
22
23 worker_leave_idle(worker);

worker 이란 포인터는 워커 쓰레드마다 있는 주소입니다. 여기서 의문이 생깁니다.

이전 절에서 프로세스를 관리할 수 있는 유일한 메모리 혹은 자료구조는 태스크 디스크립터라고 설명했다. 위 경우는 다른가?

아닙니다. 어떤 코드를 실행할 때도 태스크를 처리할 수 있는 유니크한 자료구조는 태스크 디스크립터입니다. 그런데 커널 쓰레드나 인터럽트 디스크립터의 경우 해당 프로세스 실행 용도에 따른 자료구조(구조체)가 있기 마련입니다. 모든 실행을 태스크 디스크립터로 관리하면 태스크 디스크립터 멤버를 추가하거나 불필요한 코드 실행을 해야 합니다.

이번에 프로세스에서 Race 발생 상황을 확인했습니다. 다음에는 어떤 함수가 실행 중 인터럽트가 발생해서 다시 같은 함수가 실행하는 상황을 확인해 보겠습니다.


#Reference 시스템 콜


Reference(워크큐)
워크큐(Workqueue) Overview


덧글

댓글 입력 영역