[MDEV-22512] innodb_zip.recover, innodb_gis.types failed in buildbot with server failing to restart - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.2(EOL), 10.3(EOL), 10.4(EOL)
Fix Version/s: 10.3.38, 10.4.28
Component/s: Tests
Labels:
- not-10.5

Description

Note: Possibly it has already been fixed, but I don't see a clear indication of it.

http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/3970/steps/mtr_centos_mix/logs/stdio

bb-10.2-release 75dcb74da652d8ba504b6906b2aa2ae5 2020-05-06 16:30:28
innodb_zip.recover 'innodb' w1 [ fail ]
Test ended at 2020-05-06 14:52:03

CURRENT_TEST: innodb_zip.recover
mysqltest: In included file "./include/wait_until_connected_again.inc":
included from ./include/start_mysqld.inc at line 18:
included from ./include/restart_mysqld.inc at line 11:
included from /usr/share/mysql-test/suite/innodb_zip/t/recover.test at line 29:
At line 23: Server failed to restart

The result from queries just before the failure was:
#
# MDEV-12720 recovery fails with "Generic error"
# for ROW_FORMAT=compressed
#
CREATE TABLE a(i INT PRIMARY KEY AUTO_INCREMENT, s VARCHAR(255)) ENGINE=InnoDB
ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=1;
BEGIN;
insert into a(i) select null;
insert into a select null, uuid() from a a, a b, a c;
insert into a select null, uuid() from a a, a b, a c;
insert into a select null, uuid() from a a, a b, a c;
SET GLOBAL innodb_flush_log_at_trx_commit=1;
COMMIT;

Last words in the log:

2020-05-07  9:42:08 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 17, since the redo log references ./test/t1.ibd with space ID 16.

2020-05-07  9:42:08 0 [Note] InnoDB: Starting a batch to recover 332 pages from redo log.

2020-05-07  9:42:09 0 [Warning] InnoDB: Difficult to find free blocks in the buffer pool (21 search iterations)! 21 failed attempts to flush a page! Consider increasing innodb_buffer_pool_size. Pending flushes (fsync) log: 0; buffer pool: 0. 381 OS file reads, 78 OS file writes, 78 OS fsyncs.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

mysqld.1.err.1.gz
2020-05-09 12:24
465 kB
Elena Stepanova

Issue Links

duplicates

MDEV-21351 Replace recv_sys.heap with list of buf_block_t*

Closed

relates to

MDEV-21351 Replace recv_sys.heap with list of buf_block_t*

Closed

MDEV-21826 Recovery failure : loop of Read redo log up to LSN

Closed

MDEV-23979 Corrupted page breaks recovery in innodb_gis.types

Open

MDEV-19176 Do not run out of InnoDB buffer pool during recovery

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova added a comment - 2020-05-09 12:59

Another one, on bb-10.3-release:
http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/3984

tokudb_bugs.xa-3 'innodb'                w1 [ fail ]

        Test ended at 2020-05-07 09:50:42

CURRENT_TEST: tokudb_bugs.xa-3

mysqltest: In included file "./include/wait_until_connected_again.inc":

included from /usr/share/mysql-test/plugin/tokudb/tokudb_bugs/t/xa-3.test at line 82:

At line 23: Server failed to restart

The result from queries just before the failure was:

< snip >

INSERT INTO t2 VALUES (2);

SET SESSION debug_dbug="d,crash_commit_after_prepare";

COMMIT;

ERROR HY000: Lost connection to MySQL server during query

select * from t1;

select * from t2;

drop table t1, t2;

CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=innodb;

CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=tokudb;

BEGIN;

SELECT @@log_bin;

@@log_bin

INSERT INTO t1 VALUES (1);

INSERT INTO t2 VALUES (2);

SET SESSION debug_dbug="d,crash_commit_after";

COMMIT;

ERROR HY000: Lost connection to MySQL server during query

Elena Stepanova added a comment - 2020-05-09 12:59 Another one, on bb-10.3-release: http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/3984 tokudb_bugs.xa-3 'innodb' w1 [ fail ] Test ended at 2020-05-07 09:50:42 CURRENT_TEST: tokudb_bugs.xa-3 mysqltest: In included file "./include/wait_until_connected_again.inc": included from /usr/share/mysql-test/plugin/tokudb/tokudb_bugs/t/xa-3.test at line 82: At line 23: Server failed to restart The result from queries just before the failure was: < snip > INSERT INTO t2 VALUES (2); SET SESSION debug_dbug="d,crash_commit_after_prepare"; COMMIT; ERROR HY000: Lost connection to MySQL server during query select * from t1; a select * from t2; b drop table t1, t2; CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=innodb; CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=tokudb; BEGIN; SELECT @@log_bin; @@log_bin 0 INSERT INTO t1 VALUES (1); INSERT INTO t2 VALUES (2); SET SESSION debug_dbug="d,crash_commit_after"; COMMIT; ERROR HY000: Lost connection to MySQL server during query

