BUG: ib_mad ftrace event unsupported migration

BUG: ib_mad ftrace event unsupported migration

[Leonid Ravich]

after enabling ib_mad events hit this warning 

echo 1 > /sys/kernel/debug/tracing/events/ib_mad/enable

WARNING: CPU: 0 PID: 1888000 at kernel/trace/ring_buffer.c:2492 rb_commit+0xc1/0x220
CPU: 0 PID: 1888000 Comm: kworker/u9:0 Kdump: loaded Tainted: G           OE    --------- -  - 4.18.0-305.3.1.el8.x86_64 #1
l: Hardware name: Red Hat KVM, BIOS 1.13.0-2.module_el8.3.0+555+a55c8938 04/01/2014
l: Workqueue: ib-comp-unb-wq ib_cq_poll_work [ib_core]
l: RIP: 0010:rb_commit+0xc1/0x220
l: Code: 00 00 80 fa 1f 0f 84 ec 00 00 00 48 01 87 b8 00 00 00 48 8b 87 98 00 00 00 48 85 c0 0f 85 72 ff ff ff 48 8b 47 08 f0 ff 40 08 <0f> 0b c3 48 8b 00 48 89 87 b8 00 00 00 e9 48 ff ff ff 48 8b 47 48
l: RSP: 0000:ffffa8ac80f9bca0 EFLAGS: 00010202
l: RAX: ffff8951c7c01300 RBX: ffff8951c7c14a00 RCX: 0000000000000246
l: RDX: ffff8951c707c000 RSI: ffff8951c707c57c RDI: ffff8951c7c14a00
l: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
l: R10: ffff8951c7c01300 R11: 0000000000000001 R12: 0000000000000246
l: R13: 0000000000000000 R14: ffffffff964c70c0 R15: 0000000000000000
l: FS:  0000000000000000(0000) GS:ffff8951fbc00000(0000) knlGS:0000000000000000
l: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
l: CR2: 00007f20e8f39010 CR3: 000000002ca10005 CR4: 0000000000170ef0
l: Call Trace:
l:  ring_buffer_unlock_commit+0x1d/0xa0
l:  trace_buffer_unlock_commit_regs+0x3b/0x1b0
l:  trace_event_buffer_commit+0x67/0x1d0
l:  trace_event_raw_event_ib_mad_recv_done_handler+0x11c/0x160 [ib_core]
l:  ib_mad_recv_done+0x48b/0xc10 [ib_core]
l:  ? trace_event_raw_event_cq_poll+0x6f/0xb0 [ib_core]
l:  __ib_process_cq+0x91/0x1c0 [ib_core]
l:  ib_cq_poll_work+0x26/0x80 [ib_core]
l:  process_one_work+0x1a7/0x360
l:  ? create_worker+0x1a0/0x1a0
l:  worker_thread+0x30/0x390
l:  ? create_worker+0x1a0/0x1a0
l:  kthread+0x116/0x130
l:  ? kthread_flush_work_fn+0x10/0x10
l:  ret_from_fork+0x35/0x40
l: ---[ end trace 78ba8509d3830a16 ]---

warning originated from below code (kernel/trace/ring_buffer.c)

rb_end_commit()
{
...
if (RB_WARN_ON(cpu_buffer,
                !local_read(&cpu_buffer->committing)))
...
}

after investigation  looks like there is a broken assumption of rb_end_commit and rb_start_commit are on same CPU (no migration) during trace 
looking in ib_mad trace  in include/trace/events/ib_mad.h there is a call to create_mad_addr_info during  TP assign which sleeps (at least under mlx5 ib driver)

so the scenario looks :

rb_start_commit - buffer 0xffffa0984777e400  CPU 1 pid 1368
switch from 1368 to 1605
thread 1368 () is migrating from 1 to 0
rb_end_commit - buffer 0xffffa09847c14a00  CPU 0 pid 1368

before starting throwing some patch into the the air  I would like to align with you the approach we should take here. 

