Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

180162
807
85248


[라즈베리파이] 동기화 - 인터럽트 발생으로 레이스 컨디션 발생 9장. 커널 동기화 소개

이번에는 인터럽트 발생으로 Race가 발생하는 경우를 알아보겠습니다. 
그동안 어떤 함수도 인터럽트가 발생하면 실행을 멈추고 인터럽트 벡터로 프로그램 카운터를 이동하고 인터럽트 핸들러와 서브 루틴을 실행합니다.

그런데 인터럽트 발생하기 전에 실행을 멈춘 함수가 인터럽트가 발생해서 다시 실행할 수 있습니다. 이를 확인하기 위해 다음 패치 코드를 입력합시다.
diff --git a/mm/slub.c b/mm/slub.c
--- a/mm/slub.c
+++ b/mm/slub.c
@@ -3740,10 +3740,42 @@ static int __init setup_slub_min_objects(char *str)
 
 __setup("slub_min_objects=", setup_slub_min_objects);
 
1  +extern uint32_t raspbian_debug_state; 
2  +
3  +void trace_race_dummy_call(void)
4  +{
5  + void *stack;
6  + struct thread_info *current_thread;
7  +
8  + stack = current->stack;
9  + current_thread = (struct thread_info*)stack;
10 +
11 + trace_printk("[++] comm:%s, pid:%d, in_interrupt(): 0x%08x,preempt_count = 0x%08x \n", 
12 + current->comm, current->pid, (unsigned int)in_interrupt(), (unsigned int)current_thread->preempt_count);
13 +}
14 +
15 void *__kmalloc(size_t size, gfp_t flags)
16 {
17  struct kmem_cache *s;
18  void *ret;
19 +
20 + if ( raspbian_debug_state == 5088) {
21 + trace_printk("[+] comm: %s, pid: %d, kmalloc_times: %d from(%pS) \n", 
22 + current->comm, current->pid, kmalloc_execute_times, (void *)__builtin_return_address(0));
23 +
24 + kmalloc_execute_times++;
25 +
26 + if ( in_interrupt()) {
27 + trace_race_dummy_call();
28 + }
29 + }
30 
31  if (unlikely(size > KMALLOC_MAX_CACHE_SIZE))
32  return kmalloc_large(size, flags);
@@ -3758,7 +3790,12 @@ void *__kmalloc(size_t size, gfp_t flags)
33  trace_kmalloc(_RET_IP_, ret, size, s->size, flags);
34 
35  kasan_kmalloc(s, ret, size, flags);
36 -
37 +
38 + if ( raspbian_debug_state == 5088) {
39 + trace_printk("[-] comm: %s, pid: %d, kmalloc_times: %d from(%pS) \n", 
40 + current->comm, current->pid, kmalloc_execute_times, (void *)__builtin_return_address(0));
41 + }
42 +
43  return ret;
44 }
45 EXPORT_SYMBOL(__kmalloc);

