krobe: __blkdev_put probe is missed

krobe: __blkdev_put probe is missed

[Ming Lei]

Hello Guys,

I found probe on __blkdev_put is missed, which can be observed
via bcc/perf reliably:

1) start trace
- perf probe __blkdev_put
- perf trace -a  -e probe:__blkdev_put

or

/usr/share/bcc/tools/stackcount __blkdev_put

2) run the following command:
blockdev --getbsz /dev/sda1

3) 'perf trace'  or stackcount just  dumps one trace event, and it
should have been two
__blkdev_put() traces, since one __blkdev_put() is called for
partition(/dev/sda1),
and another is for disk(/dev/sda). If trace_printk() is added in __blkdev_put(),
two events will be captured from ftrace.

The only special thing about __blkdev_put() is that the function will call into
itself. However, no such issue on __blkdev_get() which calls itself too.


Thanks,
Ming Lei

Re: kprobe: __blkdev_put probe is missed

[Ming Lei]

On Wed, Jun 17, 2020 at 06:30:39PM +0800, Ming Lei wrote:
> Hello Guys,
> 
> I found probe on __blkdev_put is missed, which can be observed
> via bcc/perf reliably:
> 
> 1) start trace
> - perf probe __blkdev_put
> - perf trace -a  -e probe:__blkdev_put
> 
> or
> 
> /usr/share/bcc/tools/stackcount __blkdev_put
> 
> 2) run the following command:
> blockdev --getbsz /dev/sda1
> 
> 3) 'perf trace'  or stackcount just  dumps one trace event, and it
> should have been two
> __blkdev_put() traces, since one __blkdev_put() is called for
> partition(/dev/sda1),
> and another is for disk(/dev/sda). If trace_printk() is added in __blkdev_put(),
> two events will be captured from ftrace.
> 

The issue can be shown by loading a kprobe module which registers on
__blkdev_put(), just by replacing _do_fork with __blkdev_put on
samples/kprobes/kprobe_example.c.

So the issue is really in kprobe code.

Thanks,
Ming

Re: kprobe: __blkdev_put probe is missed

[Masami Hiramatsu]

Hi Ming,

On Thu, 18 Jun 2020 20:54:38 +0800
Ming Lei <ming.lei@redhat.com> wrote:

> On Wed, Jun 17, 2020 at 06:30:39PM +0800, Ming Lei wrote:
> > Hello Guys,
> > 
> > I found probe on __blkdev_put is missed, which can be observed
> > via bcc/perf reliably:
> > 
> > 1) start trace
> > - perf probe __blkdev_put
> > - perf trace -a  -e probe:__blkdev_put

Could you dump the kprobe_event as below?

# cat /sys/kernel/tracing/kprobe_events


> > 
> > or
> > 
> > /usr/share/bcc/tools/stackcount __blkdev_put
> > 
> > 2) run the following command:
> > blockdev --getbsz /dev/sda1

And dump the kprobe profile?

# cat /sys/kernel/tracing/kprobe_profile

> > 
> > 3) 'perf trace'  or stackcount just  dumps one trace event, and it
> > should have been two
> > __blkdev_put() traces, since one __blkdev_put() is called for
> > partition(/dev/sda1),
> > and another is for disk(/dev/sda). If trace_printk() is added in __blkdev_put(),
> > two events will be captured from ftrace.
> > 
> 
> The issue can be shown by loading a kprobe module which registers on
> __blkdev_put(), just by replacing _do_fork with __blkdev_put on
> samples/kprobes/kprobe_example.c.

Could you tell me what kernel are you using?

I'm using 5.4 on ubuntu and can not reproduce it with kprobe_event.

root@devnote2:/sys/kernel/tracing# uname -a
Linux devnote2 5.4.0-37-generic #41-Ubuntu SMP Wed Jun 3 18:57:02 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
root@devnote2:/sys/kernel/tracing# echo p __blkdev_put > kprobe_events 
root@devnote2:/sys/kernel/tracing# echo 1 > events/kprobes/p___blkdev_put_0/enable 
root@devnote2:/sys/kernel/tracing# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
root@devnote2:/sys/kernel/tracing# blockdev --getbsz /dev/nvme0n1
4096
root@devnote2:/sys/kernel/tracing# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 1/1   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           <...>-111740 [002] .... 301734.476991: p___blkdev_put_0: (__blkdev_put+0x0/0x1e0)

Hmm, maybe some issue in the latest kernel...?


Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: kprobe: __blkdev_put probe is missed

[Ming Lei]

On Thu, Jun 18, 2020 at 10:56:02PM +0900, Masami Hiramatsu wrote:
> Hi Ming,
> 
> On Thu, 18 Jun 2020 20:54:38 +0800
> Ming Lei <ming.lei@redhat.com> wrote:
> 
> > On Wed, Jun 17, 2020 at 06:30:39PM +0800, Ming Lei wrote:
> > > Hello Guys,
> > > 
> > > I found probe on __blkdev_put is missed, which can be observed
> > > via bcc/perf reliably:
> > > 
> > > 1) start trace
> > > - perf probe __blkdev_put
> > > - perf trace -a  -e probe:__blkdev_put
> 
> Could you dump the kprobe_event as below?
> 
> # cat /sys/kernel/tracing/kprobe_events
> 
> 
> > > 
> > > or
> > > 
> > > /usr/share/bcc/tools/stackcount __blkdev_put
> > > 
> > > 2) run the following command:
> > > blockdev --getbsz /dev/sda1
> 
> And dump the kprobe profile?
> 
> # cat /sys/kernel/tracing/kprobe_profile
> 
> > > 
> > > 3) 'perf trace'  or stackcount just  dumps one trace event, and it
> > > should have been two
> > > __blkdev_put() traces, since one __blkdev_put() is called for
> > > partition(/dev/sda1),
> > > and another is for disk(/dev/sda). If trace_printk() is added in __blkdev_put(),
> > > two events will be captured from ftrace.
> > > 
> > 
> > The issue can be shown by loading a kprobe module which registers on
> > __blkdev_put(), just by replacing _do_fork with __blkdev_put on
> > samples/kprobes/kprobe_example.c.
> 
> Could you tell me what kernel are you using?
> 
> I'm using 5.4 on ubuntu and can not reproduce it with kprobe_event.
> 
> root@devnote2:/sys/kernel/tracing# uname -a
> Linux devnote2 5.4.0-37-generic #41-Ubuntu SMP Wed Jun 3 18:57:02 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
> root@devnote2:/sys/kernel/tracing# echo p __blkdev_put > kprobe_events 
> root@devnote2:/sys/kernel/tracing# echo 1 > events/kprobes/p___blkdev_put_0/enable 
> root@devnote2:/sys/kernel/tracing# cat trace
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 0/0   #P:8
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
> root@devnote2:/sys/kernel/tracing# blockdev --getbsz /dev/nvme0n1
> 4096
> root@devnote2:/sys/kernel/tracing# cat trace
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 1/1   #P:8
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>            <...>-111740 [002] .... 301734.476991: p___blkdev_put_0: (__blkdev_put+0x0/0x1e0)
> 
> Hmm, maybe some issue in the latest kernel...?

Hello Masami,

I am testing the latest upstream kernel, your trace actually reproduces
this issue.

After 'blockdev --getbsz /dev/nvme0n1' returns, __blkdev_put() should
have been called two times(one for partition, and the other for disk),
however kprobe trace just shows one time of calling this function.

