[MDEV-31254] InnoDB: Trying to read doublewrite buffer page Created: 2023-05-12  Updated: 2023-08-17  Resolved: 2023-05-15

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.5, 10.6
Fix Version/s: 10.4.32, 10.5.22, 10.6.15, 10.9.8, 10.10.6, 10.11.5, 11.0.3, 11.1.2

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: File TBR-1898.opt     File TBR-1898.test    
Issue Links:
Relates
relates to MDEV-29967 innodb_read_ahead_threshold (linear r... Closed

 Description    

origin/bb-10.6-MDEV-29911 cd5ca0b11882cfa8eafa8c687ed3084423bc7e52 2023-05-11T14:05:52+03:00
 
Build with debug+asan
 
 
 
main/TBR-1898.opt
 
================
 
--innodb_file_per_table=0
 
--innodb_page_size=4K
 
--innodb_undo_tablespaces=3
 
--innodb-buffer-pool-size=5M
 
 
 
main/TBR-1898.test
 
================
 
--source include/have_innodb.inc
 
 
 
CREATE TABLE `t1` (
 
`col1` CHAR(60) NOT NULL default '',
 
`col2` CHAR(120) NOT NULL default '',
 
`id` INT(10) unsigned NOT NULL auto_increment,
 
PRIMARY KEY (`id`)) ENGINE = InnoDB ;
 
 
 
INSERT INTO `t1` (`col1`, `col2`) VALUES ('Paléo Pyli', '0123456789');
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
 
 
DROP TABLE t1;
 
 
 
./mtr --mem --rr TBR-1898
 
...
 
TEST                                      RESULT   TIME (ms) or COMMENT
 
--------------------------------------------------------------------------
 
 
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
 
CREATE TABLE `t1` (
 
`col1` CHAR(60) NOT NULL default '',
 
`col2` CHAR(120) NOT NULL default '',
 
`id` INT(10) unsigned NOT NULL auto_increment,
 
PRIMARY KEY (`id`)) ENGINE = InnoDB ;
 
INSERT INTO `t1` (`col1`, `col2`) VALUES ('Paléo Pyli', '0123456789');
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`;
 
main.TBR-1898 'innodb'                   [ fail ]
 
        Test ended at 2023-05-12 03:41:27
 
 
 
CURRENT_TEST: main.TBR-1898
 
mysqltest: At line 25: query 'INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`' failed: <Unknown> (2013): Lost connection to server during query
 
...
 
2023-05-12  3:41:24 0 [Note] /data/Server_bin/bb-10.6-MDEV-29911D_asan_Og/bin/mariadbd: ready for connections.
 
Version: '10.6.14-MariaDB-debug-log'  socket: '/data/Server_bin/bb-10.6-MDEV-29911D_asan_Og/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
 
2023-05-12  3:41:27 4 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=256]
 
