[MDEV-15949] InnoDB: Failing assertion: space->n_pending_ops == 0 in fil_delete_tablespace upon DROP TABLE - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Won't Fix
Affects Version/s: 10.2(EOL), 10.3(EOL)
Fix Version/s: 10.5.2
Component/s: Locking, Storage Engine - InnoDB
Labels:
- need_rr

Description

Note: The problem was initially observed on 10.3, but the test below only reproduces it on 10.2, but not on 10.3 (neither on the current branch, nor on the revision bb5f4967 where it was first observed, and stack trace from which is attached). It doesn't mean that it doesn't exist there, the failure is generally poorly reproducible, that's why the duration in the command line is so high. Currently for me it usually takes 10-20 minutes, but sometimes it can be hours. I suppose it can also vary a lot, depending on the build and the machine.

10.2 f127fb98
2019-11-13 18:21:52 0x7f5d80312700 InnoDB: Assertion failure in file /data/src/10.2/storage/innobase/fil/fil0fil.cc line 2956
InnoDB: Failing assertion: space->n_pending_ops == 0

#6 0x000055c8fc37c982 in ut_dbg_assertion_failed (expr=0x55c8fc99d539 "space->n_pending_ops == 0", file=0x55c8fc99c0a8 "/data/src/10.2/storage/innobase/fil/fil0fil.cc", line=2956) at /data/src/10.2/storage/innobase/ut/ut0dbg.cc:60
#7 0x000055c8fc465625 in fil_delete_tablespace (id=10643, drop_ahi=false) at /data/src/10.2/storage/innobase/fil/fil0fil.cc:2956
#8 0x000055c8fc2b2c34 in row_drop_single_table_tablespace (space_id=10643, tablename=0x7f5d0c0fa888 "test/t8464", filepath=0x7f5d0c0605b0 "./test/t8464.ibd", table_flags=33) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3231
#9 0x000055c8fc2b3f36 in row_drop_table_for_mysql (name=0x7f5d8030e820 "test/t8464", trx=0x7f5d807995e0, sqlcom=SQLCOM_DROP_TABLE, create_failed=false, nonatomic=true) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3737
#10 0x000055c8fc190a56 in ha_innobase::delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464", sqlcom=SQLCOM_DROP_TABLE) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13158
#11 0x000055c8fc17b3e8 in ha_innobase::delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13283
#12 0x000055c8fbf6a6dc in handler::ha_delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464") at /data/src/10.2/sql/handler.cc:4454
#13 0x000055c8fbf64f2e in ha_delete_table (thd=0x7f5d0c000af0, table_type=0x55c8fe3078b0, path=0x7f5d80310390 "./test/t8464", db=0x7f5d0c011748 "test", alias=0x7f5d0c0110f8 "t8464", generate_warning=true) at /data/src/10.2/sql/handler.cc:2436
#14 0x000055c8fbda5bf0 in mysql_rm_table_no_locks (thd=0x7f5d0c000af0, tables=0x7f5d0c011130, if_exists=false, drop_temporary=false, drop_view=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.2/sql/sql_table.cc:2447
#15 0x000055c8fbda4eed in mysql_rm_table (thd=0x7f5d0c000af0, tables=0x7f5d0c011130, if_exists=0 '\000', drop_temporary=0 '\000') at /data/src/10.2/sql/sql_table.cc:2089
#16 0x000055c8fbce3988 in mysql_execute_command (thd=0x7f5d0c000af0) at /data/src/10.2/sql/sql_parse.cc:4506
#17 0x000055c8fbcedd3e in mysql_parse (thd=0x7f5d0c000af0, rawbuf=0x7f5d0c011028 "DROP TABLE t8464 /* QNO 13016 CON_ID 14 */", length=42, parser_state=0x7f5d80311250, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7740
#18 0x000055c8fbcdc059 in dispatch_command (command=COM_QUERY, thd=0x7f5d0c000af0, packet=0x7f5d0c0087b1 " DROP TABLE t8464 /* QNO 13016 CON_ID 14 */ ", packet_length=44, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1831
#19 0x000055c8fbcda9ad in do_command (thd=0x7f5d0c000af0) at /data/src/10.2/sql/sql_parse.cc:1384
#20 0x000055c8fbe30075 in do_handle_one_connection (connect=0x55c8fec64ce0) at /data/src/10.2/sql/sql_connect.cc:1336
#21 0x000055c8fbe2fde0 in handle_one_connection (arg=0x55c8fec64ce0) at /data/src/10.2/sql/sql_connect.cc:1241
#22 0x00007f5d846914a4 in start_thread (arg=0x7f5d80312700) at pthread_create.c:456
#23 0x00007f5d82bd8d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Query (0x7f5d0c011028): DROP TABLE t8464 /* QNO 13016 CON_ID 14 */
Connection ID (thread ID): 14
Status: NOT_KILLED

RQG grammar pending_ops.yy
query_init:
{ $tname= 't'.abs($$); '' } ;

query:
CREATE TABLE $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit
; INSERT INTO $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit
; DELETE FROM $tname
; REPLACE INTO $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit
; DROP TABLE $tname
;

Command line
perl runall-new.pl --basedir=<your basedir> --grammar=pending_ops.yy --duration=14400 --threads=4 --vardir=/dev/shm//var_pending --skip-gendata --reporters=Backtrace,ErrorLog

