[MDEV-22710] Assertion `mode == 16 || mode == 12 || fix_block->page.status != buf_page_t::FREED' failed in buf_page_get_low Created: 2020-05-26  Updated: 2020-08-13  Resolved: 2020-06-03

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.5.4, 10.5.3
Fix Version/s: 10.5.4

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: not-10.1, not-10.2, not-10.3, not-10.4, regression, rr-profile

Issue Links:
Problem/Incident
is caused by MDEV-15528 Avoid writing freed InnoDB pages Closed
Relates
relates to MDEV-22495 Assertion mode == 16 || mode == 12 ||... Closed
relates to MDEV-23469 Assertion `size == space->size' faile... Open

 Description    

USE test;
 
CREATE TABLE t(c INT,KEY(c));
 
INSERT INTO t VALUES(0);
 
INSERT INTO t VALUES(0);
 
set global innodb_file_per_table=OFF;
 
set global innodb_limit_optimistic_insert_debug=2;
 
set global innodb_change_buffering_debug=1;
 
CREATE TABLE t2(a INT) PARTITION BY HASH (a) PARTITIONS 13;
 
DROP TABLE t2;
 
INSERT INTO t VALUES(0);
 
ALTER TABLE t CHANGE COLUMN c c BINARY(1);

Leads to:

10.5.4 8569dac1ec9f6853a0b2f3ea9bcbda67644ead24

 
mysqld: /test/10.5_dbg/storage/innobase/buf/buf0buf.cc:3871: buf_block_t* buf_page_get_low(page_id_t, ulint, ulint, buf_block_t*, ulint, const char*, unsigned int, mtr_t*, dberr_t*, bool): Assertion `mode == 16 || mode == 12 || fix_block->page.status != buf_page_t::FREED' failed.

10.5.4 8569dac1ec9f6853a0b2f3ea9bcbda67644ead24

 
Core was generated by `/test/MD260520-mariadb-10.5.4-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x145a33356700 (LWP 758203))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x0000563929d44d7a in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
 
#2  0x00005639294ea385 in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x0000145a31a9a801 in __GI_abort () at abort.c:79
 
#6  0x0000145a31a8a39a in __assert_fail_base (fmt=0x145a31c117d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x56392a1e1e00 "mode == 16 || mode == 12 || fix_block->page.status != buf_page_t::FREED", file=file@entry=0x56392a1e08b8 "/test/10.5_dbg/storage/innobase/buf/buf0buf.cc", line=line@entry=3871, function=function@entry=0x56392a1e38e0 <buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool)::__PRETTY_FUNCTION__> "buf_block_t* buf_page_get_low(page_id_t, ulint, ulint, buf_block_t*, ulint, const char*, unsigned int, mtr_t*, dberr_t*, bool)") at assert.c:92
 
#7  0x0000145a31a8a412 in __GI___assert_fail (assertion=assertion@entry=0x56392a1e1e00 "mode == 16 || mode == 12 || fix_block->page.status != buf_page_t::FREED", file=file@entry=0x56392a1e08b8 "/test/10.5_dbg/storage/innobase/buf/buf0buf.cc", line=line@entry=3871, function=function@entry=0x56392a1e38e0 <buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*, bool)::__PRETTY_FUNCTION__> "buf_block_t* buf_page_get_low(page_id_t, ulint, ulint, buf_block_t*, ulint, const char*, unsigned int, mtr_t*, dberr_t*, bool)") at assert.c:101
 
#8  0x0000563929b79a86 in buf_page_get_low (page_id=..., page_id@entry=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=2, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, file=file@entry=0x56392a145d70 "/test/10.5_dbg/storage/innobase/ibuf/ibuf0ibuf.cc", line=<optimized out>, mtr=<optimized out>, err=<optimized out>, allow_ibuf_merge=<optimized out>) at /test/10.5_dbg/storage/innobase/buf/buf0buf.cc:3871
 
#9  0x0000563929b79aec in buf_page_get_gen (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=2, guess=guess@entry=0x0, mode=mode@entry=10, file=file@entry=0x56392a145d70 "/test/10.5_dbg/storage/innobase/ibuf/ibuf0ibuf.cc", line=1967, mtr=0x145a33350860, err=0x0, allow_ibuf_merge=false) at /test/10.5_dbg/storage/innobase/buf/buf0buf.cc:4010
 