my suggestion here : 
- ftrace infra should verify no migration happen  (end and start happens on same CPU)  in case not we will  throw warning for the issue  .
- ftrace users will be responsible to avoid migration during TP assign (RDMA in my case)

please let me know what do you think 

Re: BUG: ib_mad ftrace event unsupported migration

[Steven Rostedt]

On Wed, 2 Nov 2022 10:49:26 +0000
Leonid Ravich <leonid.ravich@toganetworks.com> wrote:

> after investigation  looks like there is a broken assumption of rb_end_commit and rb_start_commit are on same CPU (no migration) during trace 
> looking in ib_mad trace  in include/trace/events/ib_mad.h there is a call to create_mad_addr_info during  TP assign which sleeps (at least under mlx5 ib driver)

Wait, WHAT?

> 
> so the scenario looks :
> 
> rb_start_commit - buffer 0xffffa0984777e400  CPU 1 pid 1368
> switch from 1368 to 1605
> thread 1368 () is migrating from 1 to 0
> rb_end_commit - buffer 0xffffa09847c14a00  CPU 0 pid 1368

That's a MAJOR bug with the use case of tracepoints!

> 
> before starting throwing some patch into the the air  I would like to align with you the approach we should take here. 
> 
> my suggestion here : 
> - ftrace infra should verify no migration happen  (end and start happens on same CPU)  in case not we will  throw warning for the issue  .

The scheduler should have. On entering the ring buffer code
ring_buffer_lock_reserver() it disables preemption and does not
re-enable it until ring_buffer_unlock_commit().

The only way to migrate is if you re-enable preemption. WHICH IS A BUG!

> - ftrace users will be responsible to avoid migration during TP assign (RDMA in my case)

Yes, it is responsible to do that. Just like it's up to users of
spin_locks to not enable preemption and migrate while holding one.
Entering the ring buffer code is the same as holding a spin_lock except
that the ring buffer code allows for reentrancy.

> 
> please let me know what do you think 

I think that whatever enabled preemption in the ib_mad trace event
needs to be fixed.

-- Steve

Re: BUG: ib_mad ftrace event unsupported migration

[Jason Gunthorpe]

On Wed, Nov 02, 2022 at 07:44:57AM -0400, Steven Rostedt wrote:
> > before starting throwing some patch into the the air  I would like to align with you the approach we should take here. 
> > 
> > my suggestion here : 
> > - ftrace infra should verify no migration happen  (end and start happens on same CPU)  in case not we will  throw warning for the issue  .
> 
> The scheduler should have. On entering the ring buffer code
> ring_buffer_lock_reserver() it disables preemption and does not
> re-enable it until ring_buffer_unlock_commit().
> 
> The only way to migrate is if you re-enable preemption. WHICH IS A
> BUG!

So what on earth did that?

I'm guessing some driver's query_pkey op, but AFAIK we don't have any
explicit pre-emption reenablements in the code - unless it is sneaky..

Leonid what driver are you testing?

Jason

Re: BUG: ib_mad ftrace event unsupported migration

[Leonid Ravich]

> > > before starting throwing some patch into the the air  I would like to align with you the approach we should take here. 
> > > 
> > > my suggestion here : 
> > >- ftrace infra should verify no migration happen  (end and start happens on same CPU)  in case not we will  throw warning for the issue  .
> >
> >The scheduler should have. On entering the ring buffer code
> >ring_buffer_lock_reserver() it disables preemption and does not
> >re-enable it until ring_buffer_unlock_commit().
> >
> >The only way to migrate is if you re-enable preemption. WHICH IS A
> >BUG!

>So what on earth did that?

>I'm guessing some driver's query_pkey op, but AFAIK we don't have any
>explicit pre-emption reenablements in the code - unless it is sneaky..
trace infra uses preempt_disable_notrace/preempt_enable_notrace  to disable/enable preemtion but  my kernel compiled without CONFIG_PREEMPTION so this functions are only barriers - looks like the idea behind was to avoid involuntary preemtion  but in our case it is a voluntary (there is a wait_for_completion in the query_pkey  rabbit hole).

