[MDEV-27900] aio returning partial reads/writes looks like InnoDB: Database page corruption on btrfs with io_uring - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.6.7
Fix Version/s: 10.5.16, 10.6.8, 10.7.4, 10.8.3
Component/s: Storage Engine - InnoDB
Labels:
None
Environment:
NixOS 21.11 and unstable. Linux kernel 5.16.8

Description

Feb 17 23:47:45 apfelkirsch systemd[1]: Starting MySQL Server...

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] /nix/store/svbwxblrhai6fcij9p9pmyyafa5pcqls-mariadb-server-10.6.5/bin/mysqld (server 10.6.5-MariaDB) starting as process 16475 ...

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Warning] WSREP: Failed to guess base node address. Set it explicitly via wsrep_node_address.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Warning] WSREP: Failed to guess base node address. Set it explicitly via wsrep_node_address.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Warning] WSREP: Guessing address for incoming client connections failed. Try setting wsrep_node_incoming_address explicitly.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] WSREP: Node addr:

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Compressed tables use zlib 1.2.11

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Number of pools: 1

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Using liburing

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Completed initialization of buffer pool

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=42161,42161

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: 128 rollback segments are active.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Creating shared tablespace for temporary tables

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: 10.6.5 started; log sequence number 42173; transaction id 14

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] Plugin 'FEEDBACK' is disabled.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=9]. You may have to recover from a backup.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):

Feb 17 23:47:45 apfelkirsch mysql-start[16475]:  len 16384; hex 000000000000002022-02-17 23:47:45 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=243]. You may have to recover from a backup.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 09ffffffffffffffff00000000000099ab2022-02-17 23:47:45 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):

Feb 17 23:47:45 apfelkirsch mysql-start[16475]:  len 16384; hex 00000000000000f3ffff45bf000000000000000000ffffffffffff000000000000000000009e6e00030000000000022022-02-17 23:47:45 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './mysql/innodb_table_stats.ibd' page [page id: space=1, page number=0]. You may have to recover from a backup.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):

[…]

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: InnoDB: End of page dump

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Uncompressed page, stored checksum in field1 0, calculated checksums for field1: crc32 2039713970, innodb 724040756, page type 17855, stored checksum in field2 0, innodb checksum for field2: 1607711317,  page LSN 0 39339, low 4 bytes of LSN at page end 0, page number (if stored to page already) 9, space id (if created with >= MySQL-4.1.1 and stored already) 0

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Page may be an index page where index id is 5

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Index 5 is `ID_IND` in table `SYS_TABLES`

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB:  You can use CHECK TABLE to scan your table for corruption. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.

Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [ERROR] [FATAL] InnoDB: Aborting because of a corrupt database page.

Feb 17 23:47:46 apfelkirsch systemd[1]: mysql.service: Main process exited, code=killed, status=6/ABRT

See https://github.com/NixOS/nixpkgs/issues/160516 and https://github.com/NixOS/nixpkgs/issues/160145 for potentially more details.

Attachments

Issue Links

is duplicated by

MDEV-27975 mariadb-server won't startup on instalation

Closed

relates to

MDEV-24854 Change innodb_flush_method=O_DIRECT by default

Closed

links to

kernel mail list bug report - io-uring and btrfs

Activity

Ascending order - Click to sort in descending order

Marko Mäkelä added a comment - 2022-02-20 15:31

This actually looks like a duplicate of ~~MDEV-27449~~.

In both server error logs, we can observe that the io_uring interface is being used:

2022-01-09  9:46:34 0 [Note] InnoDB: Using liburing

 Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Using liburing

I am not familiar with btrfs, but I read somewhere that it could be a good idea to disable the copy-on-write feature on the data directory, with something like the following:

chattr +C /var/lib/mysql

Has that been tried?

Does the page dump in the error log match the contents of page 9 in the file?

od -Ax -t x1 -j 0x24000 -N 0x4000 ibdata1

Is this repeatable on the first startup after initializing a new database?

