[MDEV-32170] Frequent 'InnoDB: Database page corruption on disk' on MariaDB 10.11 on Debian Bookworm on arch ppc64el Created: 2023-09-14  Updated: 2023-09-15  Resolved: 2023-09-15

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.11.3
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Timothy Pearson Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: corruption, innodb, regression

Attachments: PNG File image-2023-02-25-13-11-25-771.png     PNG File screenshot-1.png     PNG File screenshot-2.png    
Issue Links:
Relates
relates to MDEV-30728 Frequent 'InnoDB: Database page corru... Closed

 Description   

This might be related to the Debian ppc64el hosts that run the autopkgtests, but reporting this upstream anyway in case other people run into the same errors.

In Debian the ci.debian.net system frequently reports failures in the upstream mariadb-test-run for arch ppc64el:

The same does not happen on other archs (no problem on amd64, arm64, s390x).

The test varies, but error is always the same: SQL fails to execute because a table or all of InnoDB was missing, followed by warnings about database page corruption and some times also a full page dump.

Example:

main.index_merge_innodb 'innodb'         w3 [ fail ]
 
        Test ended at 2023-02-23 05:11:30
 
 
 
CURRENT_TEST: main.index_merge_innodb
 
mysqltest: At line 86: query 'SELECT COUNT(*) FROM 
(SELECT * FROM t1 FORCE INDEX(primary,idx)
 
WHERE a BETWEEN 2 AND 7 OR pk=1000000) AS t' failed: ER_NOT_KEYFILE (1034): Index for table 't1' is corrupt; try to repair it
 
 
 
The result from queries just before the failure was:
 
< snip >
 
INSERT INTO t0(a,b) SELECT a+40, b+4000 FROM t0;
 
INSERT INTO t0(a,b) SELECT a+80, b+8000 FROM t0;
 
begin;
 
INSERT INTO t1(a,b) SELECT t0.a,t0.b FROM t0, seq_1_to_1024;
 
INSERT INTO t1 VALUES (1000000, 0, 0);
 
commit;
 
DROP TABLE t0;
 
SET SESSION sort_buffer_size = 1024*36;
 
set @tmp_optimizer_switch=@@optimizer_switch;
 
set optimizer_switch='derived_merge=off,derived_with_keys=off';
 
EXPLAIN
 
SELECT COUNT(*) FROM 
(SELECT * FROM t1 FORCE INDEX(primary,idx)
 
WHERE a BETWEEN 2 AND 7 OR pk=1000000) AS t;
 
id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
 
1	PRIMARY	<derived2>	ALL	NULL	NULL	NULL	NULL	#	
2	DERIVED	t1	index_merge	PRIMARY,idx	idx,PRIMARY	5,4	NULL	#	Using sort_union(idx,PRIMARY); Using where
 
SELECT COUNT(*) FROM 
(SELECT * FROM t1 FORCE INDEX(primary,idx)
 
WHERE a BETWEEN 2 AND 7 OR pk=1000000) AS t;
 
 
 
More results from queries before failure can be found in /tmp/tmp.enF8Q76mMp/var/3/log/index_merge_innodb.log
 
 
 
Warnings from just before the error:
 
Error 1034 Index for table 't1' is corrupt; try to repair it
 
 
 
 - saving '/tmp/tmp.enF8Q76mMp/var/3/log/main.index_merge_innodb-innodb/' to '/tmp/tmp.enF8Q76mMp/var/log/main.index_merge_innodb-innodb/'
 
 
 
Retrying test main.index_merge_innodb, attempt(2/3)...
 
 
 
worker[3] > Restart  - not started
 
main.rowid_filter_innodb 'innodb'        w1 [ fail ]
 
        Test ended at 2023-02-23 05:11:31
 
 
 
CURRENT_TEST: main.rowid_filter_innodb
 
mysqltest: At line 82: query 'create table t1 (a int, b int, key (b), key (a)) engine=innodb' failed: <Unknown> (2013): Lost connection to server during query
 
 
 
