[MDEV-26198] Assertion `0' failed in row_log_table_apply_op during redundant table rebuild Created: 2021-07-21  Updated: 2023-03-15  Resolved: 2023-03-15

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.4.21, 10.5.12, 10.6.3
Fix Version/s: 11.1.0, 10.11.3, 10.4.29, 10.5.20, 10.6.13, 10.8.8, 10.9.6, 10.10.4

Type: Bug Priority: Critical
Reporter: Matthias Leich Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: rr-profile-analyzed

Attachments: File 000000.log     File TBR-957-MDEV-26198-micro.yy     File TBR-957-MDEV-26198.cfg    
Issue Links:
Blocks
is blocked by MDEV-30183 Assertion `!memcmp(rec_trx_id, old_pk... Closed
Problem/Incident
is caused by MDEV-25236 Online log apply fails for redundant ... Closed
Relates
relates to MDEV-18361 row0log.cc:3057: dberr_t row_log_tabl... Closed
relates to MDEV-28122 OPTIMIZE TABLE crash Closed
relates to MDEV-28447 Assertion `!clust_index->online_log' ... Open

 Description   

mysqld: /data/Server/10.5B/storage/innobase/row/row0log.cc:2450: 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-07-20T16:23:03 [3471815] | Query (0x62b000268238): ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_string )  /* E_R Thread28 QNO 1005 CON_ID 235 */
# 2021-07-20T16:23:03 [3471815] | 
# 2021-07-20T16:23:03 [3471815] | Connection ID (thread ID): 235
# 2021-07-20T16:23:03 [3471815] | Status: NOT_KILLED
 
# 2021-07-20T16:23:03 [3471815] #3  <signal handler called>
# 2021-07-20T16:23:03 [3471815] #4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
# 2021-07-20T16:23:03 [3471815] #5  0x00007f9d5dc6a859 in __GI_abort () at abort.c:79
# 2021-07-20T16:23:03 [3471815] #6  0x00007f9d5dc6a729 in __assert_fail_base (fmt=0x7f9d5de00588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55fa2761ede0 "0", file=0x55fa27628520 "/data/Server/10.5B/storage/innobase/row/row0log.cc", line=2450, function=<optimized out>) at assert.c:92
# 2021-07-20T16:23:03 [3471815] #7  0x00007f9d5dc7bf36 in __GI___assert_fail (assertion=0x55fa2761ede0 "0", file=0x55fa27628520 "/data/Server/10.5B/storage/innobase/row/row0log.cc", line=2450, function=0x55fa2762b9e0 "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-07-20T16:23:03 [3471815] #8  0x000055fa26402b1f in row_log_table_apply_op (thr=0x6190000cead0, new_trx_id_col=2, dup=0x7f9d3acbfec0, error=0x7f9d3acbf830, offsets_heap=0x631000ac8800, heap=0x631002cec800, mrec=0x7f9d395d204f '3' <repeats 747 times>, mrec_end=0x7f9d395d237e "", offsets=0x604000b9d990) at /data/Server/10.5B/storage/innobase/row/row0log.cc:2450
# 2021-07-20T16:23:03 [3471815] #9  0x000055fa2640891b in row_log_table_apply_ops (thr=0x6190000cead0, dup=0x7f9d3acbfec0, stage=0x602000043810) at /data/Server/10.5B/storage/innobase/row/row0log.cc:3040
# 2021-07-20T16:23:03 [3471815] #10 0x000055fa264097a5 in row_log_table_apply (thr=0x6190000cead0, old_table=0x6180000de508, table=0x7f9d3acc1990, stage=0x602000043810, new_table=0x618000229908) at /data/Server/10.5B/storage/innobase/row/row0log.cc:3149
# 2021-07-20T16:23:03 [3471815] #11 0x000055fa261063db in ha_innobase::inplace_alter_table (this=0x61d0011c88b8, altered_table=0x7f9d3acc1990, ha_alter_info=0x7f9d3acc12b0) at /data/Server/10.5B/storage/innobase/handler/handler0alter.cc:8493
# 2021-07-20T16:23:03 [3471815] #12 0x000055fa25245504 in handler::ha_inplace_alter_table (this=0x61d0011c88b8, altered_table=0x7f9d3acc1990, ha_alter_info=0x7f9d3acc12b0) at /data/Server/10.5B/sql/handler.h:4536
# 2021-07-20T16:23:03 [3471815] #13 0x000055fa25227548 in mysql_inplace_alter_table (thd=0x62b000299218, table_list=0x62b0002683d8, table=0x61900015b398, altered_table=0x7f9d3acc1990, ha_alter_info=0x7f9d3acc12b0, target_mdl_request=0x7f9d3acc1390, alter_ctx=0x7f9d3acc23f0) at /data/Server/10.5B/sql/sql_table.cc:8113
# 2021-07-20T16:23:03 [3471815] #14 0x000055fa252394e7 in mysql_alter_table (thd=0x62b000299218, new_db=0x62b00029da88, new_name=0x62b00029dea8, create_info=0x7f9d3acc3760, table_list=0x62b0002683d8, alter_info=0x7f9d3acc3650, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/Server/10.5B/sql/sql_table.cc:10730
# 2021-07-20T16:23:03 [3471815] #15 0x000055fa253acda5 in Sql_cmd_alter_table::execute (this=0x62b000268c30, thd=0x62b000299218) at /data/Server/10.5B/sql/sql_alter.cc:539
# 2021-07-20T16:23:03 [3471815] #16 0x000055fa24fceb35 in mysql_execute_command (thd=0x62b000299218) at /data/Server/10.5B/sql/sql_parse.cc:6052
# 2021-07-20T16:23:03 [3471815] #17 0x000055fa24fdb072 in mysql_parse (thd=0x62b000299218, rawbuf=0x62b000268238 "ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_string )  /* E_R Thread28 QNO 1005 CON_ID 235 */", length=98, parser_state=0x7f9d3acc4cb0, is_com_multi=false, is_next_command=false) at /data/Server/10.5B/sql/sql_parse.cc:8096
# 2021-07-20T16:23:03 [3471815] #18 0x000055fa24fb3158 in dispatch_command (command=COM_QUERY, thd=0x62b000299218, packet=0x629000d4d219 " ALTER TABLE t4 ADD PRIMARY KEY ( col_text(9), col_string )  /* E_R Thread28 QNO 1005 CON_ID 235 */ ", packet_length=100, is_com_multi=false, is_next_command=false) at /data/Server/10.5B/sql/sql_parse.cc:1891
# 2021-07-20T16:23:03 [3471815] #19 0x000055fa24fb01f1 in do_command (thd=0x62b000299218) at /data/Server/10.5B/sql/sql_parse.cc:1370
# 2021-07-20T16:23:03 [3471815] #20 0x000055fa25394751 in do_handle_one_connection (connect=0x60800004e9b8, put_in_cache=true) at /data/Server/10.5B/sql/sql_connect.cc:1410
# 2021-07-20T16:23:03 [3471815] #21 0x000055fa253940b5 in handle_one_connection (arg=0x6080000ac138) at /data/Server/10.5B/sql/sql_connect.cc:1312
# 2021-07-20T16:23:03 [3471815] #22 0x00007f9d5e191609 in start_thread (arg=<optimized out>) at pthread_create.c:477
# 2021-07-20T16:23:03 [3471815] #23 0x00007f9d5dd67293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
origin/10.5 b4ec3313f6bb3a222b3528b5a8a6dca73b870c20 2021-07-20T09:32:11+03:00
 
RQG
---
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
perl rqg.pl \
--grammar=conf/mariadb/table_stress_innodb.yy \
--gendata=conf/mariadb/table_stress.zz \
--gendata_sql=conf/mariadb/table_stress.sql \
--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
--mysqld=--loose-idle_write_transaction_timeout=0 \
--mysqld=--loose-idle_transaction_timeout=0 \
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
--mysqld=--connect_timeout=60 \
--mysqld=--interactive_timeout=28800 \
--mysqld=--slave_net_timeout=60 \
--mysqld=--net_read_timeout=30 \
--mysqld=--net_write_timeout=60 \
--mysqld=--loose-table_lock_wait_timeout=50 \
--mysqld=--wait_timeout=28800 \
--mysqld=--lock-wait-timeout=86400 \
--mysqld=--innodb-lock-wait-timeout=50 \
--no-mask \
--queries=10000000 \
--seed=random \
--reporters=Backtrace \
--reporters=ErrorLog \
--reporters=Deadlock1 \
--validators=None \
--mysqld=--log_output=none \
--mysqld=--log_bin_trust_function_creators=1 \
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
--engine=InnoDB \
--restart_timeout=240 \
--mysqld=--plugin-load-add=file_key_management.so \
--mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
--duration=300 \
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
--mysqld=--loose-innodb-sync-debug \
--mysqld=--innodb_stats_persistent=off \
--mysqld=--innodb_adaptive_hash_index=on \
--mysqld=--log-bin \
--mysqld=--sync-binlog=1 \
--mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
--mysqld=--loose-max-statement-time=30 \
--threads=33 \
--mysqld=--innodb_use_native_aio=1 \
--mysqld=--innodb_page_size=64K \
--mysqld=--innodb-buffer-pool-size=24M \
--no_mask \
--workdir=<local settings> \
--vardir=<local settings> \
--mtr-build-thread=<local settings> \
--basedir1=<local settings> \
--script_debug=_nix
 
table_stress_innodb.yy is slightly modified in order to do the buffer pool resizing
all 30s instead of the default 60s.
 
Error pattern:
[ 'TBR-957', 'mysqld: .{1,200}row0log.cc:.{1,20}: const mrec_t\* row_log_table_apply_op.{1,200}: Assertion \`0\' failed.+The RQG run ended with status STATUS_SERVER_CRASHED' ],



 Comments   
Comment by Matthias Leich [ 2021-09-17 ]

origin/bb-10.6-MDEV-26623 a8b16e921e6bb73b1fff5486314b2d89b9d286aa 2021-09-17T09:14:20+03:00
MariaDB 10.6.5
 
mysqld: /data/Server/bb-10.6-MDEV-26623A/storage/innobase/row/row0log.cc:2471: 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-09-17T01:36:45 [2905646] | Query (0x62b0001a4238): OPTIMIZE TABLE `table100_innodb_int_autoinc`
# 2021-09-17T01:36:45 [2905646] | Connection ID (thread ID): 20
# 2021-09-17T01:36:45 [2905646] | [rr 2909041 1216200]Status: KILL_TIMEOUT
 
(rr) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007f1cf91a5859 in __GI_abort () at abort.c:79
#2  0x00007f1cf91a5729 in __assert_fail_base (fmt=0x7f1cf933b588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55b0a4678d20 "0", file=0x55b0a4682320 "/data/Server/bb-10.6-MDEV-26623A/storage/innobase/row/row0log.cc", line=2471, 
    function=<optimized out>) at assert.c:92
#3  0x00007f1cf91b6f36 in __GI___assert_fail (assertion=0x55b0a4678d20 "0", file=0x55b0a4682320 "/data/Server/bb-10.6-MDEV-26623A/storage/innobase/row/row0log.cc", line=2471, 
    function=0x55b0a4685900 "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
#4  0x000055b0a323333a in row_log_table_apply_op (thr=0x619000d440c0, new_trx_id_col=1, dup=0x7f1cdb0b3b70, error=0x7f1cdb0b34e0, offsets_heap=0x62500090b100, heap=0x625002316900, mrec=0x7f1cd875c037 "", mrec_end=0x7f1cd875c03c "", 
    offsets=0x60600017f300) at /data/Server/bb-10.6-MDEV-26623A/storage/innobase/row/row0log.cc:2471
#5  0x000055b0a3239205 in row_log_table_apply_ops (thr=0x619000d440c0, dup=0x7f1cdb0b3b70, stage=0x602000426a90) at /data/Server/bb-10.6-MDEV-26623A/storage/innobase/row/row0log.cc:3066
#6  0x000055b0a3239fd6 in row_log_table_apply (thr=0x619000d440c0, old_table=0x61800022b108, table=0x7f1cdb0b5510, stage=0x602000426a90, new_table=0x61800023d908) at /data/Server/bb-10.6-MDEV-26623A/storage/innobase/row/row0log.cc:3174
#7  0x000055b0a2f43be4 in alter_rebuild_apply_log (ctx=0x62b0001a8490, ha_alter_info=0x7f1cdb0b4e10, altered_table=0x7f1cdb0b5510) at /data/Server/bb-10.6-MDEV-26623A/storage/innobase/handler/handler0alter.cc:10691
#8  0x000055b0a2f45e15 in ha_innobase::commit_inplace_alter_table (this=0x61d0003804b8, altered_table=0x7f1cdb0b5510, ha_alter_info=0x7f1cdb0b4e10, commit=true) at /data/Server/bb-10.6-MDEV-26623A/storage/innobase/handler/handler0alter.cc:10904
#9  0x000055b0a25a78ee in handler::ha_commit_inplace_alter_table (this=0x61d0003804b8, altered_table=0x7f1cdb0b5510, ha_alter_info=0x7f1cdb0b4e10, commit=true) at /data/Server/bb-10.6-MDEV-26623A/sql/handler.cc:5194
#10 0x000055b0a202f2aa in mysql_inplace_alter_table (thd=0x62b00019d218, table_list=0x62b0001a4428, table=0x619000769898, altered_table=0x7f1cdb0b5510, ha_alter_info=0x7f1cdb0b4e10, target_mdl_request=0x7f1cdb0b4f10, ddl_log_state=0x7f1cdb0b4c30, 
    trigger_param=0x7f1cdb0b5960, alter_ctx=0x7f1cdb0b63e0) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_table.cc:7437
#11 0x000055b0a20427ba in mysql_alter_table (thd=0x62b00019d218, new_db=0x55b0a3d44200 <null_clex_str>, new_name=0x55b0a3d44200 <null_clex_str>, create_info=0x7f1cdb0b7800, table_list=0x62b0001a4428, alter_info=0x7f1cdb0b76d0, order_num=0, 
    order=0x0, ignore=false, if_exists=false) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_table.cc:10205
#12 0x000055b0a204aa77 in mysql_recreate_table (thd=0x62b00019d218, table_list=0x62b0001a4428, table_copy=false) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_table.cc:11253
#13 0x000055b0a21e439e in admin_recreate_table (thd=0x62b00019d218, table_list=0x62b0001a4428) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_admin.cc:68
#14 0x000055b0a21ebfa9 in mysql_admin_table (thd=0x62b00019d218, tables=0x62b0001a4428, check_opt=0x62b0001a2618, operator_name=0x55b0a4dd9d40 <msg_optimize>, lock_type=TL_WRITE, org_open_for_modify=true, repair_table_use_frm=false, 
    extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(class handler * const, class THD *, HA_CHECK_OPT *)) 0x55b0a25a655a <handler::ha_optimize(THD*, st_ha_check_opt*)>, view_operator_func=0x0, is_cmd_replicated=true)
    at /data/Server/bb-10.6-MDEV-26623A/sql/sql_admin.cc:1185
#15 0x000055b0a21ee7d5 in Sql_cmd_optimize_table::execute (this=0x62b0001a4b20, thd=0x62b00019d218) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_admin.cc:1566
#16 0x000055b0a1dd4aea in mysql_execute_command (thd=0x62b00019d218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_parse.cc:5997
#17 0x000055b0a1de0fbc in mysql_parse (thd=0x62b00019d218, rawbuf=0x62b0001a4238 "OPTIMIZE TABLE `table100_innodb_int_autoinc` /* E_R Thread7 QNO 584 CON_ID 20 */", length=80, parser_state=0x7f1cdb0b9b20)
    at /data/Server/bb-10.6-MDEV-26623A/sql/sql_parse.cc:8030
#18 0x000055b0a1db9227 in dispatch_command (command=COM_QUERY, thd=0x62b00019d218, packet=0x629000d20219 "", packet_length=81, blocking=true) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_parse.cc:1896
#19 0x000055b0a1db65ff in do_command (thd=0x62b00019d218, blocking=true) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_parse.cc:1404
#20 0x000055b0a21b5b15 in do_handle_one_connection (connect=0x608000003138, put_in_cache=true) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_connect.cc:1418
#21 0x000055b0a21b53a6 in handle_one_connection (arg=0x608000003138) at /data/Server/bb-10.6-MDEV-26623A/sql/sql_connect.cc:1312
#22 0x00007f1cf96cf609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#23 0x00007f1cf92a2293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(rr) quit
 
sdp:/data/Results/1631864137/TBR-957-MDEV-26198/dev/shm/vardir/1631864137/58/1/rr
 
$RQG_HOME/rqg.pl \
--gendata=conf/engines/innodb/full_text_search.zz \
--max_gd_duration=1200 \
--short_column_names \
--grammar=conf/engines/innodb/full_text_search.yy \
--redefine=conf/mariadb/alter_table.yy \
--redefine=conf/mariadb/instant_add.yy \
--redefine=conf/mariadb/modules/alter_table_columns.yy \
--redefine=conf/mariadb/bulk_insert1.yy \
--redefine=conf/mariadb/modules/locks.yy \
--redefine=conf/mariadb/modules/sql_mode.yy \
--redefine=conf/mariadb/redefine_temporary_tables.yy \
--redefine=conf/mariadb/sequences.yy \
--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
--mysqld=--loose-idle_write_transaction_timeout=0 \
--mysqld=--loose-idle_transaction_timeout=0 \
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
--mysqld=--connect_timeout=60 \
--mysqld=--interactive_timeout=28800 \
--mysqld=--slave_net_timeout=60 \
--mysqld=--net_read_timeout=30 \
--mysqld=--net_write_timeout=60 \
--mysqld=--loose-table_lock_wait_timeout=50 \
--mysqld=--wait_timeout=28800 \
--mysqld=--lock-wait-timeout=86400 \
--mysqld=--innodb-lock-wait-timeout=50 \
--no-mask \
--queries=10000000 \
--seed=random \
--reporters=Backtrace \
--reporters=ErrorLog \
--reporters=Deadlock1 \
--validators=None \
--mysqld=--log_output=none \
--mysqld=--log_bin_trust_function_creators=1 \
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
--engine=InnoDB \
--restart_timeout=240 \
--mysqld=--plugin-load-add=file_key_management.so \
--mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
--duration=300 \
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
--mysqld=--loose-innodb-sync-debug \
--mysqld=--innodb_stats_persistent=on \
--mysqld=--innodb_adaptive_hash_index=on \
--mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
--mysqld=--loose-max-statement-time=30 \
--threads=33 \
--mysqld=--innodb-use-native-aio=0 \
--rr=Extended \
--rr_options=--wait \
--mysqld=--innodb_page_size=8K \
--mysqld=--innodb-buffer-pool-size=8M \
--no_mask \
--workdir=<local settings> \
--vardir=<local settings> \
--mtr-build-thread=<local settings> \
--basedir1=<local settings> \
--script_debug=_nix_

Comment by Alice Sherepa [ 2021-12-23 ]

preview-10.8-MDEV-11675-rpl-lag-free-alter 8fc5d21de2530bf7c

/10.8/storage/innobase/row/row0log.cc:2471: 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.
 
Server version: 10.8.0-MariaDB-debug-log
 
??:0(__assert_fail)[0x7f9695467102]
row/row0log.cc:2472(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 short*))[0x563ec25220aa]
row/row0log.cc:3066(row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*))[0x563ec2528081]
row/row0log.cc:3174(row_log_table_apply(que_thr_t*, dict_table_t*, TABLE*, ut_stage_alter_t*, dict_table_t*))[0x563ec2528e85]
handler/handler0alter.cc:8485(ha_innobase::inplace_alter_table(TABLE*, Alter_inplace_info*))[0x563ec2202157]
sql/handler.h:4630(handler::ha_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x563ec1154dcc]
sql/sql_table.cc:7612(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, MDL_request*, st_ddl_log_state*, TRIGGER_RENAME_PARAM*, Alter_table_ctx*, bool&, unsigned long long&, bool))[0x563ec1130e03]
sql/sql_table.cc:10599(mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool, bool))[0x563ec1146d39]
sql/sql_alter.cc:543(Sql_cmd_alter_table::execute(THD*))[0x563ec12fc60e]
sql/sql_parse.cc:5989(mysql_execute_command(THD*, bool))[0x563ec0e715eb]
sql/sql_parse.cc:8028(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x563ec0e7e921]
sql/sql_parse.cc:1896(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x563ec0e5509b]
sql/sql_parse.cc:1402(do_command(THD*, bool))[0x563ec0e51d90]
sql/sql_connect.cc:1418(do_handle_one_connection(CONNECT*, bool))[0x563ec12df320]
sql/sql_connect.cc:1314(handle_one_connection)[0x563ec12deba5]
perfschema/pfs.cc:2203(pfs_spawn_thread)[0x563ec1f4bf3a]
nptl/pthread_create.c:487(start_thread)[0x7f9695925fa3]
x86_64/clone.S:97(clone)[0x7f96955304cf]
 
Query (0x62900014a2a8): ALTER  TABLE `t013` ENCRYPTED = NO

Comment by Matthias Leich [ 2022-03-14 ]

Replay on origin/bb-10.8-MDEV-28043 d8dd388f5b549000fcd2af0b576bb24154914368 2022-03-14T14:26:09+02:00
which claims to be a 10.8.3.
pluto:/data/results/1647263096/000745.tar.xz

Comment by Marko Mäkelä [ 2022-03-22 ]

For the recent replay, the last log record was written by row_log_table_low_redundant() for an INSERT. It wrote 52 bytes, but the first call to row_log_table_apply_op() only parsed 27 bytes of that. Some columns had been added instantly to the ROW_FORMAT=REDUNDANT table before the online ALTER TABLE was executed. Here, the table was rebuilt with 10 fields in the clustered index, and 1+2+1 columns were added instantly:

ALTER TABLE `oltp1` CHANGE COLUMN ecol2 `id` BIGINT UNSIGNED NULL /* E_R Thread17 QNO 707 CON_ID 32 */ ;
ALTER TABLE `oltp1` ADD COLUMN IF NOT EXISTS ecol10 SET('foo','bar') NULL, ALGORITHM=INPLACE, LOCK=SHARED /* E_R Thread4 QNO 779 CON_ID 19 */ ;
ALTER TABLE `oltp1` ADD COLUMN ( ecol5 ENUM('foo','bar'), geocol7 GEOMETRY NULL )  /* E_R Thread29 QNO 306 CON_ID 45 */ ;
ALTER TABLE `oltp1` ADD COLUMN IF NOT EXISTS ( scol3 TEXT NOT NULL ), ALGORITHM=INPLACE  /* E_R Thread7 QNO 595 CON_ID 23 */ :
OPTIMIZE TABLE `oltp1` /* E_R Thread27 QNO 398 CON_ID 42 */;

The table is missing a PRIMARY KEY. It initially contained 7 user-visible columns during the first above quoted ALTER TABLE statement execution.

I think that a test case could be something like this:

CREATE TABLE oltp1 (a INT) ENGINE=InnoDB ROW_FORMAT=REDUNDANT;
INSERT INTO oltp1 VALUES(NULL);
ALTER TABLE oltp1 ADD COLUMN (ecol10 SET('foo','bar'), ecol5 ENUM('foo','bar'), geocol7 GEOMETRY, scol3 TEXT NOT NULL);

Then, execute INSERT and OPTIMIZE concurrently.

A CREATE TABLE that would correspond to the trace that I analyze would contain the columns ecol4, ecol1, geocol1, c, icol8, id, scol9. I did not check their data types. I do not think that secondary indexes matter for reproducing this bug.

I would like to see a test case along these lines.

Comment by Matthias Leich [ 2022-03-24 ]

mysqld: /data/Server/10.5D/storage/innobase/row/row0log.cc:2450: 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.
...
Query (0x62b000103238): ALTER TABLE oltp3 ROW_FORMAT=REDUNDANT, ROW_FORMAT=REDUNDANT, ADD COLUMN IF NOT EXISTS tcol9 YEAR DEFAULT NULL, ALGORITHM=INPLACE, LOCK=NONE /* E_R Thread2 QNO 53 CON_ID 16 */
Connection ID (thread ID): 16
Status: NOT_KILLED
 
TBR-957-MDEV-26198-micro.yy  -- simplified grammar for the problem shown here
TBR-957-MDEV-26198.cfg            -- config file for the RQG batch tool
000000.log                                         -- Log of the RQG run (contains some SQL trace made by the client)

Comment by Alice Sherepa [ 2022-04-29 ]

10.9 9841a8080bd34b2edd6

Version: '10.9.0-MariaDB-debug-log'  
mysqld: /10.9/storage/innobase/row/row0log.cc:3290: const mrec_t* row_log_apply_op(dict_index_t*, row_merge_dup_t*, dberr_t*, mem_heap_t*, mem_heap_t*, bool, const mrec_t*, const mrec_t*, rec_offs*): Assertion `index->lock.have_x() == has_index_lock' failed.
220429 16:37:44 [ERROR] mysqld got signal 6 ;
 
Server version: 10.9.0-MariaDB-debug-log
 
mysys/stacktrace.c:212(my_print_stacktrace)[0x5558332ac30f]
sql/signal_handler.cc:226(handle_fatal_signal)[0x555831e3f15f]
??:0(__restore_rt)[0x7fa243be1730]
linux/raise.c:51(__GI_raise)[0x7fa24371e7bb]
stdlib/abort.c:81(__GI_abort)[0x7fa243709535]
intl/loadmsgcat.c:1177(_nl_load_domain)[0x7fa24370940f]
??:0(__assert_fail)[0x7fa243717102]
row/row0log.cc:3292(row_log_apply_op(dict_index_t*, row_merge_dup_t*, dberr_t*, mem_block_info_t*, mem_block_info_t*, bool, unsigned char const*, unsigned char const*, unsigned short*))[0x555832c8bbff]
row/row0log.cc:3632(row_log_apply_ops(trx_t const*, dict_index_t*, row_merge_dup_t*, ut_stage_alter_t*))[0x555832c8fb99]
row/row0log.cc:3744(row_log_apply(trx_t const*, dict_index_t*, TABLE*, ut_stage_alter_t*))[0x555832c90b4a]
handler/handler0alter.cc:11055(ha_innobase::commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool))[0x555832963fa4]
sql/handler.cc:5219(handler::ha_commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool))[0x555831e6c118]
sql/sql_table.cc:7751(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, MDL_request*, st_ddl_log_state*, TRIGGER_RENAME_PARAM*, Alter_table_ctx*, bool&, unsigned long long&, bool))[0x55583187152b]
sql/sql_table.cc:10708(mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool, bool))[0x555831887382]
sql/sql_alter.cc:547(Sql_cmd_alter_table::execute(THD*))[0x555831a3efc9]
sql/sql_parse.cc:6006(mysql_execute_command(THD*, bool))[0x5558315ac02a]
sql/sql_parse.cc:8046(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x5558315b928b]
sql/sql_parse.cc:1913(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x55583158fb6c]
sql/sql_parse.cc:1408(do_command(THD*, bool))[0x55583158c6a1]
sql/sql_connect.cc:1418(do_handle_one_connection(CONNECT*, bool))[0x555831a21c7c]
sql/sql_connect.cc:1314(handle_one_connection)[0x555831a21501]
perfschema/pfs.cc:2203(pfs_spawn_thread)[0x5558326ad813]
nptl/pthread_create.c:487(start_thread)[0x7fa243bd6fa3]
x86_64/clone.S:97(clone)[0x7fa2437dfeff]
 