Marko Mäkelä added a comment - 2022-02-20 15:31 This actually looks like a duplicate of MDEV-27449 . In both server error logs, we can observe that the io_uring interface is being used: 2022-01-09 9:46:34 0 [Note] InnoDB: Using liburing Feb 17 23:47:45 apfelkirsch mysql-start[16475]: 2022-02-17 23:47:45 0 [Note] InnoDB: Using liburing I am not familiar with btrfs, but I read somewhere that it could be a good idea to disable the copy-on-write feature on the data directory, with something like the following: chattr +C /var/lib/mysql Has that been tried? Does the page dump in the error log match the contents of page 9 in the file? od -Ax -t x1 -j 0x24000 -N 0x4000 ibdata1 Is this repeatable on the first startup after initializing a new database?

Marko Mäkelä added a comment - 2022-02-20 15:44

Furthermore, is this repeatable if the server was always started up with innodb_use_native_aio=0?

Marko Mäkelä added a comment - 2022-02-20 15:44 Furthermore, is this repeatable if the server was always started up with innodb_use_native_aio=0 ?

Marko Mäkelä added a comment - 2022-02-20 15:59

Could this simply be due to innodb_flush_method=O_DIRECT not being compatible with btrfs due to some reason? As it was noted in ~~MDEV-24854~~, setting innodb_flush_method=fsync (the pre-10.6 default value) allowed MariaDB to start up on btrfs.

Marko Mäkelä added a comment - 2022-02-20 15:59 Could this simply be due to innodb_flush_method=O_DIRECT not being compatible with btrfs due to some reason? As it was noted in MDEV-24854 , setting innodb_flush_method=fsync (the pre-10.6 default value) allowed MariaDB to start up on btrfs .

Daniel Black added a comment - 2022-02-21 01:16

https://github.com/NixOS/nixpkgs/issues/160516 lists innodb_use_native_aio=0 as a workaround.

Daniel Black added a comment - 2022-02-21 01:16 https://github.com/NixOS/nixpkgs/issues/160516 lists innodb_use_native_aio=0 as a workaround.

Daniel Black added a comment - 2022-02-21 04:05

Using same loopback image created in MDEV-24854.

mariadb-10.6.8-4030a9fb2eb699361c58d71878e97b282647319a, kernel - 5.17.0-0.rc4.96.fc36.x86_64
$ scripts/mysql_install_db --no-defaults --srcdir=$OLDPWD --builddir=$PWD --datadir=/mnt/btrfstest/dd
Installing MariaDB/MySQL system tables in '/mnt/btrfstest/dd' ...
OK