#10 0x000056392991cbd5 in ibuf_remove_free_page () at /test/10.5_dbg/storage/innobase/ibuf/ibuf0ibuf.cc:1967
 
#11 0x000056392991cea8 in ibuf_free_excess_pages () at /test/10.5_dbg/storage/innobase/ibuf/ibuf0ibuf.cc:2018
 
#12 0x0000563929a0344c in row_ins_sec_index_entry (index=index@entry=0x145a110bf098, entry=entry@entry=0x145a11086030, thr=thr@entry=0x145a1117a7b8, check_foreign=check_foreign@entry=true) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3278
 
#13 0x0000563929a04c1b in row_ins_index_entry (thr=0x145a1117a7b8, entry=0x145a11086030, index=0x145a110bf098) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3317
 
#14 row_ins_index_entry_step (thr=0x145a1117a7b8, node=0x145a1117a590) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3484
 
#15 row_ins (thr=0x145a1117a7b8, node=0x145a1117a590) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3621
 
#16 row_ins_step (thr=thr@entry=0x145a1117a7b8) at /test/10.5_dbg/storage/innobase/row/row0ins.cc:3760
 
#17 0x0000563929a240c1 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x145a1105a2a8 "\375\060", '\245' <repeats 14 times>, "Ȣ\005\021Z\024", prebuilt=0x145a1117a098, ins_mode=<optimized out>) at /test/10.5_dbg/storage/innobase/row/row0mysql.cc:1462
 
#18 0x00005639298b9668 in ha_innobase::write_row (this=0x145a11143aa0, record=0x145a1105a2a8 "\375\060", '\245' <repeats 14 times>, "Ȣ\005\021Z\024") at /test/10.5_dbg/storage/innobase/handler/ha_innodb.cc:7713
 
#19 0x00005639294fe142 in handler::ha_write_row (this=0x145a11143aa0, buf=0x145a1105a2a8 "\375\060", '\245' <repeats 14 times>, "Ȣ\005\021Z\024") at /test/10.5_dbg/sql/handler.cc:6986
 
#20 0x0000563929317f23 in copy_data_between_tables (alter_ctx=0x145a333536b0, keys_onoff=<optimized out>, deleted=<synthetic pointer>, copied=<synthetic pointer>, order=<optimized out>, order_num=0, ignore=false, create=..., to=0x145a1117c088, from=0x145a110fc088, thd=0x145a11015088) at /test/10.5_dbg/sql/sql_table.cc:11207
 
#21 mysql_alter_table (thd=thd@entry=0x145a11015088, new_db=new_db@entry=0x145a11019948, new_name=new_name@entry=0x145a11019d50, create_info=create_info@entry=0x145a333542a0, table_list=<optimized out>, table_list@entry=0x145a110741a0, alter_info=alter_info@entry=0x145a333541d0, order_num=0, order=0x0, ignore=false, if_exists=false) at /test/10.5_dbg/sql/sql_table.cc:10586
 
#22 0x000056392939a572 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x145a11015088) at /test/10.5_dbg/sql/sql_alter.cc:532
 
#23 0x000056392924573b in mysql_execute_command (thd=thd@entry=0x145a11015088) at /test/10.5_dbg/sql/sql_parse.cc:5950
 
#24 0x000056392924d02e in mysql_parse (thd=thd@entry=0x145a11015088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x145a333553d0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7991
 
#25 0x0000563929239b42 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x145a11015088, packet=packet@entry=0x145a11067089 "ALTER TABLE t CHANGE COLUMN c c BINARY(1)", packet_length=packet_length@entry=41, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1874
 
#26 0x000056392923831c in do_command (thd=0x145a11015088) at /test/10.5_dbg/sql/sql_parse.cc:1355
 
#27 0x000056392939273f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x145a128453a8, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
 
#28 0x0000563929392e5b in handle_one_connection (arg=arg@entry=0x145a128453a8) at /test/10.5_dbg/sql/sql_connect.cc:1313
 
#29 0x00005639297f214e in pfs_spawn_thread (arg=0x145a31045888) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#30 0x0000145a3277d6db in start_thread (arg=0x145a33356700) at pthread_create.c:463
 
