Linux Kernel(4.19) Hacks

rousalome.egloos.com

포토로그 Kernel Crash


통계 위젯 (화이트)

230224
1178
109352


[리눅스커널] 메모리관리/디버깅: ftrace로 메모리 할당 해제 확인하기 14. Memory Management

ftrace에서 지원하는 kmalloc와 kfree 이벤트를 사용하면 kmalloc()와 kfree() 함수를 호출할 때 세부 정보를 알 수 있습니다.
kmalloc 이벤트: kmalloc() 함수로 메모리 할당을 요청했을때 동작 
kfree 이벤트: 할당한 메모리를 해제했하는 동작 

kmalloc와 kfree 이벤트 소개하기

그러면 kmalloc와 kfree 이벤트를 켜서 ftrace를 받으면 어떤 패턴의 메시지를 볼 수 있을까요? 다음 로그를 같이 보겠습니다.  
[https://elinux.org/Kernel_dynamic_memory_analysis]
1 init-1[000] .N..0.170000: kmalloc: call_site=c104deff ptr=c147dd20 bytes_req=29 bytes_alloc=32 gfp_flags=GFP_KERNEL
2 init-1[000] .N..0.170000: kmalloc: call_site=c104e2ac ptr=c147dd00 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL
3 init-1[000] .N..0.170000: kmalloc: call_site=c104deff ptr=c147dce0 bytes_req=22 bytes_alloc=32 gfp_flags=GFP_KERNEL
4 init-1[000] .N..0.170000: kfree: call_site=c10bfa4a ptr=  (null)

1 번째 kmalloc 이벤트 ftrace 메시지를 분석하겠습니다. 
1 init-1[000] .N..0.170000: kmalloc: call_site=c104deff ptr=c147dd20 bytes_req=29 bytes_alloc=32 gfp_flags=GFP_KERNEL

1번째 줄에서 보이는 세부 디버깅 정보는 다음과 같습니다.
kmalloc : 커널 메모리 할당 동작
call_site=c104deff : kmalloc() 함수를 호출한 함수 주소
ptr=c147dd20 : 할당 받은 메모리 주소
bytes_req=29 : 메모리 할당을 요청한 바이트(29바이트 메모리 요청)
bytes_alloc=32 : 실제 할당한 메모리 사이즈(32바이트 메모리 할당)
gfp_flags=GFP_KERNEL: gfp 플래그

다음 4 번째 kfree 이벤트 메시지를 분석하겠습니다.
4 init-1[000] .N..0.170000: kfree: call_site=c10bfa4a ptr=  (null)
 
4번째 줄에서 보이는 세부 디버깅 정보는 다음과 같습니다.
kfree: 커널 메모리 해제
call_site=c10bfa4a: kfree() 함수를 호출한 함수 주소
ptr=  (null): 해제하는 메모리 주소

kmalloc() 함수와 kfree() 함수 호출로 메모리를 어떻게 할당하고 해제하는지 알 수 있습니다.

kmalloc와 kfree 이벤트 커널 코드 수정해보기

위에서 소개한 ftrace 메시지를 보면 한 가지 아쉬운 점이 있습니다.  
1 init-1[000] .N..0.170000: kmalloc: call_site=c104deff ptr=c147dd20 bytes_req=29 bytes_alloc=32 gfp_flags=GFP_KERNEL

메모리 관련 디버깅을 할 때 어느 함수에서 메모리를 할당하고 해제했는지 체크할 때가 많습니다. 
"call_site=c104deff"가 kmalloc() 함수를 호출한 함수 주소 위치를 표현하는데, 16진수 주소로 돼 있습니다. 

    이 정보로 어느 함수에서 kmalloc() 함수를 호출하는지 알기 어렵습니다.

kmalloc() 함수를 호출한 함수 이름을 ftrace에서 출력하면 더 효율적이지 않을까요? 어느 함수에서 메모리를 할당하고 해제했는지 알면 메모리 디버깅을 할 때 참고할 수 있습니다. 

이를 위한 패치 코드를 소개합니다.
diff --git a/include/trace/events/kmem.h b/include/trace/events/kmem.h
index 285feeadac39..1a996d91a519
--- a/include/trace/events/kmem.h
+++ b/include/trace/events/kmem.h
@@ -35,8 +35,9 @@ DECLARE_EVENT_CLASS(kmem_alloc,
  __entry->gfp_flags = gfp_flags;
  ),
 
- TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
+ TP_printk("call_site=%lx caller(%pS) ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
  __entry->call_site,
+ (void*)__entry->call_site,
  __entry->ptr,
  __entry->bytes_req,
  __entry->bytes_alloc,
@@ -88,8 +89,9 @@ DECLARE_EVENT_CLASS(kmem_alloc_node,
  __entry->node = node;
  ),
 
- TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s node=%d",
+ TP_printk("call_site=%lx caller(%pS) ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s node=%d",
  __entry->call_site,
+ (void*)__entry->call_site,
  __entry->ptr,
  __entry->bytes_req,
  __entry->bytes_alloc,
@@ -131,7 +133,7 @@ DECLARE_EVENT_CLASS(kmem_free,
  __entry->ptr = ptr;
  ),
 
- TP_printk("call_site=%lx ptr=%p", __entry->call_site, __entry->ptr)
+ TP_printk("call_site=%lx caller(%pS) ptr=%p", __entry->call_site, (void*)__entry->call_site, __entry->ptr)
 );
 
 DEFINE_EVENT(kmem_free, kfree,

패치 코드를 설명하기 전에 패치 코드를 입력하는 방법을 설명하겠습니다. 패치 코드를 보는 방법에 익숙하지 않은 분들에겐 패치 코드를 이해하기 어려울 수 있습니다.

패치 코드 입력 방법에 대한 이해를 돕기 위해 다음 그림을 같이 보겠습니다. 
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/include/trace/events/kmem.h]
 
[그림 14.28] ftrace kmalloc 이벤트 1번째 디버깅 패치 입력 위치

가장 왼쪽에 보이는 코드 라인은 다음 해더 파일에서 확인할 수 있습니다.
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/include/trace/events/kmem.h]

먼저 위 그림에서 1번으로 된 코드를 눈으로 따라가 봅시다. “caller(%pS)” 코드가 박스 안에 있는데 이 코드를 왼쪽 “call_site=%lx”와 오른쪽 “ptr=%p” 코드 사이에 추가합니다.

다음 2번 코드를 입력하겠습니다. 
"__entry->call_site," 코드 아랫 칸에 "(void*)__entry->call_site" 코드를 입력합시다.

이어서 다음 그림을 보겠습니다.

 
[그림 14.29] ftrace kmalloc 이벤트 2번째 디버깅 패치 입력 위치

패치 코드를 입력하는 라인 위치를 잘 보면서 코드를 입력합시다.

위 그림에서 3번으로 된 코드를 눈으로 따라가 봅시다. “caller(%pS)” 코드가 박스 안에 있는데 이 코드를 왼쪽 “call_site=%lx”와 오른쪽 “ptr=%p” 코드 사이에 추가합니다.

다음 4번으로 된 코드를 입력하겠습니다. 
"__entry->call_site," 코드 아랫 부분에 "(void*)__entry->call_site" 코드를 입력합시다.

이제 마지막 코드를 입력하면 됩니다.
 
[그림 14.30] ftrace kfree 이벤트 디버깅 패치 입력 위치

위 그림에서 5번으로 된 코드를 눈으로 따라가 봅시다. 이번에도 “caller(%pS)” 코드가 박스 안에 있는데 이 코드를 왼쪽 “call_site=%lx”와 오른쪽 “ptr=%p” 코드 사이에 추가합니다.

6번으로 된 코드는 "__entry->call_site," 코드 오른쪽에 입력하면 됩니다.

패치 코드 입력 방법을 설명했으니 패치 코드의 내용을 소개합니다. 다음 코드를 같이 봅시다.
diff --git a/include/trace/events/kmem.h b/include/trace/events/kmem.h
index 285feeadac39..1a996d91a519
--- a/include/trace/events/kmem.h
+++ b/include/trace/events/kmem.h
@@ -35,8 +35,9 @@ DECLARE_EVENT_CLASS(kmem_alloc,
01  __entry->gfp_flags = gfp_flags;
02 ),
03 
04- TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
05+ TP_printk("call_site=%lx caller(%pS) ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
06 __entry->call_site,
07+ (void*)__entry->call_site,
08 __entry->ptr,
09 __entry->bytes_req,
10 __entry->bytes_alloc,
@@ -88,8 +89,9 @@ DECLARE_EVENT_CLASS(kmem_alloc_node,
11 __entry->node = node;
12 ),
13 
14- TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s node=%d",
15+ TP_printk("call_site=%lx caller(%pS) ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s node=%d",
16 __entry->call_site,
17+ (void*)__entry->call_site,
18 __entry->ptr,
19 __entry->bytes_req,
20 __entry->bytes_alloc,
@@ -131,7 +133,7 @@ DECLARE_EVENT_CLASS(kmem_free,
21 __entry->ptr = ptr;
22 ),
23 
24- TP_printk("call_site=%lx ptr=%p", __entry->call_site, __entry->ptr)
25+ TP_printk("call_site=%lx caller(%pS) ptr=%p", __entry->call_site, (void*)__entry->call_site, __entry->ptr)
26 );
27 
28 DEFINE_EVENT(kmem_free, kfree,

04~08 번째 줄 코드는 kmalloc ftrace 이벤트를 출력할 때 함수 이름을 추가합니다.
04- TP_printk("call_site=%lx ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
05+ TP_printk("call_site=%lx caller(%pS) ptr=%p bytes_req=%zu bytes_alloc=%zu gfp_flags=%s",
06 __entry->call_site,
07+ (void*)__entry->call_site,
08 __entry->ptr,

여기서 “caller(%pS)”를 추가해 함수 호출 주소를 심볼로 변환해 출력합니다. 이를 위해 07 번째 줄에 __entry->call_site 를 void* 포인터 타입으로 캐스팅합니다. __entry->call_site에는 kmalloc() 함수를 호출한 함수 주소가 4바이트 포멧으로 저장돼 있습니다.

24~25 번째 줄 코드도 마찬가지입니다.
24- TP_printk("call_site=%lx ptr=%p", __entry->call_site, __entry->ptr)
25+ TP_printk("call_site=%lx caller(%pS) ptr=%p", __entry->call_site, (void*)__entry->call_site, __entry->ptr)
26 );


kfree ftrace 이벤트를 출력할 때 “caller(%pS)” 스트링으로 함수 호출 주소를 심볼로 출력합니다.

패치 코드를 입력하고 난 후 커널 빌드를 해야 합니다. 커널 빌드 후 커널 이미지를 설치한 다음 라즈베리파이를 리부팅합시다.

ftrace 설정하고 로그 추출하기

이번에는 ftrace 를 설정하는 방법을 소개합니다.
01 #!/bin/bash
02 
03 echo 0 > /sys/kernel/debug/tracing/tracing_on
04 sleep 1
05 echo "tracing_off"
06 
07 echo 0 > /sys/kernel/debug/tracing/events/enable
08 sleep 1
09 echo "events disabled"
10
11 echo nop > /sys/kernel/debug/tracing/current_tracer
12 sleep 1
13 echo "nop tracer enabled"
14
15 echo 1 > /sys/kernel/debug/tracing/events/kmem/kmalloc/enable
16 echo 1 > /sys/kernel/debug/tracing/events/kmem/kfree/enable
17
18 sleep 1
19 echo "event enabled"
20
21 echo 1 > /sys/kernel/debug/tracing/tracing_on
22 echo "tracing_on"

위 셸 스크립트 코드에서 눈여겨 볼 부분은 20~21 번째 줄입니다.
20 echo 1 > /sys/kernel/debug/tracing/events/kmem/kmalloc/enable
21 echo 1 > /sys/kernel/debug/tracing/events/kmem/kfree/enable

kmalloc와 kfree 이벤트를 키는 코드입니다. 다른 코드는 이미 많이 설명을 드렸으니 넘어가겠습니다.

위와 같은 셸 스크립트 코드를 입력한 다음 nop_kmem_trace.sh 이름으로 저장합시다.
"chmod +x nop_kmem_trace.sh" 명령어로 nop_kmem_trace.sh 셸 스크립트 파일에 실행 권한을 설정한 다음에 실행합시다. 
root@raspberrypi:/home/pi# ./nop_kmem_trace.sh

10 초 후 ftrace 로그를 받습니다. 기존에 소개한 바와 같이 다음 명령어를 get_ftrace.sh 파일로 저장한 다음 실행합시다.
#!/bin/bash

echo 0 > /sys/kernel/debug/tracing/tracing_on
echo "ftrace off"

sleep 3

cp /sys/kernel/debug/tracing/trace . 
mv trace ftrace_log.c

개선된 kmalloc와 kfree 이벤트 로그 분석해보기

이번에 분석할 ftrace 로그를 소개합니다.
1 <idle>-0 [000] d.h. 328.473305: kmalloc: call_site=805ee260 caller(__DWC_ALLOC_ATOMIC+0x24/0x28) ptr=b7d93cc0 bytes_req=12 bytes_alloc=64 gfp_flags=GFP_ATOMIC|__GFP_ZERO
2 <idle>-0 [000] ..s. 328.473324: kfree: call_site=805ee2c8 caller(__DWC_FREE+0x1c/0x20) ptr=b7d93cc0

메모리를 할당하고 해제한 함수 이름이 보입니다.

1 번째 줄 로그를 보겠습니다.
1 <idle>-0 [000] d.h. 328.473305: kmalloc: call_site=805ee260 caller(__DWC_ALLOC_ATOMIC+0x24/0x28) ptr=b7d93cc0 bytes_req=12 bytes_alloc=64 gfp_flags=GFP_ATOMIC|__GFP_ZERO

ftrace 로그에서 가운데 부분에서 다음 메시지를 확인할 수 있습니다. 

    caller(__DWC_ALLOC_ATOMIC+0x24/0x28)

이번 실습 시간에 추가한 코드가 작동해 출력하는 정보입니다. 이어서 위 메시지의 오른쪽 부분을 보면 다음 메시지가 보입니다.

    ptr=b7d93cc0

이는 kmalloc() 함수를 호출해 할당 받는 메모리 주소를 의미합니다. 

두 가지 사실을 토대로 1번째 줄 메시지는 다음과 같이 해석할 수 있습니다.

     __DWC_ALLOC_ATOMIC() 함수 시작 주소 기준 +0x24 코드에서 kmalloc() 함수를 
     호출한다. 할당 받는 메모리는 주소는 (ptr=b7d93cc0)이다.

다음 2 번째 줄 로그를 분석하겠습니다. 
2 <idle>-0 [000] ..s. 328.473324: kfree: call_site=805ee2c8 caller(__DWC_FREE+0x1c/0x20) ptr=b7d93cc0

위 로그 가운데 부분에서 다음과 같은 메시지가 보입니다.

     caller(__DWC_FREE+0x1c/0x20)

이는 kfree() 함수를 호출한 코드 정보입니다. 이 정보를 토대로 2번째 줄 로그를 해석해볼까요?

    __DWC_FREE() 함수 주소 기준 +0x1c 코드에서 kfree() 함수를 호출해 
   메모리(ptr=b7d93cc0)을 해제합니다.

여기서 한 가지 중요한 정보가 보입니다.

1 번째 줄 로그에서 "d.h." 텍스트입니다. 프로세스 세부 실행 정보를 표현하는데 이를 해석하면 다음과 같습니다.
d: 해당 CPU 인터럽트 라인을 Disable
h: 인터럽트 컨택스트

이 때 gfp_flags 부분 로그를 보면 GFP_ATOMIC|__GFP_ZERO 입니다. 이 플래그로 정보는 다음과 같이 해석할 수 있습니다.

    GFP_ATOMIC 플래그이니 휴면 없이 슬럽 오브젝트를 할당하고  __GFP_ZERO 플래그로 
   슬럽 오브젝트는 0x0으로 초기화해라.

이렇게 ftrace를 통해 메모리를 할당하고 해제하는 함수 이름을 알 수 있으니 편리합니다.

kmalloc와 kfree 이벤트를 출력한 커널 소스 분석해보기

ftrace 로그에서 본 정보를 참고하면 kmalloc() 함수와 kfree() 함수를 어디서 호출하는지 바로 확인할 수 있습니다. 

1번째 줄 로그를 참고하면 kmalloc() 함수를 호출하는 함수는 '__DWC_ALLOC_ATOMIC+0x24'입니다. 
 1 <idle>-0 [000] d.h. 328.473305: kmalloc: call_site=805ee260 caller(__DWC_ALLOC_ATOMIC+0x24/0x28) ptr=b7d93cc0 bytes_req=12 bytes_alloc=64 gfp_flags=GFP_ATOMIC|__GFP_ZERO

자, 그러면 라즈비안 커널 소스를 열고 코드 위치를 확인해볼까요?
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/drivers/usb/host/dwc_common_port/dwc_common_linux.c]
1 void *__DWC_ALLOC_ATOMIC(void *mem_ctx, uint32_t size)
2 {
3 return kzalloc(size, GFP_ATOMIC);
4 }

__DWC_ALLOC_ATOMIC() 함수 3번째 줄에서 kzalloc() 함수를 호출합니다.

kzalloc() 함수는 할당 받는 메모리를 0x0으로 초기화한다는 점만 빼고 kmalloc() 함수의 기능은 같습니다. 
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/include/linux/slab.h]
static inline void *kzalloc(size_t size, gfp_t flags)
{
return kmalloc(size, flags | __GFP_ZERO);
}

이번에는 2번째 줄 로그를 출력한 커널 소스 위치를 알아볼까요?
2 <idle>-0 [000] ..s. 328.473324: kfree: call_site=805ee2c8 caller(__DWC_FREE+0x1c/0x20) ptr=b7d93cc0

위 로그에서 보이듯 kfree() 함수를 호출하는 함수는 '__DWC_FREE+0x1c'입니다. 
라즈비안 커널 소스를 열고 kfree() 함수를 호출하는 코드 위치를 확인해볼까요?
[https://github.com/raspberrypi/linux/blob/rpi-4.19.y/drivers/usb/host/dwc_common_port/dwc_common_linux.c]
01 void __DWC_FREE(void *mem_ctx, void *addr)
02 {
03 kfree(addr);
04 }

__DWC_FREE() 함수 03번째 줄에서 kfree() 함수를 호출합니다.

이 방식을 활용하면 커널에서 kmalloc()/kfree 함수를 호출해 동적 메모리를 어느 함수가 할당하고 해제하는지 알수 있습니다. 




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

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

Reference(커널 메모리 소개) 
가상 주소를 물리 주소로 어떻게 변환할까?   
메모리 존(Zone)에 대해서   
커널 메모리 할당은 어떻게 할까   
슬랩 메모리 할당자와 kmalloc 슬랩 캐시 분석   
커널 메모리 디버깅



핑백

덧글

댓글 입력 영역