~/repos/build-mariadb-server-10.6
$ sql/mysqld --no-defaults --skip-networking --datadir=/mnt/btrfstest/dd --verbose
2022-02-21 14:43:31 0 [Note] sql/mysqld (server 10.6.8-MariaDB) starting as process 121966 ...
2022-02-21 14:43:31 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-02-21 14:43:31 0 [Note] InnoDB: Number of pools: 1
2022-02-21 14:43:31 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-02-21 14:43:31 0 [Note] InnoDB: Using liburing
2022-02-21 14:43:31 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2022-02-21 14:43:31 0 [Note] InnoDB: Completed initialization of buffer pool
2022-02-21 14:43:31 0 [Note] InnoDB: 128 rollback segments are active.
2022-02-21 14:43:31 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-02-21 14:43:31 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-02-21 14:43:31 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-02-21 14:43:31 0 [Note] InnoDB: 10.6.8 started; log sequence number 42173; transaction id 14
2022-02-21 14:43:31 0 [Note] InnoDB: Loading buffer pool(s) from /mnt/btrfstest/dd/ib_buffer_pool
2022-02-21 14:43:31 0 [Note] CONNECT: Version 1.07.0002 March 22, 2021
2022-02-21 14:43:31 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-02-21 14:43:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=9]. You may have to recover from a backup.
2022-02-21 14:43:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):
len 16384; hex 00000000000000092022-02-21 14:43:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=243]. You may have to recover from a backup.
ffffffffffffff2022-02-21 14:43:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):
len 16384; hex 00000000000000f3ffffff0000000000009c2045bf00ffffff0000000000ffffff00000000000000020171000900000000015500020006000700000000000000090000000000000000000000000500000000000000020572000000000000000204b208010000030085690000006e66696d756d000908a0d3000300000803000073757072656d756d000000000013080000100500a000000000000000000000000000000b5359535f464f524549474e18080000180500c0000000000000000c5359ffffff535f464fff0000524549474e5f434f4c531308ffffff0000200500ff0000db000000000000000d5359535f56495254550000000000000056414c00000000000020080000280501030000ffffffff0000ffffffff0000000000000000000e6d7973000000716c2f696e6e6f64625f7461626c655f7300ffffffff0000ffffffff0000000000746174732000ffff080000300501ffff0000ffffffff000005d6692b000000000000000f6d7973716c2f696e6e6f64625f696e6465785fd2007374617473220800003805015500000000000000106d7973716c2f7472616e73616374696f6e5f72656769737472791c0800004005000000f4ffffff74000000000000ffffff00116d79ffffffffffffffffffffffffffffffffffff73716c2f67ffffffffffffffffff7469645f736c6176655fffffffffffffffffff706f7300ffffffffffffff2022-02-21 14:43:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './mysql/innodb_table_stats.ibd' page [page id: space=1, page number=0]. You may have to recover from a backup.
002022-02-21 14:43:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):
len 16384; hex 00ffff00ffff00000000ff00ff000000000000ff0000ff00000000ff0000ff0000ffff000000ffffffffff00000000ffffffffff00000000ffff000000000000871dffffffffff000000ff00ff08ff00ff000000000000000000000000000000000000ffffffff000000ff00000000ffffffffff00000000ff00010000000100000000000000ff0000000000060000000000000000000000000000000000ffffffffffffffff000000000000000000000000000000000000000000000000000000004000000000150000000400000000ffff00000000000000000000ffff0000000000000000000000000000ffff000000ffffffff00ffffff0000000000000000000000000100000000009e00000000009e00000000ffffffffffff00ffffff0000000000000000000000ffffff0000000000ffff000000000000000000000000ffff000000000000ffff000000000000000000000000000000ffff00000000000000000000000000ffffff00ffffffffff0000ffff00ffffff000000000000000003000000000000000000000000000000ffffffff0000ffffffff000000000001000000000000000200000000000000570000260000000000000000000000000000000000000000000002002600ffffffff000000000000000000ff0000ffffff000000000000000000ffffffff000000000000ffffffff000000000002aaffffff00000000ffffffff00000000ff000000ff000000ff0000000000000000000000ffffffff0000ffffffff0000ff0000000000000000ff0000ff0000000000ffff000000000000000000000000000000000000ff000000000000000000000000000000000000000000ffffff0000ffffffff000005d669d2000000000000000000000000000000000000000000000000000000000000000000f5ffff00ffffff000000000000ff0000000000ffffffff00ff00ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff00000000000000ff0000000000000000000000ffffff00000000000000000000000000ffffffffffff0000000000000000ffffff000000ffffffff00000000000000000000000000ffffffffffffffffffffffffffffffffffff00000000000000580000000000000000ffffffff0000ffffffff000000000000ffffffff0000ffffffff000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000ffff0000000000000000000000000000000000000000ffff0000ffffffff000005d669d2000000f6ffffffffff000000000000000000ffffffffffffffffffffffffffffffffffffffffffffffffffffffffff

innodb_use_native_aio=0 reading the same datadir is starts without problem
$ sql/mysqld --no-defaults --skip-networking --datadir=/mnt/btrfstest/dd --verbose --innodb_use_native_aio=0 --socket /tmp/mysql.sock
2022-02-21 14:51:07 0 [Note] sql/mysqld (server 10.6.8-MariaDB) starting as process 122494 ...
2022-02-21 14:51:07 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-02-21 14:51:07 0 [Note] InnoDB: Number of pools: 1
2022-02-21 14:51:07 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-02-21 14:51:07 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2022-02-21 14:51:07 0 [Note] InnoDB: Completed initialization of buffer pool
2022-02-21 14:51:07 0 [Note] InnoDB: 128 rollback segments are active.
2022-02-21 14:51:07 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-02-21 14:51:07 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-02-21 14:51:07 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-02-21 14:51:07 0 [Note] InnoDB: 10.6.8 started; log sequence number 42197; transaction id 14
2022-02-21 14:51:07 0 [Note] InnoDB: Loading buffer pool(s) from /mnt/btrfstest/dd/ib_buffer_pool
2022-02-21 14:51:07 0 [Note] CONNECT: Version 1.07.0002 March 22, 2021
2022-02-21 14:51:07 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-02-21 14:51:07 0 [Note] InnoDB: Buffer pool(s) load completed at 220221 14:51:07
2022-02-21 14:51:07 0 [Note] sql/mysqld: ready for connections.
Version: '10.6.8-MariaDB' socket: '/tmp/mysql.sock' port: 0 MariaDB Server
^C2022-02-21 14:51:34 0 [Note] sql/mysqld (initiated by: unknown): Normal shutdown
2022-02-21 14:51:34 0 [Note] InnoDB: FTS optimize thread exiting.
2022-02-21 14:51:34 0 [Note] InnoDB: Starting shutdown...
2022-02-21 14:51:34 0 [Note] InnoDB: Dumping buffer pool(s) to /mnt/btrfstest/dd/ib_buffer_pool
2022-02-21 14:51:34 0 [Note] InnoDB: Buffer pool(s) dump completed at 220221 14:51:34
2022-02-21 14:51:35 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2022-02-21 14:51:35 0 [Note] InnoDB: Shutdown completed; log sequence number 42209; transaction id 15
2022-02-21 14:51:35 0 [Note] sql/mysqld: Shutdown complete