If trace_printk() is added at the entry of __blkdev_put() manually,
you will see that __blkdev_put() is called two times in 'blockdev
--getbsz /dev/nvme0n1'.


Thanks,
Ming

Re: kprobe: __blkdev_put probe is missed

[Masami Hiramatsu]

Hi Ming,

On Fri, 19 Jun 2020 07:19:01 +0800
Ming Lei <ming.lei@redhat.com> wrote:

> > I'm using 5.4 on ubuntu and can not reproduce it with kprobe_event.
> > 
> > root@devnote2:/sys/kernel/tracing# uname -a
> > Linux devnote2 5.4.0-37-generic #41-Ubuntu SMP Wed Jun 3 18:57:02 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
> > root@devnote2:/sys/kernel/tracing# echo p __blkdev_put > kprobe_events 
> > root@devnote2:/sys/kernel/tracing# echo 1 > events/kprobes/p___blkdev_put_0/enable 
> > root@devnote2:/sys/kernel/tracing# cat trace
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 0/0   #P:8
> > #
> > #                              _-----=> irqs-off
> > #                             / _----=> need-resched
> > #                            | / _---=> hardirq/softirq
> > #                            || / _--=> preempt-depth
> > #                            ||| /     delay
> > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > #              | |       |   ||||       |         |
> > root@devnote2:/sys/kernel/tracing# blockdev --getbsz /dev/nvme0n1
> > 4096
> > root@devnote2:/sys/kernel/tracing# cat trace
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 1/1   #P:8
> > #
> > #                              _-----=> irqs-off
> > #                             / _----=> need-resched
> > #                            | / _---=> hardirq/softirq
> > #                            || / _--=> preempt-depth
> > #                            ||| /     delay
> > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > #              | |       |   ||||       |         |
> >            <...>-111740 [002] .... 301734.476991: p___blkdev_put_0: (__blkdev_put+0x0/0x1e0)
> > 
> > Hmm, maybe some issue in the latest kernel...?
> 
> Hello Masami,
> 
> I am testing the latest upstream kernel, your trace actually reproduces
> this issue.

OK.

> 
> After 'blockdev --getbsz /dev/nvme0n1' returns, __blkdev_put() should
> have been called two times(one for partition, and the other for disk),
> however kprobe trace just shows one time of calling this function.
> 
> If trace_printk() is added at the entry of __blkdev_put() manually,
> you will see that __blkdev_put() is called two times in 'blockdev
> --getbsz /dev/nvme0n1'.

OK, let me check again on the latest kernel.
Here I tested with qemu.

root@devnote2:/sys/kernel/debug/tracing# uname -a
Linux devnote2 5.8.0-rc1+ #26 SMP PREEMPT Fri Jun 19 12:12:53 JST 2020 x86_64 x86_64 x86_64 GNU/Linux

And we have a (virtual) sda with 1 partition.

root@devnote2:/sys/kernel/debug/tracing# cat /proc/partitions 
major minor  #blocks  name

   8        0      10240 sda
   8        1       9216 sda1

OK, then let's make events (for sure)

root@devnote2:/sys/kernel/debug/tracing# echo p __blkdev_put >> kprobe_events 
root@devnote2:/sys/kernel/debug/tracing# echo r __blkdev_put >> kprobe_events 
root@devnote2:/sys/kernel/debug/tracing# echo p blkdev_put >> kprobe_events 

There are 3 events in the kernel, blkdev_put() and __blkdev_put() and
the return of __blkdev_put().
Then enable it and access to */dev/sda* (a disk)

root@devnote2:/sys/kernel/debug/tracing# echo 1 > events/kprobes/enable 
root@devnote2:/sys/kernel/debug/tracing# blockdev --getbsz /dev/sda
4096
root@devnote2:/sys/kernel/debug/tracing# echo 0 > events/kprobes/enable 
root@devnote2:/sys/kernel/debug/tracing# cat trace 
# tracer: nop
#
# entries-in-buffer/entries-written: 3/3   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        blockdev-185   [002] ...1    72.604266: p_blkdev_put_0: (blkdev_put+0x0/0x130)
        blockdev-185   [002] ...1    72.604276: p___blkdev_put_0: (__blkdev_put+0x0/0x220)
        blockdev-185   [002] d..2    72.604288: r___blkdev_put_0: (blkdev_put+0x50/0x130 <- __blkdev_put)

So the __blkdev_put() is called once from blkdev_put().
Next, we do same trace with accessing */dev/sda1* (a partition).

root@devnote2:/sys/kernel/debug/tracing# echo > trace 
root@devnote2:/sys/kernel/debug/tracing# echo 1 > events/kprobes/enable 
root@devnote2:/sys/kernel/debug/tracing# blockdev --getbsz /dev/sda1 
4096
root@devnote2:/sys/kernel/debug/tracing# echo 0 > events/kprobes/enable 
root@devnote2:/sys/kernel/debug/tracing# cat trace 
# tracer: nop
#
# entries-in-buffer/entries-written: 5/5   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        blockdev-191   [005] ...1   194.401517: p_blkdev_put_0: (blkdev_put+0x0/0x130)
        blockdev-191   [005] ...1   194.401527: p___blkdev_put_0: (__blkdev_put+0x0/0x220)
        blockdev-191   [005] ...1   194.401529: p___blkdev_put_0: (__blkdev_put+0x0/0x220)
        blockdev-191   [005] d..2   194.401535: r___blkdev_put_0: (__blkdev_put+0x1ea/0x220 <- __blkdev_put)
        blockdev-191   [005] d..2   194.401536: r___blkdev_put_0: (blkdev_put+0x50/0x130 <- __blkdev_put)

In this case, we can see the __blkdev_put() is called twice, from
blkdev_put() and __blkdev_put() itself (nested call).

So, it seems that the kprobe event correctly works.

Could you do same thing on your environment, and share the result?

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: kprobe: __blkdev_put probe is missed

[Ming Lei]

Hi Masami,

