[MDEV-22927] ER_KEY_NOT_FOUND or Assertion `(0xFUL & mode) == LOCK_S || (0xFUL & mode) == LOCK_X' failed upon sequence operations Created: 2020-06-17  Updated: 2024-01-09

Status: Confirmed
Project: MariaDB Server
Component/s: Sequences
Affects Version/s: 10.3, 10.4, 10.5, 10.6, 10.9, 10.10, 10.11, 11.0, 11.1
Fix Version/s: 10.4, 10.5, 10.6, 10.11, 11.0, 11.1, 11.2, 11.3, 11.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Golubchik
Resolution: Unresolved Votes: 0
Labels: affects-tests

Issue Links:
Blocks
Relates
relates to MDEV-19320 Sequence gets corrupted and produces ... Closed
relates to MDEV-19977 Assertion `(0xFUL & mode) == LOCK_S |... Closed

 Description   

Note: Both MDEV-19320 and MDEV-19977 fixes are not in the trees, but this case is still failing. Also, both previous bugs ended up being about operations which aren't allowed on sequences; I'm not sure which operation here is wrong.

--source include/have_innodb.inc
 
CREATE SEQUENCE s MINVALUE 0 ENGINE=Aria ROW_FORMAT=DYNAMIC;
ALTER TABLE s ENGINE=InnoDB;
ALTER SEQUENCE s INCREMENT= 1000;
 
# Cleanup
DROP SEQUENCE s;

All of 10.3-10.5 non-debug as well as 10.3-10.4 debug produce ER_KEY_NOT_FOUND:

10.3 b633b6a9

mysqltest: At line 5: query 'ALTER SEQUENCE s INCREMENT= 1000' failed: 1032: Can't find record in 's'

10.5 debug produces the assertion failure:

10.5 bd62a636