The result from queries just before the failure was:
 
< snip >
 
create table t1 (id int not null primary key) engine=innodb;
 
insert into t1 values (2),(1);
 
create table t2 (y int,x int,index (x),index (y)) engine=innodb;
 
insert into t2 values
 
(4,1),(4,777),(2,1),(2,888),(111,1),(222,1),(333,345),(444,1),
 
(555,555),(666,1);
 
select * from t1 join t2 on t1.id = t2.x where t2.y = 2 and t1.id = 1;
 
id	y	x
 
1	2	1
 
explain extended select * from t1 join t2 on t1.id = t2.x where t2.y = 2 and t1.id = 1;
 
id	select_type	table	type	possible_keys	key	key_len	ref	rows	filtered	Extra
 
1	SIMPLE	t1	const	PRIMARY	PRIMARY	4	const	1	100.00	Using index
 
1	SIMPLE	t2	index_merge	x,y	y,x	5,5	NULL	1	100.00	Using intersect(y,x); Using where; Using index
 
Warnings:
 
Note	1003	select 1 AS `id`,`test`.`t2`.`y` AS `y`,`test`.`t2`.`x` AS `x` from `test`.`t1` join `test`.`t2` where `test`.`t2`.`y` = 2 and `test`.`t2`.`x` = 1
 
drop table t1, t2;
 
#
 
# MDEV-19820: use of rowid filter for innodb table without primary key
 
#
 
create table t1 (a int, b int, key (b), key (a)) engine=innodb;
 
 
 
More results from queries before failure can be found in /tmp/tmp.enF8Q76mMp/var/1/log/rowid_filter_innodb.log
 
 
 
 
 
Server [mysqld.1 - pid: 6392, winpid: 6392, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
$ /usr/sbin/mariadbd --defaults-group-suffix=.1 --defaults-file=/tmp/tmp.enF8Q76mMp/var/1/my.cnf --log-output=file --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-lock-waits --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --loose-sequence --loose-sequence --core-file --loose-debug-sync-timeout=300
 
2023-02-23  5:11:26 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32186)
 
2023-02-23  5:11:26 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
 
2023-02-23  5:11:26 0 [Note] Starting MariaDB 10.11.2-MariaDB-1-log source revision  as process 6393
 
2023-02-23  5:11:26 0 [Note] Plugin 'partition' is disabled.
 
2023-02-23  5:11:26 0 [Note] InnoDB: Compressed tables use zlib 1.2.13
 
2023-02-23  5:11:26 0 [Note] InnoDB: Number of transaction pools: 1
 
2023-02-23  5:11:26 0 [Note] InnoDB: Using POWER8 crc32 instructions
 
2023-02-23  5:11:26 0 [Note] InnoDB: Using liburing
 
2023-02-23  5:11:26 0 [Note] InnoDB: Initializing buffer pool, total size = 8.000MiB, chunk size = 1.000MiB
 
2023-02-23  5:11:26 0 [Note] InnoDB: Completed initialization of buffer pool
 
2023-02-23  5:11:26 0 [Note] InnoDB: File system buffers for log disabled (block size=512 bytes)
 
2023-02-23  5:11:27 0 [Note] InnoDB: 128 rollback segments are active.
 
2023-02-23  5:11:27 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
 
2023-02-23  5:11:27 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
 
2023-02-23  5:11:27 0 [Note] InnoDB: log sequence number 46990; transaction id 16
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_CMP' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'user_variables' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
 
2023-02-23  5:11:27 0 [Note] Plugin 'unix_socket' is disabled.
 
2023-02-23  5:11:27 0 [Warning] /usr/sbin/mariadbd: unknown variable 'loose-feedback-debug-startup-interval=20'
 
2023-02-23  5:11:27 0 [Warning] /usr/sbin/mariadbd: unknown variable 'loose-feedback-debug-first-interval=60'
 
2023-02-23  5:11:27 0 [Warning] /usr/sbin/mariadbd: unknown variable 'loose-feedback-debug-interval=60'
 
