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

Alter table corrupts while applying the modification log

    XMLWordPrintable

Details

    Description

      Problem found during RQG testing.
      # 2019-03-25T18:56:06 [74161] | Version: '10.3.14-MariaDB-debug-log'  socket: ...
      # 2019-03-25T18:56:06 [74161] | mysqld: storage/innobase/row/row0log.cc:2432: const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, ulint*): Assertion `0' failed.
      # 2019-03-25T18:56:06 [74161] | 190325 18:55:33 [ERROR] mysqld got signal 6 ;
      ...
      Query (0x7f1a70012ac0): ALTER TABLE t3 ADD PRIMARY KEY IF NOT EXISTS ( col2 ), ADD UNIQUE INDEX IF NOT EXISTS uidX3 ( col_int ) /* E_R Thread7 QNO 499 CON_ID 75 */
      Connection ID (thread ID): 75
      Status: NOT_KILLED
      ...
      #3  <signal handler called>
      #4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58
      #5  0x00007f1b2676a37a in __GI_abort () at abort.c:89
      #6  0x00007f1b26760b47 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x560760074deb "0", file=file@entry=0x5607600764a8 "storage/innobase/row/row0log.cc", line=line@entry=2432, function=function@entry=0x56076007a6c0 <row_log_table_apply_op(que_thr_t*, unsigned long, row_merge_dup_t*, dberr_t*, mem_block_info_t*, mem_block_info_t*, unsigned char const*, unsigned char const*, unsigned long*)::__PRETTY_FUNCTION__> "const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, ulint*)") at assert.c:92
      #7  0x00007f1b26760bf2 in __GI___assert_fail (assertion=0x560760074deb "0", file=0x5607600764a8 "storage/innobase/row/row0log.cc", line=2432, function=0x56076007a6c0 <row_log_table_apply_op(que_thr_t*, unsigned long, row_merge_dup_t*, dberr_t*, mem_block_info_t*, mem_block_info_t*, unsigned char const*, unsigned char const*, unsigned long*)::__PRETTY_FUNCTION__> "const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, ulint*)") at assert.c:101
      #8  0x000056075f9001a8 in row_log_table_apply_op (thr=0x7f1a70081cd8, new_trx_id_col=1, dup=0x7f1b1c4bd5b0, error=0x7f1b1c4bd32c, offsets_heap=0x7f1a700c77f0, heap=0x7f1a700a1260, mrec=0x7f1b1c02e026 "", mrec_end=0x7f1b1c02e042 "", offsets=0x7f1a70086430) at storage/innobase/row/row0log.cc:2432
      #9  0x000056075f90264d in row_log_table_apply_ops (thr=0x7f1a70081cd8, dup=0x7f1b1c4bd5b0, stage=0x7f1a700a0210) at storage/innobase/row/row0log.cc:3029
      #10 0x000056075f902c5e in row_log_table_apply (thr=0x7f1a70081cd8, old_table=0x7f1a7008b4e8, table=0x7f1a70090778, stage=0x7f1a700a0210, new_table=0x7f1a7008b188) at storage/innobase/row/row0log.cc:3135
      #11 0x000056075f7ccd12 in ha_innobase::inplace_alter_table (this=0x7f1a7407c720, altered_table=0x7f1a70090778, ha_alter_info=0x7f1b1c4bdfd0) at storage/innobase/handler/handler0alter.cc:7260
      #12 0x000056075f363ee9 in handler::ha_inplace_alter_table (this=0x7f1a7407c720, altered_table=0x7f1a70090778, ha_alter_info=0x7f1b1c4bdfd0) at sql/handler.h:4192
      #13 0x000056075f35968c in mysql_inplace_alter_table (thd=0x7f1a70000a98, table_list=0x7f1a70012c88, table=0x7f1a7407bb48, altered_table=0x7f1a70090778, ha_alter_info=0x7f1b1c4bdfd0, inplace_supported=HA_ALTER_INPLACE_COPY_NO_LOCK, target_mdl_request=0x7f1b1c4be1c0, alter_ctx=0x7f1b1c4be920) at sql/sql_table.cc:7547
      #14 0x000056075f35fa16 in mysql_alter_table (thd=0x7f1a70000a98, new_db=0x7f1a70005168, new_name=0x7f1a70005528, create_info=0x7f1b1c4bf510, table_list=0x7f1a70012c88, alter_info=0x7f1b1c4bf450, order_num=0, order=0x0, ignore=false) at sql/sql_table.cc:9756
      #15 0x000056075f3e73bd in Sql_cmd_alter_table::execute (this=0x7f1a70013470, thd=0x7f1a70000a98) at sql/sql_alter.cc:488
      #16 0x000056075f289352 in mysql_execute_command (thd=0x7f1a70000a98) at sql/sql_parse.cc:6283
      #17 0x000056075f28e670 in mysql_parse (thd=0x7f1a70000a98, rawbuf=0x7f1a70012ac0 "ALTER TABLE t3 ADD PRIMARY KEY IF NOT EXISTS ( col2 ), ADD UNIQUE INDEX IF NOT EXISTS uidX3 ( col_int ) /* E_R Thread7 QNO 499 CON_ID 75 */", length=139, parser_state=0x7f1b1c4c0640, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:8089
      #18 0x000056075f27b6b4 in dispatch_command (command=COM_QUERY, thd=0x7f1a70000a98, packet=0x7f1a7000a7c9 "ALTER TABLE t3 ADD PRIMARY KEY IF NOT EXISTS ( col2 ), ADD UNIQUE INDEX IF NOT EXISTS uidX3 ( col_int ) /* E_R Thread7 QNO 499 CON_ID 75 */ ", packet_length=140, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:1857
      #19 0x000056075f27a0d9 in do_command (thd=0x7f1a70000a98) at sql/sql_parse.cc:1402
      #20 0x000056075f3e1981 in do_handle_one_connection (connect=0x560761f86ef8) at sql/sql_connect.cc:1402
      #21 0x000056075f3e16f8 in handle_one_connection (arg=0x560761f86ef8) at sql/sql_connect.cc:1308
      #22 0x00007f1b273a96da in start_thread (arg=0x7f1b1c4c1700) at pthread_create.c:456
      #23 0x00007f1b2683bd7f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105
       
      Replay on
      10.3 commit dbc0d576a3f402ae52423fe424ed0a68f49537ef 2019-03-25T16:14:39+02:00
      10.4 commit 8b480df63ec76963fd96d2e00b911a801b912591 2019-03-25T17:18:15+02:00
       
      The problem might be caused by a similar reason like
      https://jira.mariadb.org/browse/MDEV-18361
      because the RQG test tends to fail either with the current assert or MDEV-18361
      but not with other asserts or SEGV or .... 
       
      ###########
       
      origin/10.6 b3c470a3c7e8bb497bca5bc9fca4cf52cfc9e88e 2021-03-19T18:12:26+03:00
       
      # 2021-03-20T16:27:33 [2352135] | [rr 2352767 84442]mysqld: /Server/10.6N/storage/innobase/row/row0log.cc:2468: const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, rec_offs*): Assertion `0' failed.
       
      # 2021-03-20T16:27:33 [2352135] | Thread 3 (Thread 2352767.2354385):
      # 2021-03-20T16:27:33 [2352135] | #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
      # 2021-03-20T16:27:33 [2352135] | #1  0x00005a8b0ccb8859 in __GI_abort () at abort.c:79
      # 2021-03-20T16:27:33 [2352135] | #2  0x00005a8b0ccb8729 in __assert_fail_base (fmt=0x5a8b0ce4e588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55e8bcab9800 "0", file=0x55e8bcac3cc0 "/Server/10.6N/storage/innobase/row/row0log.cc", line=2468, function=<optimized out>) at assert.c:92
      # 2021-03-20T16:27:33 [2352135] | #3  0x00005a8b0ccc9f36 in __GI___assert_fail (assertion=0x55e8bcab9800 "0", file=0x55e8bcac3cc0 "/Server/10.6N/storage/innobase/row/row0log.cc", line=2468, function=0x55e8bcac73e0 "const mrec_t* row_log_table_apply_op(que_thr_t*, ulint, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, const mrec_t*, const mrec_t*, rec_offs*)") at assert.c:101
      # 2021-03-20T16:27:33 [2352135] | #4  0x000055e8bb3c789f in row_log_table_apply_op (thr=0x61a00026f5d8, new_trx_id_col=2, dup=0x6400035b8820, error=0x6400035b8170, offsets_heap=0x631000294818, heap=0x631000280818, mrec=0x59dd1b05e033 '1' <repeats 757 times>, mrec_end=0x59dd1b05e35a "", offsets=0x607000087b88) at /Server/10.6N/storage/innobase/row/row0log.cc:2468
      # 2021-03-20T16:27:33 [2352135] | #5  0x000055e8bb3cd989 in row_log_table_apply_ops (thr=0x61a00026f5d8, dup=0x6400035b8820, stage=0x608000051938) at /Server/10.6N/storage/innobase/row/row0log.cc:3063
      # 2021-03-20T16:27:33 [2352135] | #6  0x000055e8bb3ce7ce in row_log_table_apply (thr=0x61a00026f5d8, old_table=0x618000063920, table=0x6400035ba770, stage=0x608000051938, new_table=0x618000064120) at /Server/10.6N/storage/innobase/row/row0log.cc:3171
      # 2021-03-20T16:27:33 [2352135] | #7  0x000055e8bb0afb10 in alter_rebuild_apply_log (ctx=0x62b000136da0, ha_alter_info=0x6400035ba280, altered_table=0x6400035ba770) at /Server/10.6N/storage/innobase/handler/handler0alter.cc:10804
      # 2021-03-20T16:27:33 [2352135] | #8  0x000055e8bb0b1db5 in ha_innobase::commit_inplace_alter_table (this=0x61d000ccbab8, altered_table=0x6400035ba770, ha_alter_info=0x6400035ba280, commit=true) at /Server/10.6N/storage/innobase/handler/handler0alter.cc:11007
      # 2021-03-20T16:27:33 [2352135] | #9  0x000055e8ba4e8494 in handler::ha_commit_inplace_alter_table (this=0x61d000ccbab8, altered_table=0x6400035ba770, ha_alter_info=0x6400035ba280, commit=true) at /Server/10.6N/sql/handler.cc:4856
      # 2021-03-20T16:27:33 [2352135] | #10 0x000055e8b9f63b60 in mysql_inplace_alter_table (thd=0x62b00012d218, table_list=0x62b0001343c8, table=0x619000783c98, altered_table=0x6400035ba770, ha_alter_info=0x6400035ba280, target_mdl_request=0x6400035ba370, alter_ctx=0x6400035bb1e0) at /Server/10.6N/sql/sql_table.cc:8191
      # 2021-03-20T16:27:33 [2352135] | #11 0x000055e8b9f771ff in mysql_alter_table (thd=0x62b00012d218, new_db=0x62b000131c98, new_name=0x62b0001320b8, create_info=0x6400035bc5c0, table_list=0x62b0001343c8, alter_info=0x6400035bc490, order_num=0, order=0x0, ignore=false, if_exists=false) at /Server/10.6N/sql/sql_table.cc:10779
      # 2021-03-20T16:27:33 [2352135] | #12 0x000055e8ba1151d4 in Sql_cmd_alter_table::execute (this=0x62b000134c10, thd=0x62b00012d218) at /Server/10.6N/sql/sql_alter.cc:540
      # 2021-03-20T16:27:33 [2352135] | #13 0x000055e8b9cd6182 in mysql_execute_command (thd=0x62b00012d218) at /Server/10.6N/sql/sql_parse.cc:5973
      # 2021-03-20T16:27:33 [2352135] | #14 0x000055e8b9ce3963 in mysql_parse (thd=0x62b00012d218, rawbuf=0x62b000134238 "ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_int ) /* E_R Thread1 QNO 36 CON_ID 16 */", length=90, parser_state=0x6400035bdbc0) at /Server/10.6N/sql/sql_parse.cc:8004
      # 2021-03-20T16:27:33 [2352135] | #15 0x000055e8b9cba420 in dispatch_command (command=COM_QUERY, thd=0x62b00012d218, packet=0x629000bbd219 "ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_int ) /* E_R Thread1 QNO 36 CON_ID 16 */ ", packet_length=91, blocking=true) at /Server/10.6N/sql/sql_parse.cc:1888
      # 2021-03-20T16:27:33 [2352135] | #16 0x000055e8b9cb714f in do_command (thd=0x62b00012d218, blocking=true) at /Server/10.6N/sql/sql_parse.cc:1399
      # 2021-03-20T16:27:33 [2352135] | #17 0x000055e8ba0f8fdd in do_handle_one_connection (connect=0x6080000033b8, put_in_cache=true) at /Server/10.6N/sql/sql_connect.cc:1410
      # 2021-03-20T16:27:33 [2352135] | #18 0x000055e8ba0f893f in handle_one_connection (arg=0x6080000033b8) at /Server/10.6N/sql/sql_connect.cc:1312
      # 2021-03-20T16:27:33 [2352135] | #19 0x000055e8badf65dd in pfs_spawn_thread (arg=0x61500000af98) at /Server/10.6N/storage/perfschema/pfs.cc:2201
      # 2021-03-20T16:27:33 [2352135] | #20 0x000000007000b609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      # 2021-03-20T16:27:33 [2352135] | #21 0x00005a8b0cdb5293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      Query:   ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_int )
      Status: NOT_KILLED
       
      pluto:/data/Results/TBR-957/left_over/dev/shm/vardir/1616257591/4/1/rr
      _RR_TRACE_DIR="." rr replay --mark-stdio
       
      perl rqg.pl \                   
      --duration=100 \
      --queries=10000000 \
      --no_mask \
      --seed=random \
      --rpl_mode=none \
      --gendata_sql=conf/mariadb/table_stress.sql \
      --engine=InnoDB \
      --gendata=conf/mariadb/table_stress.zz \
      --mysqld=--innodb_stats_persistent=off \
      --mysqld=--innodb-buffer-pool-size=24M \
      --mysqld=--log_bin_trust_function_creators=1 \
      --mysqld=--loose-idle_transaction_timeout=0 \
      --mysqld=--file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
      --mysqld=--loose-idle_readonly_transaction_timeout=0 \
      --mysqld=--innodb-lock-wait-timeout=50 \
      --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
      --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
      --mysqld=--connect_timeout=60 \
      --mysqld=--lock-wait-timeout=86400 \
      --mysqld=--slave_net_timeout=60 \
      --mysqld=--innodb_page_size=64K \
      --mysqld=--loose-table_lock_wait_timeout=50 \
      --mysqld=--interactive_timeout=28800 \
      --mysqld=--loose_innodb_use_native_aio=0 \
      --mysqld=--plugin-load-add=file_key_management.so \
      --mysqld=--wait_timeout=28800 \
      --mysqld=--loose-idle_write_transaction_timeout=0 \
      --mysqld=--net_read_timeout=30 \
      --mysqld=--net_write_timeout=60 \
      --mysqld=--log-output=none \
      --mysqld=--log-bin \
      --mysqld=--loose-max-statement-time=30 \
      --validators=None \
      --grammar=MDEV-19044_2.yy \
      --threads=2 \
      --grammar=/data/Results/1616257591/c00000.yy \
      --workdir=<local settings> \
      --vardir=<local settings> \
      --mtr-build-thread=<local settings> \
      --basedir1=/Server_bin/10.6N_asan \
      --script_debug=_nix_ \
      --rr=Extended \
      --rr_options=--chaos
      
      

      Attachments

        1. 000035.log
          875 kB
        2. MDEV-19044_2.yy
          2 kB
        3. MDEV-19044.yy
          6 kB

        Issue Links

          Activity

            People

              thiru Thirunarayanan Balathandayuthapani
              mleich Matthias Leich
              Votes:
              0 Vote for this issue
              Watchers:
              5 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.