--innodb_use_native_aio=1 afterwards generated same result. chattr +C didn't change the result of the corruption.

$ od -Ax -t x1 -j 0x24000 -N 0x4000 ibdata1

024000 00 00 00 00 00 00 00 09 ff ff ff ff ff ff ff ff

024010 00 00 00 00 00 00 9c 20 45 bf 00 00 00 00 00 00

024020 00 00 00 00 00 00 00 02 01 71 00 09 00 00 00 00

024030 01 55 00 02 00 06 00 07 00 00 00 00 00 00 00 09

024040 00 00 00 00 00 00 00 00 00 05 00 00 00 00 00 00

024050 00 02 05 72 00 00 00 00 00 00 00 02 04 b2 08 01

024060 00 00 03 00 85 69 6e 66 69 6d 75 6d 00 09 08 00

024070 08 03 00 00 73 75 70 72 65 6d 75 6d 00 13 08 00

024080 00 10 05 00 a0 00 00 00 00 00 00 00 0b 53 59 53

024090 5f 46 4f 52 45 49 47 4e 18 08 00 00 18 05 00 c0

0240a0 00 00 00 00 00 00 00 0c 53 59 53 5f 46 4f 52 45

0240b0 49 47 4e 5f 43 4f 4c 53 13 08 00 00 20 05 00 db

0240c0 00 00 00 00 00 00 00 0d 53 59 53 5f 56 49 52 54

0240d0 55 41 4c 20 08 00 00 28 05 01 03 00 00 00 00 00

0240e0 00 00 0e 6d 79 73 71 6c 2f 69 6e 6e 6f 64 62 5f

0240f0 74 61 62 6c 65 5f 73 74 61 74 73 20 08 00 00 30

024100 05 01 2b 00 00 00 00 00 00 00 0f 6d 79 73 71 6c

024110 2f 69 6e 6e 6f 64 62 5f 69 6e 64 65 78 5f 73 74

024120 61 74 73 22 08 00 00 38 05 01 55 00 00 00 00 00

024130 00 00 10 6d 79 73 71 6c 2f 74 72 61 6e 73 61 63

024140 74 69 6f 6e 5f 72 65 67 69 73 74 72 79 1c 08 00

024150 00 40 05 00 74 00 00 00 00 00 00 00 11 6d 79 73

024160 71 6c 2f 67 74 69 64 5f 73 6c 61 76 65 5f 70 6f

024170 73 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

024180 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

027ff0 00 00 00 00 00 74 00 65 00 00 9c 20 b3 73 ac c6

use aio=0 on mysql_install_db (still with chattr +C)
$ scripts/mysql_install_db --no-defaults --srcdir=$OLDPWD --builddir=$PWD --datadir=/mnt/btrfstest/noaio --innodb_use_native_aio=0
Installing MariaDB/MySQL system tables in '/mnt/btrfstest/noaio' ...
OK

