[MDEV-16554] InnoDB: Assertion failure in file mariadb-10.2.14/storage/innobase/que/que0que.cc line 563 Created: 2018-06-23  Updated: 2021-04-06  Resolved: 2021-04-06

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.14
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Valerii Kravchuk Assignee: Thirunarayanan Balathandayuthapani
Resolution: Cannot Reproduce Votes: 1
Labels: None

Issue Links:
PartOf
includes MDEV-17140 DB restarted due to InnoDB: Assertion... Closed
Relates
relates to MDEV-16122 [draft] Failing assertion: prebuilt->... Open
relates to MDEV-16923 10.3.8 crashes Open
relates to MDEV-20563 Server crash in row_upd_del_mark_clus... Closed

 Description   

After upgrade from 10.1.25 to 10.2.14 (http://hasky.askmonty.org/archive/bb-10.2-compatibility/build-20620/ to be more specific) various statements end up with the assertion failure in the que_graph_free_recursive() function in /que0que.cc.

It can be ALTER, DROP TRIGGER etc, but even SELECT from I_S.TABLES crashes this way, as shown below:

2018-06-23 21:05:03 0x7f7619ee0700  InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/storage/innobase/que/que0que.cc line 563
 
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/xtradbinnodb-recovery-modes/
 
InnoDB: about forcing recovery.
 
180623 21:05:03 [ERROR] mysqld got signal 6 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed,
 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.2.14-MariaDB-log
 
key_buffer_size=67108864
 
read_buffer_size=131072
 
max_used_connections=207
 
max_threads=1002
 
thread_count=186
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2267691 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f76007d6a18
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x7f7619edfd40 thread_stack 0x40000
 
/usr/sbin/mysqld(my_print_stacktrace+0x38)[0x5606095e88bd]
 
/usr/sbin/mysqld(handle_fatal_signal+0x3d7)[0x56060901c0f2]
 
sigaction.c:0(__restore_rt)[0x7f79458ca680]
 
:0(__GI_raise)[0x7f7943dcf207]
 
:0(__GI_abort)[0x7f7943dd08f8]
 
/usr/sbin/mysqld(+0xc11b2e)[0x560609394b2e]
 
ut/ut0dbg.cc:62(__static_initialization_and_destruction_0)[0x5606092cfdca]
 
que/que0que.cc:561(que_graph_free_recursive(void*))[0x5606093049bc]
 
row/row0mysql.cc:986(row_prebuilt_free(row_prebuilt_t*, unsigned long))[0x56060921fdcd]
 
handler/ha_innodb.cc:6768(ha_innobase::close())[0x560609021883]
 
sql/handler.cc:2701(handler::ha_close())[0x560608e8dfe8]
 
sql/table.cc:3457(closefrm(TABLE*))[0x560608f755b2]
 
sql/table_cache.cc:223(intern_close_table)[0x560608f75733]
 
sql/table_cache.cc:261(tc_remove_table)[0x560608f75b86]
 
sql/table_cache.cc:384(tc_add_table(THD*, TABLE*))[0x560608d3b43e]
 
sql/sql_base.cc:1911(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x560608d3d749]
 
sql/sql_base.cc:3470(open_and_process_table)[0x560608d3e686]
 
sql/sql_base.cc:3990(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*))[0x560608d38969]
 
sql/sql_base.h:239(open_tables)[0x560608d3feb6]
 
sql/sql_base.cc:4904(open_normal_and_derived_tables(THD*, TABLE_LIST*, unsigned int, unsigned int))[0x560608d3ffb8]
 
sql/sql_base.cc:4954(open_tables_only_view_structure(THD*, TABLE_LIST*, bool))[0x560608e2e46f]
 
sql/sql_show.cc:4483(fill_schema_table_by_open)[0x560608e2fb3c]
 
sql/sql_show.cc:5133(get_all_tables(THD*, TABLE_LIST*, Item*))[0x560608e3eee2]
 
sql/sql_show.cc:8612(get_schema_tables_result(JOIN*, enum_schema_table_state))[0x560608de283e]
 
sql/sql_select.cc:3592(JOIN::exec_inner())[0x560608de200c]
 
sql/sql_select.cc:3425(JOIN::exec())[0x560608de2f5e]
 