다음 코드와 같이 커널에서 동적 메모리 할당 요청을 하려면 11번째 줄 코드와 같이 kmalloc() 함수를 호출해야 합니다.
[https://elixir.bootlin.com/linux/v4.14.43/source/crypto/cipher.c#L33]
1 static int setkey_unaligned(struct crypto_tfm *tfm, const u8 *key,
2     unsigned int keylen)
3 {
4 struct cipher_alg *cia = &tfm->__crt_alg->cra_cipher;
5 unsigned long alignmask = crypto_tfm_alg_alignmask(tfm);
6 int ret;
7 u8 *buffer, *alignbuffer;
8 unsigned long absize;
9
10 absize = keylen + alignmask;
11 buffer = kmalloc(absize, GFP_ATOMIC);
kmalloc() 함수 구현부를 보면 실제 메모리 할당은 다음 8번째 줄 코드와 같이 __kmalloc() 함수에서 실행한다는 사실을 알 수 있습니다.
1 static __always_inline void *kmalloc(size_t size, gfp_t flags)
2 {
3 if (__builtin_constant_p(size)) {
4 if (size > KMALLOC_MAX_CACHE_SIZE)
5 return kmalloc_large(size, flags);
...
6 }
7 return __kmalloc(size, flags);
8}

패치 코드 작성 방법은 간단합니다. 

다음과 같이 원래 __kmalloc() 함수 기준으로 05~06번째 줄 사이에 패치 코드 19~29번째 줄 코드를 입력합니다.
01 void *__kmalloc(size_t size, gfp_t flags)
02 {
03 struct kmem_cache *s;
04 void *ret;
05
06 if (unlikely(size > KMALLOC_MAX_CACHE_SIZE))
07 return kmalloc_large(size, flags);
08
09 s = kmalloc_slab(size, flags);
10
11 if (unlikely(ZERO_OR_NULL_PTR(s)))
12 return s;
13
14 ret = slab_alloc(s, flags, _RET_IP_);
15
16 trace_kmalloc(_RET_IP_, ret, size, s->size, flags);
17
18 kasan_kmalloc(s, ret, size, flags);
19
20 return ret;
21}
22 EXPORT_SYMBOL(__kmalloc);

__kmalloc() 함수 윗부분에 trace_race_dummy_call() 함수 구현부를 입력하고,
원래 __kmalloc() 함수 기준으로 19~20번째 줄 코드 사이에 패치 코드 38~42번째 줄 코드를 입력합니다.

위와 같이 코드를 입력한 다음에 커널 빌드 후 라즈비안에 커널 이미지를 설치합시다.

다음은 Race 발생 시 ftrace로그입니다. 이전 절에 다룬 로그보다 조금 난해한 내용이니 더 집중하면서 봅시다.
1 TaskSchedulerFo-1796  [000] dns.  4183.573504: __kmalloc+0x2bc/0x3c0: [+] comm: TaskSchedulerFo, pid: 1796, kmalloc_times: 131380 from(__DWC_ALLOC_ATOMIC+0x24/0x28) 
2 TaskSchedulerFo-1796  [000] dns.  4183.573504: trace_race_dummy_call+0x14/0x70 <-__kmalloc+0x348/0x3c0
3 TaskSchedulerFo-1796  [000] dns.  4183.573504: <stack trace>
4  => dwc_otg_hcd_qtd_create+0x2c/0x60
5  => dwc_otg_hcd_urb_enqueue+0x58/0x208
6  => dwc_otg_urb_enqueue+0x1fc/0x31c
7  => usb_hcd_submit_urb+0xc8/0x934
8  => usb_submit_urb+0x284/0x510
9  => hid_irq_in+0x74/0x230
10 => __usb_hcd_giveback_urb+0xa4/0x15c
11 => usb_hcd_giveback_urb+0x4c/0xfc
12 => completion_tasklet_func+0x80/0xac
13 => tasklet_callback+0x20/0x24
14 => tasklet_hi_action+0x70/0x104
15 => __do_softirq+0x174/0x3d8
16 => irq_exit+0xe4/0x140
17 => __handle_domain_irq+0x70/0xc4
18 => bcm2836_arm_irqchip_handle_irq+0xac/0xb0
19 => __irq_svc+0x5c/0x7c
20 => __rb_reserve_next+0xc4/0x1a0
21 => __rb_reserve_next+0xc4/0x1a0
22 => ring_buffer_lock_reserve+0x154/0x4a0
23 => trace_vbprintk+0x168/0x2a8
24 => __trace_bprintk+0x44/0x58
25 => __kmalloc+0x30c/0x3c0
26 => ext4_ext_remove_space+0x98c/0x143c
27 => ext4_ext_truncate+0xa8/0xac
28 => ext4_truncate+0x370/0x458
29 => ext4_setattr+0x310/0x9d0
30 => notify_change+0x270/0x3fc
31 => do_truncate+0x90/0xb4
32 => do_sys_ftruncate+0x12c/0x1c0
33 => SyS_ftruncate64+0x24/0x2c
34 => ret_fast_syscall+0x0/0x28
35 TaskSchedulerFo-1796  [000] dns.  4183.573504: trace_race_dummy_call+0x0/0x70: [++] comm:TaskSchedulerFo, pid:1796, in_interrupt(): 0x00000100,preempt_count = 0x00000100 
36 TaskSchedulerFo-1796  [000] dns.  4183.573504: __kmalloc+0x25c/0x3c0: [-] comm: TaskSchedulerFo, pid: 1796, kmalloc_times: 131381 from(__DWC_ALLOC_ATOMIC+0x24/0x28) 
37 TaskSchedulerFo-1796  [000] ....  4183.573765: __kmalloc+0x25c/0x3c0: [-] comm: TaskSchedulerFo, pid: 1796, kmalloc_times: 131382 from(ext4_ext_remove_space+0x98c/0x143c)

첫 번째 로그입니다.
1 TaskSchedulerFo-1796  [000] dns.  4183.573504: __kmalloc+0x2bc/0x3c0: [+] comm: TaskSchedulerFo, pid: 1796, kmalloc_times: 131380 from(__DWC_ALLOC_ATOMIC+0x24/0x28) 

__kmalloc() 함수에서 kmalloc_execute_times이란 전역 변수 값인 131380을 출력합니다.  4183.573504이란 타임스탬프 정보 옆에 dns. 란 문자열이 보입니다. 이 중 s가 있는데 이는 Soft IRQ Content에서 이 함수가 호출됐다는 정보입니다.

인터럽트가 발생한 후 인터럽트 핸들러를 처리한 다음 Soft IRQ 서비스를 실행할 때 이 __kmalloc() 함수를 실행하는 동작입니다.

2~35번째 줄 로그는 __kmalloc() 함수가 호출될 때 콜스택입니다. 
이 중에 2번째 줄 로그를 보면 역시 dns 정보로 Soft IRQ Context란 점을 알 수 있습니다.
2 TaskSchedulerFo-1796  [000] dns.  4183.573504: trace_race_dummy_call+0x14/0x70 <-__kmalloc+0x348/0x3c0

콜스택에서 중요한 디버깅 정보만 추려서 봅시다.
trace_race_dummy_call+0x14/0x70
__kmalloc+0x348/0x3c0
4  => dwc_otg_hcd_qtd_create+0x2c/0x60
...
12 => completion_tasklet_func+0x80/0xac
13 => tasklet_callback+0x20/0x24
14 => tasklet_hi_action+0x70/0x104
15 => __do_softirq+0x174/0x3d8
16 => irq_exit+0xe4/0x140
17 => __handle_domain_irq+0x70/0xc4
18 => bcm2836_arm_irqchip_handle_irq+0xac/0xb0
19 => __irq_svc+0x5c/0x7c
20 => __rb_reserve_next+0xc4/0x1a0
21 => __rb_reserve_next+0xc4/0x1a0
22 => ring_buffer_lock_reserve+0x154/0x4a0
23 => trace_vbprintk+0x168/0x2a8
24 => __trace_bprintk+0x44/0x58
25 => __kmalloc+0x30c/0x3c0
26 => ext4_ext_remove_space+0x98c/0x143c
...
32 => do_sys_ftruncate+0x12c/0x1c0
33 => SyS_ftruncate64+0x24/0x2c
34 => ret_fast_syscall+0x0/0x28

함수 호출 순서는 34번째 줄에서4번째 줄 방향입니다.

ext4_ext_remove_space() 함수에서 __kmalloc() 함수를 호출해서 메모리를 할당하고 
24~20번째 줄 로그와 같이 ftrace 로그를 처리(ring buffer) 중에 인터럽트가 발생한 겁니다. 여기서 다시 여러 의문이 생깁니다.

인터럽트가 발생했다고 어떻게 판단할 수 있을까?

19번 줄 로그를 보면 인터럽트 벡터인 __irq_svc 심볼이 보이니 인터럽트가 발생했음을 알 수 있습니다. 이후 tasklet 핸들러인 completion_tasklet_func() 함수가 실행한 이후 dwc_otg_hcd_qtd_create() 함수에서 _kmalloc() 함수를 호출한 겁니다.

이번에는 35번째 줄 로그를 보겠습니다.
35 TaskSchedulerFo-1796  [000] dns.  4183.573504: trace_race_dummy_call+0x0/0x70: [++] comm:TaskSchedulerFo, pid:1796, in_interrupt(): 0x00000100,preempt_count = 0x00000100 

이 함수는 인터럽트 컨택스트에서만 실행하는데 이때 struct thread_info.preempt_count가 0x00000100입니다.

struct thread_info.preempt_count가 0x00000100이라면 무슨 의미일까?

Soft IRQ Context에서는 struct thread_info.preempt_count에 0x100을 저장합니다.
SOFTIRQ_MASK 매크로는 다음 연산으로 0x100입니다.
#define SOFTIRQ_MASK (__IRQ_MASK(SOFTIRQ_BITS) << SOFTIRQ_SHIFT)

36번째 줄 로그를 보겠습니다.
36 TaskSchedulerFo-1796  [000] dns.  4183.573504: __kmalloc+0x25c/0x3c0: [-] comm: TaskSchedulerFo, pid: 1796, kmalloc_times: 131381 from(__DWC_ALLOC_ATOMIC+0x24/0x28) 

__kmalloc() 함수 가장 아랫부분에 추가된 ftrace 로그가 실행하면서 출력하는 로그입니다. kmalloc_execute_times 전역 변수를 +1만큼 증감한 131381을 출력합니다.
타임스탬프 옆에 dns 가 보이니 Soft IRQ Context임을 알 수 있습니다.

이제 마지막 로그를 봅시다.
37 TaskSchedulerFo-1796  [000] ....  4183.573765: __kmalloc+0x25c/0x3c0: [-] comm: TaskSchedulerFo, pid: 1796, kmalloc_times: 131382 from(ext4_ext_remove_space+0x98c/0x143c)

가장 오른쪽 메시지를 보면 이 함수를 호출한 함수는 ext4_ext_remove_space()임을 알 수 있습니다. 또한 36번째 줄 로그에 있는 dns. 란 기호가 없습니다. 프로세스 컨택스트이기 때문입니다.

다른 관점으로 위 ftrace 로그가 실행된 상황을 생각해 봅시다.
15 void *__kmalloc(size_t size, gfp_t flags)
16 {
17  struct kmem_cache *s;
18  void *ret;
19 +
20 + if ( raspbian_debug_state == 5088) {
21 + trace_printk("[+] comm: %s, pid: %d, kmalloc_times: %d from(%pS) \n", 
22 + current->comm, current->pid, kmalloc_execute_times, (void *)__builtin_return_address(0));
23 +
24 + kmalloc_execute_times++;
25 +
26 + if ( in_interrupt()) {
27 + trace_race_dummy_call();
28 + }
29 + }

프로세스 컨택스트에서 kmalloc() 함수 21번째 줄 코드를 실행하는 도중 인터럽트가 발생한 후 Soft IRQ 컨택스트에서 다시 kmalloc() 함수를 호출한 겁니다.

분석한 로그를 그림으로 정리하면 다음과 같습니다.
 
[그림] __kmalloc() 함수 실행 도중 인터럽트 발생 흐름도

[1] 단계
ex4_ext_remove_space() 이란 함수에서 __kmalloc() 함수 호출로 커널 메모리 할당을 시도합니다.
__kmalloc() 함수에서 __trace_bprintk() 함수를 호출해서 ftrace 로그로 kmalloc_execute_times 전역 변수를 출력하려는 과정에서 인터럽트가 발생했습니다.

[2] 단계
인터럽트가 발생한 후 Soft IRQ 컨텍스트에서 태스크릿이 실행하는 함수 흐름입니다.
dwc_otg_hcd_qtd_create() 함수에서 다시 __kmalloc() 함수를 호출합니다.

[3] 단계
Soft IRQ 컨택스트에서 kmalloc_execute_times 전역 변수를 출력합니다.

인터럽트와 Soft IRQ 처리가 끝났으니 인터럽트 발생으로 실행을 멈춘 __kmalloc() 함수를 다시 실행합니다.
인터럽트 발생 직전 ftrace 로그로 kmalloc_execute_times 전역 변수를 출력하려는 도중이었습니다.

다음과 같은 ftrace 로그를 출력합니다.
37 TaskSchedulerFo-1796  [000] ....  4183.573765: __kmalloc+0x25c/0x3c0: [-] comm: TaskSchedulerFo, pid: 1796, kmalloc_times: 131382 from(ext4_ext_remove_space+0x98c/0x143c)

다시 Q&A 시간을 갖겠습니다.

이전 소절에서는 같은 함수를 다른 CPU에서 구동 중인 2개의 프로세스가 접근하는 Race를 확인했는데 이전에 살펴본 Race와 어떤 차이가 있을까?

이번 소절에서는 함수 실행 도중 인터럽트가 발생해서 다시 같은 함수를 실행하는 동작입니다.
다른 CPU에서 실행 중인 프로세스가 같은 함수에 접근하는 것이 아닙니다. SMP를 적용해서 발생하는 Race가 아니라는 겁니다.

리눅스 커널 코드에서 이렇게 같은 함수 실행 도중 인터럽트가 발생해서 다시 실행하는 것을 어떻게 방지할까?

kmalloc() 으로 동적 메모리 할당을 하면 리눅스 커널 메모리 관리 루틴에서 메모리 할당 사이즈에 따라 슬럽 캐시로 관리합니다. 해당 코드에서 슬럽 오브젝트를 현재 실행 중인 프로세스가 실행 중인 스택을 써서 처리합니다.

이렇게 해도 인터럽트가 발생해서 커널 동기화 문제를 일으키면 어떻게 해야 할까?

여러 프로세스가 접근하는 임계영역에 인터럽트 발생하리라 판단하면 spin_lock_irq()와 spin_unlock_irq() 함수를 써서 임계영역을 보호합니다.

여기까지 라즈베리파이에서 Race가 발생하는 실습을 해봤습니다. 아직 실무 프로젝트를 진행하지 않은 분들은 체감하기 어려울 수도 있지만 꾸준히 ftrace 로그를 보면서 체득하는 과정을 겪을 필요가 있습니다. 

다음 시간에는 커널 동기화 기법인 스핀락, 뮤텍스와 percpu 기법을 소개합니다.


#Reference 시스템 콜


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



덧글

댓글 입력 영역