Re: [PATCH v2 0/7] tracing/probes: Support function parameter access from return probe

From: Google
Date: Thu Feb 29 2024 - 01:40:31 EST

On Thu, 29 Feb 2024 14:51:39 +0900
Masami Hiramatsu (Google) <mhiramat@xxxxxxxxxx> wrote:

> On Wed, 28 Feb 2024 17:23:34 +0100
> Jiri Olsa <olsajiri@xxxxxxxxx> wrote:
>
> > On Mon, Feb 26, 2024 at 12:57:53PM +0900, Masami Hiramatsu (Google) wrote:
> > > Hi,
> > >
> > > Here is version 2 series of patches to support accessing function entry data
> > > from function *return* probes (including kretprobe and fprobe-exit event).
> > >
> > > In this version, I added another cleanup [4/7], updated README[5/7], added
> > > testcases[6/7] and updated document[7/7].
> > >
> > > This allows us to access the results of some functions, which returns the
> > > error code and its results are passed via function parameter, such as an
> > > structure-initialization function.
> > >
> > > For example, vfs_open() will link the file structure to the inode and update
> > > mode. Thus we can trace that changes.
> > >
> > > # echo 'f vfs_open mode=file->f_mode:x32 inode=file->f_inode:x64' >> dynamic_events
> > > # echo 'f vfs_open%return mode=file->f_mode:x32 inode=file->f_inode:x64' >> dynamic_events
> > > # echo 1 > events/fprobes/enable
> > > # cat trace
> > > sh-131 [006] ...1. 1945.714346: vfs_open__entry: (vfs_open+0x4/0x40) mode=0x2 inode=0x0
> > > sh-131 [006] ...1. 1945.714358: vfs_open__exit: (do_open+0x274/0x3d0 <- vfs_open) mode=0x4d801e inode=0xffff888008470168
> > > cat-143 [007] ...1. 1945.717949: vfs_open__entry: (vfs_open+0x4/0x40) mode=0x1 inode=0x0
> > > cat-143 [007] ...1. 1945.717956: vfs_open__exit: (do_open+0x274/0x3d0 <- vfs_open) mode=0x4a801d inode=0xffff888005f78d28
> > > cat-143 [007] ...1. 1945.720616: vfs_open__entry: (vfs_open+0x4/0x40) mode=0x1 inode=0x0
> > > cat-143 [007] ...1. 1945.728263: vfs_open__exit: (do_open+0x274/0x3d0 <- vfs_open) mode=0xa800d inode=0xffff888004ada8d8
> >
> > hi,
> > I hit a crash while playing with this, by runnning:
> >
> > # echo 'f vfs_read%return $arg*' >> dynamic_events
> > # echo 1 > events/fprobes/enable
>
> Thanks for reporting! But I can not reproduce it.
> Can you share your kconfig?

No problem, I could reproduce it.

