[MDEV-26152] Assertion: prebuilt->template_type == ROW_MYSQL_WHOLE_ROW fails in row0mysql.cc line 1752 Created: 2021-07-15  Updated: 2023-11-28

Status: Confirmed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 5.5, 10.0, 10.1, 10.2, 10.3, 10.4, 10.5, 10.6, 10.7
Fix Version/s: 10.4, 10.5, 10.6, 10.11, 11.0, 11.1

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: rr-profile-analyzed

Issue Links:
Relates
relates to MDEV-21428 InnoDB: Failing assertion: prebuilt->... Confirmed
relates to MDEV-10356 rpl.rpl_parallel_temptable failure du... Closed
relates to MDEV-17805 Do not add temporary tables to dict_s... Stalled
relates to MDEV-25064 rpl.rpl_parallel_temptable failed in ... Closed

 Description   

to reproduce:

./mtr sp_temp_table.test --mysqld=--log-bin

10.2 fb0b28932ce82903f2fcf

 
Version: '10.2.40-MariaDB-debug-log'  
2021-07-15 11:46:35 0x7fbc0fd1b700  InnoDB: Assertion failure in file /git/10.2/storage/innobase/row/row0mysql.cc line 1752
 
InnoDB: Failing assertion: prebuilt->template_type == ROW_MYSQL_WHOLE_ROW
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: https://mariadb.com/kb/en/library/innodb-recovery-modes/
 
InnoDB: about forcing recovery.
 
210715 11:46:35 [ERROR] mysqld got signal 6 ;
 
 
 
 
 
Server version: 10.2.40-MariaDB-debug-log
 
 
 
linux/raise.c:51(__GI_raise)[0x7fbc25cb97bb]
 
stdlib/abort.c:81(__GI_abort)[0x7fbc25ca4535]
 
ut/ut0dbg.cc:60(_GLOBAL__sub_D_00099_0_ut0dbg.cc)[0x56074c1a8334]
 
row/row0mysql.cc:1753(row_update_for_mysql(row_prebuilt_t*))[0x56074bfb80a3]
 
handler/ha_innodb.cc:9126(ha_innobase::delete_row(unsigned char const*))[0x56074bcb204a]
 
sql/handler.cc:6178(handler::ha_delete_row(unsigned char const*))[0x56074b77a820]
 
sql/sql_delete.cc:585(mysql_delete(THD*, TABLE_LIST*, Item*, SQL_I_List<st_order>*, unsigned long long, unsigned long long, select_result*))[0x56074bb6f3b1]
 
sql/sql_parse.cc:4420(mysql_execute_command(THD*))[0x56074b0eb017]
 
sql/sp_head.cc:3331(sp_instr_stmt::exec_core(THD*, unsigned int*))[0x56074af25246]
 
sql/sp_head.cc:3094(sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*))[0x56074af23e00]
 
sql/sp_head.cc:3247(sp_instr_stmt::execute(THD*, unsigned int*))[0x56074af24af1]
 
sql/sp_head.cc:1326(sp_head::execute(THD*, bool))[0x56074af18ae6]
 
sql/sp_head.cc:2202(sp_head::execute_procedure(THD*, List<Item>*))[0x56074af1d7cd]
 
sql/sql_parse.cc:2981(do_execute_sp(THD*, sp_head*))[0x56074b0e11d5]
 
sql/sql_parse.cc:5622(mysql_execute_command(THD*))[0x56074b0f4c75]
 
sql/sp_head.cc:3331(sp_instr_stmt::exec_core(THD*, unsigned int*))[0x56074af25246]
 
sql/sp_head.cc:3094(sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*))[0x56074af23e00]
 
sql/sp_head.cc:3247(sp_instr_stmt::execute(THD*, unsigned int*))[0x56074af24af1]
 
sql/sp_head.cc:1326(sp_head::execute(THD*, bool))[0x56074af18ae6]
 
sql/sp_head.cc:1954(sp_head::execute_function(THD*, Item**, unsigned int, Field*))[0x56074af1ba04]
 
sql/item_func.cc:6752(Item_func_sp::execute_impl(THD*))[0x56074b8be3a1]
 
sql/item_func.cc:6685(Item_func_sp::execute())[0x56074b8bdc22]
 
sql/item_func.h:2419(Item_func_sp::val_real())[0x56074b8c72a6]
 
sql/item.cc:6956(Item::send(Protocol*, String*))[0x56074b7bb812]
 
sql/protocol.cc:992(Protocol::send_result_set_row(List<Item>*))[0x56074aeb21bf]
 
sql/sql_class.cc:2788(select_send::send_data(List<Item>&))[0x56074b0272e5]
 