Elena Stepanova added a comment - 2020-05-09 14:30

http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/3758

10.4 497a4169df5cd9837efd7a32b16426c9
tokudb_bugs.xa-4 'innodb' w3 [ fail ]
Test ended at 2020-03-25 17:48:09

CURRENT_TEST: tokudb_bugs.xa-4
mysqltest: In included file "./include/wait_until_connected_again.inc":
included from /usr/share/mysql-test/plugin/tokudb/tokudb_bugs/t/xa-4.test at line 59:
At line 34: Server failed to restart

The result from queries just before the failure was:
< snip >
INSERT INTO t2 VALUES (2);
SET SESSION debug_dbug="d,crash_commit_before";
COMMIT;
ERROR HY000: Lost connection to MySQL server during query
select * from t1;
a
select * from t2;
b
drop table t1, t2;
CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=innodb;
CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=tokudb;
BEGIN;
SELECT @@log_bin;
@@log_bin
0
INSERT INTO t1 VALUES (1);
INSERT INTO t2 VALUES (2);
SET SESSION debug_dbug="d,crash_commit_after";
COMMIT;
ERROR HY000: Lost connection to MySQL server during query

Elena Stepanova added a comment - 2020-05-09 14:30 http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos74-amd64-debug/builds/3758 10.4 497a4169df5cd9837efd7a32b16426c9 tokudb_bugs.xa-4 'innodb' w3 [ fail ] Test ended at 2020-03-25 17:48:09 CURRENT_TEST: tokudb_bugs.xa-4 mysqltest: In included file "./include/wait_until_connected_again.inc": included from /usr/share/mysql-test/plugin/tokudb/tokudb_bugs/t/xa-4.test at line 59: At line 34: Server failed to restart The result from queries just before the failure was: < snip > INSERT INTO t2 VALUES (2); SET SESSION debug_dbug="d,crash_commit_before"; COMMIT; ERROR HY000: Lost connection to MySQL server during query select * from t1; a select * from t2; b drop table t1, t2; CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=innodb; CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=tokudb; BEGIN; SELECT @@log_bin; @@log_bin 0 INSERT INTO t1 VALUES (1); INSERT INTO t2 VALUES (2); SET SESSION debug_dbug="d,crash_commit_after"; COMMIT; ERROR HY000: Lost connection to MySQL server during query

Marko Mäkelä added a comment - 2020-05-11 06:20

For the latest failure, we see the following in the server error log:

10.4 497a4169df5cd9837efd7a32b16426c92e3da882
2020-03-25 17:39:39 0 [Note] InnoDB: Starting a batch to recover 256 pages from redo log.
2020-03-25 17:39:40 0 [Note] InnoDB: Starting a batch to recover 378 pages from redo log.
2020-03-25 17:39:40 0 [Warning] InnoDB: Difficult to find free blocks in the buffer pool (21 search iterations)! 21 failed attempts to flush a page! Consider increasing innodb_buffer_pool_size. Pending flushes (fsync) log: 0; buffer pool: 0. 675 OS file reads, 44 OS file writes, 44 OS fsyncs.
CURRENT_TEST: tokudb_bugs.xa-4
2020-03-25 17:48:10 0 [Note] /usr/sbin/mysqld (mysqld 10.4.13-MariaDB-debug-log) starting as process 1664 ...

That is, the recovery appears to have been stuck for 8.5 minutes. The stated revision does include ~~MDEV-21826~~. In 10.5, that fix was improved further by ~~MDEV-21351~~.

I would hope that this bug has been fixed in 10.5.1 by ~~MDEV-21351~~, but I will leave this report open for a while. In older versions, a possible workaround could be to try to start up the server with a larger buffer pool size.

Marko Mäkelä added a comment - 2020-05-11 06:20 For the latest failure, we see the following in the server error log : 10.4 497a4169df5cd9837efd7a32b16426c92e3da882 2020-03-25 17:39:39 0 [Note] InnoDB: Starting a batch to recover 256 pages from redo log. 2020-03-25 17:39:40 0 [Note] InnoDB: Starting a batch to recover 378 pages from redo log. 2020-03-25 17:39:40 0 [Warning] InnoDB: Difficult to find free blocks in the buffer pool (21 search iterations)! 21 failed attempts to flush a page! Consider increasing innodb_buffer_pool_size. Pending flushes (fsync) log: 0; buffer pool: 0. 675 OS file reads, 44 OS file writes, 44 OS fsyncs. CURRENT_TEST: tokudb_bugs.xa-4 2020-03-25 17:48:10 0 [Note] /usr/sbin/mysqld (mysqld 10.4.13-MariaDB-debug-log) starting as process 1664 ... That is, the recovery appears to have been stuck for 8.5 minutes. The stated revision does include MDEV-21826 . In 10.5, that fix was improved further by MDEV-21351 . I would hope that this bug has been fixed in 10.5.1 by MDEV-21351 , but I will leave this report open for a while. In older versions, a possible workaround could be to try to start up the server with a larger buffer pool size.