so no scheduler here to warn about illegal migration. 

>Leonid what driver are you testing?
mlx5 - (MLNX_OFED-5.3-1.0.0.1)

Re: BUG: ib_mad ftrace event unsupported migration

[Jason Gunthorpe]

On Wed, Nov 02, 2022 at 02:02:49PM +0000, Leonid Ravich wrote:
> > > > before starting throwing some patch into the the air  I would like to align with you the approach we should take here. 
> > > > 
> > > > my suggestion here : 
> > > >- ftrace infra should verify no migration happen  (end and start happens on same CPU)  in case not we will  throw warning for the issue  .
> > >
> > >The scheduler should have. On entering the ring buffer code
> > >ring_buffer_lock_reserver() it disables preemption and does not
> > >re-enable it until ring_buffer_unlock_commit().
> > >
> > >The only way to migrate is if you re-enable preemption. WHICH IS A
> > >BUG!
> 
> >So what on earth did that?
> 
> >I'm guessing some driver's query_pkey op, but AFAIK we don't have any
> >explicit pre-emption reenablements in the code - unless it is sneaky..
> trace infra uses preempt_disable_notrace/preempt_enable_notrace  to disable/enable preemtion but  my kernel compiled without CONFIG_PREEMPTION so this functions are only barriers - looks like the idea behind was to avoid involuntary preemtion  but in our case it is a voluntary (there is a wait_for_completion in the query_pkey  rabbit hole).

So this tracepoint is just wrong, you can't call a sleepable function
from a tracepoint like that?

Presumably lockdep would/should warn about this?

Delete the pkey logging from the tracepoint, it can't work, I guess.

Jason

Re: BUG: ib_mad ftrace event unsupported migration

[Steven Rostedt]

On Wed, 2 Nov 2022 11:04:44 -0300
Jason Gunthorpe <jgg@ziepe.ca> wrote:

> So this tracepoint is just wrong, you can't call a sleepable function
> from a tracepoint like that?
> 
> Presumably lockdep would/should warn about this?

Why didn't it trigger a "scheduling while atomic" bug? That should
happen if you call a sleeping function while preemption is disabled. Or
does this function explicitly enable preemption? Which nothing checks
if you enable preemption while recording to the ring buffer. I guess we
could add that check, but this is not something that commonly happens
enough to bother.

-- Steve

Re: BUG: ib_mad ftrace event unsupported migration

[Jason Gunthorpe]

On Wed, Nov 02, 2022 at 10:17:19AM -0400, Steven Rostedt wrote:
> On Wed, 2 Nov 2022 11:04:44 -0300
> Jason Gunthorpe <jgg@ziepe.ca> wrote:
> 
> > So this tracepoint is just wrong, you can't call a sleepable function
> > from a tracepoint like that?
> > 
> > Presumably lockdep would/should warn about this?
> 
> Why didn't it trigger a "scheduling while atomic" bug? That should
> happen if you call a sleeping function while preemption is disabled. Or
> does this function explicitly enable preemption? Which nothing checks
> if you enable preemption while recording to the ring buffer. I guess we
> could add that check, but this is not something that commonly happens
> enough to bother.

No, it doesn't muck with preemption, it will have some sleeping lock,
eg mlx5_ib_query_pkey() does a memory allocation as the first thing

It seems like a bug that calling kmalloc(GFP_KERNEL)/might_sleep()
from within a tracepoint doesn't trigger a warning?

Jason

Re: BUG: ib_mad ftrace event unsupported migration

[Steven Rostedt]

On Wed, 2 Nov 2022 11:24:20 -0300
Jason Gunthorpe <jgg@ziepe.ca> wrote:

> No, it doesn't muck with preemption, it will have some sleeping lock,
> eg mlx5_ib_query_pkey() does a memory allocation as the first thing
> 
> It seems like a bug that calling kmalloc(GFP_KERNEL)/might_sleep()
> from within a tracepoint doesn't trigger a warning?