mariadbd: /data/src/10.5/storage/innobase/lock/lock0lock.cc:1915: dberr_t lock_rec_lock(bool, unsigned int, const buf_block_t*, ulint, dict_index_t*, que_thr_t*): Assertion `(0xFUL & mode) == LOCK_S || (0xFUL & mode) == LOCK_X' failed.
200617 20:09:34 [ERROR] mysqld got signal 6 ;
 
#7  0x00007fd3be871f12 in __GI___assert_fail (assertion=0x5606f2678bc8 "(0xFUL & mode) == LOCK_S || (0xFUL & mode) == LOCK_X", file=0x5606f2678148 "/data/src/10.5/storage/innobase/lock/lock0lock.cc", line=1915, function=0x5606f267d0c0 <lock_rec_lock(bool, unsigned int, buf_block_t const*, unsigned long, dict_index_t*, que_thr_t*)::__PRETTY_FUNCTION__> "dberr_t lock_rec_lock(bool, unsigned int, const buf_block_t*, ulint, dict_index_t*, que_thr_t*)") at assert.c:101
#8  0x00005606f1e04424 in lock_rec_lock (impl=false, mode=5, block=0x7fd3b80ac5d8, heap_no=1, index=0x7fd3841fd418, thr=0x7fd3840fa0d0) at /data/src/10.5/storage/innobase/lock/lock0lock.cc:1915
#9  0x00005606f1e12d33 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fd3b80ac5d8, rec=0x7fd3b8594070 "supremum", index=0x7fd3841fd418, offsets=0x7fd3b3db0ff0, mode=LOCK_NONE, gap_mode=0, thr=0x7fd3840fa0d0) at /data/src/10.5/storage/innobase/lock/lock0lock.cc:5803
#10 0x00005606f1f4955d in sel_set_rec_lock (pcur=0x7fd3840f9a98, rec=0x7fd3b8594070 "supremum", index=0x7fd3841fd418, offsets=0x7fd3b3db0ff0, mode=5, type=0, thr=0x7fd3840fa0d0, mtr=0x7fd3b3db1850) at /data/src/10.5/storage/innobase/row/row0sel.cc:1252
#11 0x00005606f1f52f81 in row_search_mvcc (buf=0x7fd38421f088 '\245' <repeats 128 times>, "P\361!\204\323\177", mode=PAGE_CUR_G, prebuilt=0x7fd3840f98d8, match_mode=0, direction=0) at /data/src/10.5/storage/innobase/row/row0sel.cc:4720
#12 0x00005606f1d55bfe in ha_innobase::index_read (this=0x7fd384220860, buf=0x7fd38421f088 '\245' <repeats 128 times>, "P\361!\204\323\177", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:8962
#13 0x00005606f1d56c0e in ha_innobase::index_first (this=0x7fd384220860, buf=0x7fd38421f088 '\245' <repeats 128 times>, "P\361!\204\323\177") at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:9335
#14 0x00005606f1d56de6 in ha_innobase::rnd_next (this=0x7fd384220860, buf=0x7fd38421f088 '\245' <repeats 128 times>, "P\361!\204\323\177") at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:9428
#15 0x00005606f1cf844b in ha_sequence::rnd_next (this=0x7fd3841f8930, buf=0x7fd38421f088 '\245' <repeats 128 times>, "P\361!\204\323\177") at /data/src/10.5/sql/ha_sequence.h:111
#16 0x00005606f18f7741 in handler::ha_rnd_next (this=0x7fd3841f8930, buf=0x7fd38421f088 '\245' <repeats 128 times>, "P\361!\204\323\177") at /data/src/10.5/sql/handler.cc:3037
#17 0x00005606f18fa48c in handler::read_first_row (this=0x7fd3841f8930, buf=0x7fd38421f088 '\245' <repeats 128 times>, "P\361!\204\323\177", primary_key=64) at /data/src/10.5/sql/handler.cc:3284
#18 0x00005606f16372d3 in handler::ha_read_first_row (this=0x7fd3841f8930, buf=0x7fd38421f088 '\245' <repeats 128 times>, "P\361!\204\323\177", primary_key=64) at /data/src/10.5/sql/sql_class.h:6976
#19 0x00005606f180e65c in SEQUENCE::read_stored_values (this=0x7fd3841fe080, table=0x7fd38421f9e8) at /data/src/10.5/sql/sql_sequence.cc:528
#20 0x00005606f180e493 in SEQUENCE::read_initial_values (this=0x7fd3841fe080, table=0x7fd38421f9e8) at /data/src/10.5/sql/sql_sequence.cc:489
#21 0x00005606f1cf7261 in ha_sequence::open (this=0x7fd3841f8930, name=0x7fd3841f8868 "./test/s", mode=2, flags=18) at /data/src/10.5/sql/ha_sequence.cc:118
#22 0x00005606f18f6c5e in handler::ha_open (this=0x7fd3841f8930, table_arg=0x7fd38421f9e8, name=0x7fd3841f8868 "./test/s", mode=2, test_if_locked=18, mem_root=0x0, partitions_to_open=0x0) at /data/src/10.5/sql/handler.cc:2954
#23 0x00005606f16dbc01 in open_table_from_share (thd=0x7fd384000b18, share=0x7fd3841f82d0, alias=0x7fd384013a60, db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x7fd38421f9e8, is_create_table=false, partitions_to_open=0x0) at /data/src/10.5/sql/table.cc:4186
#24 0x00005606f14f0ec4 in open_table (thd=0x7fd384000b18, table_list=0x7fd384013a18, ot_ctx=0x7fd3b3db2930) at /data/src/10.5/sql/sql_base.cc:1988
#25 0x00005606f14f4ca5 in open_and_process_table (thd=0x7fd384000b18, tables=0x7fd384013a18, counter=0x7fd3b3db29c4, flags=0, prelocking_strategy=0x7fd3b3db2a48, has_prelocking_list=false, ot_ctx=0x7fd3b3db2930) at /data/src/10.5/sql/sql_base.cc:3784
#26 0x00005606f14f5f62 in open_tables (thd=0x7fd384000b18, options=..., start=0x7fd3b3db29a8, counter=0x7fd3b3db29c4, flags=0, prelocking_strategy=0x7fd3b3db2a48) at /data/src/10.5/sql/sql_base.cc:4258
#27 0x00005606f14f80aa in open_and_lock_tables (thd=0x7fd384000b18, options=..., tables=0x7fd384013a18, derived=false, flags=0, prelocking_strategy=0x7fd3b3db2a48) at /data/src/10.5/sql/sql_base.cc:5160
#28 0x00005606f14afc27 in open_and_lock_tables (thd=0x7fd384000b18, tables=0x7fd384013a18, derived=false, flags=0) at /data/src/10.5/sql/sql_base.h:509
#29 0x00005606f180f5ab in Sql_cmd_alter_sequence::execute (this=0x7fd3840140f8, thd=0x7fd384000b18) at /data/src/10.5/sql/sql_sequence.cc:906
#30 0x00005606f15a25c6 in mysql_execute_command (thd=0x7fd384000b18) at /data/src/10.5/sql/sql_parse.cc:5951
#31 0x00005606f15a88fb in mysql_parse (thd=0x7fd384000b18, rawbuf=0x7fd3840138d0 "ALTER SEQUENCE s INCREMENT= 1000", length=32, parser_state=0x7fd3b3db3520, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7993
#32 0x00005606f1594c71 in dispatch_command (command=COM_QUERY, thd=0x7fd384000b18, packet=0x7fd3841b1819 "ALTER SEQUENCE s INCREMENT= 1000", packet_length=32, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1875
#33 0x00005606f15933a9 in do_command (thd=0x7fd384000b18) at /data/src/10.5/sql/sql_parse.cc:1356
#34 0x00005606f17384c1 in do_handle_one_connection (connect=0x5606f59cee28, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1411
#35 0x00005606f1738229 in handle_one_connection (arg=0x5606f59cee28) at /data/src/10.5/sql/sql_connect.cc:1313
#36 0x00005606f1c7292a in pfs_spawn_thread (arg=0x5606f59bafa8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
#37 0x00007fd3c07fa4a4 in start_thread (arg=0x7fd3b3db4700) at pthread_create.c:456
#38 0x00007fd3be92ed0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97



 Comments   
Comment by Elena Stepanova [ 2021-04-03 ]

In 10.6 the assertion features a new look (same test case):

10.6 609e8e38

mariadbd: /data/src/10.6/storage/innobase/lock/lock0lock.cc:1468: dberr_t lock_rec_lock(bool, unsigned int, const buf_block_t*, ulint, dict_index_t*, que_thr_t*): Assertion `((0x7 | 8U) & mode) == LOCK_S || ((0x7 | 8U) & mode) == LOCK_X' failed.
210403 20:28:27 [ERROR] mysqld got signal 6 ;
 
