search

paranlee / uftrace

Function graph tracer for C/C++/Rust
https://uftrace.github.io/slide/
GNU General Public License v2.0
1 stars 0 forks source link

커널 트레이싱 기능 개선 관련 문의 사항 #1

Open paranlee opened 1 year ago

paranlee commented 1 year ago

커널 트레이싱을 개선하고 싶은데 uftrace 코드의 어떤 루틴을 연구하고 비교 접근하면 좋을지 문의 드려도 괜찮을까요?

# ./uftrace -k --libmcount-path=. ./read
0-3
WARN: record kernel data (cpu 4) failed: No such device
# DURATION     TID     FUNCTION
   0.511 us [  7889] | __monstartup();
   0.205 us [  7889] | __cxa_atexit();
            [  7889] | main() {
  70.033 us [  7889] |   fopen();
  46.173 us [  7889] |   fgetc();
  22.802 us [  7889] |   putchar();
   0.095 us [  7889] |   fgetc();
   0.128 us [  7889] |   putchar();
   0.073 us [  7889] |   fgetc();
   0.081 us [  7889] |   putchar();
   0.072 us [  7889] |   fgetc();
  68.719 us [  7889] |   putchar();
  27.685 us [  7889] |   fclose();
 238.742 us [  7889] | } /* main */

uftrace stopped tracing with remaining functions
================================================
task: 7889
[0] __x64_sys_execve

트레이싱한 C 프로그램 read.c 의 코드는 다음과 같습니다. 하는 동작은 # cat /sys/devices/system/cpu/online 할 때와 유사하게 동작하도록 작성했습니다.

#include <stdio.h>
#include <stdlib.h>
#include <string.h>

int main()
{
        FILE* fptr;
        char chr;
        int i = 16;
        fptr = fopen("/sys/devices/system/cpu/online", "r");
        if (NULL == fptr) {
                printf("file can not open \n");
        }

        do {
                chr = fgetc(fptr);
                printf("%c", chr);
        } while (chr != '\n' && chr != '\0' && chr != EOF);
        fclose(fptr);
        return 0;
}

제가 직접 ftrace 를 활용한 hook 을 사용한 커널 모듈로 확인했을 때는 아래의 콜 스택을 확인했습니다.

[토  6월 24 08:24:18 2023]  dump_stack_lvl+0x48/0x70
[토  6월 24 08:24:18 2023]  dump_stack+0x10/0x20
[토  6월 24 08:24:18 2023]  show_cpus_attr_fn_hooked+0x31/0x90 [vmhook]
[토  6월 24 08:24:18 2023]  dev_attr_show+0x1a/0x70
[토  6월 24 08:24:18 2023]  sysfs_kf_seq_show+0xa0/0x110
[토  6월 24 08:24:18 2023]  kernfs_seq_show+0x24/0x40
[토  6월 24 08:24:18 2023]  seq_read_iter+0x132/0x4a0
[토  6월 24 08:24:18 2023]  kernfs_fop_read_iter+0x34/0x40
[토  6월 24 08:24:18 2023]  vfs_read+0x249/0x330
[토  6월 24 08:24:18 2023]  ksys_read+0x73/0x100
[토  6월 24 08:24:18 2023]  __x64_sys_read+0x19/0x30
[토  6월 24 08:24:18 2023]  do_syscall_64+0x58/0x90

[토  6월 24 08:24:18 2023] sys cpu func name : show(show_cpus_attr), store(0x0)
[토  6월 24 08:24:18 2023] sys cpu func buf : 0-3

해당 드라이버 함수는 다음과 같습니다.

DEFINE_STATIC_FUNCTION_HOOK(ssize_t, show_cpus_attr, struct device *dev,
                              struct device_attribute *attr,
                              char *buf)
{
        DEFINE_ORIGINAL(show_cpus_attr);

        //struct cpu_attr *ca = container_of(attr, struct cpu_attr, attr);

        dump_stack();

        printk("sys cpu func name : show(%ps), store(%ps)", attr->show, attr->store);

        ssize_t ret = orig_fn(dev, attr, buf);

        printk("sys cpu func buf : %s", buf);

        return ret;
}

dmesg 로그

