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 14, 2023 11:04:03 AM
> Subject: Re: Regression in io_uring, leading to data corruption

> On 11/14/23 9:59 AM, 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 14, 2023 7:17:22 AM
>>> Subject: Re: Regression in io_uring, leading to data corruption
>> 
>>> On 11/13/23 10:06 PM, Timothy Pearson wrote:
>>>>
>>>>
>>>> ----- 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: Monday, November 13, 2023 6:52:51 PM
>>>>> Subject: Re: Regression in io_uring, leading to data corruption
>>>>>
>>>>> Seemed to do what I wanted, however corruption remains.  Was worth a try...
>>>>>
>>>>> I guess I'll proceed under the assumption that somehow the thread setup is
>>>>> stomping on userspace for now.
>>>>
>>>> Finally found it!  Patch here:
>>>>
>>>> https://lore.kernel.org/regressions/19221908.47168775.1699937769845.JavaMail.zimbra@raptorengineeringinc.com/T/#u
>>>>
>>>> We were missing the appropriate barrier instruction inside the IPI
>>>> issued by the task_work_add() call, which was in turn issued during
>>>> queued io worker creation.  The explaination for how userspace was
>>>> getting corrupted boils down to an inconsistent view of main memory as
>>>> seen the two cores involved in the worker handoff and new worker
>>>> creation.
>>>>
>>>> Who doesn't love a one line fix after a week and a half of pulling
>>>> one's hair out? ;)
>>>
>>> Hate to be a debbie downer, but it still fails for me with that patch:
>>>
>>> debian@linux-kernel--io-uring:~/git/server/mysql-test$ ./mtr
>>> --mysqld=--innodb-flush-method=fsync --mysqld=--innodb-use-native-aio=1
>>> --vardir=/dev/shm/mysql  --force encryption.innodb_encryption,innodb,undo0
>>> --repeat=500
>>> [...]
>>> encryption.innodb_encryption 'innodb,undo0' [ 39 pass ]   3101
>>> encryption.innodb_encryption 'innodb,undo0' [ 40 fail ]
>>>        Test ended at 2023-11-14 13:02:52
>>>
>>> CURRENT_TEST: encryption.innodb_encryption
>>> mysqltest: At line 11: query 'SET @start_global_value =
>>> @@global.innodb_encryption_threads' failed: ER_UNKNOWN_SYSTEM_VARIABLE (1193):
>>> Unknown system variable 'innodb_encryption_threads'
>>>
>>> The result from queries just before the failure was:
>>> SET @start_global_value = @@global.innodb_encryption_threads;
>>>
>>> - saving '/dev/shm/mysql/log/encryption.innodb_encryption-innodb,undo0/' to
>>> '/dev/shm/mysql/log/encryption.innodb_encryption-innodb,undo0/'
>>> ***Warnings generated in error logs during shutdown after running tests:
>>> encryption.innodb_encryption
>>>
>>> 2023-11-14 13:02:51 0 [Warning] Plugin 'example_key_management' is of maturity
>>> level experimental while the server is stable
>>> 2023-11-14 13:02:51 0 [ERROR] InnoDB: Database page corruption on disk or a
>>> failed read of file './ibdata1' page [page id: space=0, page number=220]. You
>>> may have to recover from a backup.
>>> 2023-11-14 13:02:51 0 [ERROR] InnoDB: File './ibdata1' is corrupted
>>> 2023-11-14 13:02:51 0 [ERROR] InnoDB: Plugin initialization aborted with error
>>> Page read from tablespace is corrupted.
>>> 2023-11-14 13:02:52 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE
>>> failed.
>>>
>>> after about 40 loops. How consistent is it on your end? I know I've
>>> suspected the signaling before and tried the NO_IPI variant, but that
>>> still hit it.
>>>
>>> If it makes a difference for you, it must be close. But don't think it's
>>> quite there yet, unfortunately :-(
>> 
>> Interesting!  I've run it for thousands of loops on my test VM, no
>> failures.  Let me try on the shared test box.
> 
> So odd. I guess it must be close if it's enough to make yours sane. The
> other vm I've been using is just a small vm somewhere else, it has 8
> threads of:
> 
> debian@linux-kernel--io-uring:~$ cat /proc/cpuinfo
> processor	: 0
> cpu		: POWER9 (architected), altivec supported
> clock		: 2200.000000MHz
> revision	: 2.2 (pvr 004e 1202)
> [...]
> timebase	: 512000000
> platform	: pSeries
> model		: IBM pSeries (emulated by qemu)
> machine		: CHRP IBM pSeries (emulated by qemu)
> MMU		: Radix

At this point my concern is there might be two bugs, one related to the IPI and one related to the direct creation path.  Since I can't reproduce easily on my end, can you see if the box you have acecss to is ever hitting the io_wq_create_worker() call inside io_wq_enqueue()?