Marko Mäkelä added a comment - 2020-05-12 11:52

Here is a recovery failure of innodb_gis.types on 10.2:

10.2 0e6a5786d4fc0e96c34ccee2c59a707e3debb3b3
CURRENT_TEST: innodb_gis.types
mysqltest: In included file "./include/wait_until_connected_again.inc":
included from ./include/start_mysqld.inc at line 18:
included from ./include/restart_mysqld.inc at line 11:
included from /usr/share/mysql-test/suite/innodb_gis/t/types.test at line 74:
At line 23: Server failed to restart

The result from queries just before the failure was:
< snip >
EXPLAIN SELECT ST_AsText(g) FROM t_wl6455 WHERE g = POINT(2,2);
id select_type table type possible_keys key key_len ref rows Extra
1 SIMPLE t_wl6455 ref i_p i_p 12 const 2 #
SELECT ST_AsText(g) FROM t_wl6455 WHERE g = POINT(2,2);
ST_AsText(g)
POINT(2 2)
SET AUTOCOMMIT = 0;
INSERT INTO t_wl6455 VALUES(10, POINT(10,10));
SELECT ST_AsText(g) FROM t_wl6455 WHERE g = POINT(10,10);
ST_AsText(g)
POINT(10 10)
ROLLBACK;
SELECT ST_AsText(g) FROM t_wl6455 WHERE g = POINT(10,10);
ST_AsText(g)
INSERT INTO t_wl6455 VALUES(10, POINT(10,10));
COMMIT;
FLUSH TABLES;
INSERT INTO t_wl6455 VALUES(11, POINT(11,11));
BEGIN;
INSERT INTO t_wl6455 VALUES(1, POINT(1,1));
…
2020-05-12 9:56:25 281473290790544 [Note] InnoDB: Starting crash recovery from checkpoint LSN=23757732
2020-05-12 9:56:25 281473290790544 [Note] InnoDB: Starting a batch to recover 407 pages from redo log.
2020-05-12 9:56:25 281473290790544 [Warning] InnoDB: Difficult to find free blocks in the buffer pool (21 search iterations)! 21 failed attempts to flush a page! Consider increasing innodb_buffer_pool_size. Pending flushes (fsync) log: 0; buffer pool: 0. 432 OS file reads, 16 OS file writes, 16 OS fsyncs.
CURRENT_TEST: innodb_gis.types
2020-05-12 10:04:48 281473685382800 [Note] /usr/sbin/mysqld (mysqld 10.2.33-MariaDB-log) starting as process 7729 ...

The test does kill and restart as follows:

BEGIN;

INSERT INTO t_wl6455 VALUES(1, POINT(1,1));

--let $shutdown_timeout=0

--source include/restart_mysqld.inc

CHECK TABLE t_wl6455;

Marko Mäkelä added a comment - 2020-05-12 11:52 Here is a recovery failure of innodb_gis.types on 10.2 : 10.2 0e6a5786d4fc0e96c34ccee2c59a707e3debb3b3 CURRENT_TEST: innodb_gis.types mysqltest: In included file "./include/wait_until_connected_again.inc": included from ./include/start_mysqld.inc at line 18: included from ./include/restart_mysqld.inc at line 11: included from /usr/share/mysql-test/suite/innodb_gis/t/types.test at line 74: At line 23: Server failed to restart The result from queries just before the failure was: < snip > EXPLAIN SELECT ST_AsText(g) FROM t_wl6455 WHERE g = POINT(2,2); id select_type table type possible_keys key key_len ref rows Extra 1 SIMPLE t_wl6455 ref i_p i_p 12 const 2 # SELECT ST_AsText(g) FROM t_wl6455 WHERE g = POINT(2,2); ST_AsText(g) POINT(2 2) SET AUTOCOMMIT = 0; INSERT INTO t_wl6455 VALUES(10, POINT(10,10)); SELECT ST_AsText(g) FROM t_wl6455 WHERE g = POINT(10,10); ST_AsText(g) POINT(10 10) ROLLBACK; SELECT ST_AsText(g) FROM t_wl6455 WHERE g = POINT(10,10); ST_AsText(g) INSERT INTO t_wl6455 VALUES(10, POINT(10,10)); COMMIT; FLUSH TABLES; INSERT INTO t_wl6455 VALUES(11, POINT(11,11)); BEGIN; INSERT INTO t_wl6455 VALUES(1, POINT(1,1)); … 2020-05-12 9:56:25 281473290790544 [Note] InnoDB: Starting crash recovery from checkpoint LSN=23757732 2020-05-12 9:56:25 281473290790544 [Note] InnoDB: Starting a batch to recover 407 pages from redo log. 2020-05-12 9:56:25 281473290790544 [Warning] InnoDB: Difficult to find free blocks in the buffer pool (21 search iterations)! 21 failed attempts to flush a page! Consider increasing innodb_buffer_pool_size. Pending flushes (fsync) log: 0; buffer pool: 0. 432 OS file reads, 16 OS file writes, 16 OS fsyncs. CURRENT_TEST: innodb_gis.types 2020-05-12 10:04:48 281473685382800 [Note] /usr/sbin/mysqld (mysqld 10.2.33-MariaDB-log) starting as process 7729 ... The test does kill and restart as follows: BEGIN ; INSERT INTO t_wl6455 VALUES (1, POINT(1,1)); --let $shutdown_timeout=0 --source include/restart_mysqld.inc CHECK TABLE t_wl6455;