sql/sql_select.cc:3826(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*))[0x560608dd8723]
 
sql/sql_select.cc:379(handle_select(THD*, LEX*, select_result*, unsigned long))[0x560608daf18f]
 
sql/sql_parse.cc:6511(execute_sqlcom_select)[0x560608da68e1]
 
sql/sql_parse.cc:3736(mysql_execute_command(THD*))[0x560608db248c]
 
sql/sql_parse.cc:7978(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x560608da1e2d]
 
sql/sql_parse.cc:1837(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x560608da0a79]
 
sql/sql_parse.cc:1383(do_command(THD*))[0x560608ec9860]
 
sql/sql_connect.cc:1335(do_handle_one_connection(CONNECT*))[0x560608ec95c0]
 
pthread_create.c:0(start_thread)[0x7f79458c2dd5]
 
/lib64/libc.so.6(clone+0x6d)[0x7f7943e97b3d]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f76007e0180): SELECT concat(current_date,'-',current_time) 'DateTime', table_schema 'Database_Name', Round(Sum(data_length + index_length) / 1024 / 1024, 1) 'Database_Size_MB' FROM information_schema.tables GROUP BY table_schema order by table_schema
 
Connection ID (thread ID): 2811
 
Status: NOT_KILLED

Crashes stop after downgrading back to 10.1.25.

See some what similar MDEV-15488 also.

 Comments   
Comment by Elena Stepanova [ 2018-07-10 ]

Could you please provide the config file(s)?

Comment by Sander Pilon [ 2018-08-08 ]

I get the same error with 10.3.8

Comment by Hartmut Holzgraefe [ 2018-08-29 ]

latest stack traces were re-created, with GDB reporting potential stack corruption now

traces are available in the files section of the support issue

Comment by Elena Stepanova [ 2018-09-01 ]

valerii, hholzgra, do you know whether the instance where the problem occurs has been recently upgraded from 5.5?
We have a couple of similar reports, both of which mention that the failure started happening after upgrade from 5.5 to 10.2. It can of course be unimportant and only indicate that the problem only exists in 10.2 but not in 5.5 and affects specific workloads of these users; but it can also be that it's related to the upgrade itself, e.g. affects tables created by 5.5. It could be helpful to understand which it is.

Comment by Elena Stepanova [ 2020-06-02 ]

I have a test case which causes an identical top of stack trace on 10.3+ release builds. Unfortunately, the test case is 10.3-specific, as it involves versioning. It is possible that versioning is unrelated and it just creates the right structure and sequence of events which I fail to imitate manually.

thiru, do you think it may be sharing the same cause with the originally reported failure?

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (
 
  id INT AUTO_INCREMENT,
 
  f VARCHAR(16),
 
  s TIMESTAMP,
 
  e TIMESTAMP,
 
  row_start BIGINT UNSIGNED AS ROW START,
 
  row_end BIGINT UNSIGNED AS ROW END,
 
  PRIMARY KEY(id),
 
  PERIOD FOR SYSTEM_TIME(row_start,row_end)
 
) ENGINE=InnoDB WITH SYSTEM VERSIONING;
 
BEGIN;
 
INSERT INTO t1 (s,e) VALUES
 
    ('2019-10-31','2033-03-16'),
 
    ('2006-11-18','2007-08-28'), ('2019-04-11','2023-09-02'),
 
    ('1970-07-31','2033-10-29'), ('1993-09-17','2010-12-15'),
 
    ('1973-05-03','2034-06-29'), ('2005-11-19','2034-12-08');
 
UPDATE t1 SET s = '2019-12-09', e = '2033-06-17';
 
DELETE FROM t1;
 
COMMIT;
 
FLUSH TABLES;
 
 
 
# Cleanup
 
DROP TABLE t1;

10.3 2e1d10ec -DBUILD_CONFIG=mysql_release

 
2020-06-02 15:33:12 0x7f2305d0f700  InnoDB: Assertion failure in file /data/src/10.3/storage/innobase/que/que0que.cc line 560
 
InnoDB: We intentionally generate a memory trap.
 
 
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x00007f230cb6242a in __GI_abort () at abort.c:89
 