On Fri, Jun 19, 2020 at 02:12:39PM +0900, Masami Hiramatsu wrote:
> Hi Ming,
> 
> On Fri, 19 Jun 2020 07:19:01 +0800
> Ming Lei <ming.lei@redhat.com> wrote:
> 
> > > I'm using 5.4 on ubuntu and can not reproduce it with kprobe_event.
> > > 
> > > root@devnote2:/sys/kernel/tracing# uname -a
> > > Linux devnote2 5.4.0-37-generic #41-Ubuntu SMP Wed Jun 3 18:57:02 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
> > > root@devnote2:/sys/kernel/tracing# echo p __blkdev_put > kprobe_events 
> > > root@devnote2:/sys/kernel/tracing# echo 1 > events/kprobes/p___blkdev_put_0/enable 
> > > root@devnote2:/sys/kernel/tracing# cat trace
> > > # tracer: nop
> > > #
> > > # entries-in-buffer/entries-written: 0/0   #P:8
> > > #
> > > #                              _-----=> irqs-off
> > > #                             / _----=> need-resched
> > > #                            | / _---=> hardirq/softirq
> > > #                            || / _--=> preempt-depth
> > > #                            ||| /     delay
> > > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > > #              | |       |   ||||       |         |
> > > root@devnote2:/sys/kernel/tracing# blockdev --getbsz /dev/nvme0n1
> > > 4096
> > > root@devnote2:/sys/kernel/tracing# cat trace
> > > # tracer: nop
> > > #
> > > # entries-in-buffer/entries-written: 1/1   #P:8
> > > #
> > > #                              _-----=> irqs-off
> > > #                             / _----=> need-resched
> > > #                            | / _---=> hardirq/softirq
> > > #                            || / _--=> preempt-depth
> > > #                            ||| /     delay
> > > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > > #              | |       |   ||||       |         |
> > >            <...>-111740 [002] .... 301734.476991: p___blkdev_put_0: (__blkdev_put+0x0/0x1e0)
> > > 
> > > Hmm, maybe some issue in the latest kernel...?
> > 
> > Hello Masami,
> > 
> > I am testing the latest upstream kernel, your trace actually reproduces
> > this issue.
> 
> OK.
> 
> > 
> > After 'blockdev --getbsz /dev/nvme0n1' returns, __blkdev_put() should
> > have been called two times(one for partition, and the other for disk),
> > however kprobe trace just shows one time of calling this function.
> > 
> > If trace_printk() is added at the entry of __blkdev_put() manually,
> > you will see that __blkdev_put() is called two times in 'blockdev
> > --getbsz /dev/nvme0n1'.
> 
> OK, let me check again on the latest kernel.
> Here I tested with qemu.
> 
> root@devnote2:/sys/kernel/debug/tracing# uname -a
> Linux devnote2 5.8.0-rc1+ #26 SMP PREEMPT Fri Jun 19 12:12:53 JST 2020 x86_64 x86_64 x86_64 GNU/Linux
> 
> And we have a (virtual) sda with 1 partition.
> 
> root@devnote2:/sys/kernel/debug/tracing# cat /proc/partitions 
> major minor  #blocks  name
> 
>    8        0      10240 sda
>    8        1       9216 sda1
> 
> OK, then let's make events (for sure)
> 
> root@devnote2:/sys/kernel/debug/tracing# echo p __blkdev_put >> kprobe_events 
> root@devnote2:/sys/kernel/debug/tracing# echo r __blkdev_put >> kprobe_events 
> root@devnote2:/sys/kernel/debug/tracing# echo p blkdev_put >> kprobe_events 
> 
> There are 3 events in the kernel, blkdev_put() and __blkdev_put() and
> the return of __blkdev_put().
> Then enable it and access to */dev/sda* (a disk)
> 
> root@devnote2:/sys/kernel/debug/tracing# echo 1 > events/kprobes/enable 
> root@devnote2:/sys/kernel/debug/tracing# blockdev --getbsz /dev/sda
> 4096
> root@devnote2:/sys/kernel/debug/tracing# echo 0 > events/kprobes/enable 
> root@devnote2:/sys/kernel/debug/tracing# cat trace 
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 3/3   #P:8
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>         blockdev-185   [002] ...1    72.604266: p_blkdev_put_0: (blkdev_put+0x0/0x130)
>         blockdev-185   [002] ...1    72.604276: p___blkdev_put_0: (__blkdev_put+0x0/0x220)
>         blockdev-185   [002] d..2    72.604288: r___blkdev_put_0: (blkdev_put+0x50/0x130 <- __blkdev_put)
> 
> So the __blkdev_put() is called once from blkdev_put().
> Next, we do same trace with accessing */dev/sda1* (a partition).
> 
> root@devnote2:/sys/kernel/debug/tracing# echo > trace 
> root@devnote2:/sys/kernel/debug/tracing# echo 1 > events/kprobes/enable 

I can't find 'events/kprobes' in my VM with upstream kernel, also not found
the dir under fedora31(5.5.15-200) & rhel8(v4.18 based).

Could you share me how to enable the kprobes event? I guess some kernel
config options are required.

> root@devnote2:/sys/kernel/debug/tracing# blockdev --getbsz /dev/sda1 
> 4096
> root@devnote2:/sys/kernel/debug/tracing# echo 0 > events/kprobes/enable 

I used samples/kprobes/kprobe_example.c by replacing __do_fork with
__blkdev_put for confirming this issue, and only one __blkdev_put trace is
observed in dmesg log when running 'blockdev --getbsz /dev/sda1'.


Thanks,
Ming

Re: kprobe: __blkdev_put probe is missed

[Steven Rostedt]

On Fri, 19 Jun 2020 15:28:59 +0800
Ming Lei <ming.lei@redhat.com> wrote:

> > 
> > OK, then let's make events (for sure)
> > 
> > root@devnote2:/sys/kernel/debug/tracing# echo p __blkdev_put >> kprobe_events 
> > root@devnote2:/sys/kernel/debug/tracing# echo r __blkdev_put >> kprobe_events 
> > root@devnote2:/sys/kernel/debug/tracing# echo p blkdev_put >> kprobe_events 

Hi Ming,

Do you have the kprobe_events file?

> > root@devnote2:/sys/kernel/debug/tracing# echo 1 > events/kprobes/enable   
> 
> I can't find 'events/kprobes' in my VM with upstream kernel, also not found
> the dir under fedora31(5.5.15-200) & rhel8(v4.18 based).

The events/kprobes directly will be created when you create a
kprobe_event. It wont exist until then.

-- Steve

Re: kprobe: __blkdev_put probe is missed

[Ming Lei]

