[MDEV-29331] Assertion `in_LRU_list' failed in buf_page_t::is_old (buf0buf.h) on DROP TABLE Created: 2022-08-19  Updated: 2022-09-26

Status: Open
Project: MariaDB Server
Component/s: Partitioning, Storage Engine - InnoDB
Affects Version/s: 10.10
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Roel Van de Paar
Resolution: Unresolved Votes: 0
Labels: race, sporadic


 Description   
  • Bug is highly sporadic
  • The testcase is known to trigger the issue (it was reduced from 8k lines to the current 5 lines based on issue occurence or not), but reproducing the issue outright is not straightforward
  • The testcase is known to trigger the issue via the CLI (using mysql --execute='SOURCE input.sql') and via pquery
  • It is not known which earlier versions are affected
  • Two core dumps are available
  • Producing an rr trace may not be straighforward, so issue/testcase/core analysis first would be appreciated
  • It is not 100% established that the single mysqld option listed as required is truly required
  • It is not confirmed whetter this bug affects optimized builds or not
  • A single SQL input thread (ref CLI based SOURCE above) is sufficient to trigger the issue
  • The trace below is from an original iteration of the bb-10.10-MDEV-28883 (debug) branch, however the main 10.10.0 branch at revision e1caa4bd5e8b4645944b85d4b603bf9fc9ef6ca4 is confirmed affected also (and it was on this revision that the testcase was reduced).
  • This trace is also from the original trial (which had the 8k lines input SQL), so the trace may be slightly different, but as the reduction was done using UniqueID, the top 4 frames and assert and would have matched 100%.

# mysqld options required for replay:  --innodb_change_buffering=inserts
 
SET @@GLOBAL.innodb_limit_optimistic_insert_debug=2;
 
SET @@global.innodb_flush_neighbors=2;
 
SET @@GLOBAL.innodb_buffer_pool_size=16777216;
 
CREATE TABLE t1 (c1 BIGINT NULL, c2 CHAR(5)) PARTITION BY KEY(c1) PARTITIONS 99;
 
DROP TABLE t1;

Leads to:

10.10.0 373a00fea0ec8b1c949f90b2fc407b40035be4cc (Debug)

 
mysqld: /test/bb-10.10-MDEV-28883_dbg/storage/innobase/include/buf0buf.h:2057: bool buf_page_t::is_old() const: Assertion `in_LRU_list' failed.

