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

Hangs server with repeating log entry

Details

    Description

      Works on 10.2.14 but hangs on 10.2.15 and 10.3.8 with repeating log entry:

      [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]

      Must kill -9 server

      To reproduce, run following test case on fresh install of MariaDB server:

      CREATE SCHEMA IF NOT EXISTS test;
      		 
      USE test;
      		 
       
      		 
      DROP PROCEDURE IF EXISTS foo;
      		 
      DELIMITER $$
      		 
       
      		 
      CREATE PROCEDURE foo()
      		 
      BEGIN
      		 
       
      		 
        DECLARE var INT UNSIGNED;
      		 
        
        DROP TEMPORARY TABLE IF EXISTS bar;
      		 
        CREATE TEMPORARY TABLE bar( i1 INT UNSIGNED, i2 INT UNSIGNED, KEY( i1, i2 ) );
      		 
       
      		 
        SET TRANSACTION ISOLATION LEVEL READ COMMITTED;
      		 
        
        START TRANSACTION;
      		 
       
      		 
        INSERT INTO bar SET i1 = 1, i2 = 1;
      		 
       
        UPDATE bar SET i2 = 2;
      		 
       
      		 
        SET var = ( SELECT 1 FROM bar );
      		 
       
      		 
      END
      		 
      $$
      		 
       
      		 
      DELIMITER ;
      		 
       
      		 
      CALL foo;

      Attachments

        Issue Links

          is caused by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-15374 Server hangs and aborts with long semaphore wait or assertion `len < ((ulint) srv_page_size)' fails in trx_undo_rec_copy upon ROLLBACK on temporary table

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-16824 InnoDB should skip MVCC and transaction locking for temporary tables.

          • Major - Major loss of function.
          • Confirmed

          Activity

            Ascending order - Click to sort in descending order
            elenst Elena Stepanova added a comment -

            Thanks for the report and test case, reproducible as described.
            The problem appeared in 10.2 tree with this revision:

            commit 211842dd86f28f4610bc87ea221730c82c0e2494
            		 
            Author: Thirunarayanan Balathandayuthapani
            		 
            Date:   Mon Apr 23 11:22:58 2018 +0530
            		 
             
            		 
                MDEV-15374 Server hangs and aborts with long semaphore wait or assertion `len < ((ulint) srv_page_size)' fails in trx_undo_rec_copy upon ROLLBACK on temporary table

            10.2 non-debug 8b0d4cff07

            		 
            2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
            		 
            2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
            		 
            2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
            		 
            2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
            		 
            2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
            		 
            2018-07-10  0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134]
            		 
            ...

            10.2 debug 8b0d4cff07

            		 
            mysqld: /data/src/10.2/storage/innobase/trx/trx0rec.cc:2232: bool trx_undo_prev_version_build(const rec_t*, mtr_t*, const rec_t*, dict_index_t*, ulint*, mem_heap_t*, rec_t**, mem_heap_t*, const dtuple_t**, ulint): Assertion `!(index->table)->is_temporary()' failed.
            		 
            180710  0:18:49 [ERROR] mysqld got signal 6 ;
            		 
             
            		 
            #7  0x00007f95fe4f0ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
            		 
            #8  0x0000559bc2dd0c57 in trx_undo_prev_version_build (index_rec=0x7f95f3cc407e "", index_mtr=0x7f95f8178f40, rec=0x7f95f3cc407e "", index=0x7f95a01601e8, offsets=0x7f95a004a088, heap=0x7f95a004a490, old_vers=0x7f95f8178e28, v_heap=0x0, vrow=0x0, v_status=0) at /data/src/10.2/storage/innobase/trx/trx0rec.cc:2232
            		 
            #9  0x0000559bc2d86461 in row_vers_impl_x_locked_low (clust_rec=0x7f95f3cc407e "", clust_index=0x7f95a01601e8, rec=0x7f95f3cc807e "", index=0x7f95a0044728, offsets=0x7f95f8179ca0, mtr=0x7f95f8178f40) at /data/src/10.2/storage/innobase/row/row0vers.cc:179
            		 
            #10 0x0000559bc2d86a00 in row_vers_impl_x_locked (rec=0x7f95f3cc807e "", index=0x7f95a0044728, offsets=0x7f95f8179ca0) at /data/src/10.2/storage/innobase/row/row0vers.cc:402
            		 
            #11 0x0000559bc2d5bfdc in row_search_mvcc (buf=0x7f95a0045918 "\377", mode=PAGE_CUR_G, prebuilt=0x7f95a0046e78, match_mode=0, direction=0) at /data/src/10.2/storage/innobase/row/row0sel.cc:5039
            		 
            #12 0x0000559bc2bedc03 in ha_innobase::index_read (this=0x7f95a0045128, buf=0x7f95a0045918 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9561
            		 
            #13 0x0000559bc2beee7e in ha_innobase::index_first (this=0x7f95a0045128, buf=0x7f95a0045918 "\377") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9981
            		 
            #14 0x0000559bc28d90f3 in handler::ha_index_first (this=0x7f95a0045128, buf=0x7f95a0045918 "\377") at /data/src/10.2/sql/handler.cc:2719
            		 
            #15 0x0000559bc26d0661 in join_read_first (tab=0x7f95a0043868) at /data/src/10.2/sql/sql_select.cc:19708
            		 
            #16 0x0000559bc26ce0f2 in sub_select (join=0x7f95a00426f0, join_tab=0x7f95a0043868, end_of_records=false) at /data/src/10.2/sql/sql_select.cc:18720
            		 
            #17 0x0000559bc26cd6ed in do_select (join=0x7f95a00426f0, procedure=0x0) at /data/src/10.2/sql/sql_select.cc:18267
            		 
            #18 0x0000559bc26a7dcd in JOIN::exec_inner (this=0x7f95a00426f0) at /data/src/10.2/sql/sql_select.cc:3595
            		 
            #19 0x0000559bc26a727a in JOIN::exec (this=0x7f95a00426f0) at /data/src/10.2/sql/sql_select.cc:3390
            		 
            #20 0x0000559bc29a2e0e in subselect_single_select_engine::exec (this=0x7f95a0170fb8) at /data/src/10.2/sql/item_subselect.cc:3894
            		 
            #21 0x0000559bc2997c6f in Item_subselect::exec (this=0x7f95a0170e38) at /data/src/10.2/sql/item_subselect.cc:722
            		 
            #22 0x0000559bc299997b in Item_singlerow_subselect::val_int (this=0x7f95a0170e38) at /data/src/10.2/sql/item_subselect.cc:1329
            		 
            #23 0x0000559bc28f7af7 in Item::save_in_field (this=0x7f95a0170e38, field=0x7f95a00150a8, no_conversions=false) at /data/src/10.2/sql/item.cc:6507
            		 
            #24 0x0000559bc2a4d593 in sp_eval_expr (thd=0x7f95a0000b00, result_field=0x7f95a00150a8, expr_item_ptr=0x7f95a0171030) at /data/src/10.2/sql/sp_head.cc:430
            		 
            #25 0x0000559bc2a5b6f2 in sp_rcontext::set_variable (this=0x7f95a0013f40, thd=0x7f95a0000b00, field=0x7f95a00150a8, value=0x7f95a0171030) at /data/src/10.2/sql/sp_rcontext.cc:383
            		 
            #26 0x0000559bc2625879 in sp_rcontext::set_variable (this=0x7f95a0013f40, thd=0x7f95a0000b00, var_idx=0, value=0x7f95a0171030) at /data/src/10.2/sql/sp_rcontext.h:201
            		 
            #27 0x0000559bc2a54cb4 in sp_instr_set::exec_core (this=0x7f95a0170ff8, thd=0x7f95a0000b00, nextp=0x7f95f817b1a4) at /data/src/10.2/sql/sp_head.cc:3270
            		 
            #28 0x0000559bc2a54207 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7f95a0171040, thd=0x7f95a0000b00, nextp=0x7f95f817b1a4, open_tables=true, instr=0x7f95a0170ff8) at /data/src/10.2/sql/sp_head.cc:3009
            		 
            #29 0x0000559bc2a54c47 in sp_instr_set::execute (this=0x7f95a0170ff8, thd=0x7f95a0000b00, nextp=0x7f95f817b1a4) at /data/src/10.2/sql/sp_head.cc:3263
            		 
            #30 0x0000559bc2a4fa0b in sp_head::execute (this=0x7f95a00099c8, thd=0x7f95a0000b00, merge_da_on_success=true) at /data/src/10.2/sql/sp_head.cc:1327
            		 
            #31 0x0000559bc2a51a9b in sp_head::execute_procedure (this=0x7f95a00099c8, thd=0x7f95a0000b00, args=0x7f95a0005408) at /data/src/10.2/sql/sp_head.cc:2116
            		 
            #32 0x0000559bc265c6f2 in do_execute_sp (thd=0x7f95a0000b00, sp=0x7f95a00099c8) at /data/src/10.2/sql/sql_parse.cc:2909
            		 
            #33 0x0000559bc2665a35 in mysql_execute_command (thd=0x7f95a0000b00) at /data/src/10.2/sql/sql_parse.cc:5822
            		 
            #34 0x0000559bc266be89 in mysql_parse (thd=0x7f95a0000b00, rawbuf=0x7f95a0012478 "CALL foo", length=8, parser_state=0x7f95f817c200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7995
            		 
            #35 0x0000559bc26599ae in dispatch_command (command=COM_QUERY, thd=0x7f95a0000b00, packet=0x7f95a0075a41 "CALL foo", packet_length=8, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1821
            		 
            #36 0x0000559bc2658311 in do_command (thd=0x7f95a0000b00) at /data/src/10.2/sql/sql_parse.cc:1375
            		 
            #37 0x0000559bc27a95d2 in do_handle_one_connection (connect=0x559bc5ba0c20) at /data/src/10.2/sql/sql_connect.cc:1335
            		 
            #38 0x0000559bc27a935f in handle_one_connection (arg=0x559bc5ba0c20) at /data/src/10.2/sql/sql_connect.cc:1241
            		 
            #39 0x0000559bc2bcb658 in pfs_spawn_thread (arg=0x559bc5b7b720) at /data/src/10.2/storage/perfschema/pfs.cc:1862
            		 
            #40 0x00007f96001c7494 in start_thread (arg=0x7f95f817d700) at pthread_create.c:333
            		 
            #41 0x00007f95fe5ad93f in clone () from /lib/x86_64-linux-gnu/libc.so.6

            elenst Elena Stepanova added a comment - Thanks for the report and test case, reproducible as described. The problem appeared in 10.2 tree with this revision: commit 211842dd86f28f4610bc87ea221730c82c0e2494 Author: Thirunarayanan Balathandayuthapani Date: Mon Apr 23 11:22:58 2018 +0530   MDEV-15374 Server hangs and aborts with long semaphore wait or assertion `len < ((ulint) srv_page_size)' fails in trx_undo_rec_copy upon ROLLBACK on temporary table 10.2 non-debug 8b0d4cff07 2018-07-10 0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134] 2018-07-10 0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134] 2018-07-10 0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134] 2018-07-10 0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134] 2018-07-10 0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134] 2018-07-10 0:18:04 139965736859392 [ERROR] InnoDB: Trying to read doublewrite buffer page [page id: space=0, page number=134] ... 10.2 debug 8b0d4cff07 mysqld: /data/src/10.2/storage/innobase/trx/trx0rec.cc:2232: bool trx_undo_prev_version_build(const rec_t*, mtr_t*, const rec_t*, dict_index_t*, ulint*, mem_heap_t*, rec_t**, mem_heap_t*, const dtuple_t**, ulint): Assertion `!(index->table)->is_temporary()' failed. 180710 0:18:49 [ERROR] mysqld got signal 6 ;   #7 0x00007f95fe4f0ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000559bc2dd0c57 in trx_undo_prev_version_build (index_rec=0x7f95f3cc407e "", index_mtr=0x7f95f8178f40, rec=0x7f95f3cc407e "", index=0x7f95a01601e8, offsets=0x7f95a004a088, heap=0x7f95a004a490, old_vers=0x7f95f8178e28, v_heap=0x0, vrow=0x0, v_status=0) at /data/src/10.2/storage/innobase/trx/trx0rec.cc:2232 #9 0x0000559bc2d86461 in row_vers_impl_x_locked_low (clust_rec=0x7f95f3cc407e "", clust_index=0x7f95a01601e8, rec=0x7f95f3cc807e "", index=0x7f95a0044728, offsets=0x7f95f8179ca0, mtr=0x7f95f8178f40) at /data/src/10.2/storage/innobase/row/row0vers.cc:179 #10 0x0000559bc2d86a00 in row_vers_impl_x_locked (rec=0x7f95f3cc807e "", index=0x7f95a0044728, offsets=0x7f95f8179ca0) at /data/src/10.2/storage/innobase/row/row0vers.cc:402 #11 0x0000559bc2d5bfdc in row_search_mvcc (buf=0x7f95a0045918 "\377", mode=PAGE_CUR_G, prebuilt=0x7f95a0046e78, match_mode=0, direction=0) at /data/src/10.2/storage/innobase/row/row0sel.cc:5039 #12 0x0000559bc2bedc03 in ha_innobase::index_read (this=0x7f95a0045128, buf=0x7f95a0045918 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9561 #13 0x0000559bc2beee7e in ha_innobase::index_first (this=0x7f95a0045128, buf=0x7f95a0045918 "\377") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9981 #14 0x0000559bc28d90f3 in handler::ha_index_first (this=0x7f95a0045128, buf=0x7f95a0045918 "\377") at /data/src/10.2/sql/handler.cc:2719 #15 0x0000559bc26d0661 in join_read_first (tab=0x7f95a0043868) at /data/src/10.2/sql/sql_select.cc:19708 #16 0x0000559bc26ce0f2 in sub_select (join=0x7f95a00426f0, join_tab=0x7f95a0043868, end_of_records=false) at /data/src/10.2/sql/sql_select.cc:18720 #17 0x0000559bc26cd6ed in do_select (join=0x7f95a00426f0, procedure=0x0) at /data/src/10.2/sql/sql_select.cc:18267 #18 0x0000559bc26a7dcd in JOIN::exec_inner (this=0x7f95a00426f0) at /data/src/10.2/sql/sql_select.cc:3595 #19 0x0000559bc26a727a in JOIN::exec (this=0x7f95a00426f0) at /data/src/10.2/sql/sql_select.cc:3390 #20 0x0000559bc29a2e0e in subselect_single_select_engine::exec (this=0x7f95a0170fb8) at /data/src/10.2/sql/item_subselect.cc:3894 #21 0x0000559bc2997c6f in Item_subselect::exec (this=0x7f95a0170e38) at /data/src/10.2/sql/item_subselect.cc:722 #22 0x0000559bc299997b in Item_singlerow_subselect::val_int (this=0x7f95a0170e38) at /data/src/10.2/sql/item_subselect.cc:1329 #23 0x0000559bc28f7af7 in Item::save_in_field (this=0x7f95a0170e38, field=0x7f95a00150a8, no_conversions=false) at /data/src/10.2/sql/item.cc:6507 #24 0x0000559bc2a4d593 in sp_eval_expr (thd=0x7f95a0000b00, result_field=0x7f95a00150a8, expr_item_ptr=0x7f95a0171030) at /data/src/10.2/sql/sp_head.cc:430 #25 0x0000559bc2a5b6f2 in sp_rcontext::set_variable (this=0x7f95a0013f40, thd=0x7f95a0000b00, field=0x7f95a00150a8, value=0x7f95a0171030) at /data/src/10.2/sql/sp_rcontext.cc:383 #26 0x0000559bc2625879 in sp_rcontext::set_variable (this=0x7f95a0013f40, thd=0x7f95a0000b00, var_idx=0, value=0x7f95a0171030) at /data/src/10.2/sql/sp_rcontext.h:201 #27 0x0000559bc2a54cb4 in sp_instr_set::exec_core (this=0x7f95a0170ff8, thd=0x7f95a0000b00, nextp=0x7f95f817b1a4) at /data/src/10.2/sql/sp_head.cc:3270 #28 0x0000559bc2a54207 in sp_lex_keeper::reset_lex_and_exec_core (this=0x7f95a0171040, thd=0x7f95a0000b00, nextp=0x7f95f817b1a4, open_tables=true, instr=0x7f95a0170ff8) at /data/src/10.2/sql/sp_head.cc:3009 #29 0x0000559bc2a54c47 in sp_instr_set::execute (this=0x7f95a0170ff8, thd=0x7f95a0000b00, nextp=0x7f95f817b1a4) at /data/src/10.2/sql/sp_head.cc:3263 #30 0x0000559bc2a4fa0b in sp_head::execute (this=0x7f95a00099c8, thd=0x7f95a0000b00, merge_da_on_success=true) at /data/src/10.2/sql/sp_head.cc:1327 #31 0x0000559bc2a51a9b in sp_head::execute_procedure (this=0x7f95a00099c8, thd=0x7f95a0000b00, args=0x7f95a0005408) at /data/src/10.2/sql/sp_head.cc:2116 #32 0x0000559bc265c6f2 in do_execute_sp (thd=0x7f95a0000b00, sp=0x7f95a00099c8) at /data/src/10.2/sql/sql_parse.cc:2909 #33 0x0000559bc2665a35 in mysql_execute_command (thd=0x7f95a0000b00) at /data/src/10.2/sql/sql_parse.cc:5822 #34 0x0000559bc266be89 in mysql_parse (thd=0x7f95a0000b00, rawbuf=0x7f95a0012478 "CALL foo", length=8, parser_state=0x7f95f817c200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7995 #35 0x0000559bc26599ae in dispatch_command (command=COM_QUERY, thd=0x7f95a0000b00, packet=0x7f95a0075a41 "CALL foo", packet_length=8, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1821 #36 0x0000559bc2658311 in do_command (thd=0x7f95a0000b00) at /data/src/10.2/sql/sql_parse.cc:1375 #37 0x0000559bc27a95d2 in do_handle_one_connection (connect=0x559bc5ba0c20) at /data/src/10.2/sql/sql_connect.cc:1335 #38 0x0000559bc27a935f in handle_one_connection (arg=0x559bc5ba0c20) at /data/src/10.2/sql/sql_connect.cc:1241 #39 0x0000559bc2bcb658 in pfs_spawn_thread (arg=0x559bc5b7b720) at /data/src/10.2/storage/perfschema/pfs.cc:1862 #40 0x00007f96001c7494 in start_thread (arg=0x7f95f817d700) at pthread_create.c:333 #41 0x00007f95fe5ad93f in clone () from /lib/x86_64-linux-gnu/libc.so.6
            marko Marko Mäkelä added a comment -

            This was OK to push.
            Please file a follow-up bug that InnoDB should skip all transactional locking and multi-versioning on temporary tables in 10.2+. Temporary tables are always private to a connection, and a connection may only use one transaction at a time, so there cannot ever be locking conflicts or any need for multi-versioning for temporary tables.

            marko Marko Mäkelä added a comment - This was OK to push. Please file a follow-up bug that InnoDB should skip all transactional locking and multi-versioning on temporary tables in 10.2+. Temporary tables are always private to a connection, and a connection may only use one transaction at a time, so there cannot ever be locking conflicts or any need for multi-versioning for temporary tables.

            People

              thiru Thirunarayanan Balathandayuthapani
              Rich Rich Theobald
              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.