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

[Masami Hiramatsu (Google) <mhiramat@kernel.org>]

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

> On Wed, 28 Feb 2024 17:23:34 +0100
> Jiri Olsa <olsajiri@gmail.com> 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@kernel.org>