Query (0x629000eba2a8): ALTER  TABLE `tmp` ADD INDEX ( `fld` (48578) )

Comment by Elena Stepanova [ 2022-05-01 ]

Given the timing, the failure alice observed may be MDEV-28449 (unless they turn out to be the same after all).

Comment by Marko Mäkelä [ 2022-08-02 ]

This bug might have been fixed in 10.6.8 by MDEV-15250. The bb-10.8-MDEV-28043 d8dd388f5b549000fcd2af0b576bb24154914368 that mleich mentioned is based on 10.8 18bb95b6080ba3a23bbd43436cd99f37abdd1552, which is missing MDEV-15250.

Is this failure repeatable with recent 10.6 or later? Can we close this as a duplicate of MDEV-15250?

Comment by Alice Sherepa [ 2023-02-01 ]

I guess this report might be the same as MDEV-18361.

I've got a crash on 10.6 non-debug, but it might be a different problem:

230201 14:15:32 [ERROR] mysqld got signal 11 ;
 
Server version: 10.6.12-MariaDB-log source revision: 0e737f78980fcfe83b05c27215eb3f5ede1ea473
 
sql/signal_handler.cc:238(handle_fatal_signal)[0x562c43482605]
??:0(__restore_rt)[0x7fa9f691f730]
row/row0log.cc:2179(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 short*))[0x562c437e4dcc]
row/row0log.cc:2771(row_log_table_apply_ops(que_thr_t*, row_merge_dup_t*, ut_stage_alter_t*))[0x562c437e6ec6]
include/sux_lock.h:258(row_log_table_apply(que_thr_t*, dict_table_t*, TABLE*, ut_stage_alter_t*, dict_table_t*))[0x562c437e7778]
handler/handler0alter.cc:10946(alter_rebuild_apply_log)[0x562c4375bbb8]
sql/sql_table.cc:7484(mysql_inplace_alter_table)[0x562c4330d424]
sql/sql_alter.cc:552(Sql_cmd_alter_table::execute(THD*))[0x562c4336e291]
sql/sql_parse.cc:6000(mysql_execute_command(THD*, bool))[0x562c43275b87]
sql/sql_parse.cc:8036(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x562c432663c0]
sql/sql_parse.cc:1955(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x562c432712e0]
sql/sql_parse.cc:1409(do_command(THD*, bool))[0x562c43272810]
sql/sql_connect.cc:1416(do_handle_one_connection(CONNECT*, bool))[0x562c4336968f]
sql/sql_connect.cc:1318(handle_one_connection)[0x562c433699cd]
perfschema/pfs.cc:2204(pfs_spawn_thread)[0x562c436a7765]
nptl/pthread_create.c:487(start_thread)[0x7fa9f6914fa3]
x86_64/clone.S:97(clone)[0x7fa9f651e06f]
 
Query (0x7fa9700108c0): ALTER IGNORE TABLE IF EXISTS `D` FORCE

Comment by Marko Mäkelä [ 2023-02-27 ]

I think that it makes sense to fix MDEV-30183 (which is a regression due to MDEV-15250) before testing further for this bug.

Comment by Thirunarayanan Balathandayuthapani [ 2023-03-06 ]

--source include/have_innodb.inc
create table oltp3 (tcol1 year default null,  tcol5 year default null,
                    non_existing_column text,  tcol3 year default null,
                    tcol4 year default null, tcol7 year default null,
                    tcol2 year default null, tcol8 year default null)engine=innodb row_format=redundant;
insert into oltp3 values(1, 1, 1, 1, 1, 1, 1, 1);
ALTER TABLE oltp3 ADD COLUMN IF NOT EXISTS tcol9 year default null, ALGORITHM=INPLACE, LOCK=NONE;
 
set DEBUG_SYNC="row_log_table_apply1_before SIGNAL con1_insert WAIT_FOR con1_finish";
send ALTER TABLE oltp3 ROW_FORMAT=REDUNDANT, ROW_FORMAT=REDUNDANT, ADD COLUMN IF NOT EXISTS tcol2 YEAR DEFAULT NULL, ALGORITHM=INPLACE, LOCK=NONE;
 
connect(con1,localhost,root,,,);
SET DEBUG_SYNC="now WAIT_FOR con1_insert";
INSERT IGNORE INTO oltp3 ( `non_existing_column` ) VALUES ( 'b' );
INSERT IGNORE INTO oltp3 ( `non_existing_column` ) VALUES ( 'l' );
SET DEBUG_SYNC="now SIGNAL con1_finish";
 
connection default;
reap;
disconnect con1;
SELECT * FROM oltp3;
drop table oltp3;

Comment by Thirunarayanan Balathandayuthapani [ 2023-03-13 ]

Patch is in bb-10.5-thiru and bb-10.6-thiru

Comment by Marko Mäkelä [ 2023-03-14 ]

Thank you, the fix looks fine to me.

Can you please change the bug title to mention ROW_FORMAT=REDUNDANT? Also, update affected version to include 10.4 and set the "caused by" relation.

Comment by Matthias Leich [ 2023-03-14 ]

When RQG testing on
origin/bb-10.6-thiru ab65a262e0b5fd6f47386d5e5766722c2fac3d00 2023-03-13T15:41:39+05:30
which contains a fix for MDEV-26198
I hit
REPLACE INTO t1 (col1,col2, col_int, col_string, col_text) VALUES /* 2326 / (2326,2326,2326,REPEAT(SUBSTR(CAST( 2326 AS CHAR),1,1), 10),REPEAT(SUBSTR(CAST( 2326 AS CHAR),1,1), @fill_amount) ), (2326,2326,2326,REPEAT(SUBSTR(CAST( 2326 AS CHAR),1,1), 10),REPEAT(SUBSTR(CAST( 2326 AS CHAR),1,1), @fill_amount) )  / E_R Thread6 QNO 30 CON_ID 25 */  failed: 1032 , errstr: Can't find record in 't1'
which is per Thiru a replay of MDEV-29545 which is in other trees too.
sdp:/data1/results/1678713291/TBR-403$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio
 
In sum
origin/bb-10.6-thiru ab65a262e0b5fd6f47386d5e5766722c2fac3d00 2023-03-13T15:41:39+05:30
behaved well in RQG testing.
The problems hit
- are in other trees too
- were not more frequent than in other trees.
 

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