Remember to set the correct basedir.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

threads
2018-04-20 12:38
64 kB
Elena Stepanova

Issue Links

relates to

MDEV-8139 Fix scrubbing

Closed

MDEV-15528 Avoid writing freed InnoDB pages

Closed

MDEV-23651 InnoDB: Failing assertion: !space->referenced() on DROP TABLE

Closed

MDEV-23855 InnoDB log checkpointing causes regression for write-heavy OLTP

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova created issue - 2018-04-20 12:38

Elena Stepanova made changes - 2018-06-28 14:36

Field	Original Value	New Value
Affects Version/s		10.2 [ 14601 ]

Elena Stepanova made changes - 2019-11-12 12:31

Summary

[Draft] InnoDB: Failing assertion: space->n_pending_ops == 0

InnoDB: Failing assertion: space->n_pending_ops == 0

Elena Stepanova made changes - 2019-11-12 12:31

Summary

InnoDB: Failing assertion: space->n_pending_ops == 0

InnoDB: Failing assertion: space->n_pending_ops == 0 in fil_delete_tablespace upon DROP TABLE

Elena Stepanova made changes - 2019-11-12 12:33

Description

https://api.travis-ci.org/v3/job/367445034/log.txt
{noformat:title=10.3 bb5f4967f54d3f458bec86fb1845405a0a88bc0f}
2018-04-18 02:44:49 0x7fbfb8246700 InnoDB: Assertion failure in file /home/travis/src/storage/innobase/fil/fil0fil.cc line 2760
InnoDB: Failing assertion: space->n_pending_ops == 0

Query (0x7fbf8001fa98): DROP TABLE transforms.insert_select_24840 /* QNO 9705 CON_ID 17 */
Connection ID (thread ID): 17
Status: NOT_KILLED
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
{noformat}
{noformat}
#5 0x00007fbfcdd07028 in __GI_abort () at abort.c:89
#6 0x00005565fc26f2b3 in ut_dbg_assertion_failed (expr=0x5565fc964131 "space->n_pending_ops == 0", file=0x5565fc962e00 "/home/travis/src/storage/innobase/fil/fil0fil.cc", line=2760) at /home/travis/src/storage/innobase/ut/ut0dbg.cc:61
#7 0x00005565fc36b922 in fil_delete_tablespace (id=2315, drop_ahi=false) at /home/travis/src/storage/innobase/fil/fil0fil.cc:2760
#8 0x00005565fc19f3fa in row_drop_table_for_mysql (name=0x7fbfb8242550 "transforms/insert_select_24840", trx=0x7fbfcc0dd038, drop_db=false, create_failed=0, nonatomic=true) at /home/travis/src/storage/innobase/row/row0mysql.cc:3868
#9 0x00005565fc04e67c in ha_innobase::delete_table (this=0x7fbf80020480, name=0x7fbfb8244130 "./transforms/insert_select_24840") at /home/travis/src/storage/innobase/handler/ha_innodb.cc:12979
#10 0x00005565fbe3a258 in handler::ha_delete_table (this=0x7fbf80020480, name=0x7fbfb8244130 "./transforms/insert_select_24840") at /home/travis/src/sql/handler.cc:4522
#11 0x00005565fbe3444b in ha_delete_table (thd=0x7fbf8000b390, table_type=0x5565fdc180c0, path=0x7fbfb8244130 "./transforms/insert_select_24840", db=0x7fbfb8243dc0, alias=0x7fbf8001fc28, generate_warning=true) at /home/travis/src/sql/handler.cc:2528
#12 0x00005565fbc10828 in mysql_rm_table_no_locks (thd=0x7fbf8000b390, tables=0x7fbf8001fc00, if_exists=false, drop_temporary=false, drop_view=false, drop_sequence=false, dont_log_query=false, dont_free_locks=false) at /home/travis/src/sql/sql_table.cc:2513
#13 0x00005565fbc0f83f in mysql_rm_table (thd=0x7fbf8000b390, tables=0x7fbf8001fc00, if_exists=false, drop_temporary=false, drop_sequence=false) at /home/travis/src/sql/sql_table.cc:2127
#14 0x00005565fbb4c84c in mysql_execute_command (thd=0x7fbf8000b390) at /home/travis/src/sql/sql_parse.cc:5050
#15 0x00005565fbb55a0a in mysql_parse (thd=0x7fbf8000b390, rawbuf=0x7fbf8001fa98 "DROP TABLE transforms.insert_select_24840 /* QNO 9705 CON_ID 17 */", length=66, parser_state=0x7fbfb82455e0, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8001
#16 0x00005565fbb4322e in dispatch_command (command=COM_QUERY, thd=0x7fbf8000b390, packet=0x7fbf800176e1 "DROP TABLE transforms.insert_select_24840 /* QNO 9705 CON_ID 17 */ ", packet_length=67, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1846
#17 0x00005565fbb41c7a in do_command (thd=0x7fbf8000b390) at /home/travis/src/sql/sql_parse.cc:1391
#18 0x00005565fbca54cd in do_handle_one_connection (connect=0x5565fe808ff0) at /home/travis/src/sql/sql_connect.cc:1402
#19 0x00005565fbca525a in handle_one_connection (arg=0x5565fe808ff0) at /home/travis/src/sql/sql_connect.cc:1308
#20 0x00007fbfce8be184 in start_thread (arg=0x7fbfb8246700) at pthread_create.c:312
#21 0x00007fbfcddcb03d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
{noformat}