sql/sql_select.cc:3526(JOIN::exec_inner())[0x56074b1a78c5]
 
sql/sql_select.cc:3447(JOIN::exec())[0x56074b1a6748]
 
sql/sql_select.cc:3851(mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x56074b1a9e19]
 
sql/sql_select.cc:361(handle_select(THD*, LEX*, select_result*, unsigned long))[0x56074b1868ce]
 
sql/sql_parse.cc:6271(execute_sqlcom_select(THD*, TABLE_LIST*))[0x56074b0fa228]
 
sql/sql_parse.cc:3582(mysql_execute_command(THD*))[0x56074b0e59af]
 
sql/sql_parse.cc:7793(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x56074b103546]
 
sql/sql_parse.cc:1830(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x56074b0da593]
 
sql/sql_parse.cc:1381(do_command(THD*))[0x56074b0d6fc4]
 
sql/sql_connect.cc:1336(do_handle_one_connection(CONNECT*))[0x56074b481e5c]
 
sql/sql_connect.cc:1242(handle_one_connection)[0x56074b48171d]
 
perfschema/pfs.cc:1871(pfs_spawn_thread)[0x56074c92363c]
 
nptl/pthread_create.c:487(start_thread)[0x7fbc263f7fa3]
 
x86_64/clone.S:97(clone)[0x7fbc25d7b4cf]
 
 
 
Query (0x62500020d190): DELETE FROM cachedata WHERE
 
timestamp < DATE_SUB(@timestamp, INTERVAL 15 SECOND)

on 5.5:

5.5 821a6939087d411f9

 
Version: '5.5.69-MariaDB-debug' 
210715 11:44:15  InnoDB: Assertion failure in thread 140005887186688 in file lock0lock.c line 5494
 
InnoDB: Failing assertion: lock_table_has(thr_get_trx(thr), index->table, LOCK_IX)
 
 
 
210715 11:44:15 [ERROR] mysqld got signal 6 ;
 
 
 
Server version: 5.5.69-MariaDB-debug
 
 
 
linux/raise.c:51(__GI_raise)[0x7f55b74467bb]
 
stdlib/abort.c:81(__GI_abort)[0x7f55b7431535]
 
lock/lock0lock.c:5499(lock_sec_rec_modify_check_and_lock)[0x7f55b0ac053c]
 
btr/btr0cur.c:2994(btr_cur_del_mark_set_sec_rec)[0x7f55b0959c14]
 
row/row0upd.c:1630(row_upd_sec_index_entry)[0x7f55b0c235ff]
 
row/row0upd.c:2328(row_upd)[0x7f55b0c338b2]
 
row/row0mysql.c:1493(row_update_for_mysql)[0x7f55b0bd23da]
 
handler/ha_innodb.cc:5758(ha_innodb::delete_row(unsigned char const*))[0x7f55b0b4da51]
 
sql/handler.cc:5262(handler::ha_delete_row(unsigned char const*))[0x561d6bfd2c33]
 
sql/sql_delete.cc:344(mysql_delete(THD*, TABLE_LIST*, Item*, SQL_I_List<st_order>*, unsigned long long, unsigned long long))[0x561d6c3807bb]
 
sql/sql_parse.cc:3098(mysql_execute_command(THD*))[0x561d6bb34bfc]
 
sql/sp_head.cc:3223(sp_instr_stmt::exec_core(THD*, unsigned int*))[0x561d6c3279ea]
 
sql/sp_head.cc:2999(sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*))[0x561d6c33f893]
 
sql/sp_head.cc:3145(sp_instr_stmt::execute(THD*, unsigned int*))[0x561d6c340964]
 
sql/sp_head.cc:1432(sp_head::execute(THD*, bool))[0x561d6c330cb1]
 
sql/sp_head.cc:2200(sp_head::execute_procedure(THD*, List<Item>*))[0x561d6c3359c0]
 
sql/sql_parse.cc:4120(mysql_execute_command(THD*))[0x561d6bb3eba3]
 
sql/sp_head.cc:3223(sp_instr_stmt::exec_core(THD*, unsigned int*))[0x561d6c3279ea]
 
sql/sp_head.cc:2999(sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*))[0x561d6c33f893]
 
sql/sp_head.cc:3145(sp_instr_stmt::execute(THD*, unsigned int*))[0x561d6c340964]
 
sql/sp_head.cc:1432(sp_head::execute(THD*, bool))[0x561d6c330cb1]
 
sql/sp_head.cc:1954(sp_head::execute_function(THD*, Item**, unsigned int, Field*))[0x561d6c334b4a]
 
sql/item_func.cc:6906(Item_func_sp::execute_impl(THD*))[0x561d6c11574c]
 
sql/item_func.cc:6835(Item_func_sp::execute())[0x561d6c115a65]
 