#7  0x00007f1a0b5cef36 in __GI___assert_fail (assertion=0x556b28913898 "((0x7 | 8U) & mode) == LOCK_S || ((0x7 | 8U) & mode) == LOCK_X", file=0x556b289126e0 "/data/src/10.6/storage/innobase/lock/lock0lock.cc", line=1468, function=0x556b28913838 "dberr_t lock_rec_lock(bool, unsigned int, const buf_block_t*, ulint, dict_index_t*, que_thr_t*)") at assert.c:101
#8  0x0000556b280d2753 in lock_rec_lock (impl=false, mode=5, block=0x7f1a04c1fbc0, heap_no=1, index=0x7f19dc1f3ce8, thr=0x7f19dc236380) at /data/src/10.6/storage/innobase/lock/lock0lock.cc:1468
#9  0x0000556b280e1b68 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7f1a04c1fbc0, rec=0x7f1a050f4070 "supremum", index=0x7f19dc1f3ce8, offsets=0x7f1a04975540, mode=LOCK_NONE, gap_mode=0, thr=0x7f19dc236380) at /data/src/10.6/storage/innobase/lock/lock0lock.cc:5237
#10 0x0000556b2821e931 in sel_set_rec_lock (pcur=0x7f19dc235d58, rec=0x7f1a050f4070 "supremum", index=0x7f19dc1f3ce8, offsets=0x7f1a04975540, mode=5, type=0, thr=0x7f19dc236380, mtr=0x7f1a04975920) at /data/src/10.6/storage/innobase/row/row0sel.cc:1256
#11 0x0000556b28228713 in row_search_mvcc (buf=0x7f19dc232918 '\245' <repeats 128 times>, "\340)#\334\031\177", mode=PAGE_CUR_G, prebuilt=0x7f19dc235b98, match_mode=0, direction=0) at /data/src/10.6/storage/innobase/row/row0sel.cc:4813
#12 0x0000556b2802a0dd in ha_innobase::index_read (this=0x7f19dc232d80, buf=0x7f19dc232918 '\245' <repeats 128 times>, "\340)#\334\031\177", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:8627
#13 0x0000556b2802b106 in ha_innobase::index_first (this=0x7f19dc232d80, buf=0x7f19dc232918 '\245' <repeats 128 times>, "\340)#\334\031\177") at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:8988
#14 0x0000556b2802b2f6 in ha_innobase::rnd_next (this=0x7f19dc232d80, buf=0x7f19dc232918 '\245' <repeats 128 times>, "\340)#\334\031\177") at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:9081
#15 0x0000556b27fc9df6 in ha_sequence::rnd_next (this=0x7f19dc2335e0, buf=0x7f19dc232918 '\245' <repeats 128 times>, "\340)#\334\031\177") at /data/src/10.6/sql/ha_sequence.h:111
#16 0x0000556b27babc12 in handler::ha_rnd_next (this=0x7f19dc2335e0, buf=0x7f19dc232918 '\245' <repeats 128 times>, "\340)#\334\031\177") at /data/src/10.6/sql/handler.cc:3066
#17 0x0000556b27baea1c in handler::read_first_row (this=0x7f19dc2335e0, buf=0x7f19dc232918 '\245' <repeats 128 times>, "\340)#\334\031\177", primary_key=64) at /data/src/10.6/sql/handler.cc:3313
#18 0x0000556b278da4c1 in handler::ha_read_first_row (this=0x7f19dc2335e0, buf=0x7f19dc232918 '\245' <repeats 128 times>, "\340)#\334\031\177", primary_key=64) at /data/src/10.6/sql/sql_class.h:7260
#19 0x0000556b27abdbb8 in SEQUENCE::read_stored_values (this=0x7f19dc22c3f0, table=0x7f19dc0fb348) at /data/src/10.6/sql/sql_sequence.cc:532
#20 0x0000556b27abd9e8 in SEQUENCE::read_initial_values (this=0x7f19dc22c3f0, table=0x7f19dc0fb348) at /data/src/10.6/sql/sql_sequence.cc:494
#21 0x0000556b27fc8b5a in ha_sequence::open (this=0x7f19dc2335e0, name=0x7f19dc132dc0 "./test/s", mode=2, flags=18) at /data/src/10.6/sql/ha_sequence.cc:118
#22 0x0000556b27bab120 in handler::ha_open (this=0x7f19dc2335e0, table_arg=0x7f19dc0fb348, name=0x7f19dc132dc0 "./test/s", mode=2, test_if_locked=18, mem_root=0x0, partitions_to_open=0x0) at /data/src/10.6/sql/handler.cc:2983
#23 0x0000556b27982e75 in open_table_from_share (thd=0x7f19dc000db8, share=0x7f19dc132820, alias=0x7f19dc015338, db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x7f19dc0fb348, is_create_table=false, partitions_to_open=0x0) at /data/src/10.6/sql/table.cc:4300
#24 0x0000556b2778b5f7 in open_table (thd=0x7f19dc000db8, table_list=0x7f19dc0152f0, ot_ctx=0x7f1a049769e0) at /data/src/10.6/sql/sql_base.cc:2001
#25 0x0000556b2778f502 in open_and_process_table (thd=0x7f19dc000db8, tables=0x7f19dc0152f0, counter=0x7f1a04976a74, flags=0, prelocking_strategy=0x7f1a04976af8, has_prelocking_list=false, ot_ctx=0x7f1a049769e0) at /data/src/10.6/sql/sql_base.cc:3801
#26 0x0000556b277907ca in open_tables (thd=0x7f19dc000db8, options=..., start=0x7f1a04976a58, counter=0x7f1a04976a74, flags=0, prelocking_strategy=0x7f1a04976af8) at /data/src/10.6/sql/sql_base.cc:4275
#27 0x0000556b27792707 in open_and_lock_tables (thd=0x7f19dc000db8, options=..., tables=0x7f19dc0152f0, derived=false, flags=0, prelocking_strategy=0x7f1a04976af8) at /data/src/10.6/sql/sql_base.cc:5233
#28 0x0000556b2774878f in open_and_lock_tables (thd=0x7f19dc000db8, tables=0x7f19dc0152f0, derived=false, flags=0) at /data/src/10.6/sql/sql_base.h:507
#29 0x0000556b27abeb49 in Sql_cmd_alter_sequence::execute (this=0x7f19dc0159d0, thd=0x7f19dc000db8) at /data/src/10.6/sql/sql_sequence.cc:910
#30 0x0000556b2784158b in mysql_execute_command (thd=0x7f19dc000db8) at /data/src/10.6/sql/sql_parse.cc:5973
#31 0x0000556b27847746 in mysql_parse (thd=0x7f19dc000db8, rawbuf=0x7f19dc0151b0 "ALTER SEQUENCE s INCREMENT= 1000", length=32, parser_state=0x7f1a04977510) at /data/src/10.6/sql/sql_parse.cc:8004
#32 0x0000556b27833b6c in dispatch_command (command=COM_QUERY, thd=0x7f19dc000db8, packet=0x7f19dc00b469 "ALTER SEQUENCE s INCREMENT= 1000", packet_length=32, blocking=true) at /data/src/10.6/sql/sql_parse.cc:1888
#33 0x0000556b27832513 in do_command (thd=0x7f19dc000db8, blocking=true) at /data/src/10.6/sql/sql_parse.cc:1399
#34 0x0000556b279e0e7a in do_handle_one_connection (connect=0x556b2b311d48, put_in_cache=true) at /data/src/10.6/sql/sql_connect.cc:1410
#35 0x0000556b279e0bd6 in handle_one_connection (arg=0x556b2b312348) at /data/src/10.6/sql/sql_connect.cc:1312
#36 0x0000556b27f411ff in pfs_spawn_thread (arg=0x556b2b218778) at /data/src/10.6/storage/perfschema/pfs.cc:2201
#37 0x00007f1a0bae6609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#38 0x00007f1a0b6ba293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Elena Stepanova [ 2021-05-04 ]