{noformat:title=experimental 4feb78e17fbecf7fc7f2847b49b8c66b54879629}
perl /home/travis/rqg/runall-new.pl --duration=350 --threads=6 --seed=1524019227 --reporters=Backtrace,ErrorLog,Deadlock --validators=TransformerNoComparator --views --redefine=conf/mariadb/versioning.yy --redefine=conf/mariadb/alter_table.yy --redefine=conf/mariadb/bulk_insert.yy --redefine=conf/mariadb/sequences.yy --basedir=/home/travis/server --mysqld=--log_output=FILE --mysqld=--max-statement-time=30 --mysqld=--lock-wait-timeout=10 --mysqld=--loose-innodb-lock-wait-timeout=5 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --grammar=conf/runtime/information_schema.yy --transformers=ExecuteAsCTE,ExecuteAsDeleteReturning,ExecuteAsExcept,ExecuteAsExecuteImmediate,ExecuteAsInsertSelect,ExecuteAsIntersect,ExecuteAsUnion,ExecuteAsUpdateDelete,ExecuteAsView,ExecuteAsPreparedTwice,ExecuteAsSPTwice --vardir=/home/travis/logs/vardir1_1
{noformat}

{noformat:title=10.3 bb5f4967f54d3f458bec86fb1845405a0a88bc0f}
2018-04-18 02:44:49 0x7fbfb8246700 InnoDB: Assertion failure in file /home/travis/src/storage/innobase/fil/fil0fil.cc line 2760
InnoDB: Failing assertion: space->n_pending_ops == 0

Query (0x7fbf8001fa98): DROP TABLE transforms.insert_select_24840 /* QNO 9705 CON_ID 17 */
Connection ID (thread ID): 17
Status: NOT_KILLED
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
{noformat}
{noformat}
#5 0x00007fbfcdd07028 in __GI_abort () at abort.c:89
#6 0x00005565fc26f2b3 in ut_dbg_assertion_failed (expr=0x5565fc964131 "space->n_pending_ops == 0", file=0x5565fc962e00 "/home/travis/src/storage/innobase/fil/fil0fil.cc", line=2760) at /home/travis/src/storage/innobase/ut/ut0dbg.cc:61
#7 0x00005565fc36b922 in fil_delete_tablespace (id=2315, drop_ahi=false) at /home/travis/src/storage/innobase/fil/fil0fil.cc:2760
#8 0x00005565fc19f3fa in row_drop_table_for_mysql (name=0x7fbfb8242550 "transforms/insert_select_24840", trx=0x7fbfcc0dd038, drop_db=false, create_failed=0, nonatomic=true) at /home/travis/src/storage/innobase/row/row0mysql.cc:3868
#9 0x00005565fc04e67c in ha_innobase::delete_table (this=0x7fbf80020480, name=0x7fbfb8244130 "./transforms/insert_select_24840") at /home/travis/src/storage/innobase/handler/ha_innodb.cc:12979
#10 0x00005565fbe3a258 in handler::ha_delete_table (this=0x7fbf80020480, name=0x7fbfb8244130 "./transforms/insert_select_24840") at /home/travis/src/sql/handler.cc:4522
#11 0x00005565fbe3444b in ha_delete_table (thd=0x7fbf8000b390, table_type=0x5565fdc180c0, path=0x7fbfb8244130 "./transforms/insert_select_24840", db=0x7fbfb8243dc0, alias=0x7fbf8001fc28, generate_warning=true) at /home/travis/src/sql/handler.cc:2528
#12 0x00005565fbc10828 in mysql_rm_table_no_locks (thd=0x7fbf8000b390, tables=0x7fbf8001fc00, if_exists=false, drop_temporary=false, drop_view=false, drop_sequence=false, dont_log_query=false, dont_free_locks=false) at /home/travis/src/sql/sql_table.cc:2513
#13 0x00005565fbc0f83f in mysql_rm_table (thd=0x7fbf8000b390, tables=0x7fbf8001fc00, if_exists=false, drop_temporary=false, drop_sequence=false) at /home/travis/src/sql/sql_table.cc:2127
#14 0x00005565fbb4c84c in mysql_execute_command (thd=0x7fbf8000b390) at /home/travis/src/sql/sql_parse.cc:5050
#15 0x00005565fbb55a0a in mysql_parse (thd=0x7fbf8000b390, rawbuf=0x7fbf8001fa98 "DROP TABLE transforms.insert_select_24840 /* QNO 9705 CON_ID 17 */", length=66, parser_state=0x7fbfb82455e0, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8001
#16 0x00005565fbb4322e in dispatch_command (command=COM_QUERY, thd=0x7fbf8000b390, packet=0x7fbf800176e1 "DROP TABLE transforms.insert_select_24840 /* QNO 9705 CON_ID 17 */ ", packet_length=67, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1846
#17 0x00005565fbb41c7a in do_command (thd=0x7fbf8000b390) at /home/travis/src/sql/sql_parse.cc:1391
#18 0x00005565fbca54cd in do_handle_one_connection (connect=0x5565fe808ff0) at /home/travis/src/sql/sql_connect.cc:1402
#19 0x00005565fbca525a in handle_one_connection (arg=0x5565fe808ff0) at /home/travis/src/sql/sql_connect.cc:1308
#20 0x00007fbfce8be184 in start_thread (arg=0x7fbfb8246700) at pthread_create.c:312
#21 0x00007fbfcddcb03d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
{noformat}