mariadbd: /data/Server/bb-10.6-MDEV-29911D/storage/innobase/buf/buf0rea.cc:270: dberr_t buf_read_page_low(fil_space_t*, bool, ulint, page_id_t, ulint, bool): Assertion `0' failed.
 
...
 
(rr) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=139636108817984) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=139636108817984) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=139636108817984, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x00007eff9c509476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x00007eff9c4ef7f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x00007eff9c4ef71b in __assert_fail_base (fmt=0x7eff9c6a4150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55edb81b6300 "0", 
    file=0x55edb81b6b00 "/data/Server/bb-10.6-MDEV-29911D/storage/innobase/buf/buf0rea.cc", line=270, function=<optimized out>) at ./assert/assert.c:92
 
#6  0x00007eff9c500e96 in __GI___assert_fail (assertion=0x55edb81b6300 "0", file=0x55edb81b6b00 "/data/Server/bb-10.6-MDEV-29911D/storage/innobase/buf/buf0rea.cc", line=270, 
    function=0x55edb81b6340 "dberr_t buf_read_page_low(fil_space_t*, bool, ulint, page_id_t, ulint, bool)") at ./assert/assert.c:101
 
#7  0x000055edb7453157 in buf_read_page_low (space=space@entry=0x612000002a40, sync=sync@entry=false, mode=mode@entry=132, page_id=..., zip_size=zip_size@entry=0, unzip=unzip@entry=false)
 
    at /data/Server/bb-10.6-MDEV-29911D/storage/innobase/buf/buf0rea.cc:270
 
#8  0x000055edb74580b8 in buf_read_ahead_linear (page_id=..., zip_size=<optimized out>, ibuf=<optimized out>) at /data/Server/bb-10.6-MDEV-29911D/storage/innobase/buf/buf0rea.cc:639
 
#9  0x000055edb7404e1a in buf_page_get_low (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=1, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7eff90a9bce0, err=<optimized out>, 
    allow_ibuf_merge=<optimized out>) at /data/Server/bb-10.6-MDEV-29911D/storage/innobase/buf/buf0buf.cc:2894
 
#10 0x000055edb74051ca in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=rw_latch@entry=1, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7eff90a9bce0, err=0x7eff90a9adb0, allow_ibuf_merge=false)
 
    at /data/Server/bb-10.6-MDEV-29911D/storage/innobase/buf/buf0buf.cc:2927
 
#11 0x000055edb7325f76 in btr_block_get (index=..., page=page@entry=255, mode=<optimized out>, merge=<optimized out>, mtr=mtr@entry=0x7eff90a9bce0, err=err@entry=0x7eff90a9adb0)
 
    at /data/Server/bb-10.6-MDEV-29911D/storage/innobase/btr/btr0btr.cc:228
 
#12 0x000055edb73b7916 in btr_pcur_move_to_next_page (cursor=cursor@entry=0x6200000352e8, mtr=mtr@entry=0x7eff90a9bce0) at /data/Server/bb-10.6-MDEV-29911D/storage/innobase/btr/btr0pcur.cc:542
 
#13 0x000055edb71fe4b8 in row_search_mvcc (buf=buf@entry=0x6190000b40c8 "\377Paléo Pyli", ' ' <repeats 49 times>, "0123456789", ' ' <repeats 110 times>, "N\v", mode=PAGE_CUR_G, mode@entry=PAGE_CUR_UNSUPP, 
    prebuilt=<optimized out>, match_mode=match_mode@entry=0, direction=direction@entry=1) at /data/Server/bb-10.6-MDEV-29911D/storage/innobase/row/row0sel.cc:5808
 
#14 0x000055edb6dc47e6 in ha_innobase::general_fetch (this=this@entry=0x61d000265cb8, buf=0x6190000b40c8 "\377Paléo Pyli", ' ' <repeats 49 times>, "0123456789", ' ' <repeats 110 times>, "N\v", 
    direction=direction@entry=1, match_mode=match_mode@entry=0) at /data/Server/bb-10.6-MDEV-29911D/storage/innobase/handler/ha_innodb.cc:9369
 
#15 0x000055edb6dea312 in ha_innobase::rnd_next (this=0x61d000265cb8, buf=<optimized out>) at /data/Server/bb-10.6-MDEV-29911D/storage/innobase/handler/ha_innodb.cc:9573
 
#16 0x000055edb6344029 in handler::ha_rnd_next (this=0x61d000265cb8, buf=0x6190000b40c8 "\377Paléo Pyli", ' ' <repeats 49 times>, "0123456789", ' ' <repeats 110 times>, "N\v")
 
    at /data/Server/bb-10.6-MDEV-29911D/sql/handler.cc:3449
 
#17 0x000055edb698802a in rr_sequential (info=0x62b0000a4ae8) at /data/Server/bb-10.6-MDEV-29911D/sql/records.cc:519
 
#18 0x000055edb5b54055 in READ_RECORD::read_record (this=0x62b0000a4ae8) at /data/Server/bb-10.6-MDEV-29911D/sql/records.h:81
 
#19 sub_select (join=0x62b0000a3640, join_tab=0x62b0000a4a10, end_of_records=false) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_select.cc:21658
 
#20 0x000055edb5bcf202 in do_select (join=join@entry=0x62b0000a3640, procedure=<optimized out>) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_select.cc:21170
 
#21 0x000055edb5bf8fd0 in JOIN::exec_inner (this=this@entry=0x62b0000a3640) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_select.cc:4812
 
#22 0x000055edb5bf9303 in JOIN::exec (this=this@entry=0x62b0000a3640) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_select.cc:4590
 
#23 0x000055edb5bf2fc1 in mysql_select (thd=thd@entry=0x62b00009a218, tables=0x62b0000a2568, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2202244745984, 
    result=0x62b0000a3578, unit=0x62b00009e388, select_lex=0x62b0000a1d80) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_select.cc:5069
 
#24 0x000055edb5bf4908 in handle_select (thd=thd@entry=0x62b00009a218, lex=lex@entry=0x62b00009e2c0, result=result@entry=0x62b0000a3578, setup_tables_done_option=setup_tables_done_option@entry=1073741824)
 
    at /data/Server/bb-10.6-MDEV-29911D/sql/sql_select.cc:559
 
#25 0x000055edb5a6ee17 in mysql_execute_command (thd=thd@entry=0x62b00009a218, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_parse.cc:4719
 
#26 0x000055edb5a7aad8 in mysql_parse (thd=thd@entry=0x62b00009a218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7eff90a9d620) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_parse.cc:8036
 
#27 0x000055edb5a81313 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b00009a218, packet=packet@entry=0x62900024e219 "INSERT INTO `t1` (`col1`, `col2`) SELECT `col1`, `col2` FROM `t1`", 
    packet_length=packet_length@entry=65, blocking=blocking@entry=true) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_parse.cc:1896
 
#28 0x000055edb5a8621a in do_command (thd=0x62b00009a218, blocking=blocking@entry=true) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_parse.cc:1409
 
#29 0x000055edb5eb1674 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x608000002238, put_in_cache=put_in_cache@entry=true) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_connect.cc:1416
 
#30 0x000055edb5eb1cda in handle_one_connection (arg=0x608000002238) at /data/Server/bb-10.6-MDEV-29911D/sql/sql_connect.cc:1318
 
#31 0x00007eff9c55bb43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#32 0x00007eff9c5ecbb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
 
(rr)
 
 
 
During RQG testing I hit cases where the same assert showed up
 
a) the restart after a crash failed (again innodb_file_per_table=0)
 
b) running wild DDL on some empty table followed by TRUNCATE that table ( innodb_file_per_table=1)



 Comments   
Comment by Marko Mäkelä [ 2023-05-12 ]

At some point I had added a debug assertion next to an error message, so that the error would be caught in our internal testing if it is at all reachable.

With the provided test case, I see a call to buf_read_ahead_linear() on the page number 255, for fetching a B-tree page. When using innodb_page_size=4k, the smallest doublewrite buffer page number is 256. This is tripping the message. I believe that the correct fix is to simply remove the message and the debug assertion:

diff --git a/storage/innobase/buf/buf0rea.cc b/storage/innobase/buf/buf0rea.cc
 
--- a/storage/innobase/buf/buf0rea.cc
 
+++ b/storage/innobase/buf/buf0rea.cc
 
@@ -280,9 +280,6 @@ buf_read_page_low(
 
 	*err = DB_SUCCESS;
 
 
 	if (buf_dblwr.is_inside(page_id)) {
 
-		ib::error() << "Trying to read doublewrite buffer page "
 
-			<< page_id;
 
-		ut_ad(0);
 
 nothing_read:
 
 		space->release();
 
 		return false;

This error message could be issued with MariaDB Server 10.4 as well, but I did not test that yet.

Comment by Marko Mäkelä [ 2023-05-12 ]

It could be marginally safer to assign *err to an error code. In 10.6, starting with MDEV-26827, the function would return DB_PAGE_CORRUPTED already, which is supported by the higher-level code that was refactored in MDEV-13542.

Comment by Marko Mäkelä [ 2023-05-12 ]

I ran the test on MariaDB Server 10.4 b3cdb612491de6070c376bd98d30c5ec9aaffa87, but for some reason it did not trigger the error message. In 10.4 there is no ut_ad(0) after the message.

Comment by Matthias Leich [ 2023-05-15 ]

origin/bb-10.5-MDEV-31254 c9eff1a144ba44846373660a30d342d3f0dc91a5 2023-05-12T15:04:50+03:00
performed well in RQG testing.

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