sql/item_func.h:2060(Item_func_sp::val_real())[0x561d6c121baf]
 
sql/item.cc:6499(Item::send(Protocol*, String*))[0x561d6bfe3513]
 
sql/protocol.cc:903(Protocol::send_result_set_row(List<Item>*))[0x561d6b98c8ae]
 
sql/sql_class.cc:2388(select_send::send_data(List<Item>&))[0x561d6ba6c8e9]
 
sql/sql_select.cc:2318(JOIN::exec())[0x561d6bc59f18]
 
sql/sql_select.cc:3137(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*))[0x561d6bc4980c]
 
sql/sql_select.cc:312(handle_select(THD*, LEX*, select_result*, unsigned long))[0x561d6bc4bc9c]
 
sql/sql_parse.cc:4683(execute_sqlcom_select(THD*, TABLE_LIST*))[0x561d6bb0dd3f]
 
sql/sql_parse.cc:2221(mysql_execute_command(THD*))[0x561d6bb280e4]
 
sql/sql_parse.cc:5941(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x561d6bb434e0]
 
sql/sql_parse.cc:1069(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x561d6bb474a6]
 
sql/sql_parse.cc:793(do_command(THD*))[0x561d6bb4c0d0]
 
sql/sql_connect.cc:1268(do_handle_one_connection(THD*))[0x561d6be09b67]
 
sql/sql_connect.cc:1186(handle_one_connection)[0x561d6be09e51]
 
perfschema/pfs.cc:1018(pfs_spawn_thread)[0x561d6c7325f7]
 
nptl/pthread_create.c:487(start_thread)[0x7f55b7e1bfa3]
 
x86_64/clone.S:97(clone)[0x7f55b75084cf]
 
 
 
Query (0x625000451180): DELETE FROM cachedata WHERE timestamp < DATE_SUB(@timestamp, INTERVAL 15 SECOND)



 Comments   
Comment by Marko Mäkelä [ 2021-07-15 ]

The error occurs due to a wrong call that changes m_prebuilt->select_lock_type to be set to LOCK_S instead of LOCK_X:

10.6 789a2a363aa576af22fec412a6724140955978b5

 
#0  ha_innobase::store_lock (this=0x7f5a34b55d40, thd=0x7f5a34001ab8, to=0x7f5a340179b8, lock_type=TL_READ_NO_INSERT) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:16191
 
#1  0x0000560d5f9f2af6 in get_lock_data (thd=0x7f5a34001ab8, table_ptr=0x7f5a34017990, count=1, flags=3) at /mariadb/10.6/sql/lock.cc:809
 
#2  0x0000560d5f9f229e in mysql_lock_tables (thd=0x7f5a34001ab8, tables=0x7f5a34017990, count=1, flags=0) at /mariadb/10.6/sql/lock.cc:298
 
#3  0x0000560d5f429f7b in lock_tables (thd=0x7f5a34001ab8, tables=0x7f5a34017290, count=1, flags=0) at /mariadb/10.6/sql/sql_base.cc:5549
 
#4  0x0000560d5f42b003 in open_and_lock_tables (thd=0x7f5a34001ab8, options=@0x7f5a34007320: {m_options = DDL_options_st::OPT_NONE}, tables=0x7f5a34017290, derived=true, flags=0, 
    prelocking_strategy=0x7f5a480a21c0) at /mariadb/10.6/sql/sql_base.cc:5261
 
#5  0x0000560d5f3dae3e in open_and_lock_tables (thd=0x7f5a34001ab8, tables=0x0, derived=true, flags=0) at /mariadb/10.6/sql/sql_base.h:509
 
#6  0x0000560d5f4e6b78 in execute_sqlcom_select (thd=0x7f5a34001ab8, all_tables=0x0) at /mariadb/10.6/sql/sql_parse.cc:6173
 
#7  0x0000560d5f4dab48 in mysql_execute_command (thd=0x7f5a34001ab8, is_called_from_prepared_stmt=false) at /mariadb/10.6/sql/sql_parse.cc:3947
 
#8  0x0000560d5f4d2bbd in mysql_parse (thd=0x7f5a34001ab8, rawbuf=0x7f5a340152c0 "SELECT get_cache(1, '2014-01-01', '2014-02-01')", length=47, parser_state=0x7f5a480a3b98) at /mariadb/10.6/sql/sql_parse.cc:8026

In the correct execution, the field only alternates between LOCK_X and LOCK_NONE:

./mtr --manual-rr --mysqld=--skip-log-bin innodb.sp_temp_table

When the field is not LOCK_X, ha_innobase::build_template() will not set whole_row=true (which must always be set for DELETE).