{noformat}
query:
      CREATE TABLE { 'insert_select_'.$$ } SELECT * FROM { $last_database = 'INFORMATION_SCHEMA' } . _table LIMIT _digit
    ; INSERT INTO { 'insert_select_'.$$ } SELECT * FROM INFORMATION_SCHEMA.{ $last_table } LIMIT _digit
    ; DELETE FROM { 'insert_select_'.$$ }
    ; REPLACE INTO { 'insert_select_'.$$ } SELECT * FROM INFORMATION_SCHEMA.{ $last_table } LIMIT _digit
    ; DROP TABLE { 'insert_select_'.$$ }
;
{noformat}
{noformat:title=rqg-ment 3dcb1063}
perl runall-new.pl --grammar=/archive/to_process/pending_ops2.yy --duration=14400 --threads=4 --vardir=/home/elenst/logs/pending51 --skip-gendata --basedir=/data/bld/10.2-enterprise-debug --reporters=Backtrace,ErrorLog
{noformat}

Elena Stepanova made changes - 2019-11-13 17:40

Component/s		Locking [ 10900 ]
Fix Version/s		10.2 [ 14601 ]
Fix Version/s		10.3 [ 22126 ]
Assignee	Elena Stepanova [ elenst ]	Sergey Vojtovich [ svoj ]
Description	{noformat:title=10.3 bb5f4967f54d3f458bec86fb1845405a0a88bc0f} 2018-04-18 02:44:49 0x7fbfb8246700 InnoDB: Assertion failure in file /home/travis/src/storage/innobase/fil/fil0fil.cc line 2760 InnoDB: Failing assertion: space->n_pending_ops == 0 Query (0x7fbf8001fa98): DROP TABLE transforms.insert_select_24840 /* QNO 9705 CON_ID 17 / Connection ID (thread ID): 17 Status: NOT_KILLED Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on {noformat} {noformat} #5 0x00007fbfcdd07028 in __GI_abort () at abort.c:89 #6 0x00005565fc26f2b3 in ut_dbg_assertion_failed (expr=0x5565fc964131 "space->n_pending_ops == 0", file=0x5565fc962e00 "/home/travis/src/storage/innobase/fil/fil0fil.cc", line=2760) at /home/travis/src/storage/innobase/ut/ut0dbg.cc:61 #7 0x00005565fc36b922 in fil_delete_tablespace (id=2315, drop_ahi=false) at /home/travis/src/storage/innobase/fil/fil0fil.cc:2760 #8 0x00005565fc19f3fa in row_drop_table_for_mysql (name=0x7fbfb8242550 "transforms/insert_select_24840", trx=0x7fbfcc0dd038, drop_db=false, create_failed=0, nonatomic=true) at /home/travis/src/storage/innobase/row/row0mysql.cc:3868 #9 0x00005565fc04e67c in ha_innobase::delete_table (this=0x7fbf80020480, name=0x7fbfb8244130 "./transforms/insert_select_24840") at /home/travis/src/storage/innobase/handler/ha_innodb.cc:12979 #10 0x00005565fbe3a258 in handler::ha_delete_table (this=0x7fbf80020480, name=0x7fbfb8244130 "./transforms/insert_select_24840") at /home/travis/src/sql/handler.cc:4522 #11 0x00005565fbe3444b in ha_delete_table (thd=0x7fbf8000b390, table_type=0x5565fdc180c0, path=0x7fbfb8244130 "./transforms/insert_select_24840", db=0x7fbfb8243dc0, alias=0x7fbf8001fc28, generate_warning=true) at /home/travis/src/sql/handler.cc:2528 #12 0x00005565fbc10828 in mysql_rm_table_no_locks (thd=0x7fbf8000b390, tables=0x7fbf8001fc00, if_exists=false, drop_temporary=false, drop_view=false, drop_sequence=false, dont_log_query=false, dont_free_locks=false) at /home/travis/src/sql/sql_table.cc:2513 #13 0x00005565fbc0f83f in mysql_rm_table (thd=0x7fbf8000b390, tables=0x7fbf8001fc00, if_exists=false, drop_temporary=false, drop_sequence=false) at /home/travis/src/sql/sql_table.cc:2127 #14 0x00005565fbb4c84c in mysql_execute_command (thd=0x7fbf8000b390) at /home/travis/src/sql/sql_parse.cc:5050 #15 0x00005565fbb55a0a in mysql_parse (thd=0x7fbf8000b390, rawbuf=0x7fbf8001fa98 "DROP TABLE transforms.insert_select_24840 / QNO 9705 CON_ID 17 /", length=66, parser_state=0x7fbfb82455e0, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8001 #16 0x00005565fbb4322e in dispatch_command (command=COM_QUERY, thd=0x7fbf8000b390, packet=0x7fbf800176e1 "DROP TABLE transforms.insert_select_24840 / QNO 9705 CON_ID 17 / ", packet_length=67, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1846 #17 0x00005565fbb41c7a in do_command (thd=0x7fbf8000b390) at /home/travis/src/sql/sql_parse.cc:1391 #18 0x00005565fbca54cd in do_handle_one_connection (connect=0x5565fe808ff0) at /home/travis/src/sql/sql_connect.cc:1402 #19 0x00005565fbca525a in handle_one_connection (arg=0x5565fe808ff0) at /home/travis/src/sql/sql_connect.cc:1308 #20 0x00007fbfce8be184 in start_thread (arg=0x7fbfb8246700) at pthread_create.c:312 #21 0x00007fbfcddcb03d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111 {noformat} {noformat} query: CREATE TABLE { 'insert_select_'.$$ } SELECT FROM { $last_database = 'INFORMATION_SCHEMA' } . _table LIMIT _digit ; INSERT INTO { 'insert_select_'.$$ } SELECT * FROM INFORMATION_SCHEMA.{ $last_table } LIMIT _digit ; DELETE FROM { 'insert_select_'.$$ } ; REPLACE INTO { 'insert_select_'.$$ } SELECT * FROM INFORMATION_SCHEMA.{ $last_table } LIMIT _digit ; DROP TABLE { 'insert_select_'.$$ } ; {noformat} {noformat:title=rqg-ment 3dcb1063} perl runall-new.pl --grammar=/archive/to_process/pending_ops2.yy --duration=14400 --threads=4 --vardir=/home/elenst/logs/pending51 --skip-gendata --basedir=/data/bld/10.2-enterprise-debug --reporters=Backtrace,ErrorLog {noformat}	_Note: The problem was initially observed on 10.3, but the test below only reproduces it on 10.2, but not on 10.3 (neither on the current branch, nor on the revision where it was first observed). It doesn't mean that it doesn't exist there, the failure is generally poorly reproducible, that's why the duration in the command line is so high. Currently for me it usually takes 10-20 minutes, but sometimes it can be hours. I suppose it can also vary a lot, depending on the build and the machine._ {noformat:title=10.2 f127fb98} 2019-11-13 18:21:52 0x7f5d80312700 InnoDB: Assertion failure in file /data/src/10.2/storage/innobase/fil/fil0fil.cc line 2956 InnoDB: Failing assertion: space->n_pending_ops == 0 #6 0x000055c8fc37c982 in ut_dbg_assertion_failed (expr=0x55c8fc99d539 "space->n_pending_ops == 0", file=0x55c8fc99c0a8 "/data/src/10.2/storage/innobase/fil/fil0fil.cc", line=2956) at /data/src/10.2/storage/innobase/ut/ut0dbg.cc:60 #7 0x000055c8fc465625 in fil_delete_tablespace (id=10643, drop_ahi=false) at /data/src/10.2/storage/innobase/fil/fil0fil.cc:2956 #8 0x000055c8fc2b2c34 in row_drop_single_table_tablespace (space_id=10643, tablename=0x7f5d0c0fa888 "test/t8464", filepath=0x7f5d0c0605b0 "./test/t8464.ibd", table_flags=33) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3231 #9 0x000055c8fc2b3f36 in row_drop_table_for_mysql (name=0x7f5d8030e820 "test/t8464", trx=0x7f5d807995e0, sqlcom=SQLCOM_DROP_TABLE, create_failed=false, nonatomic=true) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3737 #10 0x000055c8fc190a56 in ha_innobase::delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464", sqlcom=SQLCOM_DROP_TABLE) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13158 #11 0x000055c8fc17b3e8 in ha_innobase::delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13283 #12 0x000055c8fbf6a6dc in handler::ha_delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464") at /data/src/10.2/sql/handler.cc:4454 #13 0x000055c8fbf64f2e in ha_delete_table (thd=0x7f5d0c000af0, table_type=0x55c8fe3078b0, path=0x7f5d80310390 "./test/t8464", db=0x7f5d0c011748 "test", alias=0x7f5d0c0110f8 "t8464", generate_warning=true) at /data/src/10.2/sql/handler.cc:2436 #14 0x000055c8fbda5bf0 in mysql_rm_table_no_locks (thd=0x7f5d0c000af0, tables=0x7f5d0c011130, if_exists=false, drop_temporary=false, drop_view=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.2/sql/sql_table.cc:2447 #15 0x000055c8fbda4eed in mysql_rm_table (thd=0x7f5d0c000af0, tables=0x7f5d0c011130, if_exists=0 '\000', drop_temporary=0 '\000') at /data/src/10.2/sql/sql_table.cc:2089 #16 0x000055c8fbce3988 in mysql_execute_command (thd=0x7f5d0c000af0) at /data/src/10.2/sql/sql_parse.cc:4506 #17 0x000055c8fbcedd3e in mysql_parse (thd=0x7f5d0c000af0, rawbuf=0x7f5d0c011028 "DROP TABLE t8464 /* QNO 13016 CON_ID 14 /", length=42, parser_state=0x7f5d80311250, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7740 #18 0x000055c8fbcdc059 in dispatch_command (command=COM_QUERY, thd=0x7f5d0c000af0, packet=0x7f5d0c0087b1 " DROP TABLE t8464 / QNO 13016 CON_ID 14 / ", packet_length=44, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1831 #19 0x000055c8fbcda9ad in do_command (thd=0x7f5d0c000af0) at /data/src/10.2/sql/sql_parse.cc:1384 #20 0x000055c8fbe30075 in do_handle_one_connection (connect=0x55c8fec64ce0) at /data/src/10.2/sql/sql_connect.cc:1336 #21 0x000055c8fbe2fde0 in handle_one_connection (arg=0x55c8fec64ce0) at /data/src/10.2/sql/sql_connect.cc:1241 #22 0x00007f5d846914a4 in start_thread (arg=0x7f5d80312700) at pthread_create.c:456 #23 0x00007f5d82bd8d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97 Query (0x7f5d0c011028): DROP TABLE t8464 / QNO 13016 CON_ID 14 / Connection ID (thread ID): 14 Status: NOT_KILLED {noformat} {noformat:title=RQG grammar pending_ops.yy} query_init: { $tname= 't'.abs($$); '' } ; query: CREATE TABLE $tname SELECT FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit ; INSERT INTO $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit ; DELETE FROM $tname ; REPLACE INTO $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit ; DROP TABLE $tname ; {noformat} {noformat:title=Command line} perl runall-new.pl --basedir=<your basedir> --grammar=pending_ops.yy --duration=14400 --threads=4 --vardir=/dev/shm//var_pending --skip-gendata --reporters=Backtrace,ErrorLog {noformat} Remember to set the correct basedir.

Elena Stepanova made changes - 2019-11-13 17:41

Comment

[ On 10.2:
https://travis-ci.org/elenst/travis-tests/jobs/397574265 ]

Elena Stepanova made changes - 2019-11-13 17:41

Comment

[ New occurrence on 10.2:
https://travis-ci.org/elenst/travis-tests/jobs/405581556
1324,3,3
Server: 10.2 9827c5e1031ca5ebe1c6c7d4f5eac3cce5749d8e

For this, datadir, coredump etc. are available, should anyone want to try solve it by the coredump alone. ]

Elena Stepanova made changes - 2019-11-13 17:43

Description

_Note: The problem was initially observed on 10.3, but the test below only reproduces it on 10.2, but not on 10.3 (neither on the current branch, nor on the revision where it was first observed). It doesn't mean that it doesn't exist there, the failure is generally poorly reproducible, that's why the duration in the command line is so high. Currently for me it usually takes 10-20 minutes, but sometimes it can be hours. I suppose it can also vary a lot, depending on the build and the machine._

{noformat:title=10.2 f127fb98}
2019-11-13 18:21:52 0x7f5d80312700 InnoDB: Assertion failure in file /data/src/10.2/storage/innobase/fil/fil0fil.cc line 2956
InnoDB: Failing assertion: space->n_pending_ops == 0

#6 0x000055c8fc37c982 in ut_dbg_assertion_failed (expr=0x55c8fc99d539 "space->n_pending_ops == 0", file=0x55c8fc99c0a8 "/data/src/10.2/storage/innobase/fil/fil0fil.cc", line=2956) at /data/src/10.2/storage/innobase/ut/ut0dbg.cc:60
#7 0x000055c8fc465625 in fil_delete_tablespace (id=10643, drop_ahi=false) at /data/src/10.2/storage/innobase/fil/fil0fil.cc:2956
#8 0x000055c8fc2b2c34 in row_drop_single_table_tablespace (space_id=10643, tablename=0x7f5d0c0fa888 "test/t8464", filepath=0x7f5d0c0605b0 "./test/t8464.ibd", table_flags=33) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3231
#9 0x000055c8fc2b3f36 in row_drop_table_for_mysql (name=0x7f5d8030e820 "test/t8464", trx=0x7f5d807995e0, sqlcom=SQLCOM_DROP_TABLE, create_failed=false, nonatomic=true) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3737
#10 0x000055c8fc190a56 in ha_innobase::delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464", sqlcom=SQLCOM_DROP_TABLE) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13158
#11 0x000055c8fc17b3e8 in ha_innobase::delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13283
#12 0x000055c8fbf6a6dc in handler::ha_delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464") at /data/src/10.2/sql/handler.cc:4454
#13 0x000055c8fbf64f2e in ha_delete_table (thd=0x7f5d0c000af0, table_type=0x55c8fe3078b0, path=0x7f5d80310390 "./test/t8464", db=0x7f5d0c011748 "test", alias=0x7f5d0c0110f8 "t8464", generate_warning=true) at /data/src/10.2/sql/handler.cc:2436
#14 0x000055c8fbda5bf0 in mysql_rm_table_no_locks (thd=0x7f5d0c000af0, tables=0x7f5d0c011130, if_exists=false, drop_temporary=false, drop_view=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.2/sql/sql_table.cc:2447
#15 0x000055c8fbda4eed in mysql_rm_table (thd=0x7f5d0c000af0, tables=0x7f5d0c011130, if_exists=0 '\000', drop_temporary=0 '\000') at /data/src/10.2/sql/sql_table.cc:2089
#16 0x000055c8fbce3988 in mysql_execute_command (thd=0x7f5d0c000af0) at /data/src/10.2/sql/sql_parse.cc:4506
#17 0x000055c8fbcedd3e in mysql_parse (thd=0x7f5d0c000af0, rawbuf=0x7f5d0c011028 "DROP TABLE t8464 /* QNO 13016 CON_ID 14 */", length=42, parser_state=0x7f5d80311250, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7740
#18 0x000055c8fbcdc059 in dispatch_command (command=COM_QUERY, thd=0x7f5d0c000af0, packet=0x7f5d0c0087b1 " DROP TABLE t8464 /* QNO 13016 CON_ID 14 */ ", packet_length=44, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1831
#19 0x000055c8fbcda9ad in do_command (thd=0x7f5d0c000af0) at /data/src/10.2/sql/sql_parse.cc:1384
#20 0x000055c8fbe30075 in do_handle_one_connection (connect=0x55c8fec64ce0) at /data/src/10.2/sql/sql_connect.cc:1336
#21 0x000055c8fbe2fde0 in handle_one_connection (arg=0x55c8fec64ce0) at /data/src/10.2/sql/sql_connect.cc:1241
#22 0x00007f5d846914a4 in start_thread (arg=0x7f5d80312700) at pthread_create.c:456
#23 0x00007f5d82bd8d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Query (0x7f5d0c011028): DROP TABLE t8464 /* QNO 13016 CON_ID 14 */
Connection ID (thread ID): 14
Status: NOT_KILLED
{noformat}

