Re: Regression in io_uring, leading to data corruption

[Jens Axboe <axboe@kernel.dk>]

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

-- 
Jens Axboe