Re: Regression in io_uring, leading to data corruption

[Timothy Pearson <tpearson@raptorengineering.com>]

----- Original Message -----
> From: "Timothy Pearson" <tpearson@raptorengineering.com>
> To: "Jens Axboe" <axboe@kernel.dk>
> Cc: "regressions" <regressions@lists.linux.dev>, "Pavel Begunkov" <asml.silence@gmail.com>
> Sent: Thursday, November 9, 2023 10:35:08 PM
> Subject: Re: Regression in io_uring, leading to data corruption

> ----- Original Message -----
>> From: "Jens Axboe" <axboe@kernel.dk>
>> To: "Timothy Pearson" <tpearson@raptorengineering.com>
>> Cc: "regressions" <regressions@lists.linux.dev>, "Pavel Begunkov"
>> <asml.silence@gmail.com>
>> Sent: Thursday, November 9, 2023 9:51:09 PM
>> Subject: Re: Regression in io_uring, leading to data corruption
> 
>> Just to go back to basics, can you try this one? It'll do the exact same
>> retry that io-wq is doing, just from the same task itself. If this
>> fails, then something core is wrong. I don't think it will, or we'd see
>> this on other platforms too of course. If this works, then it validates
>> that it's some oddity on ppc with punting this operation to a thread off
>> this main task.
>> 
>> diff --git a/io_uring/rw.c b/io_uring/rw.c
>> index 64390d4e20c1..1d760570df04 100644
>> --- a/io_uring/rw.c
>> +++ b/io_uring/rw.c
>> @@ -968,7 +968,7 @@ int io_read_mshot(struct io_kiocb *req, unsigned int
>> issue_flags)
>> 	return IOU_OK;
>> }
>> 
>> -int io_write(struct io_kiocb *req, unsigned int issue_flags)
>> +static int __io_write(struct io_kiocb *req, unsigned int issue_flags)
>> {
>> 	struct io_rw *rw = io_kiocb_to_cmd(req, struct io_rw);
>> 	struct io_rw_state __s, *s = &__s;
>> @@ -1092,6 +1092,19 @@ int io_write(struct io_kiocb *req, unsigned int
>> issue_flags)
>> 	return ret;
>> }
>> 
>> +int io_write(struct io_kiocb *req, unsigned int issue_flags)
>> +{
>> +	int ret;
>> +
>> +	ret = __io_write(req, issue_flags);
>> +	if (ret != -EAGAIN)
>> +		return ret;
>> +
>> +	ret = __io_write(req, issue_flags & ~IO_URING_F_NONBLOCK);
>> +	WARN_ON_ONCE(ret == -EAGAIN);
>> +	return ret;
>> +}
>> +
>> void io_rw_fail(struct io_kiocb *req)
>> {
>> 	int res;
>> 
> 
> That does indeed "fix" the corruption issue.
> 
> Where is the punting actually taking place?  I can see at least one location but
> if it's a general issue with the punting process I should probably apply any
> test mitigations to all locations, and I'm not familiar enough with the
> codebase to be sure I've got them all...
> 
> Thanks!

I've been exploring a bunch of other possibilities, and one that has been slowly coalescing is whether we're triggering a bug somewhere else in the kernel.  Now that I know the io_write call is somehow related to this issue, I went back and went over some of the earlier logs, and might have found something.

When I enable KCSAN I sporadically see this type of race:

[ 1549.152381] ==================================================================
[ 1549.152515] BUG: KCSAN: data-race in dd_has_work / dd_insert_requests
[ 1549.152609]
[ 1549.152644] read (marked) to 0xc0000000080c2e98 of 8 bytes by task 3372 on cpu 27:
[ 1549.153193]  dd_has_work+0x160/0x1b0
[ 1549.153259]  __blk_mq_sched_dispatch_requests+0x42c/0xdf0
[ 1549.153331]  blk_mq_sched_dispatch_requests+0xe4/0x120
[ 1549.153403]  blk_mq_run_hw_queue+0x358/0x390
[ 1549.153479]  blk_mq_flush_plug_list+0x8fc/0xea0
[ 1549.153556]  __blk_flush_plug+0x2bc/0x360
[ 1549.153622]  blk_finish_plug+0x60/0xa0
[ 1549.153689]  __iomap_dio_rw+0xd28/0x1140
[ 1549.153759]  iomap_dio_rw+0x80/0xf0
[ 1549.153825]  ext4_file_write_iter+0x9f8/0xff0 [ext4]
[ 1549.154249]  io_write+0x4bc/0x900
[ 1549.154309]  io_issue_sqe+0x12c/0x5f0
[ 1549.154370]  io_submit_sqes+0xdd4/0x1050
[ 1549.154429]  sys_io_uring_enter+0x344/0x15d0
[ 1549.154499]  system_call_exception+0x354/0x400
[ 1549.154569]  system_call_vectored_common+0x15c/0x2ec
[ 1549.154651]
[ 1549.154685] write to 0xc0000000080c2e98 of 8 bytes by task 3667 on cpu 32:
[ 1549.154757]  dd_insert_requests+0x81c/0xac0
[ 1549.154825]  blk_mq_flush_plug_list+0x8ec/0xea0
[ 1549.154902]  __blk_flush_plug+0x2bc/0x360
[ 1549.154968]  blk_finish_plug+0x60/0xa0
[ 1549.155034]  __iomap_dio_rw+0xd28/0x1140
[ 1549.155100]  iomap_dio_rw+0x80/0xf0
[ 1549.155166]  ext4_file_write_iter+0x9f8/0xff0 [ext4]
[ 1549.155563]  io_write+0x4bc/0x900
[ 1549.155606]  io_issue_sqe+0x12c/0x5f0
[ 1549.155648]  io_wq_submit_work+0x2e4/0x490
[ 1549.155692]  io_worker_handle_work+0xbac/0x1020
[ 1549.155745]  io_wq_worker+0x224/0x7b0
[ 1549.155792]  ret_from_kernel_user_thread+0x14/0x1c
[ 1549.155841]
[ 1549.155864] Reported by Kernel Concurrency Sanitizer on:
[ 1549.155904] CPU: 32 PID: 3667 Comm: iou-wrk-3372 Not tainted 6.6.0+ #10
[ 1549.155961] Hardware name: IBM pSeries (emulated by qemu) POWER9 (raw) 0x4e1202 0xf000005 of:SLOF,HEAD hv:linux,kvm pSeries
[ 1549.156032] ==================================================================

Notably, the io_write calls are in the chain, and there were exactly two of these races and two test failures in the this test run.

io_write+0x4bc seems to be WRITE_ONCE(list->first, last->next) in wq_list_cut.

Do yuo see similar races on x86 with this workload if you enable KCSAN?