{noformat:title=RQG grammar pending_ops.yy}
query_init:
    { $tname= 't'.abs($$); '' } ;

query:
      CREATE TABLE $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit
    ; INSERT INTO $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit
    ; DELETE FROM $tname
    ; REPLACE INTO $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit
    ; DROP TABLE $tname
;
{noformat}

{noformat:title=Command line}
perl runall-new.pl --basedir=<your basedir> --grammar=pending_ops.yy --duration=14400 --threads=4 --vardir=/dev/shm//var_pending --skip-gendata --reporters=Backtrace,ErrorLog
{noformat}
*Remember to set the correct basedir.*

_Note: The problem was initially observed on 10.3, but the test below only reproduces it on 10.2, but not on 10.3 (neither on the current branch, nor on the revision bb5f4967 where it was first observed, and stack trace from which is attached). It doesn't mean that it doesn't exist there, the failure is generally poorly reproducible, that's why the duration in the command line is so high. Currently for me it usually takes 10-20 minutes, but sometimes it can be hours. I suppose it can also vary a lot, depending on the build and the machine._

{noformat:title=10.2 f127fb98}
2019-11-13 18:21:52 0x7f5d80312700 InnoDB: Assertion failure in file /data/src/10.2/storage/innobase/fil/fil0fil.cc line 2956
InnoDB: Failing assertion: space->n_pending_ops == 0