[-- Attachment #1: Type: text/plain, Size: 2469 bytes --]

On Fri, Jun 19, 2020 at 08:19:54AM -0400, Steven Rostedt wrote:
> On Fri, 19 Jun 2020 15:28:59 +0800
> Ming Lei <ming.lei@redhat.com> wrote:
> 
> > > 
> > > OK, then let's make events (for sure)
> > > 
> > > root@devnote2:/sys/kernel/debug/tracing# echo p __blkdev_put >> kprobe_events 
> > > root@devnote2:/sys/kernel/debug/tracing# echo r __blkdev_put >> kprobe_events 
> > > root@devnote2:/sys/kernel/debug/tracing# echo p blkdev_put >> kprobe_events 
> 
> Hi Ming,
> 
> Do you have the kprobe_events file?
> 
> > > root@devnote2:/sys/kernel/debug/tracing# echo 1 > events/kprobes/enable   
> > 
> > I can't find 'events/kprobes' in my VM with upstream kernel, also not found
> > the dir under fedora31(5.5.15-200) & rhel8(v4.18 based).
> 
> The events/kprobes directly will be created when you create a
> kprobe_event. It wont exist until then.

Hi Steven and Masami,

Got it, thanks for your help, now I can run the test, follows the steps
and results, and there is still one __blkdev_put probed.

And it is observed in my VM reliably with 5.7+ or Fedora kernel reliably,
kernel config is attached.

[root@ktest-01 tracing]# uname -a
Linux ktest-01 5.7.0+ #1900 SMP Fri Jun 19 16:26:47 CST 2020 x86_64 x86_64 x86_64 GNU/Linux
[root@ktest-01 tracing]#
[root@ktest-01 tracing]# cat kprobe_events
[root@ktest-01 tracing]#
[root@ktest-01 tracing]# echo p blkdev_put >> kprobe_events
[root@ktest-01 tracing]# echo p __blkdev_put >> kprobe_events
[root@ktest-01 tracing]# echo r __blkdev_put >> kprobe_events
[root@ktest-01 tracing]#
[root@ktest-01 tracing]# echo 1 > events/kprobes/enable
[root@ktest-01 tracing]# blockdev --getbsz /dev/sda1
4096
[root@ktest-01 tracing]# echo 0 > events/kprobes/enable
[root@ktest-01 tracing]# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 3/3   #P:8
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        blockdev-970   [005] .... 17603.447236: p_blkdev_put_0: (blkdev_put+0x0/0xb4)
        blockdev-970   [005] .... 17603.447244: p___blkdev_put_0: (__blkdev_put+0x0/0x19d)
        blockdev-970   [005] d... 17603.447251: r___blkdev_put_0: (blkdev_close+0x22/0x25 <- __blkdev_put)


Thanks,
Ming

[-- Attachment #2: config.tar.gz --]
[-- Type: application/gzip, Size: 25982 bytes --]

Re: kprobe: __blkdev_put probe is missed

[Masami Hiramatsu]

Hi Ming,

On Fri, 19 Jun 2020 21:32:40 +0800
Ming Lei <ming.lei@redhat.com> wrote:

> On Fri, Jun 19, 2020 at 08:19:54AM -0400, Steven Rostedt wrote:
> > On Fri, 19 Jun 2020 15:28:59 +0800
> > Ming Lei <ming.lei@redhat.com> wrote:
> > 
> > > > 
> > > > OK, then let's make events (for sure)
> > > > 
> > > > root@devnote2:/sys/kernel/debug/tracing# echo p __blkdev_put >> kprobe_events 
> > > > root@devnote2:/sys/kernel/debug/tracing# echo r __blkdev_put >> kprobe_events 
> > > > root@devnote2:/sys/kernel/debug/tracing# echo p blkdev_put >> kprobe_events 
> > 
> > Hi Ming,
> > 
> > Do you have the kprobe_events file?
> > 
> > > > root@devnote2:/sys/kernel/debug/tracing# echo 1 > events/kprobes/enable   
> > > 
> > > I can't find 'events/kprobes' in my VM with upstream kernel, also not found
> > > the dir under fedora31(5.5.15-200) & rhel8(v4.18 based).
> > 
> > The events/kprobes directly will be created when you create a
> > kprobe_event. It wont exist until then.
> 
> Hi Steven and Masami,
> 
> Got it, thanks for your help, now I can run the test, follows the steps
> and results, and there is still one __blkdev_put probed.

Hmm, strange...

> And it is observed in my VM reliably with 5.7+ or Fedora kernel reliably,
> kernel config is attached.

Thanks for sharing it.

> 
> [root@ktest-01 tracing]# uname -a
> Linux ktest-01 5.7.0+ #1900 SMP Fri Jun 19 16:26:47 CST 2020 x86_64 x86_64 x86_64 GNU/Linux
> [root@ktest-01 tracing]#
> [root@ktest-01 tracing]# cat kprobe_events
> [root@ktest-01 tracing]#
> [root@ktest-01 tracing]# echo p blkdev_put >> kprobe_events
> [root@ktest-01 tracing]# echo p __blkdev_put >> kprobe_events
> [root@ktest-01 tracing]# echo r __blkdev_put >> kprobe_events
> [root@ktest-01 tracing]#
> [root@ktest-01 tracing]# echo 1 > events/kprobes/enable
> [root@ktest-01 tracing]# blockdev --getbsz /dev/sda1
> 4096
> [root@ktest-01 tracing]# echo 0 > events/kprobes/enable
> [root@ktest-01 tracing]# cat trace
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 3/3   #P:8
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>         blockdev-970   [005] .... 17603.447236: p_blkdev_put_0: (blkdev_put+0x0/0xb4)
>         blockdev-970   [005] .... 17603.447244: p___blkdev_put_0: (__blkdev_put+0x0/0x19d)
>         blockdev-970   [005] d... 17603.447251: r___blkdev_put_0: (blkdev_close+0x22/0x25 <- __blkdev_put)

This shows __blkdev_put() is a tail-call. It is possible that the
internal (nested) __blkdev_put() call becomes a goto inside the
function by the gcc optimization.

Ah, after all it is as expected. With your kconfig, the kernel is
very agressively optimized.

$ objdump -dS vmlinux | less
...
ffffffff81256dc3 <__blkdev_put>:
{
ffffffff81256dc3:       e8 98 85 df ff          callq  ffffffff8104f360 <__fentry__>
ffffffff81256dc8:       41 57                   push   %r15
ffffffff81256dca:       41 56                   push   %r14
ffffffff81256dcc:       41 55                   push   %r13
...
ffffffff81256f05:       75 02                   jne    ffffffff81256f09 <__blkdev_put+0x146>
        struct block_device *victim = NULL;
ffffffff81256f07:       31 db                   xor    %ebx,%ebx
                bdev->bd_contains = NULL;
ffffffff81256f09:       48 c7 45 60 00 00 00    movq   $0x0,0x60(%rbp)
ffffffff81256f10:       00 
                put_disk_and_module(disk);
ffffffff81256f11:       4c 89 f7                mov    %r14,%rdi
ffffffff81256f14:       e8 c6 3d 11 00          callq  ffffffff8136acdf <put_disk_and_module>
        mutex_unlock(&bdev->bd_mutex);
ffffffff81256f19:       4c 89 ff                mov    %r15,%rdi
                __blkdev_put(victim, mode, 1);
ffffffff81256f1c:       41 bc 01 00 00 00       mov    $0x1,%r12d
        mutex_unlock(&bdev->bd_mutex);
ffffffff81256f22:       e8 8d d7 48 00          callq  ffffffff816e46b4 <mutex_unlock>
        bdput(bdev);
ffffffff81256f27:       48 89 ef                mov    %rbp,%rdi
ffffffff81256f2a:       e8 f0 e9 ff ff          callq  ffffffff8125591f <bdput>
        if (victim)
ffffffff81256f2f:       48 85 db                test   %rbx,%rbx
ffffffff81256f32:       74 08                   je     ffffffff81256f3c <__blkdev_put+0x179>
ffffffff81256f34:       48 89 dd                mov    %rbx,%rbp
ffffffff81256f37:       e9 b4 fe ff ff          jmpq   ffffffff81256df0 <__blkdev_put+0x2d> <<-----THIS!!
}
ffffffff81256f3c:       48 8b 44 24 28          mov    0x28(%rsp),%rax
ffffffff81256f41:       65 48 33 04 25 28 00    xor    %gs:0x28,%rax
ffffffff81256f48:       00 00 
ffffffff81256f4a:       74 05                   je     ffffffff81256f51 <__blkdev_put+0x18e>
ffffffff81256f4c:       e8 5a 4e 48 00          callq  ffffffff816dbdab <__stack_chk_fail>
ffffffff81256f51:       48 83 c4 30             add    $0x30,%rsp
ffffffff81256f55:       5b                      pop    %rbx
ffffffff81256f56:       5d                      pop    %rbp
ffffffff81256f57:       41 5c                   pop    %r12
ffffffff81256f59:       41 5d                   pop    %r13
ffffffff81256f5b:       41 5e                   pop    %r14
ffffffff81256f5d:       41 5f                   pop    %r15
ffffffff81256f5f:       c3                      retq   


As you can see, the nested __blkdev_put() is coverted to a loop.
If you put kprobe on __blkdev_put+0x2d, you'll see the event twice.

Thank you,
 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: kprobe: __blkdev_put probe is missed

[Ming Lei]

Hi Masami,

On Sat, Jun 20, 2020 at 12:35:09AM +0900, Masami Hiramatsu wrote:
> Hi Ming,
> 
> On Fri, 19 Jun 2020 21:32:40 +0800
> Ming Lei <ming.lei@redhat.com> wrote:
> 
> > On Fri, Jun 19, 2020 at 08:19:54AM -0400, Steven Rostedt wrote:
> > > On Fri, 19 Jun 2020 15:28:59 +0800
> > > Ming Lei <ming.lei@redhat.com> wrote:
> > > 
> > > > > 
> > > > > OK, then let's make events (for sure)
> > > > > 
> > > > > root@devnote2:/sys/kernel/debug/tracing# echo p __blkdev_put >> kprobe_events 
> > > > > root@devnote2:/sys/kernel/debug/tracing# echo r __blkdev_put >> kprobe_events 
> > > > > root@devnote2:/sys/kernel/debug/tracing# echo p blkdev_put >> kprobe_events 
> > > 
> > > Hi Ming,
> > > 
> > > Do you have the kprobe_events file?
> > > 
> > > > > root@devnote2:/sys/kernel/debug/tracing# echo 1 > events/kprobes/enable   
> > > > 
> > > > I can't find 'events/kprobes' in my VM with upstream kernel, also not found
> > > > the dir under fedora31(5.5.15-200) & rhel8(v4.18 based).
> > > 
> > > The events/kprobes directly will be created when you create a
> > > kprobe_event. It wont exist until then.
> > 
> > Hi Steven and Masami,
> > 
> > Got it, thanks for your help, now I can run the test, follows the steps
> > and results, and there is still one __blkdev_put probed.
> 
> Hmm, strange...
> 
> > And it is observed in my VM reliably with 5.7+ or Fedora kernel reliably,
> > kernel config is attached.
> 
> Thanks for sharing it.
> 
> > 
> > [root@ktest-01 tracing]# uname -a
> > Linux ktest-01 5.7.0+ #1900 SMP Fri Jun 19 16:26:47 CST 2020 x86_64 x86_64 x86_64 GNU/Linux
> > [root@ktest-01 tracing]#
> > [root@ktest-01 tracing]# cat kprobe_events
> > [root@ktest-01 tracing]#
> > [root@ktest-01 tracing]# echo p blkdev_put >> kprobe_events
> > [root@ktest-01 tracing]# echo p __blkdev_put >> kprobe_events
> > [root@ktest-01 tracing]# echo r __blkdev_put >> kprobe_events
> > [root@ktest-01 tracing]#
> > [root@ktest-01 tracing]# echo 1 > events/kprobes/enable
> > [root@ktest-01 tracing]# blockdev --getbsz /dev/sda1
> > 4096
> > [root@ktest-01 tracing]# echo 0 > events/kprobes/enable
> > [root@ktest-01 tracing]# cat trace
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 3/3   #P:8
> > #
> > #                              _-----=> irqs-off
> > #                             / _----=> need-resched
> > #                            | / _---=> hardirq/softirq
> > #                            || / _--=> preempt-depth
> > #                            ||| /     delay
> > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > #              | |       |   ||||       |         |
> >         blockdev-970   [005] .... 17603.447236: p_blkdev_put_0: (blkdev_put+0x0/0xb4)
> >         blockdev-970   [005] .... 17603.447244: p___blkdev_put_0: (__blkdev_put+0x0/0x19d)
> >         blockdev-970   [005] d... 17603.447251: r___blkdev_put_0: (blkdev_close+0x22/0x25 <- __blkdev_put)
> 
> This shows __blkdev_put() is a tail-call. It is possible that the
> internal (nested) __blkdev_put() call becomes a goto inside the
> function by the gcc optimization.
> 
> Ah, after all it is as expected. With your kconfig, the kernel is
> very agressively optimized.
> 
> $ objdump -dS vmlinux | less
> ...
> ffffffff81256dc3 <__blkdev_put>:
> {
> ffffffff81256dc3:       e8 98 85 df ff          callq  ffffffff8104f360 <__fentry__>
> ffffffff81256dc8:       41 57                   push   %r15
> ffffffff81256dca:       41 56                   push   %r14
> ffffffff81256dcc:       41 55                   push   %r13
> ...
> ffffffff81256f05:       75 02                   jne    ffffffff81256f09 <__blkdev_put+0x146>
>         struct block_device *victim = NULL;
> ffffffff81256f07:       31 db                   xor    %ebx,%ebx
>                 bdev->bd_contains = NULL;
> ffffffff81256f09:       48 c7 45 60 00 00 00    movq   $0x0,0x60(%rbp)
> ffffffff81256f10:       00 
>                 put_disk_and_module(disk);
> ffffffff81256f11:       4c 89 f7                mov    %r14,%rdi
> ffffffff81256f14:       e8 c6 3d 11 00          callq  ffffffff8136acdf <put_disk_and_module>
>         mutex_unlock(&bdev->bd_mutex);
> ffffffff81256f19:       4c 89 ff                mov    %r15,%rdi
>                 __blkdev_put(victim, mode, 1);
> ffffffff81256f1c:       41 bc 01 00 00 00       mov    $0x1,%r12d
>         mutex_unlock(&bdev->bd_mutex);
> ffffffff81256f22:       e8 8d d7 48 00          callq  ffffffff816e46b4 <mutex_unlock>
>         bdput(bdev);
> ffffffff81256f27:       48 89 ef                mov    %rbp,%rdi
> ffffffff81256f2a:       e8 f0 e9 ff ff          callq  ffffffff8125591f <bdput>
>         if (victim)
> ffffffff81256f2f:       48 85 db                test   %rbx,%rbx
> ffffffff81256f32:       74 08                   je     ffffffff81256f3c <__blkdev_put+0x179>
> ffffffff81256f34:       48 89 dd                mov    %rbx,%rbp
> ffffffff81256f37:       e9 b4 fe ff ff          jmpq   ffffffff81256df0 <__blkdev_put+0x2d> <<-----THIS!!
> }
> ffffffff81256f3c:       48 8b 44 24 28          mov    0x28(%rsp),%rax
> ffffffff81256f41:       65 48 33 04 25 28 00    xor    %gs:0x28,%rax
> ffffffff81256f48:       00 00 
> ffffffff81256f4a:       74 05                   je     ffffffff81256f51 <__blkdev_put+0x18e>
> ffffffff81256f4c:       e8 5a 4e 48 00          callq  ffffffff816dbdab <__stack_chk_fail>
> ffffffff81256f51:       48 83 c4 30             add    $0x30,%rsp
> ffffffff81256f55:       5b                      pop    %rbx
> ffffffff81256f56:       5d                      pop    %rbp
> ffffffff81256f57:       41 5c                   pop    %r12
> ffffffff81256f59:       41 5d                   pop    %r13
> ffffffff81256f5b:       41 5e                   pop    %r14
> ffffffff81256f5d:       41 5f                   pop    %r15
> ffffffff81256f5f:       c3                      retq   
> 
> 
> As you can see, the nested __blkdev_put() is coverted to a loop.
> If you put kprobe on __blkdev_put+0x2d, you'll see the event twice.

Thanks for your investigation.

Some trace tools can just trace on function entry, such as bcc, and some
user script always trace on function entry.

I guess the issue should belong to kprobe implementation:

1) __blkdev_put() is capable of being kprobed, so from user view, the
probe on entry of __blkdev_put() should be triggered

2) from implementation view, I understand exception should be trapped
on the entry of __blkdev_put(), looks it isn't done.