We might argue that because temporary tables are private to a connection or thread (something that is being blatantly violated in parallel replication; see MDEV-10356, MDEV-17805, MDEV-25064) the assertion could be relaxed. But until the parallel replication has been fixed, I would be very reluctant to do that. (Besides, we might want to implement globally visible temporary tables some day.)

Comment by Andrei Elkin [ 2022-02-22 ]

marko, there's no parallel replication involved. I think innodb team need to check how exactly
m_prebuilt->select_lock_type gets set incorrectly. Bouncing it to you.

Comment by Marko Mäkelä [ 2023-08-11 ]

Elkin, a careful read of the stack trace that I provided should have lead you to notice that the unexpected TL_READ_NO_INSERT (instead of TL_READ) was passed from table->reginfo.lock_type, which was updated slightly earlier:

10.6 0be4781428a4044b13b085965820a995652bb0e9

 
Thread 2 hit Hardware watchpoint 2: -location table.reginfo.lock_type
 
 
 
Old value = TL_WRITE
 
New value = TL_READ_NO_INSERT
 
0x000056222c68ac06 in open_tables (thd=0x62b0000cb218, options=..., 
    start=0x7f7993c6a640, counter=0x7f7993c6a630, flags=0, 
    prelocking_strategy=0x7f7993a5ce20) at /mariadb/10.6/sql/sql_base.cc:4496
 
4496	          tbl->reginfo.lock_type= read_lock_type_for_table(thd, thd->lex, tables,
 
(rr) backtrace
 
#0  0x000056222c68ac06 in open_tables (thd=0x62b0000cb218, options=..., 
    start=0x7f7993c6a640, counter=0x7f7993c6a630, flags=0, 
    prelocking_strategy=0x7f7993a5ce20) at /mariadb/10.6/sql/sql_base.cc:4496
 
#1  0x000056222c68ef51 in open_and_lock_tables (thd=0x62b0000cb218, 
    options=..., tables=0x62b0000d43a0, derived=true, flags=0, 
    prelocking_strategy=0x7f7993a5ce20) at /mariadb/10.6/sql/sql_base.cc:5313
 
#2  0x000056222c5e71b4 in open_and_lock_tables (thd=0x62b0000cb218, 
    tables=0x0, derived=true, flags=0) at /mariadb/10.6/sql/sql_base.h:509
 
#3  0x000056222c82c176 in execute_sqlcom_select (thd=0x62b0000cb218, 
    all_tables=0x0) at /mariadb/10.6/sql/sql_parse.cc:6204
 
#4  0x000056222c81b566 in mysql_execute_command (thd=0x62b0000cb218, 
    is_called_from_prepared_stmt=false) at /mariadb/10.6/sql/sql_parse.cc:3959
 
#5  0x000056222c837a49 in mysql_parse (thd=0x62b0000cb218, 
    rawbuf=0x62b0000d2238 "SELECT get_cache(1, '2014-01-01', '2014-02-01')", 
    length=47, parser_state=0x7f79940ea260)
 
    at /mariadb/10.6/sql/sql_parse.cc:8053

I duplicated the relevant code in its entirety below:

thr_lock_type read_lock_type_for_table(THD *thd,
 
                                       Query_tables_list *prelocking_ctx,
 
                                       TABLE_LIST *table_list,
 
                                       bool routine_modifies_data)
 
{
 
  /*
 
    In cases when this function is called for a sub-statement executed in
 
    prelocked mode we can't rely on OPTION_BIN_LOG flag in THD::options
 
    bitmap to determine that binary logging is turned on as this bit can
 
    be cleared before executing sub-statement. So instead we have to look
 
    at THD::variables::sql_log_bin member.
 
  */
 
  bool log_on= mysql_bin_log.is_open() && thd->variables.sql_log_bin;
 
  if ((log_on == FALSE) || (thd->wsrep_binlog_format() == BINLOG_FORMAT_ROW) ||
 
      (table_list->table->s->table_category == TABLE_CATEGORY_LOG) ||
 
      (table_list->table->s->table_category == TABLE_CATEGORY_PERFORMANCE) ||
 
      !(is_update_query(prelocking_ctx->sql_command) ||
 
        (routine_modifies_data && table_list->prelocking_placeholder) ||
 
        (thd->locked_tables_mode > LTM_LOCK_TABLES)))
 
    return TL_READ;
 
  else
 
    return TL_READ_NO_INSERT;
 
}

For the plain run ./mtr innodb.sp_temp_table, all 29 invocations of ha_innobase::store_lock() passed lock_type=TL_READ.

Comment by Marko Mäkelä [ 2023-08-11 ]

This may have to be assigned to someone who understands the intended logic of handler::external_lock() and handler::store_lock(). It always was unclear to me.

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