#6 0x000055c8fc37c982 in ut_dbg_assertion_failed (expr=0x55c8fc99d539 "space->n_pending_ops == 0", file=0x55c8fc99c0a8 "/data/src/10.2/storage/innobase/fil/fil0fil.cc", line=2956) at /data/src/10.2/storage/innobase/ut/ut0dbg.cc:60
#7 0x000055c8fc465625 in fil_delete_tablespace (id=10643, drop_ahi=false) at /data/src/10.2/storage/innobase/fil/fil0fil.cc:2956
#8 0x000055c8fc2b2c34 in row_drop_single_table_tablespace (space_id=10643, tablename=0x7f5d0c0fa888 "test/t8464", filepath=0x7f5d0c0605b0 "./test/t8464.ibd", table_flags=33) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3231
#9 0x000055c8fc2b3f36 in row_drop_table_for_mysql (name=0x7f5d8030e820 "test/t8464", trx=0x7f5d807995e0, sqlcom=SQLCOM_DROP_TABLE, create_failed=false, nonatomic=true) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3737
#10 0x000055c8fc190a56 in ha_innobase::delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464", sqlcom=SQLCOM_DROP_TABLE) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13158
#11 0x000055c8fc17b3e8 in ha_innobase::delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13283
#12 0x000055c8fbf6a6dc in handler::ha_delete_table (this=0x7f5d0c011978, name=0x7f5d80310390 "./test/t8464") at /data/src/10.2/sql/handler.cc:4454
#13 0x000055c8fbf64f2e in ha_delete_table (thd=0x7f5d0c000af0, table_type=0x55c8fe3078b0, path=0x7f5d80310390 "./test/t8464", db=0x7f5d0c011748 "test", alias=0x7f5d0c0110f8 "t8464", generate_warning=true) at /data/src/10.2/sql/handler.cc:2436
#14 0x000055c8fbda5bf0 in mysql_rm_table_no_locks (thd=0x7f5d0c000af0, tables=0x7f5d0c011130, if_exists=false, drop_temporary=false, drop_view=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.2/sql/sql_table.cc:2447
#15 0x000055c8fbda4eed in mysql_rm_table (thd=0x7f5d0c000af0, tables=0x7f5d0c011130, if_exists=0 '\000', drop_temporary=0 '\000') at /data/src/10.2/sql/sql_table.cc:2089
#16 0x000055c8fbce3988 in mysql_execute_command (thd=0x7f5d0c000af0) at /data/src/10.2/sql/sql_parse.cc:4506
#17 0x000055c8fbcedd3e in mysql_parse (thd=0x7f5d0c000af0, rawbuf=0x7f5d0c011028 "DROP TABLE t8464 /* QNO 13016 CON_ID 14 */", length=42, parser_state=0x7f5d80311250, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7740
#18 0x000055c8fbcdc059 in dispatch_command (command=COM_QUERY, thd=0x7f5d0c000af0, packet=0x7f5d0c0087b1 " DROP TABLE t8464 /* QNO 13016 CON_ID 14 */ ", packet_length=44, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1831
#19 0x000055c8fbcda9ad in do_command (thd=0x7f5d0c000af0) at /data/src/10.2/sql/sql_parse.cc:1384
#20 0x000055c8fbe30075 in do_handle_one_connection (connect=0x55c8fec64ce0) at /data/src/10.2/sql/sql_connect.cc:1336
#21 0x000055c8fbe2fde0 in handle_one_connection (arg=0x55c8fec64ce0) at /data/src/10.2/sql/sql_connect.cc:1241
#22 0x00007f5d846914a4 in start_thread (arg=0x7f5d80312700) at pthread_create.c:456
#23 0x00007f5d82bd8d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Query (0x7f5d0c011028): DROP TABLE t8464 /* QNO 13016 CON_ID 14 */
Connection ID (thread ID): 14
Status: NOT_KILLED
{noformat}