~/repos/build-mariadb-server-10.6
$ sql/mysqld --no-defaults --skip-networking --datadir=/mnt/btrfstest/noaio --verbose --innodb_use_native_aio=1 --socket /tmp/mysql.sock
2022-02-21 14:59:31 0 [Note] sql/mysqld (server 10.6.8-MariaDB) starting as process 123017 ...
2022-02-21 14:59:31 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-02-21 14:59:31 0 [Note] InnoDB: Number of pools: 1
2022-02-21 14:59:31 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2022-02-21 14:59:31 0 [Note] InnoDB: Using liburing
2022-02-21 14:59:31 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
2022-02-21 14:59:31 0 [Note] InnoDB: Completed initialization of buffer pool
2022-02-21 14:59:31 0 [Note] InnoDB: 128 rollback segments are active.
2022-02-21 14:59:31 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-02-21 14:59:31 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-02-21 14:59:31 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-02-21 14:59:31 0 [Note] InnoDB: 10.6.8 started; log sequence number 42173; transaction id 14
2022-02-21 14:59:31 0 [Note] InnoDB: Loading buffer pool(s) from /mnt/btrfstest/noaio/ib_buffer_pool
2022-02-21 14:59:31 0 [Note] CONNECT: Version 1.07.0002 March 22, 2021
2022-02-21 14:59:31 0 [Note] Plugin 'FEEDBACK' is disabled.
2022-02-21 14:59:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=9]. You may have to recover from a backup.
2022-02-21 14:59:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):
len 16384; hex 0000000000000009ffffffffffffffff0000000000009c2045bf0000000000000000000000000002012022-02-21 14:59:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=243]. You may have to recover from a backup.
710009002022-02-21 14:59:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):