It also badly affects crash recovery (I assume it is the same root cause, or a very close one).
Note: SELECT * FROM s in the test case is informational, it doesn't affect the outcome.

CREATE SEQUENCE s;
SELECT NEXTVAL(s);
SELECT * FROM s;
--let $shutdown_timeout= 0
--source include/restart_mysqld.inc
SELECT NEXTVAL(s);
SELECT * FROM s;
 
# Cleanup
DROP SEQUENCE s;

10.5 c6846757, ENGINE=MyISAM or Aria

# restart
SELECT NEXTVAL(s);
NEXTVAL(s)
1001
Warnings:
Error	145	Table './test/s' is marked as crashed and should be repaired
Warning	1034	1 client is using or hasn't closed the table properly
Note	1034	Table is fixed

10.5 c6846757, ENGINE=InnoDB, innodb_stats_persistent=ON

CREATE SEQUENCE s;
SELECT NEXTVAL(s);
NEXTVAL(s)
1
SELECT * FROM s;
next_not_cached_value	minimum_value	maximum_value	start_value	increment	cache_size	cycle_option	cycle_count
1001	1	9223372036854775806	1	1	1000	0	0
# restart
SELECT NEXTVAL(s);
NEXTVAL(s)
1
SELECT * FROM s;
next_not_cached_value	minimum_value	maximum_value	start_value	increment	cache_size	cycle_option	cycle_count
1001	1	9223372036854775806	1	1	1000	0	0
DROP SEQUENCE s;

