Re: Regression in io_uring, leading to data corruption

[Timothy Pearson <tpearson@raptorengineering.com>]

----- 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 6:09:39 PM
> Subject: Re: Regression in io_uring, leading to data corruption

> On 11/7/23 5:02 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 5:52:54 PM
>>> Subject: Re: Regression in io_uring, leading to data corruption
>> 
>>> On 11/7/23 4:34 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 5:16:24 PM
>>>>> Subject: Re: Regression in io_uring, leading to data corruption
>>>>>
>>>>> But since you said you're seeing exits on signal 9, that would seem to
>>>>> indicate that someone ran SIGKILL with potentially pending IO.
>>>>
>>>> Just to make sure we're talking about the same thing, when I refer to
>>>> signal 9 I am referring to instrumentation I added to the
>>>> get_signal(&ksig) call.  I am seeing 9 in the ksig.sig field.  I
>>>> assume the SIGKILL is not expected, i.e. not coming from another
>>>> location in the io_uring kernel code?
>>>
>>> ksig.sig is set to signr, which is the number of the signal. So that
>>> would seem to indicate that _someone_ is sending SIGKILL. But at the
>>> same time, you don't see any of the cancel-on-exit triggering. Puzzling!
>>> io_uring or io-wq doesn't send any signals.
>>>
>>> In your instrumentation, are you checking where the signal is coming
>>> from?Is it being dequeued as an actual signal, or is it some other
>>> condition in get_signal() that ends up setting it to SIGKILL?
>> 
>> I still need to check this in more detail.  What I do know at the
>> moment is that the kill seems to be related to the entire workqueue
>> going down, i.e. it is sent to the workers of a given workqueue after
>> io_wq_put_and_exit() and io_wq_exit_workers() are called for that
>> workqueue.  Not sure if that helps any, will keep digging...
> 
> Another option is that it's doing exec() with pending IO, which will
> cancel it. But I'm also assuming that mtr/friends will check result
> values of writes and would've caught that there.

Here's something potentially more useful, the stack trace of what's calling the workqueue exit function:

[   35.074923] Call Trace:
[   35.074939] [c000000007183890] [c0000000005c0804] io_wq_exit_workers+0x48/0x214 (unreliable)
[   35.074994] [c000000007183920] [c0000000005c0410] io_wq_put+0xa0/0x27c
[   35.075034] [c0000000071839f0] [c0000000005a92a8] io_uring_clean_tctx+0x98/0xe0
[   35.075082] [c000000007183a30] [c0000000005bdc78] __io_uring_files_cancel+0x4f8/0x580
[   35.075129] [c000000007183b20] [c000000000153fc8] do_exit+0x1c8/0xce0
[   35.075169] [c000000007183bf0] [c000000000154c58] do_group_exit+0x108/0x110
[   35.075209] [c000000007183c30] [c00000000016ac6c] get_signal+0xbfc/0xce0
[   35.075251] [c000000007183d10] [c00000000001ed50] do_notify_resume+0xd0/0x420
[   35.075298] [c000000007183dc0] [c00000000002dbbc] syscall_exit_prepare+0x15c/0x360
[   35.075348] [c000000007183e10] [c00000000000cf74] system_call_vectored_common+0xf4/0x260

This call is associated with the mariadb userspace PID:

[   35.074242] CPU: 12 PID: 1260 Comm: mariadbd

To me, it almost looks like the mariadb I/O worker thread is getting terminated via signal and that this termination is taking out the write before it can complete.  Is that even possible?