Daniel Black added a comment - 2022-02-21 04:05 Using same loopback image created in MDEV-24854 . mariadb-10.6.8-4030a9fb2eb699361c58d71878e97b282647319a, kernel - 5.17.0-0.rc4.96.fc36.x86_64 $ scripts/mysql_install_db --no-defaults --srcdir=$OLDPWD --builddir=$PWD --datadir=/mnt/btrfstest/dd Installing MariaDB/MySQL system tables in '/mnt/btrfstest/dd' ... OK ~/repos/build-mariadb-server-10.6 $ sql/mysqld --no-defaults --skip-networking --datadir=/mnt/btrfstest/dd --verbose 2022-02-21 14:43:31 0 [Note] sql/mysqld (server 10.6.8-MariaDB) starting as process 121966 ... 2022-02-21 14:43:31 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2022-02-21 14:43:31 0 [Note] InnoDB: Number of pools: 1 2022-02-21 14:43:31 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions 2022-02-21 14:43:31 0 [Note] InnoDB: Using liburing 2022-02-21 14:43:31 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728 2022-02-21 14:43:31 0 [Note] InnoDB: Completed initialization of buffer pool 2022-02-21 14:43:31 0 [Note] InnoDB: 128 rollback segments are active. 2022-02-21 14:43:31 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2022-02-21 14:43:31 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2022-02-21 14:43:31 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2022-02-21 14:43:31 0 [Note] InnoDB: 10.6.8 started; log sequence number 42173; transaction id 14 2022-02-21 14:43:31 0 [Note] InnoDB: Loading buffer pool(s) from /mnt/btrfstest/dd/ib_buffer_pool 2022-02-21 14:43:31 0 [Note] CONNECT: Version 1.07.0002 March 22, 2021 2022-02-21 14:43:31 0 [Note] Plugin 'FEEDBACK' is disabled. 2022-02-21 14:43:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=9]. You may have to recover from a backup. 2022-02-21 14:43:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes): len 16384; hex 00000000000000092022-02-21 14:43:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=243]. You may have to recover from a backup. ffffffffffffff2022-02-21 14:43:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes): len 16384; hex 00000000000000f3ffffff0000000000009c2045bf00ffffff0000000000ffffff00000000000000020171000900000000015500020006000700000000000000090000000000000000000000000500000000000000020572000000000000000204b208010000030085690000006e66696d756d000908a0d3000300000803000073757072656d756d000000000013080000100500a000000000000000000000000000000b5359535f464f524549474e18080000180500c0000000000000000c5359ffffff535f464fff0000524549474e5f434f4c531308ffffff0000200500ff0000db000000000000000d5359535f56495254550000000000000056414c00000000000020080000280501030000ffffffff0000ffffffff0000000000000000000e6d7973000000716c2f696e6e6f64625f7461626c655f7300ffffffff0000ffffffff0000000000746174732000ffff080000300501ffff0000ffffffff000005d6692b000000000000000f6d7973716c2f696e6e6f64625f696e6465785fd2007374617473220800003805015500000000000000106d7973716c2f7472616e73616374696f6e5f72656769737472791c0800004005000000f4ffffff74000000000000ffffff00116d79ffffffffffffffffffffffffffffffffffff73716c2f67ffffffffffffffffff7469645f736c6176655fffffffffffffffffff706f7300ffffffffffffff2022-02-21 14:43:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './mysql/innodb_table_stats.ibd' page [page id: space=1, page number=0]. You may have to recover from a backup. 002022-02-21 14:43:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes): len 16384; hex 00ffff00ffff00000000ff00ff000000000000ff0000ff00000000ff0000ff0000ffff000000ffffffffff00000000ffffffffff00000000ffff000000000000871dffffffffff000000ff00ff08ff00ff000000000000000000000000000000000000ffffffff000000ff00000000ffffffffff00000000ff00010000000100000000000000ff0000000000060000000000000000000000000000000000ffffffffffffffff000000000000000000000000000000000000000000000000000000004000000000150000000400000000ffff00000000000000000000ffff0000000000000000000000000000ffff000000ffffffff00ffffff0000000000000000000000000100000000009e00000000009e00000000ffffffffffff00ffffff0000000000000000000000ffffff0000000000ffff000000000000000000000000ffff000000000000ffff000000000000000000000000000000ffff00000000000000000000000000ffffff00ffffffffff0000ffff00ffffff000000000000000003000000000000000000000000000000ffffffff0000ffffffff000000000001000000000000000200000000000000570000260000000000000000000000000000000000000000000002002600ffffffff000000000000000000ff0000ffffff000000000000000000ffffffff000000000000ffffffff000000000002aaffffff00000000ffffffff00000000ff000000ff000000ff0000000000000000000000ffffffff0000ffffffff0000ff0000000000000000ff0000ff0000000000ffff000000000000000000000000000000000000ff000000000000000000000000000000000000000000ffffff0000ffffffff000005d669d2000000000000000000000000000000000000000000000000000000000000000000f5ffff00ffffff000000000000ff0000000000ffffffff00ff00ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff00000000000000ff0000000000000000000000ffffff00000000000000000000000000ffffffffffff0000000000000000ffffff000000ffffffff00000000000000000000000000ffffffffffffffffffffffffffffffffffff00000000000000580000000000000000ffffffff0000ffffffff000000000000ffffffff0000ffffffff000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000ffff0000000000000000000000000000000000000000ffff0000ffffffff000005d669d2000000f6ffffffffff000000000000000000ffffffffffffffffffffffffffffffffffffffffffffffffffffffffff innodb_use_native_aio=0 reading the same datadir is starts without problem $ sql/mysqld --no-defaults --skip-networking --datadir=/mnt/btrfstest/dd --verbose --innodb_use_native_aio=0 --socket /tmp/mysql.sock 2022-02-21 14:51:07 0 [Note] sql/mysqld (server 10.6.8-MariaDB) starting as process 122494 ... 2022-02-21 14:51:07 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2022-02-21 14:51:07 0 [Note] InnoDB: Number of pools: 1 2022-02-21 14:51:07 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions 2022-02-21 14:51:07 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728 2022-02-21 14:51:07 0 [Note] InnoDB: Completed initialization of buffer pool 2022-02-21 14:51:07 0 [Note] InnoDB: 128 rollback segments are active. 2022-02-21 14:51:07 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2022-02-21 14:51:07 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2022-02-21 14:51:07 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2022-02-21 14:51:07 0 [Note] InnoDB: 10.6.8 started; log sequence number 42197; transaction id 14 2022-02-21 14:51:07 0 [Note] InnoDB: Loading buffer pool(s) from /mnt/btrfstest/dd/ib_buffer_pool 2022-02-21 14:51:07 0 [Note] CONNECT: Version 1.07.0002 March 22, 2021 2022-02-21 14:51:07 0 [Note] Plugin 'FEEDBACK' is disabled. 2022-02-21 14:51:07 0 [Note] InnoDB: Buffer pool(s) load completed at 220221 14:51:07 2022-02-21 14:51:07 0 [Note] sql/mysqld: ready for connections. Version: '10.6.8-MariaDB' socket: '/tmp/mysql.sock' port: 0 MariaDB Server ^C2022-02-21 14:51:34 0 [Note] sql/mysqld (initiated by: unknown): Normal shutdown 2022-02-21 14:51:34 0 [Note] InnoDB: FTS optimize thread exiting. 2022-02-21 14:51:34 0 [Note] InnoDB: Starting shutdown... 2022-02-21 14:51:34 0 [Note] InnoDB: Dumping buffer pool(s) to /mnt/btrfstest/dd/ib_buffer_pool 2022-02-21 14:51:34 0 [Note] InnoDB: Buffer pool(s) dump completed at 220221 14:51:34 2022-02-21 14:51:35 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1" 2022-02-21 14:51:35 0 [Note] InnoDB: Shutdown completed; log sequence number 42209; transaction id 15 2022-02-21 14:51:35 0 [Note] sql/mysqld: Shutdown complete --innodb_use_native_aio=1 afterwards generated same result. chattr +C didn't change the result of the corruption. $ od -Ax -t x1 -j 0x24000 -N 0x4000 ibdata1 024000 00 00 00 00 00 00 00 09 ff ff ff ff ff ff ff ff 024010 00 00 00 00 00 00 9c 20 45 bf 00 00 00 00 00 00 024020 00 00 00 00 00 00 00 02 01 71 00 09 00 00 00 00 024030 01 55 00 02 00 06 00 07 00 00 00 00 00 00 00 09 024040 00 00 00 00 00 00 00 00 00 05 00 00 00 00 00 00 024050 00 02 05 72 00 00 00 00 00 00 00 02 04 b2 08 01 024060 00 00 03 00 85 69 6e 66 69 6d 75 6d 00 09 08 00 024070 08 03 00 00 73 75 70 72 65 6d 75 6d 00 13 08 00 024080 00 10 05 00 a0 00 00 00 00 00 00 00 0b 53 59 53 024090 5f 46 4f 52 45 49 47 4e 18 08 00 00 18 05 00 c0 0240a0 00 00 00 00 00 00 00 0c 53 59 53 5f 46 4f 52 45 0240b0 49 47 4e 5f 43 4f 4c 53 13 08 00 00 20 05 00 db 0240c0 00 00 00 00 00 00 00 0d 53 59 53 5f 56 49 52 54 0240d0 55 41 4c 20 08 00 00 28 05 01 03 00 00 00 00 00 0240e0 00 00 0e 6d 79 73 71 6c 2f 69 6e 6e 6f 64 62 5f 0240f0 74 61 62 6c 65 5f 73 74 61 74 73 20 08 00 00 30 024100 05 01 2b 00 00 00 00 00 00 00 0f 6d 79 73 71 6c 024110 2f 69 6e 6e 6f 64 62 5f 69 6e 64 65 78 5f 73 74 024120 61 74 73 22 08 00 00 38 05 01 55 00 00 00 00 00 024130 00 00 10 6d 79 73 71 6c 2f 74 72 61 6e 73 61 63 024140 74 69 6f 6e 5f 72 65 67 69 73 74 72 79 1c 08 00 024150 00 40 05 00 74 00 00 00 00 00 00 00 11 6d 79 73 024160 71 6c 2f 67 74 69 64 5f 73 6c 61 76 65 5f 70 6f 024170 73 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 024180 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 * 027ff0 00 00 00 00 00 74 00 65 00 00 9c 20 b3 73 ac c6 028000 use aio=0 on mysql_install_db (still with chattr +C) $ scripts/mysql_install_db --no-defaults --srcdir=$OLDPWD --builddir=$PWD --datadir=/mnt/btrfstest/noaio --innodb_use_native_aio=0 Installing MariaDB/MySQL system tables in '/mnt/btrfstest/noaio' ... OK ~/repos/build-mariadb-server-10.6 $ sql/mysqld --no-defaults --skip-networking --datadir=/mnt/btrfstest/noaio --verbose --innodb_use_native_aio=1 --socket /tmp/mysql.sock 2022-02-21 14:59:31 0 [Note] sql/mysqld (server 10.6.8-MariaDB) starting as process 123017 ... 2022-02-21 14:59:31 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2022-02-21 14:59:31 0 [Note] InnoDB: Number of pools: 1 2022-02-21 14:59:31 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions 2022-02-21 14:59:31 0 [Note] InnoDB: Using liburing 2022-02-21 14:59:31 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728 2022-02-21 14:59:31 0 [Note] InnoDB: Completed initialization of buffer pool 2022-02-21 14:59:31 0 [Note] InnoDB: 128 rollback segments are active. 2022-02-21 14:59:31 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2022-02-21 14:59:31 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2022-02-21 14:59:31 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2022-02-21 14:59:31 0 [Note] InnoDB: 10.6.8 started; log sequence number 42173; transaction id 14 2022-02-21 14:59:31 0 [Note] InnoDB: Loading buffer pool(s) from /mnt/btrfstest/noaio/ib_buffer_pool 2022-02-21 14:59:31 0 [Note] CONNECT: Version 1.07.0002 March 22, 2021 2022-02-21 14:59:31 0 [Note] Plugin 'FEEDBACK' is disabled. 2022-02-21 14:59:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=9]. You may have to recover from a backup. 2022-02-21 14:59:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes): len 16384; hex 0000000000000009ffffffffffffffff0000000000009c2045bf0000000000000000000000000002012022-02-21 14:59:31 0 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=243]. You may have to recover from a backup. 710009002022-02-21 14:59:31 0 [Note] InnoDB: Page dump in ascii and hex (16384 bytes):