2023-02-23  5:11:27 0 [Warning] /usr/sbin/mariadbd: unknown option '--loose-pam-debug'
 
2023-02-23  5:11:27 0 [Warning] /usr/sbin/mariadbd: unknown option '--loose-aria'
 
2023-02-23  5:11:27 0 [Warning] /usr/sbin/mariadbd: unknown variable 'loose-debug-sync-timeout=300'
 
2023-02-23  5:11:27 0 [Note] InnoDB: Loading buffer pool(s) from /tmp/tmp.enF8Q76mMp/var/1/mysqld.1/data/ib_buffer_pool
 
2023-02-23  5:11:27 0 [Note] Server socket created on IP: '127.0.0.1'.
 
2023-02-23  5:11:27 0 [Note] /usr/sbin/mariadbd: ready for connections.
 
Version: '10.11.2-MariaDB-1-log'  socket: '/tmp/tmp.enF8Q76mMp/tmp/1/mysqld.1.sock'  port: 16000  Debian n/a
 
2023-02-23  5:11:27 0 [Note] InnoDB: Buffer pool(s) load completed at 230223  5:11:27
 
2023-02-23  5:11:30 4 [ERROR] InnoDB: Database page corruption on disk or a failed read of file './ibdata1' page [page id: space=0, page number=289]. You may have to recover from a backup.
 
2023-02-23  5:11:30 4 [Note] InnoDB: Page dump (16384 bytes):
 
2023-02-23  5:11:30 4 [Note] InnoDB: 0000000000000121ffffffffffffffff00000000002ea01f0006000000000000
 
2023-02-23  5:11:30 4 [Note] InnoDB: 000000000000000000000000000000000002000001a80330000001a800780000
 
2023-02-23  5:11:30 4 [Note] InnoDB: 0000000000f321f2000001a8ffffffffffffffffffffffffffffffffffffffff
 
2023-02-23  5:11:30 4 [Note] InnoDB: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
 
2023-02-23  5:11:30 4 [Note] InnoDB: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
 
2023-02-23  5:11:30 4 [Note] InnoDB: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
 
2023-02-23  5:11:30 4 [Note] InnoDB: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
 
2023-02-23  5:11:30 4 [Note] InnoDB: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
 
2023-02-23  5:11:30 4 [Note] InnoDB: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
 
2023-02-23  5:11:30 4 [Note] InnoDB: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
 
2023-02-23  5:11:30 4 [Note] InnoDB: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
 
...

Full logs:
Failing test(s): main.index_merge_innodb main.rowid_filter_innodb main.bootstrap_innodb main.parser_bug21114_innodb
Failing test(s): main.xa_prepared_binlog_off
Failing test(s): main.ctype_utf8mb4_innodb main.range_vs_index_merge_innodb
Failing test(s): main.innodb_ext_key main.index_merge_innodb
Failing test(s): main.innodb_ext_key
Failing test(s): main.index_merge_innodb
Failing test(s): main.rowid_filter_innodb main.range_vs_index_merge_innodb
Failing test(s): main.innodb_ext_key

 Comments   
Comment by Timothy Pearson [ 2023-09-14 ]

Cloned original bug as the original bug was closed with no way to reopen, and this is a major issue that is corrupting data on production systems as soon as they are upgraded to Debian Bookworm.

Full details provided in original (improperly closed) bug starting here:
https://jira.mariadb.org/browse/MDEV-30728?focusedCommentId=269069

I have confirmed this is NOT a kernel issue – the corruption persisted (albeit much less likely to happen, took a day to reproduce vs. minutes) all the way back to the ancient 4.19 Buster kernel. Downgrading the database from 10.11 to either 10.3 or 10.5 completely resolves the corruption issues, as confirmed by over a week of uncorrupted uptime on the same hardware and same OS as before.

Comment by Marko Mäkelä [ 2023-09-15 ]

Sorry, I was not aware that only developers can reopen bugs. Let’s continue the analysis in MDEV-30728.

Generated at Thu Feb 08 10:29:22 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.