Note that next_not_cached_value is not increased, and NEXTVAL doesn't either. If we selected more NEXTVALs before the crash, after the recovery the value would have been even lower than the last fetched one.

10.5 c6846757, ENGINE=InnoDB, innodb_stats_persistent=OFF

1001	1	9223372036854775806	1	1	1000	0	0
# restart
SELECT NEXTVAL(s);
bug.seq1                                 [ fail ]
        Test ended at 2021-05-04 13:56:33
 
CURRENT_TEST: bug.seq1
mysqltest: At line 6: query 'SELECT NEXTVAL(s)' failed: 1032: Can't find record in 's'

or, to link it even closer with the original report,

--source include/have_innodb.inc
CREATE SEQUENCE s ENGINE=InnoDB;
SELECT NEXTVAL(s);
--let $shutdown_timeout= 0
--source include/restart_mysqld.inc
SET @stats.save= @@innodb_stats_persistent;
SET GLOBAL innodb_stats_persistent= ON;
OPTIMIZE TABLE s;
 
# Cleanup
DROP SEQUENCE s;
SET GLOBAL innodb_stats_persistent= @stats.save;

mariadbd: /data/src/10.5/storage/innobase/lock/lock0lock.cc:1859: dberr_t lock_rec_lock(bool, unsigned int, const buf_block_t*, ulint, dict_index_t*, que_thr_t*): Assertion `(0xFUL & mode) == LOCK_S ||
 (0xFUL & mode) == LOCK_X' failed.
210504 14:03:02 [ERROR] mysqld got signal 6 ;
 
#7  0x00007ff3bf5f4f36 in __GI___assert_fail (assertion=0x55d6ed1b6e60 "(0xFUL & mode) == LOCK_S || (0xFUL & mode) == LOCK_X", file=0x55d6ed1b5ef0 "/data/src/10.5/storage/innobase/lock/lock0lock.cc", line=1859, function=0x55d6ed1b6e00 "dberr_t lock_rec_lock(bool, unsigned int, const buf_block_t*, ulint, dict_index_t*, que_thr_t*)") at assert.c:101
#8  0x000055d6ec9521c0 in lock_rec_lock (impl=false, mode=5, block=0x7ff3b8af4b60, heap_no=1, index=0x7ff36002b708, thr=0x7ff360136330) at /data/src/10.5/storage/innobase/lock/lock0lock.cc:1859
#9  0x000055d6ec96063a in lock_clust_rec_read_check_and_lock (flags=0, block=0x7ff3b8af4b60, rec=0x7ff3b8d84070 "supremum", index=0x7ff36002b708, offsets=0x7ff3b884ce10, mode=LOCK_NONE, gap_mode=0, thr=0x7ff360136330) at /data/src/10.5/storage/innobase/lock/lock0lock.cc:5717
#10 0x000055d6eca99e25 in sel_set_rec_lock (pcur=0x7ff360135d08, rec=0x7ff3b8d84070 "supremum", index=0x7ff36002b708, offsets=0x7ff3b884ce10, mode=5, type=0, thr=0x7ff360136330, mtr=0x7ff3b884d1f0) at /data/src/10.5/storage/innobase/row/row0sel.cc:1266
#11 0x000055d6ecaa3b3d in row_search_mvcc (buf=0x7ff360028248 '\245' <repeats 128 times>, "\020\203\002`\363\177", mode=PAGE_CUR_G, prebuilt=0x7ff360135b48, match_mode=0, direction=0) at /data/src/10.5/storage/innobase/row/row0sel.cc:4783
#12 0x000055d6ec8a0f69 in ha_innobase::index_read (this=0x7ff3600286b0, buf=0x7ff360028248 '\245' <repeats 128 times>, "\020\203\002`\363\177", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:8854
#13 0x000055d6ec8a1f92 in ha_innobase::index_first (this=0x7ff3600286b0, buf=0x7ff360028248 '\245' <repeats 128 times>, "\020\203\002`\363\177") at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:9215
#14 0x000055d6ec8a2182 in ha_innobase::rnd_next (this=0x7ff3600286b0, buf=0x7ff360028248 '\245' <repeats 128 times>, "\020\203\002`\363\177") at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:9308
#15 0x000055d6ec83f70e in ha_sequence::rnd_next (this=0x7ff360028f10, buf=0x7ff360028248 '\245' <repeats 128 times>, "\020\203\002`\363\177") at /data/src/10.5/sql/ha_sequence.h:111
#16 0x000055d6ec41db94 in handler::ha_rnd_next (this=0x7ff360028f10, buf=0x7ff360028248 '\245' <repeats 128 times>, "\020\203\002`\363\177") at /data/src/10.5/sql/handler.cc:3066
#17 0x000055d6ec42099e in handler::read_first_row (this=0x7ff360028f10, buf=0x7ff360028248 '\245' <repeats 128 times>, "\020\203\002`\363\177", primary_key=64) at /data/src/10.5/sql/handler.cc:3313
#18 0x000055d6ec14b54d in handler::ha_read_first_row (this=0x7ff360028f10, buf=0x7ff360028248 '\245' <repeats 128 times>, "\020\203\002`\363\177", primary_key=64) at /data/src/10.5/sql/sql_class.h:7043
#19 0x000055d6ec32fe18 in SEQUENCE::read_stored_values (this=0x7ff36013ae30, table=0x7ff36002ce88) at /data/src/10.5/sql/sql_sequence.cc:532
#20 0x000055d6ec32fc48 in SEQUENCE::read_initial_values (this=0x7ff36013ae30, table=0x7ff36002ce88) at /data/src/10.5/sql/sql_sequence.cc:494
#21 0x000055d6ec83e472 in ha_sequence::open (this=0x7ff360028f10, name=0x7ff3600279b8 "./test/s", mode=2, flags=18) at /data/src/10.5/sql/ha_sequence.cc:118
#22 0x000055d6ec41d0a2 in handler::ha_open (this=0x7ff360028f10, table_arg=0x7ff36002ce88, name=0x7ff3600279b8 "./test/s", mode=2, test_if_locked=18, mem_root=0x0, partitions_to_open=0x0) at /data/src/10.5/sql/handler.cc:2983
#23 0x000055d6ec1f42c9 in open_table_from_share (thd=0x7ff360000db8, share=0x7ff360027420, alias=0x7ff360017ad0, db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x7ff36002ce88, is_create_table=false, partitions_to_open=0x0) at /data/src/10.5/sql/table.cc:4218
#24 0x000055d6ebffc4b3 in open_table (thd=0x7ff360000db8, table_list=0x7ff360017a88, ot_ctx=0x7ff3b884e2a0) at /data/src/10.5/sql/sql_base.cc:2001
#25 0x000055d6ec0003be in open_and_process_table (thd=0x7ff360000db8, tables=0x7ff360017a88, counter=0x7ff3b884e334, flags=0, prelocking_strategy=0x7ff3b884e3b8, has_prelocking_list=false, ot_ctx=0x7ff3b884e2a0) at /data/src/10.5/sql/sql_base.cc:3801
#26 0x000055d6ec001686 in open_tables (thd=0x7ff360000db8, options=..., start=0x7ff3b884e318, counter=0x7ff3b884e334, flags=0, prelocking_strategy=0x7ff3b884e3b8) at /data/src/10.5/sql/sql_base.cc:4275
#27 0x000055d6ec00362b in open_and_lock_tables (thd=0x7ff360000db8, options=..., tables=0x7ff360017a88, derived=true, flags=0, prelocking_strategy=0x7ff3b884e3b8) at /data/src/10.5/sql/sql_base.cc:5211
#28 0x000055d6ebfb8f59 in open_and_lock_tables (thd=0x7ff360000db8, tables=0x7ff360017a88, derived=true, flags=0) at /data/src/10.5/sql/sql_base.h:507
#29 0x000055d6ec268e01 in open_only_one_table (thd=0x7ff360000db8, table=0x7ff360017a88, repair_table_use_frm=false, is_view_operator_func=false) at /data/src/10.5/sql/sql_admin.cc:405
#30 0x000055d6ec269620 in mysql_admin_table (thd=0x7ff360000db8, tables=0x7ff360017a88, check_opt=0x7ff360006220, operator_name=0x55d6ecee2210 "optimize", lock_type=TL_WRITE, org_open_for_modify=true, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(class handler * const, class THD *, HA_CHECK_OPT *)) 0x55d6ec423f48 <handler::ha_optimize(THD*, st_ha_check_opt*)>, view_operator_func=0x0) at /data/src/10.5/sql/sql_admin.cc:580
#31 0x000055d6ec26c88a in Sql_cmd_optimize_table::execute (this=0x7ff360018160, thd=0x7ff360000db8) at /data/src/10.5/sql/sql_admin.cc:1451
#32 0x000055d6ec0b25e5 in mysql_execute_command (thd=0x7ff360000db8) at /data/src/10.5/sql/sql_parse.cc:6055
#33 0x000055d6ec0b87f6 in mysql_parse (thd=0x7ff360000db8, rawbuf=0x7ff3600179d0 "OPTIMIZE TABLE s", length=16, parser_state=0x7ff3b884f490, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:8099
#34 0x000055d6ec0a476d in dispatch_command (command=COM_QUERY, thd=0x7ff360000db8, packet=0x7ff36000b5b9 "", packet_length=16, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1891
#35 0x000055d6ec0a2f5f in do_command (thd=0x7ff360000db8) at /data/src/10.5/sql/sql_parse.cc:1370
#36 0x000055d6ec252705 in do_handle_one_connection (connect=0x55d6eedb9178, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1410
#37 0x000055d6ec252468 in handle_one_connection (arg=0x55d6eedb9178) at /data/src/10.5/sql/sql_connect.cc:1312
#38 0x000055d6ec7b6743 in pfs_spawn_thread (arg=0x55d6eecfa118) at /data/src/10.5/storage/perfschema/pfs.cc:2201
#39 0x00007ff3bfb0c609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#40 0x00007ff3bf6e0293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

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