{noformat:title=RQG grammar pending_ops.yy}
query_init:
    { $tname= 't'.abs($$); '' } ;

query:
      CREATE TABLE $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit
    ; INSERT INTO $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit
    ; DELETE FROM $tname
    ; REPLACE INTO $tname SELECT * FROM INFORMATION_SCHEMA.INNODB_TABLESPACES_SCRUBBING LIMIT _digit
    ; DROP TABLE $tname
;
{noformat}

{noformat:title=Command line}
perl runall-new.pl --basedir=<your basedir> --grammar=pending_ops.yy --duration=14400 --threads=4 --vardir=/dev/shm//var_pending --skip-gendata --reporters=Backtrace,ErrorLog
{noformat}
*Remember to set the correct basedir.*

Marko Mäkelä added a comment - 2020-12-17 14:48

elenst, this looks like an InnoDB-internal issue. I wonder if you can reproduce this on recent 10.3 or 10.4 (after ~~MDEV-23651~~ was fixed) or 10.5.7 or later (with the ~~MDEV-23855~~ fix).

This should be easy to fix based on an rr replay trace of a failure. I expect the versions 10.2, 10.3, and 10.5 to differ from each other with respect to this.

Marko Mäkelä added a comment - 2020-12-17 14:48 elenst , this looks like an InnoDB-internal issue. I wonder if you can reproduce this on recent 10.3 or 10.4 (after MDEV-23651 was fixed) or 10.5.7 or later (with the MDEV-23855 fix). This should be easy to fix based on an rr replay trace of a failure. I expect the versions 10.2, 10.3, and 10.5 to differ from each other with respect to this.

