[MDEV-23801] Assertion `index->table->instant' failed / Assertion `index->table->instant || block->page.id.page_no() != index->page' failed in btr_pcur_store_position / Assertion `block->page.id.page_no() != index->page' failed in btr_pcur_store_position Created: 2020-09-24  Updated: 2023-07-27  Resolved: 2022-09-13

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3, 10.4
Fix Version/s: 10.3.37, 10.4.27, 10.5.18, 10.6.11, 10.7.7, 10.8.6, 10.9.4, 10.10.2

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Issue split
split from MDEV-22714 Assertion `index->table->is_instant()... Closed
Relates
relates to MDEV-24796 Assertion `page_has_next(block->frame... Closed
relates to MDEV-31784 [draft]Assertion `index->table->is_in... Open

 Description   

Split from MDEV-22714:

I cannot get the testcase to repeat at the command prompt, however I have been able to reduce is using the C-API/pquery to the following;

# mysqld options that were in use during reduction: --sql_mode=ONLY_FULL_GROUP_BY --performance-schema --performance-schema-instrument='%=on' --default-tmp-storage-engine=MyISAM --innodb_file_per_table=1 --innodb_flush_method=O_DIRECT
USE test;
CREATE TABLE t1(a BIGINT UNSIGNED) ENGINE=InnoDB;
set global innodb_limit_optimistic_insert_debug = 2;
INSERT INTO t1 VALUES(12979);
ALTER TABLE t1 algorithm=inplace, ADD f DECIMAL(5,2);
insert into t1 values (5175,'abcdefghijklmnopqrstuvwxyz');
DELETE FROM t1;
SELECT HEX(a), HEX(@a:=CONVERT(a USING utf8mb4)), HEX(CONVERT(@a USING utf16le)) FROM t1; ;

10.4.15 eae968f62d285de97ed607c87bc131cd863d5d03

mysqld: /test/10.4_dbg/storage/innobase/btr/btr0pcur.cc:154: void btr_pcur_store_position(btr_pcur_t*, mtr_t*): Assertion `index->table->instant' failed.

10.4.15 eae968f62d285de97ed607c87bc131cd863d5d03

Core was generated by `/test/MD110820-mariadb-10.4.15-linux-x86_64-dbg/bin/mysqld --no-defaults --max_'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
[Current thread is 1 (Thread 0x14d82c06d700 (LWP 1089182))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055943ec758a6 in my_write_core (sig=sig@entry=6) at /test/10.4_dbg/mysys/stacktrace.c:482
#2  0x000055943e3f1cdc in handle_fatal_signal (sig=6) at /test/10.4_dbg/sql/signal_handler.cc:343
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x000014d834a778b1 in __GI_abort () at abort.c:79
#6  0x000014d834a6742a in __assert_fail_base (fmt=0x14d834beea38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55943ef93086 "index->table->instant", file=file@entry=0x55943efe8838 "/test/10.4_dbg/storage/innobase/btr/btr0pcur.cc", line=line@entry=154, function=function@entry=0x55943efe9e00 <btr_pcur_store_position(btr_pcur_t*, mtr_t*)::__PRETTY_FUNCTION__> "void btr_pcur_store_position(btr_pcur_t*, mtr_t*)") at assert.c:92
#7  0x000014d834a674a2 in __GI___assert_fail (assertion=assertion@entry=0x55943ef93086 "index->table->instant", file=file@entry=0x55943efe8838 "/test/10.4_dbg/storage/innobase/btr/btr0pcur.cc", line=line@entry=154, function=function@entry=0x55943efe9e00 <btr_pcur_store_position(btr_pcur_t*, mtr_t*)::__PRETTY_FUNCTION__> "void btr_pcur_store_position(btr_pcur_t*, mtr_t*)") at assert.c:101
#8  0x000055943e8d646f in btr_pcur_store_position (cursor=cursor@entry=0x14d7c43ae988, mtr=mtr@entry=0x14d82c069430) at /test/10.4_dbg/storage/innobase/btr/btr0pcur.cc:154
#9  0x000055943e7eccf3 in row_search_mvcc (buf=buf@entry=0x14d7c4433650 "\377", mode=mode@entry=PAGE_CUR_G, prebuilt=0x14d7c43ae7c0, match_mode=match_mode@entry=0, direction=direction@entry=0) at /test/10.4_dbg/storage/innobase/row/row0sel.cc:5632
#10 0x000055943e6304f4 in ha_innobase::index_read (this=this@entry=0x14d7c4432358, buf=buf@entry=0x14d7c4433650 "\377", key_ptr=key_ptr@entry=0x0, key_len=key_len@entry=0, find_flag=find_flag@entry=HA_READ_AFTER_KEY) at /test/10.4_dbg/storage/innobase/handler/ha_innodb.cc:9214
#11 0x000055943e630772 in ha_innobase::index_first (this=this@entry=0x14d7c4432358, buf=buf@entry=0x14d7c4433650 "\377") at /test/10.4_dbg/storage/innobase/handler/ha_innodb.cc:9588
#12 0x000055943e6307f3 in ha_innobase::rnd_next (this=0x14d7c4432358, buf=0x14d7c4433650 "\377") at /test/10.4_dbg/storage/innobase/handler/ha_innodb.cc:9681
#13 0x000055943e3f95d7 in handler::ha_rnd_next (this=0x14d7c4432358, buf=0x14d7c4433650 "\377") at /test/10.4_dbg/sql/handler.cc:2862
#14 0x000055943e58f634 in rr_sequential (info=0x14d7c4015768) at /test/10.4_dbg/sql/records.cc:485
#15 0x000055943e19f94a in READ_RECORD::read_record (this=0x14d7c4015768) at /test/10.4_dbg/sql/records.h:70
#16 join_init_read_record (tab=0x14d7c40156a0) at /test/10.4_dbg/sql/sql_select.cc:21342
#17 0x000055943e189eeb in sub_select (join=0x14d7c40142c0, join_tab=0x14d7c40156a0, end_of_records=<optimized out>) at /test/10.4_dbg/sql/sql_select.cc:20397
#18 0x000055943e1bba70 in do_select (procedure=0x0, join=0x14d7c40142c0) at /test/10.4_dbg/sql/sql_select.cc:19938
#19 JOIN::exec_inner (this=this@entry=0x14d7c40142c0) at /test/10.4_dbg/sql/sql_select.cc:4473
#20 0x000055943e1bc04d in JOIN::exec (this=this@entry=0x14d7c40142c0) at /test/10.4_dbg/sql/sql_select.cc:4255
#21 0x000055943e1ba3f3 in mysql_select (thd=thd@entry=0x14d7c4000d50, tables=<optimized out>, wild_num=0, fields=@0x14d7c4012398: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x14d7c4012908, last = 0x14d7c4013240, elements = 3}, <No data fields>}, conds=0x0, og_num=<optimized out>, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2148803328, result=0x14d7c4014298, unit=0x14d7c4004c78, select_lex=0x14d7c4012250) at /test/10.4_dbg/sql/sql_select.cc:4687
#22 0x000055943e1ba71e in handle_select (thd=thd@entry=0x14d7c4000d50, lex=lex@entry=0x14d7c4004bb8, result=result@entry=0x14d7c4014298, setup_tables_done_option=setup_tables_done_option@entry=0) at /test/10.4_dbg/sql/sql_select.cc:410
#23 0x000055943e1333c6 in execute_sqlcom_select (thd=thd@entry=0x14d7c4000d50, all_tables=0x14d7c40132e8) at /test/10.4_dbg/sql/sql_parse.cc:6355
#24 0x000055943e13e79a in mysql_execute_command (thd=thd@entry=0x14d7c4000d50) at /test/10.4_dbg/sql/sql_parse.cc:3889
#25 0x000055943e149090 in mysql_parse (thd=thd@entry=0x14d7c4000d50, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14d82c06c470, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:7896
#26 0x000055943e14b920 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14d7c4000d50, packet=packet@entry=0x14d7c401a4b1 "", packet_length=packet_length@entry=90, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:1834
#27 0x000055943e14f35b in do_command (thd=0x14d7c4000d50) at /test/10.4_dbg/sql/sql_parse.cc:1352
#28 0x000055943e27b8b6 in do_handle_one_connection (connect=connect@entry=0x55944187a4f0) at /test/10.4_dbg/sql/sql_connect.cc:1412
#29 0x000055943e27b9d6 in handle_one_connection (arg=arg@entry=0x55944187a4f0) at /test/10.4_dbg/sql/sql_connect.cc:1316
#30 0x000055943eb88898 in pfs_spawn_thread (arg=0x5594417874f0) at /test/10.4_dbg/storage/perfschema/pfs.cc:1869
#31 0x000014d8359de6db in start_thread (arg=0x14d82c06d700) at pthread_create.c:463
#32 0x000014d834b58a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

This in turn may be connected to the other `innodb_limit_optimistic_insert_debug` bugs out there.



 Comments   
Comment by Roel Van de Paar [ 2020-09-24 ]

I have disabled the filter for this issue in the hope of getting a new occurrence. Hopefully the issue is clear from the reduced SQL + stack though.

Comment by Elena Stepanova [ 2022-07-25 ]

marko,
Try this one (with big enough --repeat):

--source include/have_innodb.inc
 
CREATE TABLE t (
  pk int auto_increment,
  c01 char(255) not null default repeat('a',255),
  c02 char(255) default repeat('a',255),
  c03 char(255) default repeat('a',255),
  c04 char(255) default repeat('a',255),
  c05 char(255) not null default repeat('a',255),
  c06 char(255) default repeat('a',255),
  c07 char(255) default repeat('a',255),
  c08 char(255) not null default repeat('a',255),
  c09 char(255) default repeat('a',255),
  c10 char(255) default repeat('a',255),
  c11 char(255) default repeat('a',255),
  c12 char(255) not null default repeat('a',255),
  primary key (pk)
) ENGINE=InnoDB CHARACTER SET ucs2;
 
INSERT INTO t () VALUES (),(),(),(),(),(),(),(),();
 
ALTER TABLE t ADD c INT;
DELETE FROM t LIMIT 9;
DELETE FROM t LIMIT 9;
 
CREATE TABLE tt ENGINE=InnoDB AS SELECT c FROM t;
DROP TABLE t, tt;

Of course, the assertion has changed since the original report, it is now

mysqld: /data/src/10.4/storage/innobase/btr/btr0pcur.cc:155: void btr_pcur_store_position(btr_pcur_t*, mtr_t*): Assertion `index->table->instant || block->page.id.page_no() != index->page' failed.

It fails reasonably well for me, within ~30 attempts on a debug build. It doesn't seem to be rr-able though, so you may have to fall back to the old-fashioned debugging.

Comment by Marko Mäkelä [ 2022-09-12 ]

elenst, thank you. The failing assertion says that whenever a hidden metadata record for MDEV-11369 or MDEV-15562 exists, the index metadata must indicate that instant ALTER TABLE is being used.

I repeated this once without and once with AddressSanitizer so far. The entire contents of the table is a hidden metadata record due to the instantly added column c. For MDEV-11369 instant ADD COLUMN, the design constraint is that whenever the table becomes empty, then the index metadata will be converted to the canonical format (pretending that all columns always existed) and the index page should be emptied as well. This constraint was abolished for MDEV-15562 instant DROP COLUMN, that is, a table or partition on which instant DROP COLUMN or reordering columns was ever performed will stay in that format even if is emptied.

Indeed, it looks like this won’t repeat under rr. Old-fashioning debugging with core dumps and some added some diagnostic output should work.

Comment by Marko Mäkelä [ 2022-09-12 ]

If I disable the purge of history in the test by adding the following to the start, then it will not fail:

connect stop_purge,localhost,root;
START TRANSACTION WITH CONSISTENT SNAPSHOT;
connection default;

Comment by Marko Mäkelä [ 2022-09-12 ]

I tried to make the test a little more deterministic. The test still fails, but only occasionally, and never under rr.

--source include/have_innodb.inc
 
SET @saved_frequency = @@GLOBAL.innodb_purge_rseg_truncate_frequency;
SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
 
CREATE TABLE t (
  pk int auto_increment,
  c01 char(255) not null default repeat('a',255),
  c02 char(255) default repeat('a',255),
  c03 char(255) default repeat('a',255),
  c04 char(255) default repeat('a',255),
  c05 char(255) not null default repeat('a',255),
  c06 char(255) default repeat('a',255),
  c07 char(255) default repeat('a',255),
  c08 char(255) not null default repeat('a',255),
  c09 char(255) default repeat('a',255),
  c10 char(255) default repeat('a',255),
  c11 char(255) default repeat('a',255),
  c12 char(255) not null default repeat('a',255),
  primary key (pk)
) ENGINE=InnoDB CHARACTER SET ucs2;
 
INSERT INTO t () VALUES (),(),(),(),(),(),(),(),();
 
ALTER TABLE t ADD c INT;
DELETE FROM t;
 
--source include/wait_all_purged.inc
 
CREATE TABLE tt ENGINE=InnoDB AS SELECT c FROM t;
DROP TABLE t, tt;
 
SET GLOBAL innodb_purge_rseg_truncate_frequency = @saved_frequency;

Because rr is out of the picture, I planted quite a few abort() or my_print_stacktrace() to the code to see where the metadata would be reset, but did not get any breakthrough yet.

Finally, I realized that the assertion expression is actually claiming that MDEV-15562 (instant DROP or reordering of columns) has been used. That is too strict an assertion for this case:

#11 0x000055fd6de27863 in btr_pcur_store_position (
    cursor=cursor@entry=0x7fecd419fc60, mtr=mtr@entry=0x7fed213a0450)
    at /mariadb/10.4/storage/innobase/btr/btr0pcur.cc:155