Heinz Wiesinger added a comment - 2022-03-01 11:55

I ran into this issue on Slackware (-current 2022-02-25) with both 10.6.7 and 10.7.3. After discussing on zulip I can confirm that setting either innodb_use_native_aio=0 or innodb_flush_method=fsync work around the bug for me.

Heinz Wiesinger added a comment - 2022-03-01 11:55 I ran into this issue on Slackware (-current 2022-02-25) with both 10.6.7 and 10.7.3. After discussing on zulip I can confirm that setting either innodb_use_native_aio=0 or innodb_flush_method=fsync work around the bug for me.

Marko Mäkelä added a comment - 2022-03-01 11:56

I think that this needs to be resolved in the Linux kernel somehow.

Marko Mäkelä added a comment - 2022-03-01 11:56 I think that this needs to be resolved in the Linux kernel somehow.

Daniel Black added a comment - 2022-03-01 21:50

pprkut from zulip - your kernel version was 5.16.11. Chasing up now.

Daniel Black added a comment - 2022-03-01 21:50 pprkut from zulip - your kernel version was 5.16.11. Chasing up now.

Daniel Black added a comment - 2022-03-03 04:08

Kernel patch: https://lore.kernel.org/linux-btrfs/CABVffENfbsC6HjGbskRZGR2NvxbnQi17gAuW65eOM+QRzsr8Bg@mail.gmail.com/T/#mb2738e675e48e0e0778a2e8d1537dec5ec0d3d3a thanks to the great work by Filipe Manana (Suse).