#6  0x0000558f361a0658 in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x558f36bd8918 "/data/src/10.3/storage/innobase/que/que0que.cc", line=line@entry=560) at /data/src/10.3/storage/innobase/ut/ut0dbg.cc:60
 
#7  0x0000558f36678bd3 in que_graph_free_recursive (node=<optimized out>) at /data/src/10.3/storage/innobase/que/que0que.cc:560
 
#8  0x0000558f366ab030 in row_prebuilt_free (prebuilt=0x7f22b4068e28, dict_locked=dict_locked@entry=0) at /data/src/10.3/storage/innobase/row/row0mysql.cc:1005
 
#9  0x0000558f365d870a in ha_innobase::close (this=0x7f22b4067af0) at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:6482
 
#10 0x0000558f36322fe9 in closefrm (table=table@entry=0x7f22b4066e38) at /data/src/10.3/sql/table.cc:3660
 
#11 0x0000558f363e0b89 in intern_close_table (table=0x7f22b4066e38) at /data/src/10.3/sql/table_cache.cc:222
 
#12 tc_purge (mark_flushed=mark_flushed@entry=true) at /data/src/10.3/sql/table_cache.cc:335
 
#13 0x0000558f3621cb47 in close_cached_tables (thd=thd@entry=0x7f22b40009a8, tables=tables@entry=0x0, wait_for_refresh=wait_for_refresh@entry=true, timeout=86400) at /data/src/10.3/sql/sql_base.cc:377
 
#14 0x0000558f36371873 in reload_acl_and_cache (thd=thd@entry=0x7f22b40009a8, options=4, tables=tables@entry=0x0, write_to_binlog=write_to_binlog@entry=0x7f2305d0cfe0) at /data/src/10.3/sql/sql_reload.cc:337
 
#15 0x0000558f36278315 in mysql_execute_command (thd=thd@entry=0x7f22b40009a8) at /data/src/10.3/sql/sql_parse.cc:5367
 
#16 0x0000558f3627f57a in mysql_parse (thd=thd@entry=0x7f22b40009a8, rawbuf=<optimized out>, length=12, parser_state=parser_state@entry=0x7f2305d0e5f0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.3/sql/sql_parse.cc:7818
 
#17 0x0000558f36281192 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f22b40009a8, packet=packet@entry=0x7f22b40070c9 "FLUSH TABLES", packet_length=packet_length@entry=12, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.3/sql/sql_parse.cc:1856
 
#18 0x0000558f36282be5 in do_command (thd=0x7f22b40009a8) at /data/src/10.3/sql/sql_parse.cc:1401
 
#19 0x0000558f36357422 in do_handle_one_connection (connect=connect@entry=0x558f395320e8) at /data/src/10.3/sql/sql_connect.cc:1403
 
#20 0x0000558f3635757d in handle_one_connection (arg=arg@entry=0x558f395320e8) at /data/src/10.3/sql/sql_connect.cc:1308
 
#21 0x0000558f36958241 in pfs_spawn_thread (arg=0x558f39838248) at /data/src/10.3/storage/perfschema/pfs.cc:1869
 
#22 0x00007f230db984a4 in start_thread (arg=0x7f2305d0f700) at pthread_create.c:456
 
#23 0x00007f230cc16d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

On debug and ASAN builds it causes failures reported in MDEV-20563.

Comment by Thirunarayanan Balathandayuthapani [ 2021-04-06 ]

The Above test case in release build corrupts the upd_node_t while setting the field.
The following stack trace changes the common type from QUE_NODE_FORK to QUE_NODE_AGGREGATE.

(gdb) where
 
#0  upd_field_set_field_no (index=<optimized out>, field_no=<optimized out>, upd_field=0x7fffa40d5068)
 
    at /home/thiru/mariarepo/10.3/10.3-sample/storage/innobase/include/row0upd.ic:101
 
#1  upd_node_t::make_versioned_helper (this=this@entry=0x7fffa40d4d68, trx=trx@entry=0x7ffff01b9090, idx=<optimized out>)
 
    at /home/thiru/mariarepo/10.3/10.3-sample/storage/innobase/row/row0upd.cc:3504
 
#2  0x0000555555ee0f19 in upd_node_t::make_versioned_update (trx=0x7ffff01b9090, this=0x7fffa40d4d68)
 
    at /home/thiru/mariarepo/10.3/10.3-sample/storage/innobase/include/row0upd.h:597
 