Correct me if the above is wrong, and is it possible to fix it in kprobe?


Thanks,
Ming

Re: kprobe: __blkdev_put probe is missed

[Steven Rostedt]

On Sat, 20 Jun 2020 07:28:20 +0800
Ming Lei <ming.lei@redhat.com> wrote:

> Thanks for your investigation.
> 
> Some trace tools can just trace on function entry, such as bcc, and some
> user script always trace on function entry.
> 
> I guess the issue should belong to kprobe implementation:

The issue is that kprobes is to dynamically add trace events into an
already compiled kernel. I'm guessing you would get the same result
from ftrace's function tracer. That's because the compiler has no idea
about what or where you intend to add these dynamically created trace
events (that's basically the point of kprobes). But if you add static
events (and this includes trace_printk()), the compiler knows about
them, because they exist at compile time, and will make sure they
execute the number of times the code shows it. But if you don't have
these events at compile time, the compiler is free to modify the code
in such a way it doesn't make sense if you add a probe at run time.

gdb suffers the same problem on user space debugging if you let the
compiler aggressively optimize the code. If you step through highly
optimized user space code with gdb, the position jumps all over the
place. This is basically the same effect.

> 
> 1) __blkdev_put() is capable of being kprobed, so from user view, the
> probe on entry of __blkdev_put() should be triggered
> 
> 2) from implementation view, I understand exception should be trapped
> on the entry of __blkdev_put(), looks it isn't done.