/sys/kernel/tracing # echo 'f vfs_read%return $arg* $retval' >> dynamic_events
/sys/kernel/tracing # echo 1 > events/fprobes/enable
/sys/kernel/tracing #
/sys/kernel/tracing # [ 67.709725] general protection fault, maybe for address 0xffffc9000047bef8: 0000 [#1] PREEMPT SMP PTI
[ 67.714672] CPU: 5 PID: 132 Comm: sh Tainted: G N 6.8.0-rc5-00007-gd5e41e4cee7e #149
[ 67.716491] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.15.0-1 04/01/2014
[ 67.718036] RIP: 0010:__x86_indirect_thunk_r13+0xa/0x20
[ 67.719087] Code: e8 01 00 00 00 cc 4c 89 24 24 c3 cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 66 0f 1f 44 00 00 e8 01 00 00 00 cc 4c 89 2c 24 <c3> cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 66 0f 1f 44 00 00
[ 67.722314] RSP: 0018:ffffc9000047bdf0 EFLAGS: 00010286
[ 67.723251] RAX: ffffc9000047bef8 RBX: ffff8880073258e0 RCX: ffffc9000047be48
[ 67.724704] RDX: ffffffff813aba09 RSI: 0000000000000000 RDI: ffff8880073258d0
[ 67.725840] RBP: ffff8880073258e0 R08: 0000000000000000 R09: ffff888005053648
[ 67.727017] R10: ffff888008452388 R11: 0000000000000001 R12: ffffffff813aba09
[ 67.728107] R13: 9c73d7ba3660c600 R14: ffffc9000047bef0 R15: ffffc9000047be48
[ 67.729630] FS: 000000000115d8c0(0000) GS:ffff88807d940000(0000) knlGS:0000000000000000
[ 67.731231] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 67.732285] CR2: 00000000005a2319 CR3: 0000000005ad6000 CR4: 00000000000006b0
[ 67.733502] Call Trace:
[ 67.734013] <TASK>
[ 67.734504] ? die_addr+0x37/0x90
[ 67.735307] ? exc_general_protection+0x1ac/0x3f0
[ 67.736158] ? asm_exc_general_protection+0x26/0x30
[ 67.736984] ? ksys_read+0x69/0xf0
[ 67.737559] ? ksys_read+0x69/0xf0
[ 67.738142] ? __x86_indirect_thunk_r13+0xa/0x20
[ 67.739160] ? rethook_trampoline_handler+0x95/0x200
[ 67.739919] ? arch_rethook_trampoline_callback+0x3a/0x50
[ 67.740665] ? arch_rethook_trampoline+0x2c/0x60
[ 67.741362] ? ksys_read+0x69/0xf0
[ 67.741980] ? trace_clock_x86_tsc+0x20/0x20
[ 67.742662] ? do_syscall_64+0xcc/0x1e0
[ 67.743289] ? entry_SYSCALL_64_after_hwframe+0x6f/0x77
[ 67.744620] </TASK>
[ 67.745044] Modules linked in:
[ 67.745559] ---[ end trace 0000000000000000 ]---
[ 67.746221] RIP: 0010:__x86_indirect_thunk_r13+0xa/0x20
[ 67.746927] Code: e8 01 00 00 00 cc 4c 89 24 24 c3 cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 66 0f 1f 44 00 00 e8 01 00 00 00 cc 4c 89 2c 24 <c3> cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 66 0f 1f 44 00 00
[ 67.749176] RSP: 0018:ffffc9000047bdf0 EFLAGS: 00010286
[ 67.749835] RAX: ffffc9000047bef8 RBX: ffff8880073258e0 RCX: ffffc9000047be48
[ 67.750687] RDX: ffffffff813aba09 RSI: 0000000000000000 RDI: ffff8880073258d0
[ 67.751880] RBP: ffff8880073258e0 R08: 0000000000000000 R09: ffff888005053648
[ 67.752810] R10: ffff888008452388 R11: 0000000000000001 R12: ffffffff813aba09
[ 67.753721] R13: 9c73d7ba3660c600 R14: ffffc9000047bef0 R15: ffffc9000047be48
[ 67.754554] FS: 000000000115d8c0(0000) GS:ffff88807d940000(0000) knlGS:0000000000000000
[ 67.755568] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 67.756278] CR2: 00000000005a2319 CR3: 0000000005ad6000 CR4: 00000000000006b0
[ 67.757089] Kernel panic - not syncing: Fatal exception
[ 67.757917] Kernel Offset: disabled
[ 67.758404] ---[ end Kernel panic - not syncing: Fatal exception ]---

Hmm, this seems arch_rethook_trampoline caused the issue.

And curiously, it depends on the number of stored data.

OK:
/sys/kernel/tracing # echo 'f vfs_read%return $arg1 $arg2 $arg3' >> dynamic_events
/sys/kernel/tracing # echo 1 > events/fprobes/enable

NG:
/sys/kernel/tracing # echo 'f vfs_read%return $arg1 $arg2 $arg3 $arg4' >> dynamic_events
/sys/kernel/tracing # echo 1 > events/fprobes/enable

I also confirmed that on 'vfs_write' caused the same result. 3 arguments(24 bytes) is OK,
but 4 arguments (32bytes) is NG.

Thank you,


--
Masami Hiramatsu (Google) <mhiramat@xxxxxxxxxx>