155				ut_ad(index->table->instant
(gdb) p index.n_fields
$1 = 16
(gdb) p index.n_core_fields
$2 = 15

That is, the index is indeed still in "instant ADD" format, containing just the metadata record. If I relax that debug assertion, then it will not crash:

diff --git a/storage/innobase/btr/btr0pcur.cc b/storage/innobase/btr/btr0pcur.cc
index c31db34186c..36cdc5f0f77 100644
--- a/storage/innobase/btr/btr0pcur.cc
+++ b/storage/innobase/btr/btr0pcur.cc
@@ -152,7 +152,7 @@ btr_pcur_store_position(
 
 		ut_ad(!page_rec_is_infimum(rec));
 		if (UNIV_UNLIKELY(rec_is_metadata(rec, *index))) {
-			ut_ad(index->table->instant
+			ut_ad(index->is_instant() || index->table->instant
 			      || block->page.id.page_no() != index->page);
 			ut_ad(page_get_n_recs(block->frame) == 1);
 			ut_ad(page_is_leaf(block->frame));

I think that it would be an incorrect fix. We really want the instant ADD COLUMN metadata to be removed at every opportunity when the table becomes empty. I will search further.

Comment by Marko Mäkelä [ 2022-09-12 ]

At the time of the assertion failure, the buffer pool contains pages 3 (the clustered index root page which is supposed to be empty) and pages 4 and 5 (former leaf pages of the index, from an earlier point of time when the root page 3 was a non-leaf page and pointing to those leaf pages). Page 4 only contains the hidden metadata record, and page 5 would contain 1 delete-marked record. This observation led me to the right track:

diff --git a/storage/innobase/btr/btr0btr.cc b/storage/innobase/btr/btr0btr.cc
index 67ac5e357f6..7215632c9cc 100644
--- a/storage/innobase/btr/btr0btr.cc
+++ b/storage/innobase/btr/btr0btr.cc
@@ -3489,6 +3489,7 @@ btr_lift_page_up(
 	if (index->is_instant()
 	    && father_block->page.id.page_no() == root_page_no) {
 		ut_ad(!father_page_zip);
+		ut_ad(page_get_n_recs(block->frame) > 1);
 		btr_set_instant(father_block, *index, mtr);
 	}
 

In btr_lift_page_up(), we miss the opportunity to remove the MDEV-11369 metadata when the table becomes empty.

Comment by Marko Mäkelä [ 2022-09-12 ]

I think that I figured out one source of nondeterminism. With the default value innodb_purge_threads=4, there would be multiple threads deleting the individual records from the index page, in any order. I could not get the test to crash when using innodb_purge_threads=1, until I tweaked the test so that the records would be deleted in descending order. Even with that, the failure is not deterministic, but it does occasionally fail with innodb_purge_threads=1:

--source include/have_innodb.inc
 
SET @saved_frequency = @@GLOBAL.innodb_purge_rseg_truncate_frequency;
SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
 
CREATE TABLE t (
  pk int auto_increment,
  c01 char(255) not null default repeat('a',255),
  c02 char(255) default repeat('a',255),
  c03 char(255) default repeat('a',255),
  c04 char(255) default repeat('a',255),
  c05 char(255) not null default repeat('a',255),
  c06 char(255) default repeat('a',255),
  c07 char(255) default repeat('a',255),
  c08 char(255) not null default repeat('a',255),
  c09 char(255) default repeat('a',255),
  c10 char(255) default repeat('a',255),
  c11 char(255) default repeat('a',255),
  c12 char(255) not null default repeat('a',255),
  primary key (pk)
) ENGINE=InnoDB CHARACTER SET ucs2;
 
INSERT INTO t () VALUES (),(),(),(),(),(),(),(),();
 
ALTER TABLE t ADD c INT;
DELETE FROM t WHERE pk=9;
DELETE FROM t WHERE pk=8;
DELETE FROM t WHERE pk=7;
DELETE FROM t WHERE pk=6;
DELETE FROM t WHERE pk=5;
DELETE FROM t WHERE pk=4;
DELETE FROM t WHERE pk=3;
DELETE FROM t WHERE pk=2;
DELETE FROM t;
 
--source include/wait_all_purged.inc
SET GLOBAL innodb_purge_rseg_truncate_frequency = @saved_frequency;
 
CREATE TABLE tt ENGINE=InnoDB AS SELECT c FROM t;
DROP TABLE t, tt;

Comment by Marko Mäkelä [ 2022-09-12 ]

The following will deterministically fail for me, with any amount of innodb_purge_threads. The ROLLBACK of INSERT is instantaneous.

--source include/have_innodb.inc
 
SET @saved_frequency = @@GLOBAL.innodb_purge_rseg_truncate_frequency;
SET GLOBAL innodb_purge_rseg_truncate_frequency = 1;
 
CREATE TABLE t (
  pk int auto_increment primary key,
  c01 char(255) not null default repeat('a',255),
  c02 char(255) default repeat('a',255),
  c03 char(255) default repeat('a',255),
  c04 char(255) default repeat('a',255),
  c05 char(255) not null default repeat('a',255),
  c06 char(255) default repeat('a',255),
  c07 char(255) default repeat('a',255),
  c08 char(255) not null default repeat('a',255),
  c09 char(255) default repeat('a',255),
  c10 char(255) default repeat('a',255),
  c11 char(255) default repeat('a',255),
  c12 char(255) not null default repeat('a',255)
) ENGINE=InnoDB CHARACTER SET ucs2;
 
INSERT INTO t () VALUES ();
ALTER TABLE t ADD c INT;
 
BEGIN;
INSERT INTO t () VALUES (),(),(),(),(),(),(),();
ROLLBACK;
DELETE FROM t;
 
--source include/wait_all_purged.inc
SET GLOBAL innodb_purge_rseg_truncate_frequency = @saved_frequency;
 
CREATE TABLE tt ENGINE=InnoDB AS SELECT c FROM t;
DROP TABLE t, tt;

Comment by Marko Mäkelä [ 2022-09-12 ]

Note: The debug assertion is merely complaining about a failure to optimize the table when it becomes empty. The user impact of this should be minimal.

Comment by Roel Van de Paar [ 2022-09-13 ]

Using Marko's last testcase, I used reducer to simplify it further. It looks like it is almost-deterministic (let's say 98%). Here is the reduced testcase + full report (note especially the 10.3 assert):

CREATE TABLE t (c0 CHAR(255) NOT NULL DEFAULT REPEAT ('',255),c1 CHAR(255) DEFAULT REPEAT ('',255),c2 CHAR(255) DEFAULT REPEAT ('',255),c3 CHAR(255) NOT NULL DEFAULT REPEAT ('',255),c4 CHAR(255) DEFAULT REPEAT ('',255),c6 CHAR(255) DEFAULT REPEAT ('',255),c7 CHAR(255) DEFAULT REPEAT ('',255),c8 CHAR(255) DEFAULT REPEAT ('',255),c9 CHAR(255) NOT NULL DEFAULT REPEAT ('',255)) ENGINE=InnoDB CHARACTER SET ucs2;
INSERT INTO t() VALUES ();
ALTER TABLE t ADD c INT;
BEGIN;
INSERT INTO t() VALUES (),();
DELETE FROM t;
CREATE TABLE tt ENGINE=InnoDB AS SELECT c FROM t;

Leads to:

10.3.37 a1055ab35d29437b717e83b1a388eaa02901c42f (Debug)

mysqld: /test/10.3_dbg/storage/innobase/btr/btr0pcur.cc:161: void btr_pcur_store_position(btr_pcur_t*, mtr_t*): Assertion `block->page.id.page_no() != index->page' failed.

10.3.37 a1055ab35d29437b717e83b1a388eaa02901c42f (Debug)

Core was generated by `/test/MD200822-mariadb-10.3.37-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
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 0x147c5482b700 (LWP 1297176))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000147c7b059859 in __GI_abort () at abort.c:79
#2  0x0000147c7b059729 in __assert_fail_base (fmt=0x147c7b1ef588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5593e7241b08 "block->page.id.page_no() != index->page", file=0x5593e72489e0 "/test/10.3_dbg/storage/innobase/btr/btr0pcur.cc", line=161, function=<optimized out>) at assert.c:92
#3  0x0000147c7b06afd6 in __GI___assert_fail (assertion=assertion@entry=0x5593e7241b08 "block->page.id.page_no() != index->page", file=file@entry=0x5593e72489e0 "/test/10.3_dbg/storage/innobase/btr/btr0pcur.cc", line=line@entry=161, function=function@entry=0x5593e7248a10 "void btr_pcur_store_position(btr_pcur_t*, mtr_t*)") at assert.c:101
#4  0x00005593e6ccd7cd in btr_pcur_store_position (cursor=cursor@entry=0x147c1c022200, mtr=mtr@entry=0x147c548283d0) at /test/10.3_dbg/storage/innobase/include/buf0types.h:163
#5  0x00005593e6bd7c7a in row_search_mvcc (buf=buf@entry=0x147c1c04ed38 "\377", mode=<optimized out>, mode@entry=PAGE_CUR_G, prebuilt=0x147c1c022040, match_mode=match_mode@entry=0, direction=direction@entry=0) at /test/10.3_dbg/storage/innobase/row/row0sel.cc:5739
#6  0x00005593e6a0dbef in ha_innobase::index_read (this=0x147c1c02fad8, buf=0x147c1c04ed38 "\377", key_ptr=<optimized out>, key_len=<optimized out>, find_flag=<optimized out>) at /test/10.3_dbg/storage/innobase/handler/ha_innodb.cc:9413
#7  0x00005593e69f1ccd in ha_innobase::index_first (this=<optimized out>, buf=<optimized out>) at /test/10.3_dbg/storage/innobase/handler/ha_innodb.cc:9795
#8  0x00005593e6a041ce in ha_innobase::rnd_next (this=0x147c1c02fad8, buf=<optimized out>) at /test/10.3_dbg/storage/innobase/handler/ha_innodb.cc:9888
#9  0x00005593e67ff56b in handler::ha_rnd_next (this=0x147c1c02fad8, buf=0x147c1c04ed38 "\377") at /test/10.3_dbg/sql/handler.cc:2858
#10 0x00005593e6980781 in rr_sequential (info=0x147c1c014288) at /test/10.3_dbg/sql/records.h:71
#11 0x00005593e65fa77d in READ_RECORD::read_record (this=0x147c1c014288) at /test/10.3_dbg/sql/records.h:70
#12 join_init_read_record (tab=0x147c1c0141c0) at /test/10.3_dbg/sql/sql_select.cc:20874
#13 0x00005593e65e499e in sub_select (join=0x147c1c012620, join_tab=0x147c1c0141c0, end_of_records=false) at /test/10.3_dbg/sql/sql_select.cc:19929
#14 0x00005593e6610d39 in do_select (procedure=<optimized out>, join=0x147c1c012620) at /test/10.3_dbg/sql/sql_select.cc:19470
#15 JOIN::exec_inner (this=this@entry=0x147c1c012620) at /test/10.3_dbg/sql/sql_select.cc:4171
#16 0x00005593e66113d2 in JOIN::exec (this=this@entry=0x147c1c012620) at /test/10.3_dbg/sql/sql_select.cc:3965
#17 0x00005593e66115c5 in mysql_select (thd=thd@entry=0x147c1c000d90, tables=0x147c1c011cc8, wild_num=0, fields=@0x147c1c005368: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x147c1c011c80, last = 0x147c1c011c80, elements = 1}, <No data fields>}, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2416184064, result=0x147c1c012528, unit=0x147c1c004aa8, select_lex=0x147c1c005240) at /test/10.3_dbg/sql/sql_select.cc:4374
#18 0x00005593e6612096 in handle_select (thd=thd@entry=0x147c1c000d90, lex=lex@entry=0x147c1c0049e8, result=result@entry=0x147c1c012528, setup_tables_done_option=setup_tables_done_option@entry=0) at /test/10.3_dbg/sql/sql_select.cc:372
#19 0x00005593e6652750 in Sql_cmd_create_table_like::execute (this=0x147c1c0114d8, thd=0x147c1c000d90) at /test/10.3_dbg/sql/sql_table.cc:11399
#20 0x00005593e65aa140 in mysql_execute_command (thd=thd@entry=0x147c1c000d90) at /test/10.3_dbg/sql/sql_parse.cc:6076
#21 0x00005593e65aba65 in mysql_parse (thd=thd@entry=0x147c1c000d90, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x147c5482a5e0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.3_dbg/sql/sql_parse.cc:7871
#22 0x00005593e65adaf9 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x147c1c000d90, packet=packet@entry=0x147c1c019751 "CREATE TABLE tt ENGINE=InnoDB AS SELECT c FROM t", packet_length=packet_length@entry=48, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.3_dbg/sql/sql_class.h:1152
#23 0x00005593e65aff75 in do_command (thd=0x147c1c000d90) at /test/10.3_dbg/sql/sql_parse.cc:1398
#24 0x00005593e66ba18f in do_handle_one_connection (connect=<optimized out>) at /test/10.3_dbg/sql/sql_connect.cc:1403
#25 0x00005593e66ba2bf in handle_one_connection (arg=<optimized out>) at /test/10.3_dbg/sql/sql_connect.cc:1308
#26 0x0000147c7b231609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#27 0x0000147c7b156133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.4.27 3101751f505f39d2ccecd03a916ecdbf2f380740 (Debug)

mysqld: /test/10.4_dbg/storage/innobase/btr/btr0pcur.cc:155: void btr_pcur_store_position(btr_pcur_t*, mtr_t*): Assertion `index->table->instant || block->page.id.page_no() != index->page' failed.

10.4.27 3101751f505f39d2ccecd03a916ecdbf2f380740 (Debug)

Core was generated by `/test/MD200822-mariadb-10.4.27-linux-x86_64-dbg/bin/mysqld --no-defaults --core'.
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 0x1546d4eac700 (LWP 1297164))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00001546ef971859 in __GI_abort () at abort.c:79
#2  0x00001546ef971729 in __assert_fail_base (fmt=0x1546efb07588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5577914c9340 "index->table->instant || block->page.id.page_no() != index->page", file=0x5577914c91c0 "/test/10.4_dbg/storage/innobase/btr/btr0pcur.cc", line=155, function=<optimized out>) at assert.c:92
#3  0x00001546ef982fd6 in __GI___assert_fail (assertion=assertion@entry=0x5577914c9340 "index->table->instant || block->page.id.page_no() != index->page", file=file@entry=0x5577914c91c0 "/test/10.4_dbg/storage/innobase/btr/btr0pcur.cc", line=line@entry=155, function=function@entry=0x5577914c91f0 "void btr_pcur_store_position(btr_pcur_t*, mtr_t*)") at assert.c:101
#4  0x0000557790ef5c59 in btr_pcur_store_position (cursor=cursor@entry=0x154690022c88, mtr=mtr@entry=0x1546d4ea8ff0) at /test/10.4_dbg/storage/innobase/include/buf0types.h:172
#5  0x0000557790e03cff in row_search_mvcc (buf=buf@entry=0x1546900779f8 "\377", mode=<optimized out>, mode@entry=PAGE_CUR_G, prebuilt=0x154690022ac0, match_mode=match_mode@entry=0, direction=direction@entry=0) at /test/10.4_dbg/storage/innobase/row/row0sel.cc:5745
#6  0x0000557790c1f72a in ha_innobase::index_read (this=this@entry=0x1546900771f8, buf=0x1546900779f8 "\377", key_ptr=key_ptr@entry=0x0, key_len=key_len@entry=0, find_flag=find_flag@entry=HA_READ_AFTER_KEY) at /test/10.4_dbg/storage/innobase/handler/ha_innodb.cc:9396
#7  0x0000557790c1fa85 in ha_innobase::index_first (this=this@entry=0x1546900771f8, buf=<optimized out>) at /test/10.4_dbg/storage/innobase/handler/ha_innodb.cc:9778
#8  0x0000557790c1fab0 in ha_innobase::rnd_next (this=0x1546900771f8, buf=<optimized out>) at /test/10.4_dbg/storage/innobase/handler/ha_innodb.cc:9871
#9  0x00005577908e3760 in handler::ha_rnd_next (this=0x1546900771f8, buf=0x1546900779f8 "\377") at /test/10.4_dbg/sql/handler.cc:2891
#10 0x0000557790a94843 in rr_sequential (info=0x154690016dd8) at /test/10.4_dbg/sql/records.h:71
#11 0x00005577906b9fa1 in READ_RECORD::read_record (this=0x154690016dd8) at /test/10.4_dbg/sql/records.h:70
#12 join_init_read_record (tab=0x154690016d10) at /test/10.4_dbg/sql/sql_select.cc:21632
#13 0x00005577906a3da6 in sub_select (join=0x154690015070, join_tab=0x154690016d10, end_of_records=false) at /test/10.4_dbg/sql/sql_select.cc:20681
#14 0x00005577906d633d in do_select (procedure=<optimized out>, join=0x154690015070) at /test/10.4_dbg/sql/sql_select.cc:20220
#15 JOIN::exec_inner (this=this@entry=0x154690015070) at /test/10.4_dbg/sql/sql_select.cc:4565
#16 0x00005577906d6854 in JOIN::exec (this=this@entry=0x154690015070) at /test/10.4_dbg/sql/sql_select.cc:4347
#17 0x00005577906d4d0d in mysql_select (thd=thd@entry=0x154690000d90, tables=0x154690013e88, wild_num=0, fields=@0x1546900139e8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x154690013e40, last = 0x154690013e40, elements = 1}, <No data fields>}, conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=<optimized out>, result=0x154690014f78, unit=0x154690004b28, select_lex=0x1546900138a0) at /test/10.4_dbg/sql/sql_select.cc:4786
#18 0x00005577906d4fbd in handle_select (thd=thd@entry=0x154690000d90, lex=lex@entry=0x154690004a68, result=result@entry=0x154690014f78, setup_tables_done_option=setup_tables_done_option@entry=0) at /test/10.4_dbg/sql/sql_select.cc:436
#19 0x000055779071cdae in Sql_cmd_create_table_like::execute (this=<optimized out>, thd=0x154690000d90) at /test/10.4_dbg/sql/sql_table.cc:11615
#20 0x0000557790661e05 in mysql_execute_command (thd=thd@entry=0x154690000d90) at /test/10.4_dbg/sql/sql_parse.cc:6193
#21 0x0000557790663f3d in mysql_parse (thd=thd@entry=0x154690000d90, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1546d4eab3f0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:7996
#22 0x0000557790666a63 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x154690000d90, packet=packet@entry=0x15469001a1d1 "CREATE TABLE tt ENGINE=InnoDB AS SELECT c FROM t", packet_length=packet_length@entry=48, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_class.h:1201
#23 0x0000557790669524 in do_command (thd=0x154690000d90) at /test/10.4_dbg/sql/sql_parse.cc:1378
#24 0x000055779078a86b in do_handle_one_connection (connect=<optimized out>) at /test/10.4_dbg/sql/sql_connect.cc:1420
#25 0x000055779078a92b in handle_one_connection (arg=<optimized out>) at /test/10.4_dbg/sql/sql_connect.cc:1316
#26 0x00001546efe82609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#27 0x00001546efa6e133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.3.37 (dbg), 10.4.27 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.3.37 (opt), 10.4.27 (opt), 10.5.18 (dbg), 10.5.18 (opt), 10.6.10 (dbg), 10.6.10 (opt), 10.7.6 (dbg), 10.7.6 (opt), 10.8.5 (dbg), 10.8.5 (opt), 10.9.2 (dbg), 10.9.2 (opt), 10.10.2 (dbg), 10.10.2 (opt), 10.11.0 (dbg), 10.11.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.38 (dbg), 5.7.38 (opt), 8.0.29 (dbg), 8.0.29 (opt)

Comment by Roel Van de Paar [ 2022-09-13 ]

All UniqueID's/stacks observed thus far (past + now):

index->table->is_instant()|SIGABRT|btr_cur_upd_rec_in_place|btr_cur_update_in_place|btr_cur_optimistic_update|row_upd_clust_rec
index->table->instant|SIGABRT|btr_pcur_store_position|row_search_mvcc|ha_innobase::index_read|ha_innobase::index_first
block->page.id.page_no() != index->page|SIGABRT|btr_pcur_store_position|row_search_mvcc|ha_innobase::index_read|ha_innobase::index_first
index->table->instant || block->page.id.page_no() != index->page|SIGABRT|btr_pcur_store_position|row_search_mvcc|ha_innobase::index_read|ha_innobase::index_first

Comment by Marko Mäkelä [ 2022-09-13 ]

Indeed, it suffices to write 2 rows instead of 8 in the BEGIN;INSERT;ROLLBACK transaction, and a debug assertion about the missed optimization opportunity does fail in 10.3 as well.

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