[MDEV-23197] Assertion `(index)->is_clust() || !dict_index_is_online_ddl(index)' failed. in lock_rec_create_low Created: 2020-07-16  Updated: 2023-03-03  Resolved: 2023-03-03

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.0, 10.1, 10.5.5, 10.2, 10.3, 10.4, 10.5
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Cannot Reproduce Votes: 0
Labels: rr-profile-analyzed, upstream

Issue Links:
Relates
relates to MDEV-15250 UPSERT during ALTER-TABLE results in ... Closed
relates to MDEV-20605 Awaken transaction can miss inserted ... Closed

 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
 
 



 Comments   
Comment by Marko Mäkelä [ 2020-07-20 ]

In the rr replay trace that I analyzed, we have the following:

  1. A unique index was created by ALTER TABLE t4 ADD UNIQUE INDEX `Marvão_uidx3` ( col_text(9) ) but not yet committed
  2. Before the ALTER TABLE was committed, INSERT INTO t4… will invoke lock_rec_convert_impl_to_expl() deep inside row_ins_scan_sec_index_for_duplicate(). We have index->online_status=ONLINE_INDEX_COMPLETE and index->uncommitted=true at this point.

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:

  1. Discard the explicit locks when we are discarding the index metadata. But, it would be better to never invoke any ‘break the locks’ code, especially after MDEV-15061 (MariaDB 10.3.5) made an effort to remove such code.
  2. In lock_move_rec_list_end() and similar functions, skip or discard anything if lock->index->online_status is not ONLINE_INDEX_COMPLETE. Add a debug assertion that the status must not be ONLINE_INDEX_CREATION.
Comment by Marko Mäkelä [ 2023-03-03 ]

This may have been fixed by MDEV-15250 in 10.6. Is it the case?

Comment by Matthias Leich [ 2023-03-03 ]

The assert was hit last time 2021-07-20 on
origin/10.5 b4ec3313f6bb3a222b3528b5a8a6dca73b870c20 2021-07-20T09:32:11+03:00
which claims to be a 10.5.12.

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