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@xxxxxxxxxx> 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
