[PATCH] nvme-tcp: Fix possible race of io_work and direct send

[Yi Zhang]

On 1/8/21 3:05 AM, Or Gerlitz wrote:
> On Mon, Dec 21, 2020 at 10:06 AM Sagi Grimberg <sagi at grimberg.me> wrote:
>> We may send a request (with or without its data) from two paths:
>> 1. From our I/O context nvme_tcp_io_work which is triggered from:
>> - queue_rq
>> - r2t reception
>> - socket data_ready and write_space callbacks
>> 2. Directly from queue_rq if the send_list is empty (because
>> we want to save the context switch associated with scheduling
>> our io_work).
>> Fixes: db5ad6b7f8cd ("nvme-tcp: try to send request in queue_rq context")
>> Reported-by: Potnuri Bharat Teja <bharat at chelsio.com>
>> Reported-by: Samuel Jones <sjones at kalrayinc.com>
>> --- a/drivers/nvme/host/tcp.c
>> +++ b/drivers/nvme/host/tcp.c
>> @@ -279,7 +289,7 @@ static inline void nvme_tcp_queue_request(struct nvme_tcp_request *req,
>>          if (queue->io_cpu == smp_processor_id() &&
>>              sync && empty && mutex_trylock(&queue->send_mutex)) {
> but we can't rely on the processor id if we are on preemptible state..
>
>    373.940336] BUG: using smp_processor_id() in preemptible [00000000]
> code: kworker/u8:4/457
> [  373.942037] caller is nvme_tcp_submit_async_event+0x4da/0x690 [nvme_tcp]
> [  373.942144] CPU: 0 PID: 457 Comm: kworker/u8:4 Not tainted 5.11.0-rc1+ #116
> [  373.942171] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
> BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
> [  373.942196] Workqueue: nvme-wq nvme_async_event_work [nvme_core]
> [  373.942259] Call Trace:
> [  373.942286]  dump_stack+0xd0/0x119
> [  373.942346]  check_preemption_disabled+0xec/0xf0
> [  373.942397]  nvme_tcp_submit_async_event+0x4da/0x690 [nvme_tcp]
> [  373.942449]  nvme_async_event_work+0x11d/0x1f0 [nvme_core]
> [  373.942496]  ? nvme_ctrl_loss_tmo_show+0x140/0x140 [nvme_core]
> [  373.942576]  process_one_work+0x9f3/0x1630
> [  373.942649]  ? pwq_dec_nr_in_flight+0x330/0x330
> [  373.942765]  worker_thread+0x9e/0xf60
> [  373.942849]  ? process_one_work+0x1630/0x1630
> [  373.942889]  kthread+0x362/0x480
> [  373.942918]  ? kthread_create_on_node+0x100/0x100
>
>         /*
> +        * if we're the first on the send_list and we can try to send
> +        * directly, otherwise queue io_work. Also, only do that if we
> +        * are on the same cpu, so we don't introduce contention.
> +        */
> +       if (queue->io_cpu == smp_processor_id() &&
> +           sync && empty && mutex_trylock(&queue->send_mutex)) {
> +               nvme_tcp_try_send(queue);
> +               mutex_unlock(&queue->send_mutex);
> +       } else {
> +               queue_work_on(queue->io_cpu, nvme_tcp_wq, &queue->io_work);
> +       }
>
> so before this patch that check was not needed? I was not sure re all
> the involved contexts and how to fix that.. so just sending the report
Yeah, I met similar issue after enable PREEMPT.

[  135.285366] run blktests nvme/003 at 2021-01-08 06:13:04
[  135.358457] loop: module loaded
[  135.368607] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[  135.369568] nvmet_tcp: enabling port 0 (127.0.0.1:4420)
[  135.374261] nvmet: creating controller 1 for subsystem 
nqn.2014-08.org.nvmexpress.discovery for NQN 
nqn.2014-08.org.nvmexpress:uuid:0d2e879c-9efb-4026-a82e-450e4283175e.
[  135.374381] nvme nvme0: new ctrl: NQN 
"nqn.2014-08.org.nvmexpress.discovery", addr 127.0.0.1:4420
[  135.374382] BUG: using smp_processor_id() in preemptible [00000000] 
code: kworker/u64:18/187
[  135.374387] caller is nvme_tcp_submit_async_event+0x111/0x140 [nvme_tcp]
[  135.389518] CPU: 31 PID: 187 Comm: kworker/u64:18 Tainted: G S        
I       5.11.0-rc2.v1 #2
[  135.398121] Hardware name: Dell Inc. PowerEdge R640/06NR82, BIOS 
2.10.0 11/12/2020
[  135.405688] Workqueue: nvme-wq nvme_async_event_work [nvme_core]
[  135.411704] Call Trace:
[  135.414157]  dump_stack+0x57/0x6a
[  135.417475]  check_preemption_disabled+0xb6/0xd0
[  135.422094]  nvme_tcp_submit_async_event+0x111/0x140 [nvme_tcp]
[  135.428014]  nvme_async_event_work+0x5d/0xc0 [nvme_core]
[  135.433324]  process_one_work+0x1b6/0x3b0
[  135.437337]  worker_thread+0x30/0x370
[  135.441002]  ? process_one_work+0x3b0/0x3b0
[  135.445190]  kthread+0x13d/0x160
[  135.448423]  ? kthread_park+0x80/0x80
[  135.452089]  ret_from_fork+0x1f/0x30
[  145.394927] nvme nvme0: Removing ctrl: NQN 
"nqn.2014-08.org.nvmexpress.discovery"


> _______________________________________________
> Linux-nvme mailing list
> Linux-nvme at lists.infradead.org
> http://lists.infradead.org/mailman/listinfo/linux-nvme
>