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

Deadlock or assertion ret < srv_page_size failure on concurrent ALTER TABLE and SELECT from I_S

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 10.0.1, 5.5.29, 5.3.10, 5.3.11, 5.2.13, 5.1.66
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None

      Description

      It's a recent regression which seems to have appeared after merge from Percona-Server 5.1.66-rel14.1.
      A bug for Percona Server hasn't been filed yet as on some reason it's less reliably reproducible there, although I've seen it once.

      On MariaDB, reproducible starting from maria/5.1 revno 3163, maria/5.3 revno 3592.

      +----+------+-----------------+------+---------+------+-------------------+-----------------------------------------------------------------+----------+
      | Id | User | Host            | db   | Command | Time | State             | Info                                                            | Progress |
      +----+------+-----------------+------+---------+------+-------------------+-----------------------------------------------------------------+----------+
      |  2 | root | 127.0.0.1:59063 | test | Sleep   |  115 |                   | NULL                                                            |    0.000 |
      |  7 | root | 127.0.0.1:59068 | test | Query   |  106 | copy to tmp table | ALTER TABLE `E` ADD COLUMN o INTEGER                            |   54.524 |
      |  8 | root | 127.0.0.1:59069 | test | Query   |  105 | executing         | SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1 |    0.000 |
      |  9 | root | 127.0.0.1:59070 | test | Query   |  105 | executing         | SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1 |    0.000 |
      | 13 | root | 127.0.0.1:59074 | NULL | Query   |    0 | NULL              | show full processlist                                           |    0.000 |
      +----+------+-----------------+------+---------+------+-------------------+-----------------------------------------------------------------+----------+

      Stacks of the three threads executing statements:

      Thread 4 (Thread 0x7f818aa0f710 (LWP 3794)):
      #0  0x00007f81a940e39c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x0000000000bdb882 in safe_cond_wait (cond=0x7f81990945f0, mp=0x7f8199094540,
          file=0xdfaa60 "os/os0sync.c", line=210) at thr_mutex.c:498
      #2  0x0000000000ae990b in os_cond_wait (cond=0x7f81990945f0, mutex=0x7f8199094540)
          at os/os0sync.c:210
      #3  0x0000000000aea131 in os_event_wait_low (event=0x7f8199094540, reset_sig_count=26)
          at os/os0sync.c:636
      #4  0x0000000000b2b9d6 in sync_array_wait_event (arr=0x7f8198008e90, index=0)
          at sync/sync0arr.c:451
      #5  0x0000000000b2cd93 in rw_lock_x_lock_wait (lock=0x7f818ffedd70,
          file_name=0xe05040 "trx/trx0rec.c", line=1270) at sync/sync0rw.c:520
      #6  0x0000000000b2ce72 in rw_lock_x_lock_low (lock=0x7f818ffedd70, pass=0,
          file_name=0xe05040 "trx/trx0rec.c", line=1270) at sync/sync0rw.c:563
      #7  0x0000000000b2cf47 in rw_lock_x_lock_func (lock=0x7f818ffedd70, pass=0,
          file_name=0xe05040 "trx/trx0rec.c", line=1270) at sync/sync0rw.c:622
      #8  0x0000000000b62caf in buf_page_get_gen (space=0, zip_size=0, offset=46, rw_latch=2, guess=0x0,
          mode=10, file=0xe05040 "trx/trx0rec.c", line=1270, mtr=0x7f818aa0b060) at buf/buf0buf.c:2230
      #9  0x0000000000b3454a in trx_undo_report_row_operation (flags=0, op_type=1, thr=0x7f81992cc630,
          index=0x7f819930b518, clust_entry=0x7f8199308df8, update=0x0, cmpl_info=0, rec=0x0,
          roll_ptr=0x7f818aa0b5c0) at trx/trx0rec.c:1268
      #10 0x0000000000b51bed in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7f818aa0bbf0,
          entry=0x7f8199308df8, thr=0x7f81992cc630, mtr=0x7f818aa0b740, inherit=0x7f818aa0b640)
          at btr/btr0cur.c:1083
      #11 0x0000000000b52092 in btr_cur_optimistic_insert (flags=0, cursor=0x7f818aa0bbf0,
          entry=0x7f8199308df8, rec=0x7f818aa0bbe8, big_rec=0x7f818aa0bbe0, n_ext=0, thr=0x7f81992cc630,
          mtr=0x7f818aa0b740) at btr/btr0cur.c:1284
      #12 0x0000000000b06c08 in row_ins_index_entry_low (mode=2, index=0x7f819930b518,
          entry=0x7f8199308df8, n_ext=0, thr=0x7f81992cc630) at row/row0ins.c:2184
      #13 0x0000000000b07053 in row_ins_index_entry (index=0x7f819930b518, entry=0x7f8199308df8,
          n_ext=0, foreign=1, thr=0x7f81992cc630) at row/row0ins.c:2296
      #14 0x0000000000b07295 in row_ins_index_entry_step (node=0x7f8199451070, thr=0x7f81992cc630)
          at row/row0ins.c:2381
      #15 0x0000000000b074e0 in row_ins (node=0x7f8199451070, thr=0x7f81992cc630) at row/row0ins.c:2513
      #16 0x0000000000b076f3 in row_ins_step (thr=0x7f81992cc630) at row/row0ins.c:2623
      #17 0x0000000000b0d460 in row_insert_for_mysql (mysql_rec=0x7f8199307230 "\f\374\210\003",
          prebuilt=0x7f819947c958) at row/row0mysql.c:1168
      #18 0x0000000000aafe21 in ha_innobase::write_row (this=0x7f819944ff40,
          record=0x7f8199307230 "\f\374\210\003") at handler/ha_innodb.cc:5649
      #19 0x0000000000862b85 in handler::ha_write_row (this=0x7f819944ff40,
          buf=0x7f8199307230 "\f\374\210\003") at handler.cc:4978
      #20 0x0000000000890d3f in copy_data_between_tables (thd=0x7f8199297e38, from=0x7f818400c768,
          to=0x7f81992a9428, create=..., ignore=false, order_num=0, order=0x0, copied=0x7f818aa0db30,
          deleted=0x7f818aa0db28, keys_onoff=LEAVE_AS_IS, error_if_not_empty=false) at sql_table.cc:8118
      #21 0x000000000088f000 in mysql_alter_table (thd=0x7f8199297e38, new_db=0x1c19148 "test",
          new_name=0x1c18d18 "E", create_info=0x7f818aa0e100, table_list=0x1c18d50,
          alter_info=0x7f818aa0e200, order_num=0, order=0x0, ignore=false, require_online=false)
          at sql_table.cc:7540
      #22 0x00000000006e4002 in mysql_execute_command (thd=0x7f8199297e38) at sql_parse.cc:2974
      #23 0x00000000006edc50 in mysql_parse (thd=0x7f8199297e38,
          rawbuf=0x1c18c50 "ALTER TABLE `E` ADD COLUMN o INTEGER", length=36,
          found_semicolon=0x7f818aa0ec98) at sql_parse.cc:6158
      #24 0x00000000006dfa90 in dispatch_command (command=COM_QUERY, thd=0x7f8199297e38,
          packet=0x7f81992dbe59 "ALTER TABLE `E` ADD COLUMN o INTEGER", packet_length=36)
          at sql_parse.cc:1228
      #25 0x00000000006dedc4 in do_command (thd=0x7f8199297e38) at sql_parse.cc:923
      #26 0x00000000006dbc12 in handle_one_connection (arg=0x7f8199297e38) at sql_connect.cc:1218
      #27 0x00007f81a9409a4f in start_thread () from /lib64/libpthread.so.0
      #28 0x00007f81a87f382d in clone () from /lib64/libc.so.6
      #29 0x0000000000000000 in ?? ()
       
      Thread 3 (Thread 0x7f818a9c7710 (LWP 3796)):
      #0  0x00007f81a940e39c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x0000000000bdb882 in safe_cond_wait (cond=0x7f8199086bf0, mp=0x7f8199086b40,
          file=0xdfaa60 "os/os0sync.c", line=210) at thr_mutex.c:498
      #2  0x0000000000ae990b in os_cond_wait (cond=0x7f8199086bf0, mutex=0x7f8199086b40)
          at os/os0sync.c:210
      #3  0x0000000000aea131 in os_event_wait_low (event=0x7f8199086b40, reset_sig_count=1)
          at os/os0sync.c:636
      #4  0x0000000000b2b9d6 in sync_array_wait_event (arr=0x7f8198008e90, index=2)
          at sync/sync0arr.c:451
      #5  0x0000000000b2d6a8 in mutex_spin_wait (mutex=0x7f818ffe65f8,
          file_name=0xe09b88 "./include/buf0buf.ic", line=347) at sync/sync0sync.c:621
      #6  0x0000000000b2d22b in mutex_enter_func (mutex=0x7f818ffe65f8,
          file_name=0xe09b88 "./include/buf0buf.ic", line=347) at ./include/sync0sync.ic:221
      #7  0x0000000000b5ee12 in buf_page_get_mutex_enter (bpage=0x7f818ffe6540)
          at ./include/buf0buf.ic:347
      #8  0x0000000000ac72fc in i_s_innodb_fill_buffer_pool (thd=0x7f81992dfe98, tables=0x1ba1918)
          at handler/i_s.cc:5796
      #9  0x0000000000ac74d7 in i_s_innodb_buffer_page_fill_table (thd=0x7f81992dfe98, tables=0x1ba1918)
          at handler/i_s.cc:5852
      #10 0x00000000008b27ed in get_schema_tables_result (join=0x1e514e0,
          executed_place=PROCESSED_BY_JOIN_EXEC) at sql_show.cc:7089
      #11 0x0000000000763e67 in JOIN::exec (this=0x1e514e0) at sql_select.cc:2225
      #12 0x00000000007668fd in mysql_select (thd=0x7f81992dfe98, rref_pointer_array=0x7f81992e2b88,
          tables=0x1ba1918, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0,
          having=0x0, proc_param=0x0, select_options=2684635648, result=0x1ba3410, unit=0x7f81992e2428,
          select_lex=0x7f81992e2930) at sql_select.cc:2983
      #13 0x000000000075d449 in handle_select (thd=0x7f81992dfe98, lex=0x7f81992e2388, result=0x1ba3410,
          setup_tables_done_option=0) at sql_select.cc:286
      #14 0x00000000006eb275 in execute_sqlcom_select (thd=0x7f81992dfe98, all_tables=0x1ba1918)
          at sql_parse.cc:5157
      #15 0x00000000006e2332 in mysql_execute_command (thd=0x7f81992dfe98) at sql_parse.cc:2290
      #16 0x00000000006edc50 in mysql_parse (thd=0x7f81992dfe98,
          rawbuf=0x1ba1670 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1", length=63,
          found_semicolon=0x7f818a9c6c98) at sql_parse.cc:6158
      #17 0x00000000006dfa90 in dispatch_command (command=COM_QUERY, thd=0x7f81992dfe98,
          packet=0x7f81992e35c9 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1",
          packet_length=63) at sql_parse.cc:1228
      #18 0x00000000006dedc4 in do_command (thd=0x7f81992dfe98) at sql_parse.cc:923
      #19 0x00000000006dbc12 in handle_one_connection (arg=0x7f81992dfe98) at sql_connect.cc:1218
      #20 0x00007f81a9409a4f in start_thread () from /lib64/libpthread.so.0
      #21 0x00007f81a87f382d in clone () from /lib64/libc.so.6
      #22 0x0000000000000000 in ?? ()
       
      Thread 2 (Thread 0x7f818a97f710 (LWP 3798)):
      #0  0x00007f81a940e39c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
      #1  0x0000000000bdb882 in safe_cond_wait (cond=0x7f8198ab38e0, mp=0x7f8198ab3830,
          file=0xdfaa60 "os/os0sync.c", line=210) at thr_mutex.c:498
      #2  0x0000000000ae990b in os_cond_wait (cond=0x7f8198ab38e0, mutex=0x7f8198ab3830)
          at os/os0sync.c:210
      #3  0x0000000000aea131 in os_event_wait_low (event=0x7f8198ab3830, reset_sig_count=16)
          at os/os0sync.c:636
      #4  0x0000000000b2b9d6 in sync_array_wait_event (arr=0x7f8198008e90, index=3)
          at sync/sync0arr.c:451
      #5  0x0000000000b2d6a8 in mutex_spin_wait (mutex=0x1a8b5e0, file_name=0xdf407f "handler/i_s.cc",
          line=5792) at sync/sync0sync.c:621
      #6  0x0000000000b2d22b in mutex_enter_func (mutex=0x1a8b5e0, file_name=0xdf407f "handler/i_s.cc",
          line=5792) at ./include/sync0sync.ic:221
      #7  0x0000000000ac72e6 in i_s_innodb_fill_buffer_pool (thd=0x7f81992f12f8, tables=0x1ea22e8)
          at handler/i_s.cc:5792
      #8  0x0000000000ac74d7 in i_s_innodb_buffer_page_fill_table (thd=0x7f81992f12f8, tables=0x1ea22e8)
          at handler/i_s.cc:5852
      #9  0x00000000008b27ed in get_schema_tables_result (join=0x7f818403d9b0,
          executed_place=PROCESSED_BY_JOIN_EXEC) at sql_show.cc:7089
      #10 0x0000000000763e67 in JOIN::exec (this=0x7f818403d9b0) at sql_select.cc:2225
      #11 0x00000000007668fd in mysql_select (thd=0x7f81992f12f8, rref_pointer_array=0x7f81992f3fe8,
          tables=0x1ea22e8, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0,
          having=0x0, proc_param=0x0, select_options=2684635648, result=0x1ea3de0, unit=0x7f81992f3888,
          select_lex=0x7f81992f3d90) at sql_select.cc:2983
      #12 0x000000000075d449 in handle_select (thd=0x7f81992f12f8, lex=0x7f81992f37e8, result=0x1ea3de0,
          setup_tables_done_option=0) at sql_select.cc:286
      #13 0x00000000006eb275 in execute_sqlcom_select (thd=0x7f81992f12f8, all_tables=0x1ea22e8)
          at sql_parse.cc:5157
      #14 0x00000000006e2332 in mysql_execute_command (thd=0x7f81992f12f8) at sql_parse.cc:2290
      #15 0x00000000006edc50 in mysql_parse (thd=0x7f81992f12f8,
          rawbuf=0x1ea2040 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1", length=63,
          found_semicolon=0x7f818a97ec98) at sql_parse.cc:6158
      #16 0x00000000006dfa90 in dispatch_command (command=COM_QUERY, thd=0x7f81992f12f8,
          packet=0x7f81992f4a29 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_PAGE` LIMIT 1",
          packet_length=63) at sql_parse.cc:1228
      #17 0x00000000006dedc4 in do_command (thd=0x7f81992f12f8) at sql_parse.cc:923
      #18 0x00000000006dbc12 in handle_one_connection (arg=0x7f81992f12f8) at sql_connect.cc:1218
      #19 0x00007f81a9409a4f in start_thread () from /lib64/libpthread.so.0
      #20 0x00007f81a87f382d in clone () from /lib64/libc.so.6
      #21 0x0000000000000000 in ?? ()

      RQG grammar (mdev-3853.yy):

      query:
              SELECT * FROM { $last_database = 'INFORMATION_SCHEMA' } . _table LIMIT 1 ;
       
      thread1:
              ALTER TABLE _table ADD COLUMN _letter INTEGER |
              ALTER TABLE _table DROP COLUMN _letter ;

      RQG command line, assuming you already have server up and running on port 3306:

       perl ./gentest.pl --threads=3 --duration=600 --queries=100M --grammar=mdev-3853.yy --engine=InnoDB --dsn=dbi:mysql:host=127.0.0.1:port=3306:user=root:database=test --gendata 

      The deadlock is reproducible on maria/5.1 revno 3180, maria/5.2 revno 3204, maria/5.3 revno 3619.
      I didn't see the deadlock on 5.5 and 10.0, but I'm getting the assertion failure instead (not every time, but often enough):

      130128  2:39:35  InnoDB: Assertion failure in thread 140451356055296 in file page0page.ic line 934
      InnoDB: Failing assertion: ret < srv_page_size

      #5  0x00007fbd5fc5fb0b in __GI_abort () at abort.c:92
      #6  0x0000000000b6f3fa in page_get_data_size (page=0x7fbd4d6ac000 "") at 10.0-base/storage/xtradb/include/page0page.ic:934
      #7  0x0000000000a688ea in i_s_innodb_buffer_pool_pages_index_fill (thd=0x43bb0b8, tables=0x7fbd3c1662d0, cond=0x0) at 10.0-base/storage/xtradb/handler/i_s.cc:6564
      #8  0x000000000069ec20 in do_fill_table (thd=0x43bb0b8, table_list=0x7fbd3c1662d0, join_table=0x7fbd3c284260) at 10.0-base/sql/sql_show.cc:7914
      #9  0x000000000069f032 in get_schema_tables_result (join=0x7fbd3c1f2330, executed_place=PROCESSED_BY_JOIN_EXEC) at 10.0-base/sql/sql_show.cc:8021
      #10 0x0000000000648560 in JOIN::exec_inner (this=0x7fbd3c1f2330) at 10.0-base/sql/sql_select.cc:2414
      #11 0x0000000000647bbd in JOIN::exec (this=0x7fbd3c1f2330) at 10.0-base/sql/sql_select.cc:2258
      #12 0x000000000064b1e5 in mysql_select (thd=0x43bb0b8, rref_pointer_array=0x43be040, tables=0x7fbd3c1662d0, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, result=0x7fbd3c0a7890, unit=0x43bd698, select_lex=0x43bdd90) at 10.0-base/sql/sql_select.cc:3194
      #13 0x0000000000641a76 in handle_select (thd=0x43bb0b8, lex=0x43bd5e0, result=0x7fbd3c0a7890, setup_tables_done_option=0) at 10.0-base/sql/sql_select.cc:368
      #14 0x00000000006192b1 in execute_sqlcom_select (thd=0x43bb0b8, all_tables=0x7fbd3c1662d0) at 10.0-base/sql/sql_parse.cc:4765
      #15 0x0000000000611941 in mysql_execute_command (thd=0x43bb0b8) at 10.0-base/sql/sql_parse.cc:2245
      #16 0x000000000061bb1b in mysql_parse (thd=0x43bb0b8, rawbuf=0x7fbd3c1c0680 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_POOL_PAGES_INDEX` LIMIT 1", length=75, parser_state=0x7fbd612f8540) at 10.0-base/sql/sql_parse.cc:5881
      #17 0x000000000060ec8b in dispatch_command (command=COM_QUERY, thd=0x43bb0b8, packet=0x43c04d9 "SELECT * FROM INFORMATION_SCHEMA . `INNODB_BUFFER_POOL_PAGES_INDEX` LIMIT 1", packet_length=75) at 10.0-base/sql/sql_parse.cc:1070
      #18 0x000000000060df42 in do_command (thd=0x43bb0b8) at 10.0-base/sql/sql_parse.cc:809
      #19 0x0000000000722735 in do_handle_one_connection (thd_arg=0x43bb0b8) at 10.0-base/sql/sql_connect.cc:1253
      #20 0x0000000000722120 in handle_one_connection (arg=0x43bb0b8) at 10.0-base/sql/sql_connect.cc:1168
      #21 0x00007fbd60998efc in start_thread (arg=0x7fbd612f9700) at pthread_create.c:304

      The stack trace is from

      revision-id: sergii@pisem.net-20130124165225-gczln6zrzi4lz4bx
      revno: 3485
      branch-nick: 10.0-base

      In all cases the server was built with BUILD/compile-pentium-valgrind-max-no-ndb.

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              Unassigned
              Reporter:
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated: