Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Cannot Reproduce
-
10.5.5, 10.0(EOL), 10.1(EOL), 10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5
Description
Assert hit during RQG testing on
|
10.5.5 (origin/10.5 054f10365c49b70a3868edc0c955ffe187f8344c 2020-07-16T07:15:06+03:00)
|
...
|
[rr 79842 73136]mysqld: storage/innobase/lock/lock0lock.cc:1329: ib_lock_t* lock_rec_create_low(ib_lock_t*, que_thr_t*, unsigned int, ulint, ulint, const ib_page_t*, ulint, dict_index_t*, trx_t*, bool): Assertion `(index)->is_clust() || !dict_index_is_online_ddl(index)' failed.
|
Query (0x62b000181238): INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 46, 46 - 1, 46, REPEAT(SUBSTR(CAST( 46 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 46 AS CHAR),1,1), @fill_amount) )
|
Connection ID (thread ID): 22
|
Status: NOT_KILLED
|
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
|
#1 0x00005ceb3263a8b1 in __GI_abort () at abort.c:79
|
#2 0x00005ceb3262a42a in __assert_fail_base (fmt=0x5ceb327b1a38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x5590c7ad9020 "(index)->is_clust() || !dict_index_is_online_ddl(index)",
|
file=file@entry=0x5590c7ad2700 "storage/innobase/lock/lock0lock.cc", line=line@entry=1329,
|
function=function@entry=0x5590c7ae0320 <lock_rec_create_low(ib_lock_t*, que_thr_t*, unsigned int, unsigned long, unsigned long, unsigned char const*, unsigned long, dict_index_t*, trx_t*, bool)::__PRETTY_FUNCTION__> "ib_lock_t* lock_rec_create_low(ib_lock_t*, que_thr_t*, unsigned int, ulint, ulint, const ib_page_t*, ulint, dict_index_t*, trx_t*, bool)") at assert.c:92
|
#3 0x00005ceb3262a4a2 in __GI___assert_fail (assertion=assertion@entry=0x5590c7ad9020 "(index)->is_clust() || !dict_index_is_online_ddl(index)", file=file@entry=0x5590c7ad2700 "storage/innobase/lock/lock0lock.cc",
|
line=line@entry=1329,
|
function=function@entry=0x5590c7ae0320 <lock_rec_create_low(ib_lock_t*, que_thr_t*, unsigned int, unsigned long, unsigned long, unsigned char const*, unsigned long, dict_index_t*, trx_t*, bool)::__PRETTY_FUNCTION__> "ib_lock_t* lock_rec_create_low(ib_lock_t*, que_thr_t*, unsigned int, ulint, ulint, const ib_page_t*, ulint, dict_index_t*, trx_t*, bool)") at assert.c:101
|
#4 0x00005590c6743918 in lock_rec_create_low (c_lock=c_lock@entry=0x0, thr=thr@entry=0x0, type_mode=type_mode@entry=1059, space=<optimized out>, page_no=<optimized out>, page=0x4e28147c7000 "", heap_no=<optimized out>, index=<optimized out>,
|
trx=<optimized out>, holds_trx_mutex=<optimized out>) at storage/innobase/lock/lock0lock.cc:1329
|
#5 0x00005590c6746169 in lock_rec_create (caller_owns_trx_mutex=false, trx=0x5c321b25d660, index=0x6180001a0d20, heap_no=2, block=0x4e28145626e0, type_mode=1059, thr=0x0, c_lock=0x0) at storage/innobase/include/lock0lock.ic:132
|
#6 lock_rec_add_to_queue (type_mode=type_mode@entry=1059, block=block@entry=0x4e28145626e0, heap_no=heap_no@entry=2, index=0x6180001a0d20, trx=<optimized out>, caller_owns_trx_mutex=caller_owns_trx_mutex@entry=false)
|
at storage/innobase/lock/lock0lock.cc:1877
|
#7 0x00005590c674a38b in lock_move_rec_list_end (new_block=new_block@entry=0x4e28145626e0, block=block@entry=0x4e281455d618, rec=rec@entry=0x4e2814790741 "\200") at storage/innobase/lock/lock0lock.cc:2807
|
#8 0x00005590c6856a38 in page_copy_rec_list_end (new_block=new_block@entry=0x4e28145626e0, block=block@entry=0x4e281455d618, rec=rec@entry=0x4e2814790741 "\200", index=index@entry=0x61800002b520, mtr=mtr@entry=0x3c463b080220)
|
at storage/innobase/page/page0page.cc:658
|
#9 0x00005590c6857520 in page_move_rec_list_end (new_block=new_block@entry=0x4e28145626e0, block=block@entry=0x4e281455d618, split_rec=split_rec@entry=0x4e2814790741 "\200", index=0x61800002b520, mtr=mtr@entry=0x3c463b080220)
|
at storage/innobase/page/page0page.cc:1159
|
#10 0x00005590c6c3da3b in btr_page_split_and_insert (flags=flags@entry=0, cursor=cursor@entry=0x3c463b07fe80, offsets=offsets@entry=0x3c463b07fc80, heap=heap@entry=0x3c463b07fc40, tuple=tuple@entry=0x6170002940a0, n_ext=n_ext@entry=1,
|
mtr=<optimized out>) at storage/innobase/btr/btr0btr.cc:2995
|
#11 0x00005590c6c3f304 in btr_root_raise_and_insert (flags=flags@entry=0, cursor=cursor@entry=0x3c463b07fe80, offsets=offsets@entry=0x3c463b07fc80, heap=heap@entry=0x3c463b07fc40, tuple=tuple@entry=0x6170002940a0, n_ext=<optimized out>,
|
mtr=<optimized out>) at storage/innobase/btr/btr0btr.cc:2040
|
#12 0x00005590c6c7a8d8 in btr_cur_pessimistic_insert (flags=flags@entry=0, cursor=cursor@entry=0x3c463b07fe80, offsets=offsets@entry=0x3c463b07fc80, heap=heap@entry=0x3c463b07fc40, entry=entry@entry=0x6170002940a0, rec=rec@entry=0x3c463b07fcc0,
|
big_rec=<optimized out>, n_ext=<optimized out>, thr=<optimized out>, mtr=<optimized out>) at storage/innobase/btr/btr0cur.cc:3722
|
#13 0x00005590c6940e2d in row_ins_clust_index_entry_low (flags=flags@entry=0, mode=mode@entry=33, index=index@entry=0x61800002b520, n_uniq=n_uniq@entry=1, entry=entry@entry=0x6170002940a0, n_ext=n_ext@entry=0, thr=<optimized out>)
|
at storage/innobase/row/row0ins.cc:2733
|
#14 0x00005590c694fe5a in row_ins_clust_index_entry (index=index@entry=0x61800002b520, entry=entry@entry=0x6170002940a0, thr=thr@entry=0x621000472590, n_ext=n_ext@entry=0) at storage/innobase/row/row0ins.cc:3203
|
#15 0x00005590c69509dc in row_ins_index_entry (index=0x61800002b520, entry=0x6170002940a0, thr=thr@entry=0x621000472590) at storage/innobase/row/row0ins.cc:3311
|
#16 0x00005590c6950d23 in row_ins_index_entry_step (node=node@entry=0x621000472050, thr=thr@entry=0x621000472590) at storage/innobase/row/row0ins.cc:3480
|
#17 0x00005590c69523e6 in row_ins (node=node@entry=0x621000472050, thr=thr@entry=0x621000472590) at storage/innobase/row/row0ins.cc:3617
|
#18 0x00005590c69531bd in row_ins_step (thr=thr@entry=0x621000472590) at storage/innobase/row/row0ins.cc:3756
|
#19 0x00005590c69a5154 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x61a0002244b8 "\350.", prebuilt=0x6210004719a0, ins_mode=<optimized out>) at storage/innobase/row/row0mysql.cc:1459
|
#20 0x00005590c65c7c4d in ha_innobase::write_row (this=0x61d000aee2b8, record=<optimized out>) at storage/innobase/handler/ha_innodb.cc:7729
|
#21 0x00005590c5a20a86 in handler::ha_write_row (this=0x61d000aee2b8, buf=0x61a0002244b8 "\350.") at sql/handler.cc:7133
|
#22 0x00005590c5086564 in write_record (thd=thd@entry=0x62b00017a218, table=table@entry=0x619000746898, info=info@entry=0x3c463b082310, sink=sink@entry=0x0) at sql/sql_insert.cc:2090
|
#23 0x00005590c50aa60e in mysql_insert (thd=thd@entry=0x62b00017a218, table_list=0x62b0001814c0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=<optimized out>, ignore=<optimized out>, result=<optimized out>)
|
at sql/sql_insert.cc:1087
|
#24 0x00005590c5161bfd in mysql_execute_command (thd=thd@entry=0x62b00017a218) at sql/sql_parse.cc:4545
|
#25 0x00005590c5183ed7 in mysql_parse (thd=thd@entry=0x62b00017a218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x3c463b083ff0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false)
|
at sql/sql_parse.cc:7993
|
#26 0x00005590c5149366 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b00017a218,
|
packet=packet@entry=0x629000b7c219 " INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 46, 46 - 1, 46, REPEAT(SUBSTR(CAST( 46 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 46 AS CHAR),1,1), @fill_amount) ) /* E_R Thread8 QNO "...,
|
packet_length=packet_length@entry=216, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at sql/sql_parse.cc:1866
|
#27 0x00005590c51441b7 in do_command (thd=0x62b00017a218) at sql/sql_parse.cc:1347
|
#28 0x00005590c55e4281 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x608000003538, put_in_cache=put_in_cache@entry=true) at sql/sql_connect.cc:1411
|
#29 0x00005590c55e5525 in handle_one_connection (arg=arg@entry=0x608000003538) at sql/sql_connect.cc:1313
|
#30 0x00005590c635eca2 in pfs_spawn_thread (arg=0x61500000a598) at storage/perfschema/pfs.cc:2201
|
#31 0x00002bdd0de166db in start_thread (arg=0x3c463b086300) at pthread_create.c:463
|
#32 0x00005ceb3271ba3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr)
|
|
RQG
|
-------
|
git clone https://github.com/mleich1/rqg --branch experimental RQG
|
origin/experimental f3d72ce51b150ee1f52a93d18f2024af293d925e 2020-07-13T20:46:53+02:00
|
|
rqg.pl \
|
--mysqld=--loose-innodb_lock_schedule_algorithm=fcfs \
|
--gendata=conf/mariadb/table_stress.zz \
|
--gendata_sql=conf/mariadb/table_stress.sql \
|
--engine=Innodb \
|
--reporters=Deadlock1,ErrorLog,Backtrace \
|
--mysqld=--connect_timeout=60 \
|
--mysqld=--net_read_timeout=30 \
|
--mysqld=--net_write_timeout=60 \
|
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
|
--mysqld=--loose-idle_transaction_timeout=0 \
|
--mysqld=--loose-idle_write_transaction_timeout=0 \
|
--mysqld=--interactive_timeout=28800 \
|
--mysqld=--lock_wait_timeout=86400 \
|
--mysqld=--innodb-lock-wait-timeout=50 \
|
--mysqld=--loose-table_lock_wait_timeout=50 \
|
--mysqld=--wait_timeout=28800 \
|
--mysqld=--slave_net_timeout=60 \
|
--mysqld=--loose-max-statement-time=30 \
|
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
|
--mysqld=--log-output=none \
|
--seed=random \
|
--grammar=conf/mariadb/table_stress_innodb_nocopy.yy \
|
--threads=33 \
|
--mysqld=--innodb_adaptive_hash_index=OFF \
|
--mysqld=--innodb_page_size=4K \
|
--mysqld=--innodb-buffer-pool-size=8M \
|
--duration=300 \
|
--no_mask \
|
--workdir=<local settings> \
|
--vardir=<local settings> \
|
--mtr-build-thread=<local settings> \
|
--basedir1=<local settings> \
|
--script_debug=_nix_ \
|
--rr=Server \
|
--rr_options=--chaos
|
|
|
Attachments
Issue Links
- relates to
-
MDEV-15250 UPSERT during ALTER-TABLE results in 'Duplicate entry' error for alter
-
- Closed
-
-
MDEV-20605 Awaken transaction can miss inserted by other transaction records due to wrong persistent cursor restoration
-
- Closed
-
- mentioned in
-
Page Failed to load
In the rr replay trace that I analyzed, we have the following:
Actually, at this point, the ALTER TABLE thread was already executing a rollback in Thread 27:
bb-10.5-MDEV-23190 054f10365c49b70a3868edc0c955ffe187f8344c (similar to 10.5 4d4865de6f124ed0a97573bf784102077f7296e7)
#7 0x00005590c6af80b7 in rw_lock_x_lock_func (lock=0x5590c8b41418 <dict_sys+152>, pass=pass@entry=0, file_name=file_name@entry=0x5590c7a99880 "/home/mleich/10.5_A/storage/innobase/handler/handler0alter.cc",
line=line@entry=8651) at /home/mleich/10.5_A/storage/innobase/sync/sync0rw.cc:659
#8 0x00005590c69a8c53 in dict_sys_t::lock (line=8651, file=0x5590c7a99880 "/home/mleich/10.5_A/storage/innobase/handler/handler0alter.cc", this=<optimized out>)
at /home/mleich/10.5_A/storage/innobase/include/dict0dict.h:1573
#9 row_mysql_lock_data_dictionary_func (trx=0x5c321b27b678, file=file@entry=0x5590c7a99880 "/home/mleich/10.5_A/storage/innobase/handler/handler0alter.cc", line=line@entry=8651)
at /home/mleich/10.5_A/storage/innobase/row/row0mysql.cc:2317
#10 0x00005590c665ebbe in rollback_inplace_alter_table (ha_alter_info=ha_alter_info@entry=0x2b65542bd950, table=0x619000832798, prebuilt=0x6210003b25a0)
at /home/mleich/10.5_A/storage/innobase/handler/handler0alter.cc:8651
#11 0x00005590c663b82f in ha_innobase::commit_inplace_alter_table (this=<optimized out>, altered_table=<optimized out>, ha_alter_info=<optimized out>, commit=<optimized out>)
at /home/mleich/10.5_A/storage/innobase/handler/handler0alter.cc:10731
#12 0x00005590c5a0ed9d in handler::ha_commit_inplace_alter_table (this=0x61d000bca2b8, altered_table=altered_table@entry=0x2b65542bde90, ha_alter_info=ha_alter_info@entry=0x2b65542bd950,
commit=commit@entry=false) at /home/mleich/10.5_A/sql/handler.cc:4839
#13 0x00005590c541dedd in mysql_inplace_alter_table (thd=thd@entry=0x62b00023e218, table_list=<optimized out>, table=table@entry=0x619000832798, altered_table=<optimized out>, ha_alter_info=<optimized out>,
inplace_supported=inplace_supported@entry=HA_ALTER_INPLACE_NOCOPY_NO_LOCK, target_mdl_request=<optimized out>, alter_ctx=<optimized out>) at /home/mleich/10.5_A/sql/sql_table.cc:8129
#14 0x00005590c54540c6 in mysql_alter_table (thd=thd@entry=0x62b00023e218, new_db=<optimized out>, new_name=new_name@entry=0x62b000242ee0, create_info=create_info@entry=0x2b65542bfb50,
table_list=<optimized out>, table_list@entry=0x62b000245428, alter_info=alter_info@entry=0x2b65542bfa50, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>, if_exists=<optimized out>)
at /home/mleich/10.5_A/sql/sql_table.cc:10564
#15 0x00005590c55ff26a in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x62b00023e218) at /home/mleich/10.5_A/sql/sql_alter.cc:532
#16 0x00005590c516bab3 in mysql_execute_command (thd=thd@entry=0x62b00023e218) at /home/mleich/10.5_A/sql/sql_parse.cc:5951
#17 0x00005590c5183ed7 in mysql_parse (thd=thd@entry=0x62b00023e218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x2b65542c1ff0, is_com_multi=is_com_multi@entry=false,
is_next_command=is_next_command@entry=false) at /home/mleich/10.5_A/sql/sql_parse.cc:7993
#18 0x00005590c5149366 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b00023e218,
packet=packet@entry=0x629000c80219 " ALTER TABLE t4 ADD UNIQUE INDEX `Marvão_uidx3` ( col_text(9) ), ALGORITHM = NOCOPY, LOCK = DEFAULT /* E_R Thread32 QNO 26 CON_ID 36 */ ",
packet_length=packet_length@entry=138, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /home/mleich/10.5_A/sql/sql_parse.cc:1866
Finally, the rollback will set index->online_status will be set from ONLINE_INDEX_COMPLETE to ONLINE_INDEX_ABORTED and subsequently to ONLINE_INDEX_ABORTED_DROPPED.
Ultimately, the assertion will fail for updating a PRIMARY index on the table. It just happens that lock_move_rec_list_end() finds a lock->index that is pointing to the index that does not officially exist.
I see two possible fixes of this:
MDEV-15061(MariaDB 10.3.5) made an effort to remove such code.