[토  6월 24 08:24:08 2023] vmhook: initializing...
[토  6월 24 08:24:08 2023] vmhook: KVMHook initialized!
[토  6월 24 08:24:18 2023] CPU: 2 PID: 7854 Comm: cat Kdump: loaded Tainted: G        W  OE      6.3.0-7-generic #7-Ubuntu
[토  6월 24 08:24:18 2023] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 11/12/2020
[토  6월 24 08:24:18 2023] Call Trace:
[토  6월 24 08:24:18 2023]  <TASK>
[토  6월 24 08:24:18 2023]  dump_stack_lvl+0x48/0x70
[토  6월 24 08:24:18 2023]  dump_stack+0x10/0x20
[토  6월 24 08:24:18 2023]  show_cpus_attr_fn_hooked+0x31/0x90 [vmhook]
[토  6월 24 08:24:18 2023]  dev_attr_show+0x1a/0x70
[토  6월 24 08:24:18 2023]  sysfs_kf_seq_show+0xa0/0x110
[토  6월 24 08:24:18 2023]  kernfs_seq_show+0x24/0x40
[토  6월 24 08:24:18 2023]  seq_read_iter+0x132/0x4a0
[토  6월 24 08:24:18 2023]  kernfs_fop_read_iter+0x34/0x40
[토  6월 24 08:24:18 2023]  vfs_read+0x249/0x330
[토  6월 24 08:24:18 2023]  ksys_read+0x73/0x100
[토  6월 24 08:24:18 2023]  __x64_sys_read+0x19/0x30
[토  6월 24 08:24:18 2023]  do_syscall_64+0x58/0x90
[토  6월 24 08:24:18 2023]  ? handle_mm_fault+0x135/0x340
[토  6월 24 08:24:18 2023]  ? do_user_addr_fault+0x1e8/0x720
[토  6월 24 08:24:18 2023]  ? exit_to_user_mode_prepare+0x30/0xb0
[토  6월 24 08:24:18 2023]  ? irqentry_exit_to_user_mode+0x9/0x20
[토  6월 24 08:24:18 2023]  ? irqentry_exit+0x43/0x50
[토  6월 24 08:24:18 2023]  ? exc_page_fault+0x91/0x1b0
[토  6월 24 08:24:18 2023]  entry_SYSCALL_64_after_hwframe+0x72/0xdc
[토  6월 24 08:24:18 2023] RIP: 0033:0x7fd07270b941
[토  6월 24 08:24:18 2023] Code: 31 c0 e9 b2 fe ff ff 50 48 8d 3d 62 13 0b 00 e8 d5 32 02 00 0f 1f 44 00 00 f3 0f 1e fa 80 3d 9d 2c 0f 00 00 74 13 31 c0 0f 05 <48> 3d 00 f0 ff ff 77 57 c3 66 0f 1f 44 00 00 48 83 ec 28 48 89 54
[토  6월 24 08:24:18 2023] RSP: 002b:00007ffd5a8f7bc8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[토  6월 24 08:24:18 2023] RAX: ffffffffffffffda RBX: 0000000000020000 RCX: 00007fd07270b941
[토  6월 24 08:24:18 2023] RDX: 0000000000020000 RSI: 00007fd0728bf000 RDI: 0000000000000003
[토  6월 24 08:24:18 2023] RBP: 0000000000020000 R08: 00000000ffffffff R09: 0000000000000000
[토  6월 24 08:24:18 2023] R10: 0000000000000022 R11: 0000000000000246 R12: 00007fd0728bf000
[토  6월 24 08:24:18 2023] R13: 0000000000000003 R14: 0000000000020000 R15: 0000000000000000
[토  6월 24 08:24:18 2023]  </TASK>
[토  6월 24 08:24:18 2023] sys cpu func name : show(show_cpus_attr), store(0x0)
[토  6월 24 08:24:18 2023] sys cpu func buf : 0-3
[토  6월 24 08:24:28 2023] vmhook: unloading...
[토  6월 24 08:24:28 2023] vmhook: KVMHook unloaded!
paranlee commented 1 year ago

https://uftrace.github.io/slide/#39

paranlee commented 1 year ago

Add options --debug-domain kernel:3.

# ./uftrace -k --libmcount-path=. --debug-domain kernel:3 ./read
kernel: setting up kernel tracing
kernel: writing filter file failed, but ignoring...
kernel: writing filter file failed, but ignoring...
kernel: writing filter file failed, but ignoring...
kernel: writing filter file failed, but ignoring...
kernel: writing filter file failed, but ignoring...
kernel: kernel tracing started..
0-3
kernel: kernel tracing stopped.
WARN: record kernel data (cpu 4) failed: No such device
kernel: found kernel ftrace data for 128 cpus
# DURATION     TID     FUNCTION
   0.829 us [  2285] | __monstartup();
   0.233 us [  2285] | __cxa_atexit();
            [  2285] | main() {
  60.538 us [  2285] |   fopen();
  22.987 us [  2285] |   fgetc();
   9.420 us [  2285] |   putchar();
   0.145 us [  2285] |   fgetc();
   0.166 us [  2285] |   putchar();
   0.092 us [  2285] |   fgetc();
   0.119 us [  2285] |   putchar();
   0.095 us [  2285] |   fgetc();
            [  2285] |   putchar() {
 345.883 us [  2285] |     /* linux:schedule (pre-empted) */
 167.730 us [  2285] |     /* linux:schedule (pre-empted) */
 682.194 us [  2285] |   } /* putchar */
  16.459 us [  2285] |   fclose();
 796.131 us [  2285] | } /* main */

uftrace stopped tracing with remaining functions
================================================
task: 2285
[0] find_vma