Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-22710

Assertion `mode == 16 || mode == 12 || fix_block->page.status != buf_page_t::FREED' failed in buf_page_get_low

Details

    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)

      Attachments

        Issue Links

          Activity

            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.

            marko Marko Mäkelä added a comment - 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.
            marko Marko Mäkelä added a comment - - edited

            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.

            marko Marko Mäkelä added a comment - - edited 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.

            People

              marko Marko Mäkelä
              Roel Roel Van de Paar
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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