Daniel Black added a comment - 2022-03-03 04:08 Kernel patch: https://lore.kernel.org/linux-btrfs/CABVffENfbsC6HjGbskRZGR2NvxbnQi17gAuW65eOM+QRzsr8Bg@mail.gmail.com/T/#mb2738e675e48e0e0778a2e8d1537dec5ec0d3d3a thanks to the great work by Filipe Manana (Suse).

Daniel Black added a comment - 2022-03-10 07:29

So the problem as Filipe Manana described is that we didn't look at the return values.

And its true, the in the aio code we set m_ret_len to be the value returned by the underlying call, and except for the Windows case, we otherwise ignore it.

If we assume the the cb->m_buffer isn't used by the AIO handlers, which was the case for innodb, we can just resubmit.

bb-10.6-danielblack-~~MDEV-27900~~-resubmit-partial-reads for going through tests. Discussions on the linux mailing lists indicates that under some circumstances it might happen in AIO. So most of the patch will go into 10.5, and the uring to 10.6.

Daniel Black added a comment - 2022-03-10 07:29 So the problem as Filipe Manana described is that we didn't look at the return values. And its true, the in the aio code we set m_ret_len to be the value returned by the underlying call, and except for the Windows case, we otherwise ignore it. If we assume the the cb->m_buffer isn't used by the AIO handlers, which was the case for innodb, we can just resubmit. bb-10.6-danielblack- MDEV-27900 -resubmit-partial-reads for going through tests. Discussions on the linux mailing lists indicates that under some circumstances it might happen in AIO. So most of the patch will go into 10.5, and the uring to 10.6.

People

Assignee:: Daniel Black

Reporter:: ajs124

Votes:: 1 Vote for this issue

Watchers:: 10 Start watching this issue

Dates

Created:: 2022-02-20 12:45

Updated:: 2022-07-25 00:31

Resolved:: 2022-03-12 05:54

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.