Date:   Wed, 2 Nov 2022 10:49:26 +0000
From:   Leonid Ravich <leonid.ravich@...anetworks.com>
To:     "linux-trace-kernel@...r.kernel.org" 
        <IMCEAMAILTO-linux-trace-kernel+40vger+2Ekernel+2Eorg@...prd02.prod.outlook.com>,
        "mingo@...hat.com" <mingo@...hat.com>,
        "rostedt@...dmis.org" <rostedt@...dmis.org>,
        "linux-rdma@...r.kernel.org" <linux-rdma@...r.kernel.org>,
        "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>
CC:     Yigal Korman <yigal.korman@...anetworks.com>
Subject: BUG:  ib_mad ftrace event unsupported migration

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 

Powered by blists - more mailing lists