But it is done! But the compiler removed the second call and basically
just inlined it. So that entry no longer exists. When you added a
"trace_printk()" in there, the compiler is not allowed to skip that
trace call. But because there's nothing in here to tell the compiler
that it can't just remove the second call (which it did, and the kprobe
is just showing you what the compiler did!) then there's nothing
kprobes can do about it.

> 
> Correct me if the above is wrong, and is it possible to fix it in kprobe?

No.

-- Steve

Re: kprobe: __blkdev_put probe is missed

[Masami Hiramatsu]

Hi Ming,

On Sat, 20 Jun 2020 07:28:20 +0800
Ming Lei <ming.lei@redhat.com> wrote:

> > 
> > Ah, after all it is as expected. With your kconfig, the kernel is
> > very agressively optimized.
> > 
> > $ objdump -dS vmlinux | less
> > ...
> > ffffffff81256dc3 <__blkdev_put>:
> > {
> > ffffffff81256dc3:       e8 98 85 df ff          callq  ffffffff8104f360 <__fentry__>
> > ffffffff81256dc8:       41 57                   push   %r15
> > ffffffff81256dca:       41 56                   push   %r14
> > ffffffff81256dcc:       41 55                   push   %r13
> > ...
> > ffffffff81256f05:       75 02                   jne    ffffffff81256f09 <__blkdev_put+0x146>
> >         struct block_device *victim = NULL;
> > ffffffff81256f07:       31 db                   xor    %ebx,%ebx
> >                 bdev->bd_contains = NULL;
> > ffffffff81256f09:       48 c7 45 60 00 00 00    movq   $0x0,0x60(%rbp)
> > ffffffff81256f10:       00 
> >                 put_disk_and_module(disk);
> > ffffffff81256f11:       4c 89 f7                mov    %r14,%rdi
> > ffffffff81256f14:       e8 c6 3d 11 00          callq  ffffffff8136acdf <put_disk_and_module>
> >         mutex_unlock(&bdev->bd_mutex);
> > ffffffff81256f19:       4c 89 ff                mov    %r15,%rdi
> >                 __blkdev_put(victim, mode, 1);
> > ffffffff81256f1c:       41 bc 01 00 00 00       mov    $0x1,%r12d
> >         mutex_unlock(&bdev->bd_mutex);
> > ffffffff81256f22:       e8 8d d7 48 00          callq  ffffffff816e46b4 <mutex_unlock>
> >         bdput(bdev);
> > ffffffff81256f27:       48 89 ef                mov    %rbp,%rdi
> > ffffffff81256f2a:       e8 f0 e9 ff ff          callq  ffffffff8125591f <bdput>
> >         if (victim)
> > ffffffff81256f2f:       48 85 db                test   %rbx,%rbx
> > ffffffff81256f32:       74 08                   je     ffffffff81256f3c <__blkdev_put+0x179>
> > ffffffff81256f34:       48 89 dd                mov    %rbx,%rbp
> > ffffffff81256f37:       e9 b4 fe ff ff          jmpq   ffffffff81256df0 <__blkdev_put+0x2d> <<-----THIS!!
> > }
> > ffffffff81256f3c:       48 8b 44 24 28          mov    0x28(%rsp),%rax
> > ffffffff81256f41:       65 48 33 04 25 28 00    xor    %gs:0x28,%rax
> > ffffffff81256f48:       00 00 
> > ffffffff81256f4a:       74 05                   je     ffffffff81256f51 <__blkdev_put+0x18e>
> > ffffffff81256f4c:       e8 5a 4e 48 00          callq  ffffffff816dbdab <__stack_chk_fail>
> > ffffffff81256f51:       48 83 c4 30             add    $0x30,%rsp
> > ffffffff81256f55:       5b                      pop    %rbx
> > ffffffff81256f56:       5d                      pop    %rbp
> > ffffffff81256f57:       41 5c                   pop    %r12
> > ffffffff81256f59:       41 5d                   pop    %r13
> > ffffffff81256f5b:       41 5e                   pop    %r14
> > ffffffff81256f5d:       41 5f                   pop    %r15
> > ffffffff81256f5f:       c3                      retq   
> > 
> > 
> > As you can see, the nested __blkdev_put() is coverted to a loop.
> > If you put kprobe on __blkdev_put+0x2d, you'll see the event twice.
> 
> Thanks for your investigation.
> 
> Some trace tools can just trace on function entry, such as bcc, and some
> user script always trace on function entry.
> 
> I guess the issue should belong to kprobe implementation:
> 
> 1) __blkdev_put() is capable of being kprobed, so from user view, the
> probe on entry of __blkdev_put() should be triggered

Yes, it is correctly triggered.

> 
> 2) from implementation view, I understand exception should be trapped
> on the entry of __blkdev_put(), looks it isn't done.

No, it is correctly trapped the function entry address. The problem is
that the gcc optimized the nested function call into jump to the
beginning of function body (skip prologue).

Usually, a function is compiled as below