Marko Mäkelä made changes - 2020-12-17 14:48

Link

This issue relates to ~~MDEV-23855~~ [ ~~MDEV-23855~~ ]

Marko Mäkelä made changes - 2020-12-17 14:48

Link

This issue relates to ~~MDEV-23651~~ [ ~~MDEV-23651~~ ]

Marko Mäkelä made changes - 2020-12-17 14:48

Assignee	Sergey Vojtovich [ svoj ]	Marko Mäkelä [ marko ]
Labels		need_rr

Sergei Golubchik made changes - 2021-12-06 21:33

Workflow

MariaDB v3 [ 86680 ]

MariaDB v4 [ 140745 ]

Ralf Gebhardt made changes - 2022-08-04 08:45

Fix Version/s

10.2 [ 14601 ]

Marko Mäkelä made changes - 2023-04-14 14:21

Assignee	Marko Mäkelä [ marko ]	Elena Stepanova [ elenst ]
Status	Open [ 1 ]	Needs Feedback [ 10501 ]

Marko Mäkelä made changes - 2023-04-14 18:31

Link

This issue relates to ~~MDEV-15528~~ [ ~~MDEV-15528~~ ]

Marko Mäkelä made changes - 2023-04-14 18:31

Link

This issue relates to ~~MDEV-8139~~ [ ~~MDEV-8139~~ ]

Marko Mäkelä added a comment - 2023-04-14 18:31

This crash ought to be caused by some logic for information_schema.innodb_tablespaces_scrubbing. That view was removed in ~~MDEV-15528~~, which implemented the most part of ~~MDEV-8139~~.

Marko Mäkelä added a comment - 2023-04-14 18:31 This crash ought to be caused by some logic for information_schema.innodb_tablespaces_scrubbing . That view was removed in MDEV-15528 , which implemented the most part of MDEV-8139 .

Marko Mäkelä made changes - 2023-04-14 18:32

Assignee	Elena Stepanova [ elenst ]	Marko Mäkelä [ marko ]
Status	Needs Feedback [ 10501 ]	Open [ 1 ]

Marko Mäkelä added a comment - 2023-04-14 18:33

~~MDEV-15528~~ was closed in MariaDB Server 10.5.2.

Marko Mäkelä added a comment - 2023-04-14 18:33 MDEV-15528 was closed in MariaDB Server 10.5.2.

Marko Mäkelä made changes - 2023-04-14 18:33

Fix Version/s		10.5.2 [ 24030 ]
Fix Version/s	10.3 [ 22126 ]
Resolution		Won't Fix [ 2 ]
Status	Open [ 1 ]	Closed [ 6 ]

People

Assignee:: Marko Mäkelä

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2018-04-20 12:38

Updated:: 2023-04-14 18:33

Resolved:: 2023-04-14 18:33

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.