Has nothing to do with tracepoints. You could call it a bug that it
doesn't trigger a warning when preemption is disabled. But then again,
it would if you enabled DEBUG_PREEMPT and possibly LOCKDEP too. So, I chalk
this up to a lack of proper testing.

-- Steve

Re: BUG: ib_mad ftrace event unsupported migration

[Jason Gunthorpe]

On Wed, Nov 02, 2022 at 11:59:47AM -0400, Steven Rostedt wrote:
> On Wed, 2 Nov 2022 11:24:20 -0300
> Jason Gunthorpe <jgg@ziepe.ca> wrote:
> 
> > No, it doesn't muck with preemption, it will have some sleeping lock,
> > eg mlx5_ib_query_pkey() does a memory allocation as the first thing
> > 
> > It seems like a bug that calling kmalloc(GFP_KERNEL)/might_sleep()
> > from within a tracepoint doesn't trigger a warning?
> 
> Has nothing to do with tracepoints. You could call it a bug that it
> doesn't trigger a warning when preemption is disabled. But then again,
> it would if you enabled DEBUG_PREEMPT and possibly LOCKDEP too. So, I chalk
> this up to a lack of proper testing.

That makes sense, assuming it does trigger in those cases.

It is interesting nobody has run those tracepoints on a debug kernel.

Jason

Re: BUG: ib_mad ftrace event unsupported migration

[Leonid Ravich]

> On Wed, 2 Nov 2022 11:24:20 -0300
> Jason Gunthorpe <jgg@ziepe.ca> wrote:
> 
> > No, it doesn't muck with preemption, it will have some sleeping lock,
> > eg mlx5_ib_query_pkey() does a memory allocation as the first thing
> > 
> > It seems like a bug that calling kmalloc(GFP_KERNEL)/might_sleep()
> > from within a tracepoint doesn't trigger a warning?
> 
> Has nothing to do with tracepoints. You could call it a bug that it
> doesn't trigger a warning when preemption is disabled. But then again,
> it would if you enabled DEBUG_PREEMPT and possibly LOCKDEP too. So, I chalk
> this up to a lack of proper testing.
>

disagree, without CONFIG_PREEMPTION (which is the default case in some
destros) we will not get any warning, because there will not be
preamption disable.

second issue I see and maybe it is only me, is that the assuption of
atomicity in trace is not a common knowledge for trace users.     

Re: BUG: ib_mad ftrace event unsupported migration

[Steven Rostedt]

On Wed, 2 Nov 2022 22:01:17 +0200
Leonid Ravich <lravich@gmail.com> wrote:

> disagree, without CONFIG_PREEMPTION (which is the default case in some
> destros) we will not get any warning, because there will not be
> preamption disable.

I test all for my code (NON_PREEMPT, VOLUNTEER_PREEMPT, PREEMPT) and
with and without lockdep enabled.

This would be a bug if you called kmalloc(X, GFP_KERNEL) in *any* non
preempt section.

> 
> second issue I see and maybe it is only me, is that the assuption of
> atomicity in trace is not a common knowledge for trace users.     

Well, I suppose we could add more documentation. Would that help? Where
would you see it? In the sample code?

I advise not even grabbing locks in trace events, because in most cases
lockdep will not catch any issues with them (it will be hidden unless
the trace event is enabled).

-- Steve

Re: BUG: ib_mad ftrace event unsupported migration

[Leonid Ravich]

On Wed, Nov 02, 2022 at 06:19:00PM -0400, Steven Rostedt wrote:
> On Wed, 2 Nov 2022 22:01:17 +0200
> Leonid Ravich <lravich@gmail.com> wrote:
> 
> > disagree, without CONFIG_PREEMPTION (which is the default case in some
> > destros) we will not get any warning, because there will not be
> > preamption disable.
> 
> I test all for my code (NON_PREEMPT, VOLUNTEER_PREEMPT, PREEMPT) and
> with and without lockdep enabled.
> 
> This would be a bug if you called kmalloc(X, GFP_KERNEL) in *any* non
> preempt section.
yes, but for NON_PREEMPT trace is not non preempt section,
actualy the problem is with CONFIG_PREEMPT_COUNT not set. 