func()     (1) the entry address (func:)
{          (2) the function prologue (setup stackframe)  
  int a    (3) the beginning of function body 
   ...
  func()   (4) the nested function call

And in this case, the gcc optimized (4) into jump to (3) instead of
actual function call instruction. Thus, for the nested case (1) and
(2) are skipped.
 IOW, the code flow becomes
  (1)->(2)->(3)->(4)->(3)
 instead of 
  (1)->(2)->(3)->(4)->(1)->(2)->(3)

In this case, if we put a probe on (1) or (2), those are disappeared
in the nested call. Thus if you put a probe on (3) ('perf probe __blkdev_put:2')
you'll see the event twice.

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: kprobe: __blkdev_put probe is missed

[Ming Lei]

Hi Masami,

On Sat, Jun 20, 2020 at 10:37:47AM +0900, Masami Hiramatsu wrote:
> Hi Ming,
> 
> On Sat, 20 Jun 2020 07:28:20 +0800
> Ming Lei <ming.lei@redhat.com> wrote:
> 
> > > 
> > > Ah, after all it is as expected. With your kconfig, the kernel is
> > > very agressively optimized.
> > > 
> > > $ objdump -dS vmlinux | less
> > > ...
> > > ffffffff81256dc3 <__blkdev_put>:
> > > {
> > > ffffffff81256dc3:       e8 98 85 df ff          callq  ffffffff8104f360 <__fentry__>
> > > ffffffff81256dc8:       41 57                   push   %r15
> > > ffffffff81256dca:       41 56                   push   %r14
> > > ffffffff81256dcc:       41 55                   push   %r13
> > > ...
> > > ffffffff81256f05:       75 02                   jne    ffffffff81256f09 <__blkdev_put+0x146>
> > >         struct block_device *victim = NULL;
> > > ffffffff81256f07:       31 db                   xor    %ebx,%ebx
> > >                 bdev->bd_contains = NULL;
> > > ffffffff81256f09:       48 c7 45 60 00 00 00    movq   $0x0,0x60(%rbp)
> > > ffffffff81256f10:       00 
> > >                 put_disk_and_module(disk);
> > > ffffffff81256f11:       4c 89 f7                mov    %r14,%rdi
> > > ffffffff81256f14:       e8 c6 3d 11 00          callq  ffffffff8136acdf <put_disk_and_module>
> > >         mutex_unlock(&bdev->bd_mutex);
> > > ffffffff81256f19:       4c 89 ff                mov    %r15,%rdi
> > >                 __blkdev_put(victim, mode, 1);
> > > ffffffff81256f1c:       41 bc 01 00 00 00       mov    $0x1,%r12d
> > >         mutex_unlock(&bdev->bd_mutex);
> > > ffffffff81256f22:       e8 8d d7 48 00          callq  ffffffff816e46b4 <mutex_unlock>
> > >         bdput(bdev);
> > > ffffffff81256f27:       48 89 ef                mov    %rbp,%rdi
> > > ffffffff81256f2a:       e8 f0 e9 ff ff          callq  ffffffff8125591f <bdput>
> > >         if (victim)
> > > ffffffff81256f2f:       48 85 db                test   %rbx,%rbx
> > > ffffffff81256f32:       74 08                   je     ffffffff81256f3c <__blkdev_put+0x179>
> > > ffffffff81256f34:       48 89 dd                mov    %rbx,%rbp
> > > ffffffff81256f37:       e9 b4 fe ff ff          jmpq   ffffffff81256df0 <__blkdev_put+0x2d> <<-----THIS!!
> > > }
> > > ffffffff81256f3c:       48 8b 44 24 28          mov    0x28(%rsp),%rax
> > > ffffffff81256f41:       65 48 33 04 25 28 00    xor    %gs:0x28,%rax
> > > ffffffff81256f48:       00 00 
> > > ffffffff81256f4a:       74 05                   je     ffffffff81256f51 <__blkdev_put+0x18e>
> > > ffffffff81256f4c:       e8 5a 4e 48 00          callq  ffffffff816dbdab <__stack_chk_fail>
> > > ffffffff81256f51:       48 83 c4 30             add    $0x30,%rsp
> > > ffffffff81256f55:       5b                      pop    %rbx
> > > ffffffff81256f56:       5d                      pop    %rbp
> > > ffffffff81256f57:       41 5c                   pop    %r12
> > > ffffffff81256f59:       41 5d                   pop    %r13
> > > ffffffff81256f5b:       41 5e                   pop    %r14
> > > ffffffff81256f5d:       41 5f                   pop    %r15
> > > ffffffff81256f5f:       c3                      retq   
> > > 
> > > 
> > > As you can see, the nested __blkdev_put() is coverted to a loop.
> > > If you put kprobe on __blkdev_put+0x2d, you'll see the event twice.
> > 
> > Thanks for your investigation.
> > 
> > Some trace tools can just trace on function entry, such as bcc, and some
> > user script always trace on function entry.
> > 
> > I guess the issue should belong to kprobe implementation:
> > 
> > 1) __blkdev_put() is capable of being kprobed, so from user view, the
> > probe on entry of __blkdev_put() should be triggered
> 
> Yes, it is correctly triggered.

I mean it isn't from user's viewpoint, and the binary code is usually a
black box for final kprobe user.

IMO, all your and Steven's input are just from kprobe/trace developer's viewpoint.
Can you think about the issue from kprobe real/final user?

Trace is very useful tools to observe system internal, and people often
relies on trace to understand system. However, missed probe often causes
trouble for us to understand the system correctly.

> 
> > 
> > 2) from implementation view, I understand exception should be trapped
> > on the entry of __blkdev_put(), looks it isn't done.
> 
> No, it is correctly trapped the function entry address. The problem is
> that the gcc optimized the nested function call into jump to the
> beginning of function body (skip prologue).
> 
> Usually, a function is compiled as below
> 
> func()     (1) the entry address (func:)
> {          (2) the function prologue (setup stackframe)  
>   int a    (3) the beginning of function body 
>    ...
>   func()   (4) the nested function call
> 
> And in this case, the gcc optimized (4) into jump to (3) instead of
> actual function call instruction. Thus, for the nested case (1) and
> (2) are skipped.
>  IOW, the code flow becomes
>   (1)->(2)->(3)->(4)->(3)
>  instead of 
>   (1)->(2)->(3)->(4)->(1)->(2)->(3)
> 
> In this case, if we put a probe on (1) or (2), those are disappeared
> in the nested call. Thus if you put a probe on (3) ('perf probe __blkdev_put:2')
> you'll see the event twice.

Thanks for your explanation.

Can you kprobe guys improve the implementation for covering this case?
For example, put probe on 3) in case the above situation is recognized.



Thanks,
Ming

Re: kprobe: __blkdev_put probe is missed

[Masami Hiramatsu]

On Mon, 22 Jun 2020 08:27:53 +0800
Ming Lei <ming.lei@redhat.com> wrote:

> I mean it isn't from user's viewpoint, and the binary code is usually a
> black box for final kprobe user.
> 
> IMO, all your and Steven's input are just from kprobe/trace developer's viewpoint.
> Can you think about the issue from kprobe real/final user?
> 
> Trace is very useful tools to observe system internal, and people often
> relies on trace to understand system. However, missed probe often causes
> trouble for us to understand the system correctly.

Agreed. However, since kprobes related tracing tools are layered
to provide different features (e.g. kprobes abstructs sw breakpoint,
ftrace kprobe-events provides a minimum CUI, and perf-probe provides
binary analysis, etc.), this issue should be solved by user-level
binary analysis layer. (it is not good idea to analyze the optimized
code in kernel)


> > > 2) from implementation view, I understand exception should be trapped
> > > on the entry of __blkdev_put(), looks it isn't done.
> > 
> > No, it is correctly trapped the function entry address. The problem is
> > that the gcc optimized the nested function call into jump to the
> > beginning of function body (skip prologue).
> > 
> > Usually, a function is compiled as below
> > 
> > func()     (1) the entry address (func:)
> > {          (2) the function prologue (setup stackframe)  
> >   int a    (3) the beginning of function body 
> >    ...
> >   func()   (4) the nested function call
> > 
> > And in this case, the gcc optimized (4) into jump to (3) instead of
> > actual function call instruction. Thus, for the nested case (1) and
> > (2) are skipped.
> >  IOW, the code flow becomes
> >   (1)->(2)->(3)->(4)->(3)
> >  instead of 
> >   (1)->(2)->(3)->(4)->(1)->(2)->(3)
> > 
> > In this case, if we put a probe on (1) or (2), those are disappeared
> > in the nested call. Thus if you put a probe on (3) ('perf probe __blkdev_put:2')
> > you'll see the event twice.
> 
> Thanks for your explanation.
> 
> Can you kprobe guys improve the implementation for covering this case?
> For example, put probe on 3) in case the above situation is recognized.

OK, let me try to fix this in perf-probe since that is the simplest
binary analysis part in user-space.

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: kprobe: __blkdev_put probe is missed

[Steven Rostedt]