10.10.0 373a00fea0ec8b1c949f90b2fc407b40035be4cc (Debug)

 
Core was generated by `/test/MDEV-28883_MD050822-mariadb-10.10.0-linux-x86_64-dbg/bin/mysqld --no-defa'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x1530409a8700 (LWP 3106926))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x0000153065483859 in __GI_abort () at abort.c:79
 
#2  0x0000153065483729 in __assert_fail_base (fmt=0x153065619588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x56523c6e6a91 "in_LRU_list", file=0x56523c6c2bd8 "/test/bb-10.10-MDEV-28883_dbg/storage/innobase/include/buf0buf.h", line=2057, function=<optimized out>) at assert.c:92
 
#3  0x0000153065494fd6 in __GI___assert_fail (assertion=assertion@entry=0x56523c6e6a91 "in_LRU_list", file=file@entry=0x56523c6c2bd8 "/test/bb-10.10-MDEV-28883_dbg/storage/innobase/include/buf0buf.h", line=line@entry=2057, function=function@entry=0x56523c7270a0 "bool buf_page_t::is_old() const") at assert.c:101
 
#4  0x000056523c18dfab in buf_page_t::is_old (this=0x56523cd11808 <buf_pool+22728>) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/include/buf0buf.h:2057
 
#5  buf_flush_try_neighbors (space=space@entry=0x56523e5956a0, page_id=<optimized out>, page_id@entry={m_id = 2015}, contiguous=contiguous@entry=false, lru=lru@entry=true, n_flushed=n_flushed@entry=12, n_to_flush=n_to_flush@entry=32) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0flu.cc:1077
 
#6  0x000056523c18fe43 in buf_flush_LRU_list_batch (n=<synthetic pointer>, max=32) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0flu.cc:1270
 
#7  buf_do_LRU_batch (max=32) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0flu.cc:1313
 
#8  buf_flush_LRU (max_n=32) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0flu.cc:1654
 
#9  0x000056523c19e400 in buf_LRU_get_free_block (have_mutex=have_mutex@entry=false) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0lru.cc:486
 
#10 0x000056523c19ef9a in buf_page_init_for_read (mode=mode@entry=132, page_id=<optimized out>, zip_size=zip_size@entry=0, unzip=unzip@entry=false) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0rea.cc:119
 
#11 0x000056523c1a191f in buf_read_page_low (err=err@entry=0x1530409a2df8, space=0x56523e5d4de0, sync=sync@entry=true, mode=mode@entry=132, page_id={m_id = 4294967730}, zip_size=zip_size@entry=0, unzip=false) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0rea.cc:299
 
#12 0x000056523c1a3ce0 in buf_read_page (page_id=page_id@entry={m_id = 4294967730}, zip_size=zip_size@entry=0) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0rea.cc:456
 
#13 0x000056523c179818 in buf_page_get_low (page_id=page_id@entry={m_id = 4294967730}, zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=1, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x1530409a4390, err=0x1530409a3214, allow_ibuf_merge=false) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0buf.cc:2579
 
#14 0x000056523c17b752 in buf_page_get_gen (page_id=page_id@entry={m_id = 4294967730}, zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=1, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x1530409a4390, err=0x1530409a3214, allow_ibuf_merge=false) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/buf/buf0buf.cc:3049
 
#15 0x000056523c145c8f in btr_cur_search_to_nth_level_func (index=index@entry=0x153018015c20, level=level@entry=0, tuple=<optimized out>, mode=<optimized out>, latch_mode=<optimized out>, latch_mode@entry=1, cursor=cursor@entry=0x152fe04c91c0, ahi_latch=<optimized out>, mtr=<optimized out>, autoinc=<optimized out>) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/btr/btr0cur.cc:1585
 
#16 0x000056523c07b5d8 in btr_pcur_open_with_no_init_func (mtr=0x1530409a4390, ahi_latch=0x0, cursor=0x152fe04c91c0, latch_mode=1, mode=<optimized out>, tuple=<optimized out>, index=0x153018015c20) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/include/btr0pcur.inl:390
 
#17 row_sel_open_pcur (plan=plan@entry=0x152fe04c91b0, mtr=mtr@entry=0x1530409a4390) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/row/row0sel.cc:1412
 
#18 0x000056523c086e39 in row_sel (node=node@entry=0x152fe04c90c0, thr=thr@entry=0x152fe04c95c8) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/row/row0sel.cc:1740
 
#19 0x000056523c089059 in row_sel_step (thr=thr@entry=0x152fe04c95c8) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/row/row0sel.cc:2401
 
#20 0x000056523bfe192b in que_thr_step (thr=0x152fe04c95c8) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/que/que0que.cc:629
 
#21 que_run_threads_low (thr=0x152fe04c95c8) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/que/que0que.cc:709
 
#22 que_run_threads (thr=0x152fe04c95c8) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/que/que0que.cc:729
 
#23 0x000056523bfe2024 in que_eval_sql (info=info@entry=0x152fe01c60b0, sql=sql@entry=0x56523c730810 "PROCEDURE DELETE_FROM_TABLE_STATS () IS\nBEGIN\nDELETE FROM \"mysql/innodb_table_stats\" WHERE\ndatabase_name = :database_name AND\ntable_name = :table_name;\nEND;\n", trx=trx@entry=0x15305cd1f180) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/que/que0que.cc:768
 
#24 0x000056523c1ed76d in dict_stats_exec_sql (pinfo=pinfo@entry=0x152fe01c60b0, sql=sql@entry=0x56523c730810 "PROCEDURE DELETE_FROM_TABLE_STATS () IS\nBEGIN\nDELETE FROM \"mysql/innodb_table_stats\" WHERE\ndatabase_name = :database_name AND\ntable_name = :table_name;\nEND;\n", trx=trx@entry=0x15305cd1f180) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/dict/dict0stats.cc:529
 
#25 0x000056523c1ed868 in dict_stats_delete_from_table_stats (database_name=database_name@entry=0x1530409a49d0 "test", table_name=table_name@entry=0x1530409a4aa0 "t1#P#p43", trx=trx@entry=0x15305cd1f180) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/dict/dict0stats.cc:4059
 
#26 0x000056523c1fa8f9 in trx_t::drop_table_statistics (this=this@entry=0x15305cd1f180, name=<optimized out>) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/dict/drop.cc:133
 
#27 0x000056523bedbf68 in ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /test/bb-10.10-MDEV-28883_dbg/storage/innobase/handler/ha_innodb.cc:13646
 
#28 0x000056523be68f14 in ha_partition::del_ren_table (this=0x152fe0014758, from=0x1530409a69c0 "./test/t1", to=to@entry=0x0) at /test/bb-10.10-MDEV-28883_dbg/sql/ha_partition.cc:2510
 
#29 0x000056523be691da in ha_partition::delete_table (this=<optimized out>, name=<optimized out>) at /test/bb-10.10-MDEV-28883_dbg/sql/ha_partition.cc:632
 
#30 0x000056523bbb537a in hton_drop_table (hton=<optimized out>, path=<optimized out>) at /test/bb-10.10-MDEV-28883_dbg/sql/handler.cc:576
 
#31 0x000056523bbbcf39 in ha_delete_table (thd=thd@entry=0x152fe0000db8, hton=hton@entry=0x56523e687ba8, path=path@entry=0x1530409a69c0 "./test/t1", db=db@entry=0x1530409a67b0, alias=alias@entry=0x1530409a67c0, generate_warning=generate_warning@entry=true) at /test/bb-10.10-MDEV-28883_dbg/sql/handler.cc:3119
 
#32 0x000056523b995f90 in mysql_rm_table_no_locks (thd=thd@entry=0x152fe0000db8, tables=tables@entry=0x152fe0013e10, current_db=current_db@entry=0x152fe0000e50, ddl_log_state=0x1530409a67e0, ddl_log_state@entry=0x0, if_exists=if_exists@entry=false, drop_temporary=drop_temporary@entry=false, drop_view=false, drop_sequence=false, dont_log_query=false, dont_free_locks=false) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_table.cc:1611
 
#33 0x000056523b997dd6 in mysql_rm_table (thd=thd@entry=0x152fe0000db8, tables=tables@entry=0x152fe0013e10, if_exists=<optimized out>, drop_temporary=<optimized out>, drop_sequence=<optimized out>, dont_log_query=dont_log_query@entry=false) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_table.cc:1186
 
#34 0x000056523b8d0ec3 in mysql_execute_command (thd=thd@entry=0x152fe0000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/bb-10.10-MDEV-28883_dbg/sql/structs.h:569
 
#35 0x000056523b8bcf8b in mysql_parse (thd=thd@entry=0x152fe0000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1530409a7460) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_parse.cc:7797
 
#36 0x000056523b8ca4e0 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x152fe0000db8, packet=packet@entry=0x152fe011a369 "DROP TABLE t1;", packet_length=packet_length@entry=14, blocking=blocking@entry=true) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_class.h:1364
 
#37 0x000056523b8ccbed in do_command (thd=0x152fe0000db8, blocking=blocking@entry=true) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_parse.cc:1405
 
#38 0x000056523ba2ba9e in do_handle_one_connection (connect=<optimized out>, connect@entry=0x56523e8ecdc8, put_in_cache=put_in_cache@entry=true) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_connect.cc:1418
 
#39 0x000056523ba2bfa7 in handle_one_connection (arg=0x56523e8ecdc8) at /test/bb-10.10-MDEV-28883_dbg/sql/sql_connect.cc:1312
 
#40 0x0000153065994609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#41 0x0000153065580133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95



 Comments   
Comment by Marko Mäkelä [ 2022-08-19 ]

I think that this should be equally well reproducible on 10.6 if not earlier versions. I can’t really debug this without having a reproducible test case or an rr replay trace.

For more convenient debugging with rr, I would suggest using the minimum innodb_buffer_pool_size=5M and fewer partitions. I was unable to reproduce this with the following test case:

--source include/have_innodb.inc
 
--source include/have_partition.inc
 
--source include/have_debug.inc
 
CREATE TABLE t1 (c1 BIGINT NULL, c2 CHAR(5)) PARTITION BY KEY(c1) PARTITIONS 99;
 
DROP TABLE t1;


./mtr --mysqld=--innodb-{buffer-pool-size=5m,file-per-table=0,change-buffering=inserts,flush-neighbors=2,limit-optimistic-insert-debug=2} mdev-29331

I tried both values of innodb_file_per_table. I also tried --repeat.

Comment by Roel Van de Paar [ 2022-08-19 ]

marko Thank you. Two rr traces ready for you here:

rr:/data/KEEP/MDEV-28883_MD080822-mariadb-10.10.0-linux-x86_64-dbg/rr/

Comment by Roel Van de Paar [ 2022-08-19 ]

Two additional traces using more recent 10.10 here:

rr:/data/KEEP/MD060822-mariadb-10.10.0-linux-x86_64-dbg/rr/

Comment by Roel Van de Paar [ 2022-08-19 ]

Will now try to get one with less partitions and smaller buffer pool.

Comment by Roel Van de Paar [ 2022-08-20 ]

Attempted many reductions, but none produced a single failure.

Please see 4 rr traces with original T/C above.

Comment by Roel Van de Paar [ 2022-08-25 ]

Re-assigning to myself as traces needs more work (current ones are not suitable)

Generated at Thu Feb 08 10:07:41 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.