ftrace uses preemot_enable/disable_notrace macro to "mark" it as non preempt section
which do it only for CONFIG_PREEMPT_COUNT. 

from include/linux/preempt.h
if !CONFIG_PREEMPT_COUNT
#define preempt_enable_notrace()                barrier()

this is why there is no any warning on my system.
> 
> > 
> > second issue I see and maybe it is only me, is that the assuption of
> > atomicity in trace is not a common knowledge for trace users.     
> 
> Well, I suppose we could add more documentation. Would that help? Where
> would you see it? In the sample code?
> 
I think if we fix the first issue and make kernel cry for any miss
behave it we do the job. 
> I advise not even grabbing locks in trace events, because in most cases
> lockdep will not catch any issues with them (it will be hidden unless
> the trace event is enabled).
> 

-- Leonid 

Re: BUG: ib_mad ftrace event unsupported migration

[Steven Rostedt]

On Thu, 3 Nov 2022 14:22:01 +0200
Leonid Ravich <lravich@gmail.com> wrote:

> On Wed, Nov 02, 2022 at 06:19:00PM -0400, Steven Rostedt wrote:
> > On Wed, 2 Nov 2022 22:01:17 +0200
> > Leonid Ravich <lravich@gmail.com> wrote:
> >   
> > > disagree, without CONFIG_PREEMPTION (which is the default case in some
> > > destros) we will not get any warning, because there will not be
> > > preamption disable.  
> > 
> > I test all for my code (NON_PREEMPT, VOLUNTEER_PREEMPT, PREEMPT) and
> > with and without lockdep enabled.
> > 
> > This would be a bug if you called kmalloc(X, GFP_KERNEL) in *any* non
> > preempt section.  
> yes, but for NON_PREEMPT trace is not non preempt section,
> actualy the problem is with CONFIG_PREEMPT_COUNT not set. 
> 
> ftrace uses preemot_enable/disable_notrace macro to "mark" it as non preempt section
> which do it only for CONFIG_PREEMPT_COUNT. 

Correct.

> 
> from include/linux/preempt.h
> if !CONFIG_PREEMPT_COUNT
> #define preempt_enable_notrace()                barrier()
> 
> this is why there is no any warning on my system.

Correct.

> >   
> > > 
> > > second issue I see and maybe it is only me, is that the assuption of
> > > atomicity in trace is not a common knowledge for trace users.       
> > 
> > Well, I suppose we could add more documentation. Would that help? Where
> > would you see it? In the sample code?
> >   
> I think if we fix the first issue and make kernel cry for any miss
> behave it we do the job. 

It does with the right configs enable. I will NACK any change to add
more checks here for the production case. This is an extremely fast
path where every nanosecond counts (trace events can be under 100ns).
The fact that it doesn't do anything is a feature not a bug.

It's up to the developer to run their code with lockdep and other debug
settings (and possibly even PREEMPT config tests) while developing
their code. Not to expect the production use case to do it for them.

-- Steve

Re: BUG: ib_mad ftrace event unsupported migration

[Steven Rostedt]

On Wed, 2 Nov 2022 14:02:49 +0000
Leonid Ravich <leonid.ravich@toganetworks.com> wrote:

> >I'm guessing some driver's query_pkey op, but AFAIK we don't have any
> >explicit pre-emption reenablements in the code - unless it is sneaky..  
> trace infra uses preempt_disable_notrace/preempt_enable_notrace  to disable/enable preemtion but  my kernel compiled without CONFIG_PREEMPTION so this functions are only barriers - looks like the idea behind was to avoid involuntary preemtion  but in our case it is a voluntary (there is a wait_for_completion in the query_pkey  rabbit hole).
> 
> so no scheduler here to warn about illegal migration. 

Well, you should be testing under different configs ;-)

It would have given you the reason for the real bug.

-- Steve