#3  row_update_for_mysql (prebuilt=0x7fffa40d4198) at /home/thiru/mariarepo/10.3/10.3-sample/storage/innobase/row/row0mysql.cc:1879
 
#4  0x0000555555e401ab in ha_innobase::delete_row (this=0x7fffa4176060, record=0x7fffa4116eb8 "\377\a")
 
    at /home/thiru/mariarepo/10.3/10.3-sample/storage/innobase/handler/ha_innodb.cc:8955
 
#5  0x0000555555cde0f1 in handler::ha_delete_row (this=0x7fffa4176060, buf=0x7fffa4116eb8 "\377\a") at /home/thiru/mariarepo/10.3/10.3-sample/sql/handler.cc:6554
 
#6  0x0000555555de98db in mysql_delete (thd=thd@entry=0x7fffa4000c08, table_list=0x7fffa400f798, conds=<optimized out>, order_list=<optimized out>, 
    limit=18446744073709551609, options=<optimized out>, result=<optimized out>) at /home/thiru/mariarepo/10.3/10.3-sample/sql/sql_delete.cc:720
 
#7  0x0000555555b148fb in mysql_execute_command (thd=0x7fffa4000c08) at /home/thiru/mariarepo/10.3/10.3-sample/sql/sql_parse.cc:4657
 
#8  0x0000555555b15d88 in mysql_parse (thd=0x7fffa4000c08, rawbuf=<optimized out>, length=14, parser_state=0x7fffeaecd600, is_com_multi=<optimized out>, 
    is_next_command=<optimized out>) at /home/thiru/mariarepo/10.3/10.3-sample/sql/sql_parse.cc:7818
 
#9  0x0000555555b17ab5 in dispatch_command (command=COM_QUERY, thd=0x7fffa4000c08, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, 
    is_next_command=<optimized out>) at /home/thiru/mariarepo/10.3/10.3-sample/sql/sql_class.h:1137
 
#10 0x0000555555b19106 in do_command (thd=0x7fffa4000c08) at /home/thiru/mariarepo/10.3/10.3-sample/sql/sql_parse.cc:1401
 
#11 0x0000555555be4d64 in do_handle_one_connection (connect=connect@entry=0x55555776af98) at /home/thiru/mariarepo/10.3/10.3-sample/sql/sql_connect.cc:1403
 
#12 0x0000555555be4ef4 in handle_one_connection (arg=arg@entry=0x55555776af98) at /home/thiru/mariarepo/10.3/10.3-sample/sql/sql_connect.cc:1308
 
#13 0x0000555556102e5f in pfs_spawn_thread (arg=0x5555577e6578) at /home/thiru/mariarepo/10.3/10.3-sample/storage/perfschema/pfs.cc:1869
 
#14 0x00007ffff687a6db in start_thread (arg=0x7fffeaece700) at pthread_create.c:463
 
#15 0x00007ffff5c1971f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

In debug build, this corruption was stopped by the debug assert

25
 
        /* row_create_update_node_for_mysql() pre-allocated this much.
 
           At least one PK column always remains unchanged. */
 
        ut_ad(update->n_fields < ulint(table->n_cols + table->n_v_cols));
 
        update->n_fields++;
 
        upd_field_t* ufield = upd_get_nth_field(update, update->n_fields - 1);
 
        const dict_col_t* col = dict_table_get_nth_col(table, idx);
 
        upd_field_set_field_no(ufield, dict_col_get_clust_pos(col, clust_index),
 
                               clust_index);

The Above test case issue is solved by MDEV-22061. Reported issue could have different
root cause then the given test case.

Comment by Thirunarayanan Balathandayuthapani [ 2021-04-06 ]

10.1 is already EOL

Comment by Marko Mäkelä [ 2021-04-06 ]

Thank you, thiru! It turns out that the 10.3 specific breakage was something else (MDEV-22061).

When it comes to the originally reported failure, that custom build (bb-10.2-compatibility) definitely did not support system-versioned tables. I have one more idea as to the root cause: MDEV-12023. Without having access to an old data directory that caused the problem on upgrade, it is virtually impossible to guess what might have gone wrong, or whether such upgrade problems still exist.

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