On Mon, 22 Jun 2020 08:27:53 +0800
Ming Lei <ming.lei@redhat.com> wrote:

> Can you kprobe guys improve the implementation for covering this case?
> For example, put probe on 3) in case the above situation is recognized.

To do so would require solving the halting problem.

  https://en.wikipedia.org/wiki/Halting_problem

Or perhaps reading the DWARF output of the compiler to determine if it
optimized the location you are looking for.

The first case is impossible to solve, the second would take a lot of
work, (are you going to fund it?)

Your comment about tracing internals is valid, but if you can't
understand the optimization of the compiler on the kernel, I suggest
you stick with the static trace events. kprobes can be added virtual
anywhere in the kernel. It's very function requires a kprobe *user* to
understand the internals of the kernel as well as its executable binary
code, and not expect the kprobe to figure it out for you.

We are all for adding infrastructure to make kprobes easier. But
figuring out that the kernel optimized a function call so that we can
add some wrapper to *simulate* the optimized out function call is
something I believe is out of scope for a kprobe. In fact, I would call
that a feature! I would like to know that a function was optimized out.
When I add a kprobe, I'm more interested in what the compiler actually
did to the kernel than what the source code shows us. That is very
useful information.

-- Steve

Re: kprobe: __blkdev_put probe is missed

[Masami Hiramatsu]

On Mon, 22 Jun 2020 09:01:48 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Mon, 22 Jun 2020 08:27:53 +0800
> Ming Lei <ming.lei@redhat.com> wrote:
> 
> > Can you kprobe guys improve the implementation for covering this case?
> > For example, put probe on 3) in case the above situation is recognized.
> 
> To do so would require solving the halting problem.
> 
>   https://en.wikipedia.org/wiki/Halting_problem
> 
> Or perhaps reading the DWARF output of the compiler to determine if it
> optimized the location you are looking for.

As far as I can see, gcc-9.3 doesn't generate this information :(
Maybe the optimizer forgot to push the tail-call callsite information
to dwarf generator when making a recursive tail-call to a loop.

> The first case is impossible to solve, the second would take a lot of
> work, (are you going to fund it?)

What I can provide is "--skip-prologue" option for the perf-probe
which will be similar to the "-P" option. If the compiler correctly
generates the information, we can enable it automatically. But
as far as I can see, it doesn't.

[OT] DWARF has its option(and GNU extension) but it seems not correctly
implemented yet.
 
http://www.dwarfstd.org/ShowIssue.php?issue=100909.2

What I found on __blkdev_put and the callers, the "tail-call to other
function" were recorded as a call-site DIE with DW_AT_tail_call. But
if the "tail-call to itself (recursive call)" was expanded as a loop,
it was just disappeared. No call-site information, nor the DW_AT_tail_call.

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: kprobe: __blkdev_put probe is missed

[Masami Hiramatsu]

On Tue, 23 Jun 2020 08:47:06 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> On Mon, 22 Jun 2020 09:01:48 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Mon, 22 Jun 2020 08:27:53 +0800
> > Ming Lei <ming.lei@redhat.com> wrote:
> > 
> > > Can you kprobe guys improve the implementation for covering this case?
> > > For example, put probe on 3) in case the above situation is recognized.
> > 
> > To do so would require solving the halting problem.
> > 
> >   https://en.wikipedia.org/wiki/Halting_problem
> > 
> > Or perhaps reading the DWARF output of the compiler to determine if it
> > optimized the location you are looking for.
> 
> As far as I can see, gcc-9.3 doesn't generate this information :(
> Maybe the optimizer forgot to push the tail-call callsite information
> to dwarf generator when making a recursive tail-call to a loop.
> 
> > The first case is impossible to solve, the second would take a lot of
> > work, (are you going to fund it?)
> 
> What I can provide is "--skip-prologue" option for the perf-probe
> which will be similar to the "-P" option. If the compiler correctly
> generates the information, we can enable it automatically. But
> as far as I can see, it doesn't.
> 
> [OT] DWARF has its option(and GNU extension) but it seems not correctly
> implemented yet.
>  
> http://www.dwarfstd.org/ShowIssue.php?issue=100909.2

Oops, sorry, I missed the following sentences.

"Tail calls are jump-like instructions which transfer control to the start
of some subprogram, but the call site location address isn't visible in the
unwind information."

"Tail recursion is a call to the current function which is compiled as a
loop into the middle of the current function."

"The DW_TAG_call_site entries describe normal and tail calls."

This means, the gcc is correctly implemented and this __blkdev_put() case
is NOT covered by DT_TAG_call_site.
So we can not detect it from the debuginfo.

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: kprobe: __blkdev_put probe is missed

[Masami Hiramatsu]

On Tue, 23 Jun 2020 09:38:01 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> On Tue, 23 Jun 2020 08:47:06 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > On Mon, 22 Jun 2020 09:01:48 -0400
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > On Mon, 22 Jun 2020 08:27:53 +0800
> > > Ming Lei <ming.lei@redhat.com> wrote:
> > > 
> > > > Can you kprobe guys improve the implementation for covering this case?
> > > > For example, put probe on 3) in case the above situation is recognized.
> > > 
> > > To do so would require solving the halting problem.
> > > 
> > >   https://en.wikipedia.org/wiki/Halting_problem
> > > 
> > > Or perhaps reading the DWARF output of the compiler to determine if it
> > > optimized the location you are looking for.
> > 
> > As far as I can see, gcc-9.3 doesn't generate this information :(
> > Maybe the optimizer forgot to push the tail-call callsite information
> > to dwarf generator when making a recursive tail-call to a loop.
> > 
> > > The first case is impossible to solve, the second would take a lot of
> > > work, (are you going to fund it?)
> > 
> > What I can provide is "--skip-prologue" option for the perf-probe
> > which will be similar to the "-P" option. If the compiler correctly
> > generates the information, we can enable it automatically. But
> > as far as I can see, it doesn't.
> > 
> > [OT] DWARF has its option(and GNU extension) but it seems not correctly
> > implemented yet.
> >  
> > http://www.dwarfstd.org/ShowIssue.php?issue=100909.2
> 
> Oops, sorry, I missed the following sentences.
> 
> "Tail calls are jump-like instructions which transfer control to the start
> of some subprogram, but the call site location address isn't visible in the
> unwind information."
> 
> "Tail recursion is a call to the current function which is compiled as a
> loop into the middle of the current function."
> 
> "The DW_TAG_call_site entries describe normal and tail calls."
> 
> This means, the gcc is correctly implemented and this __blkdev_put() case
> is NOT covered by DT_TAG_call_site.
> So we can not detect it from the debuginfo.

Hmm, BTW, if optimization is further advanced, it is possible that
the loop start position is not always at the beginning of the function.
It is easy to provide --skip-prologue to perf probe but it doesn't
ensure that works always as you expected.

For example,

func()
{
1:
	{ /* block which doesn't executed in tail-recursion call */
	...
	}
2:
	{ /* block which always executed in tail-recursion call */
	...
	}
	func()
}

In this case, it is natural that the optimizer put a jump to 2 instead
of 1. Moreover, if the number of recursion is fixed, the optimizer
can unroll the loop. In that case there are no jumps. 

So, as Steve pointed, strictly speaking, the developer needs to understand
what the source code was compiled into, before tracing/debuging it.

For the perf-probe case, I'm now thinking it is better user to
choose the line in the function explicitly. I wish I had another flag
that there was a tail-recursion, then I can warn users...

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>