ha_innobase::store_lock() was asked to acquire LOCK_S on the sequence for the ALTER SEQUENCE. Could we perhaps avoid doing that?
I can work around that with the following:

15:56:10 /mariadb/10.6$PAGER=cat git diff
diff --git a/storage/innobase/row/row0sel.cc b/storage/innobase/row/row0sel.cc
index 9312e46e46c..0f811cbb694 100644
--- a/storage/innobase/row/row0sel.cc
+++ b/storage/innobase/row/row0sel.cc
@@ -4586,6 +4586,7 @@ row_search_mvcc(
 	isolation level */
 	const bool set_also_gap_locks =
 		prebuilt->select_lock_type != LOCK_NONE
+		&& !prebuilt->table->no_rollback()
 		&& trx->isolation_level > TRX_ISO_READ_COMMITTED
 #ifdef WITH_WSREP
 		&& !wsrep_thd_skip_locking(trx->mysql_thd)

But, the error remains:

10.6 11597e02f3bcca6d3f7b7992c0fa63e45e614b1c with patch

mysqltest: At line 5: query 'ALTER SEQUENCE s INCREMENT= 1000' failed: 1032: Can't find record in 's'

The same error would be reported even if the sequence had previously been altered to ENGINE=MyISAM instead of ENGINE=InnoDB.

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

To make SEQUENCE skip the useless InnoDB persistent statistics:

diff --git a/storage/innobase/include/dict0stats.ic b/storage/innobase/include/dict0stats.ic
index 68592404253..a7f1d877afd 100644
--- a/storage/innobase/include/dict0stats.ic
+++ b/storage/innobase/include/dict0stats.ic
@@ -80,6 +80,10 @@ dict_stats_is_persistent_enabled(const dict_table_t* table)
 	especially when this function is called from
 	dict_stats_update_if_needed(). */
 
+	if (table->no_rollback()) {
+		return false;
+	}
+
 	/* we rely on this read to be atomic */
 	ib_uint32_t	stat_persistent = table->stat_persistent;
 

Finally, to avoid a situation where CREATE SEQUENCE will be recovered as an empty InnoDB "table" (empty, instead of 1 row), the equivalent of FLUSH LOGS could be called:

diff --git a/sql/ha_sequence.cc b/sql/ha_sequence.cc
index 596f8584041..3233b6ab3c1 100644
--- a/sql/ha_sequence.cc
+++ b/sql/ha_sequence.cc
@@ -215,11 +215,13 @@ int ha_sequence::write_row(const uchar *buf)
   if (unlikely(sequence->initialized == SEQUENCE::SEQ_IN_PREPARE))
   {
     /* This calls is from ha_open() as part of create table */
-    DBUG_RETURN(file->write_row(buf));
+    if (likely(!(error= file->write_row(buf))))
+      if (bool (*flush_logs)(handlerton *)= file->ht->flush_logs)
+        flush_logs(file->ht);
+    DBUG_RETURN(error);
   }
   if (unlikely(sequence->initialized == SEQUENCE::SEQ_IN_ALTER))
   {
-    int error= 0;
     /* This is called from alter table */
     tmp_seq.read_fields(table);
     if (tmp_seq.check_and_adjust(0))

monty, I think that your input will be needed on the last one. Also, I still think that it would be better to avoid the ha_innobase::store_lock() call for sequences, so that the work-around condition on every row fetch can be avoided.

Comment by Elena Stepanova [ 2021-11-11 ]

Clearly the same issue, but in this case it's ASAN errors on a non-debug build (so my tests failed to recognize the known problem at first).

--source include/have_innodb.inc
 
CREATE SEQUENCE s start with 0 minvalue -1 ENGINE=Aria ROW_FORMAT=DYNAMIC;
ALTER TABLE s ENGINE InnoDB;
 
--connect (con1,localhost,root,,test)
--error 0,ER_KEY_NOT_FOUND
INSERT INTO s (cache_size) VALUES (1000);
 
--connection default
INSERT IGNORE INTO s (cache_size, cache_size) VALUES (NULL, 817889280);

10.5 9c18b966 non-debug ASAN

==79144==ERROR: AddressSanitizer: global-buffer-overflow on address 0x55f1065ab4fe at pc 0x55f1058e88b7 bp 0x7ff79cd1e450 sp 0x7ff79cd1e440
READ of size 1 at 0x55f1065ab4fe thread T31
    #0 0x55f1058e88b6 in lock_mode_compatible /data/src/10.5/storage/innobase/include/lock0priv.ic:247
    #1 0x55f1058e88b6 in lock_rec_has_to_wait /data/src/10.5/storage/innobase/lock/lock0lock.cc:714
    #2 0x55f1058e88b6 in lock_rec_other_has_conflicting /data/src/10.5/storage/innobase/lock/lock0lock.cc:1102
    #3 0x55f10590715b in lock_rec_lock /data/src/10.5/storage/innobase/lock/lock0lock.cc:1903
    #4 0x55f105908f2e in lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned char const*, dict_index_t*, unsigned short const*, lock_mode, unsigned int, que_thr_t*) /data/src/10.5/storage/innobase/lock/lock0lock.cc:5797
    #5 0x55f105adc810 in sel_set_rec_lock /data/src/10.5/storage/innobase/row/row0sel.cc:1309
    #6 0x55f105adc810 in row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) /data/src/10.5/storage/innobase/row/row0sel.cc:4826
    #7 0x55f1057de6a7 in ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) /data/src/10.5/storage/innobase/handler/ha_innodb.cc:8838
    #8 0x55f1057defce in ha_innobase::index_first(unsigned char*) /data/src/10.5/storage/innobase/handler/ha_innodb.cc:9199
    #9 0x55f1057defce in ha_innobase::rnd_next(unsigned char*) /data/src/10.5/storage/innobase/handler/ha_innodb.cc:9292
    #10 0x55f1057defce in ha_innobase::rnd_next(unsigned char*) /data/src/10.5/storage/innobase/handler/ha_innodb.cc:9282
    #11 0x55f1056f0969 in ha_sequence::rnd_next(unsigned char*) /data/src/10.5/sql/ha_sequence.h:111
    #12 0x55f104d9eb9d in handler::ha_rnd_next(unsigned char*) /data/src/10.5/sql/handler.cc:3080
    #13 0x55f104da4a40 in handler::read_first_row(unsigned char*, unsigned int) /data/src/10.5/sql/handler.cc:3327
    #14 0x55f104beff31 in handler::ha_read_first_row(unsigned char*, unsigned int) /data/src/10.5/sql/sql_class.h:7043
    #15 0x55f104beff31 in SEQUENCE::read_stored_values(TABLE*) /data/src/10.5/sql/sql_sequence.cc:532
    #16 0x55f104bf050b in SEQUENCE::read_initial_values(TABLE*) /data/src/10.5/sql/sql_sequence.cc:494
    #17 0x55f1056ee511 in ha_sequence::open(char const*, int, unsigned int) /data/src/10.5/sql/ha_sequence.cc:118
    #18 0x55f104d9df73 in handler::ha_open(TABLE*, char const*, int, unsigned int, st_mem_root*, List<String>*) /data/src/10.5/sql/handler.cc:2997
    #19 0x55f1049945ea in open_table_from_share(THD*, TABLE_SHARE*, st_mysql_const_lex_string const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, List<String>*) /data/src/10.5/sql/table.cc:4242
    #20 0x55f1044fe084 in open_table(THD*, TABLE_LIST*, Open_table_context*) /data/src/10.5/sql/sql_base.cc:2001
    #21 0x55f104508391 in open_and_process_table /data/src/10.5/sql/sql_base.cc:3786
    #22 0x55f104508391 in open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*) /data/src/10.5/sql/sql_base.cc:4269
    #23 0x55f10450a5f1 in open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*) /data/src/10.5/sql/sql_base.cc:5215
    #24 0x55f1045b4927 in open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int) /data/src/10.5/sql/sql_base.h:507
    #25 0x55f1045b4927 in mysql_insert(THD*, TABLE_LIST*, List<Item>&, List<List<Item> >&, List<Item>&, List<Item>&, enum_duplicates, bool, select_result*) /data/src/10.5/sql/sql_insert.cc:757
    #26 0x55f10468ae38 in mysql_execute_command(THD*) /data/src/10.5/sql/sql_parse.cc:4624
    #27 0x55f10464ec3c in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.5/sql/sql_parse.cc:8100
    #28 0x55f10467cd3d in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.5/sql/sql_parse.cc:1891
    #29 0x55f1046843fa in do_command(THD*) /data/src/10.5/sql/sql_parse.cc:1370
    #30 0x55f104a2dc9c in do_handle_one_connection(CONNECT*, bool) /data/src/10.5/sql/sql_connect.cc:1418
    #31 0x55f104a2e844 in handle_one_connection /data/src/10.5/sql/sql_connect.cc:1312
    #32 0x55f1055bf418 in pfs_spawn_thread /data/src/10.5/storage/perfschema/pfs.cc:2201
    #33 0x7ff7b5271608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477
    #34 0x7ff7b4e44292 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x122292)

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