Marko Mäkelä added a comment - 2020-10-19 08:50

In 10.5, the buildbot cross-reference does not find this kind of failures at all. I believe that the problem was fixed by ~~MDEV-21351~~ in 10.5.1 (and to lesser extent ~~MDEV-19176~~, which did not completely fix the problem in earlier versions).

Marko Mäkelä added a comment - 2020-10-19 08:50 In 10.5, the buildbot cross-reference does not find this kind of failures at all. I believe that the problem was fixed by MDEV-21351 in 10.5.1 (and to lesser extent MDEV-19176 , which did not completely fix the problem in earlier versions).

Aleksey Midenkov added a comment - 2020-12-21 17:30 - edited

10.2 fail:

innodb_gis.types 'innodb'                w1 [ fail ]

        Test ended at 2020-12-12 07:26:34

CURRENT_TEST: innodb_gis.types

mysqltest: In included file "./include/wait_until_connected_again.inc":

included from ./include/start_mysqld.inc at line 18:

included from ./include/restart_mysqld.inc at line 11:

included from /usr/share/mysql/mysql-test/suite/innodb_gis/t/types.test at line 74:

At line 23: Server failed to restart

10.3 fail:

innodb_gis.types 'innodb'                w2 [ fail ]

        Test ended at 2020-12-03 16:53:16

CURRENT_TEST: innodb_gis.types

mysqltest: In included file "./include/wait_until_connected_again.inc":

included from ./include/start_mysqld.inc at line 18:

included from ./include/restart_mysqld.inc at line 11:

included from /usr/share/mysql-test/suite/innodb_gis/t/types.test at line 74:

At line 23: Server failed to restart

More fails...

Please disable or make another workaround for pre-10.5.

Aleksey Midenkov added a comment - 2020-12-21 17:30 - edited 10.2 fail : innodb_gis.types 'innodb' w1 [ fail ] Test ended at 2020-12-12 07:26:34 CURRENT_TEST: innodb_gis.types mysqltest: In included file "./include/wait_until_connected_again.inc": included from ./include/start_mysqld.inc at line 18: included from ./include/restart_mysqld.inc at line 11: included from /usr/share/mysql/mysql-test/suite/innodb_gis/t/types.test at line 74: At line 23: Server failed to restart 10.3 fail : innodb_gis.types 'innodb' w2 [ fail ] Test ended at 2020-12-03 16:53:16 CURRENT_TEST: innodb_gis.types mysqltest: In included file "./include/wait_until_connected_again.inc": included from ./include/start_mysqld.inc at line 18: included from ./include/restart_mysqld.inc at line 11: included from /usr/share/mysql-test/suite/innodb_gis/t/types.test at line 74: At line 23: Server failed to restart More fails... Please disable or make another workaround for pre-10.5.

Elena Stepanova added a comment - 2022-04-16 13:08

Still fails and not disabled.

Elena Stepanova added a comment - 2022-04-16 13:08 Still fails and not disabled.

Marko Mäkelä added a comment - 2022-11-08 16:42

Fixed by disabling the tests in 10.3 and 10.4 (but not 10.5 or later).

Marko Mäkelä added a comment - 2022-11-08 16:42 Fixed by disabling the tests in 10.3 and 10.4 (but not 10.5 or later).

People

Assignee:: Marko Mäkelä

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 2020-05-09 12:24

Updated:: 2022-11-08 16:42

Resolved:: 2022-11-08 16:42

Git Integration

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

MariaDB Server

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration