Re: Regression in io_uring, leading to data corruption

[Jens Axboe <axboe@kernel.dk>]

On 11/7/23 4:12 PM, Timothy Pearson wrote:
> 
> 
> ----- 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: Tuesday, November 7, 2023 4:44:56 PM
>> Subject: Re: Regression in io_uring, leading to data corruption
> 
>> On 11/7/23 3:29 PM, Timothy Pearson wrote:
>>>
>>>
>>> ----- 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: Tuesday, November 7, 2023 4:16:51 PM
>>>> Subject: Re: Regression in io_uring, leading to data corruption
>>>
>>>> On 11/7/23 3:07 PM, Timothy Pearson wrote:
>>>>> Interestingly enough that's where my current investigation is leading
>>>>> as well.  After instrumenting and re-instrumenting the codebase far
>>>>> more times than I'd like to admit, I've noticed that the workers don't
>>>>> time out on kernel builds that show the corruption, they are directly
>>>>> terminated via signal (SIGKILL).  On kernel builds with the delay, the
>>>>> workers time out and self-terminate.  I'm still trying to parse out
>>>>> what the exact difference between these two mechanisms would be and
>>>>> how it plays into the corruption, but at least it's a start...
>>>>
>>>> Maybe poke at how they are exiting - you say timeout, so they've been
>>>> idle for a while and then go away? This would then cause worker creation
>>>> again later on if, say, we have 1 worker left and it goes to sleep. So
>>>> the timeout itself may not tell you much, outside of then causing that
>>>> other condition to happen. You could even try and shrink the timeout to
>>>> HZ / 10 or something like that to make it more likely to happen.
>>>
>>> Agreed.  As of right now I can confirm that with the delay in place
>>> (no corruption) the workers are exiting on their own, no signals and
>>> no IO_EXIT bit being set.  When I remove the delay (reintroducing the
>>> corruption) I see signal 9 being sent to the workers, and a mix of
>>> IO_EXIT being set and not being set.
>>>
>>> Ignoring the signal 9 does not fix the corruption, which makes me
>>> wonder more about IO_EXIT and whether things are not fully committed /
>>> properly torn down when the worker thread terminates.  This also
>>> dovetails nicely with the fact that the observed write corruption
>>> always seems to be in the latter portions of the page, never at the
>>> beginning of the page, also indicating rapid / unclean termination of
>>> the writer process.
>>>
>>> Will keep digging...
>>
>> This is useful. If the workers are exiting, they will try and process
>> work that is still pending. And it obviously does, or the process would
>> hang on exit or ring exit. But it'll also cancel said work, which
>> obviously did not happen for the old kthread scheme, as there was no way
>> to do that. So you'd just wait for it. Hence maybe what's happening here
>> is that mtr/mysql/mariadb isn't properly waiting for pending writes to
>> finish? It's just assuming that previously submitted writes will finish
>> if the task is killed?
> 
> It's entirely possible.  What is the correct way to wait for pending
> writes via the liburing API?  MariaDB uses liburing under the hood,
> and if I know the call(s) to look for I can make sure it's properly
> handling task exit.

I'd expect the task to wait and verify the results of pending requests
before doing io_uring_queue_exit(). But I'm not familiar with the code
base, maybe the task just exits? Closing the io_uring fd from an exiting
task would do the same.

I tried the below patch when running mtr here, but don't see any of them
trigger. You can try that, that'll tell you if we ever run cancelations
on pending io-wq work. If that triggers, I can try and cook up something
that would figure out where that is coming from.

But since you said you're seeing exits on signal 9, that would seem to
indicate that someone ran SIGKILL with potentially pending IO.

>> What page size are you using?
> 
> I've tested on both 4k and 64k page kernels with no difference.
> MariaDB is using a 16k page size on disk, and when the corruption
> happens it's apparently only writing part of the 16k page.

OK.


diff --git a/io_uring/io-wq.c b/io_uring/io-wq.c
index 522196dfb0ff..2ee18905d57e 100644
--- a/io_uring/io-wq.c
+++ b/io_uring/io-wq.c
@@ -553,6 +553,8 @@ static void io_worker_handle_work(struct io_wq_acct *acct,
 	struct io_wq *wq = worker->wq;
 	bool do_kill = test_bit(IO_WQ_BIT_EXIT, &wq->state);
 
+	WARN_ON_ONCE(do_kill);
+
 	do {
 		struct io_wq_work *work;
 
@@ -889,6 +891,7 @@ static bool io_wq_worker_wake(struct io_worker *worker, void *data)
 static void io_run_cancel(struct io_wq_work *work, struct io_wq *wq)
 {
 	do {
+		WARN_ON_ONCE(1);
 		work->flags |= IO_WQ_WORK_CANCEL;
 		wq->do_work(work);
 		work = wq->free_work(work);
@@ -934,6 +937,7 @@ void io_wq_enqueue(struct io_wq *wq, struct io_wq_work *work)
 	 */
 	if (test_bit(IO_WQ_BIT_EXIT, &wq->state) ||
 	    (work->flags & IO_WQ_WORK_CANCEL)) {
+		WARN_ON_ONCE(1);
 		io_run_cancel(work, wq);
 		return;
 	}
diff --git a/io_uring/io_uring.c b/io_uring/io_uring.c
index ed254076c723..c0bd35e5429a 100644
--- a/io_uring/io_uring.c
+++ b/io_uring/io_uring.c
@@ -1943,7 +1943,9 @@ void io_wq_submit_work(struct io_wq_work *work)
 
 	/* either cancelled or io-wq is dying, so don't touch tctx->iowq */
 	if (work->flags & IO_WQ_WORK_CANCEL) {
+		WARN_ON_ONCE(1);
 fail:
+		WARN_ON_ONCE(1);
 		io_req_task_queue_fail(req, err);
 		return;
 	}

-- 
Jens Axboe