#31 0x0000145a31b7b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.5.3 (dbg), 10.5.4 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.46 (dbg), 10.1.46 (opt), 10.2.33 (dbg), 10.2.33 (opt), 10.3.24 (dbg), 10.3.24 (opt), 10.4.14 (dbg), 10.4.14 (opt), 10.5.3 (opt), 10.5.4 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

 Comments   
Comment by Marko Mäkelä [ 2020-06-03 ]

Quoting MDEV-14711:

Note: MDEV-15528 in 10.5.2 replaced !fix_block->page.file_page_was_freed with fix_block->page.status != buf_page_t::FREED in the assertion expression.

That said, I am able to reproduce this. Here is a little simplified test. It does not fail every time, but it fails often enough, and most notably, it fails within rr replay:

--source include/have_innodb.inc
 
CREATE TABLE t(c INT,KEY(c)) ENGINE=InnoDB;
 
INSERT INTO t VALUES(0),(0);
 
set global innodb_file_per_table=OFF;
 
set global innodb_limit_optimistic_insert_debug=2;
 
set global innodb_change_buffering_debug=1;
 
--let $i=13
 
while ($i)
 
{
 
eval CREATE TABLE t$i(a INT) ENGINE=InnoDB;
 
dec $i;
 
}
 
--let $i=13
 
while ($i)
 
{
 
eval DROP TABLE t$i;
 
dec $i;
 
}
 
INSERT INTO t VALUES(0);
 
ALTER TABLE t FORCE, ALGORITHM=COPY;

10.5 701efbb25b738f0c971798c5234d4d66b9235e47

 
Version: '10.5.4-MariaDB-debug-log'  socket: '/dev/shm/10.5m/mysql-test/var/tmp/1/mysqld.1.sock'  port: 16020  Source distribution
 
mariadbd: /mariadb/10.5m/storage/innobase/buf/buf0buf.cc:3869: buf_block_t *buf_page_get_low(const page_id_t, ulint, ulint, buf_block_t *, ulint, const char *, unsigned int, mtr_t *, dberr_t *, bool): Assertion `mode == 16 || mode == 12 || fix_block->page.status != buf_page_t::FREED' failed.
 
…
 
#4  0x000055e7ad7d1b69 in buf_page_get_low (page_id=<optimized out>, zip_size=0, rw_latch=2, guess=<optimized out>, mode=10, file=0x55e7adc4ac20 "/mariadb/10.5m/storage/innobase/ibuf/ibuf0ibuf.cc", line=1967, mtr=0x7ff084059bb8, err=0x0, allow_ibuf_merge=<optimized out>) at /mariadb/10.5m/storage/innobase/buf/buf0buf.cc:3867
 
#5  0x000055e7ad7d2d95 in buf_page_get_gen (page_id=<optimized out>, zip_size=<optimized out>, rw_latch=<optimized out>, guess=<optimized out>, mode=<optimized out>, file=<optimized out>, line=257, mtr=0x0, err=0x0, allow_ibuf_merge=<optimized out>) at /mariadb/10.5m/storage/innobase/buf/buf0buf.cc:4005
 
#6  0x000055e7ad5714a2 in ibuf_remove_free_page () at /mariadb/10.5m/storage/innobase/ibuf/ibuf0ibuf.cc:1967
 
#7  ibuf_free_excess_pages () at /mariadb/10.5m/storage/innobase/ibuf/ibuf0ibuf.cc:2018
 
#8  0x000055e7ad662798 in row_ins_sec_index_entry (index=<optimized out>, entry=<optimized out>, thr=0x7feff806e0f0, check_foreign=<optimized out>) at /mariadb/10.5m/storage/innobase/row/row0ins.cc:3278

My educated guess (without analyzing the trace further yet) is that the CREATE TABLE t2 is evicting the KEY(c) leaf page from the buffer pool. Then, the last INSERT would be buffered, and finally, the table-rebuilding ALTER TABLE triggers the change buffer merge, which fails.

Comment by Marko Mäkelä [ 2020-06-03 ]

This debug assertion failure was introduced by MDEV-15528. A function call has to be removed from fseg_free_page() to its callers, because in the change buffer, we must not call that function before accessing the page. It turns out that a call to buf_page_free() already existed at the end of ibuf_remove_free_page(), and the call in fseg_free_page() was redundant.

Generated at Thu Feb 08 09:16:51 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.