[MDEV-24072] Assertion 'ib_table.n_v_cols' failed in instant_alter_column_possible Created: 2020-10-31  Updated: 2020-11-10  Resolved: 2020-11-02

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Virtual Columns
Affects Version/s: 10.4, 10.5, 10.6
Fix Version/s: 10.4.18, 10.5.9

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: debug, not-10.1, not-10.2, not-10.3


 Description    

USE test;
 
CREATE TABLE t (a BLOB) ENGINE=InnoDB;
 
INSERT INTO t VALUES ('a');
 
ALTER TABLE t ADD COLUMN (c INT GENERATED ALWAYS AS (a+1) VIRTUAL), ADD INDEX idx1 (c);
 
ALTER TABLE t ADD d INT, ALGORITHM=INPLACE;

Leads to:

10.5.7 e3fc9c1db04bdc5566bcdafcc3d5159199089c00 (Debug)

 
mysqld: /test/10.5_dbg/storage/innobase/handler/handler0alter.cc:1467: bool instant_alter_column_possible(const dict_table_t&, const Alter_inplace_info*, const TABLE*, const TABLE*, bool): Assertion `ib_table.n_v_cols' failed.

10.5.7 e3fc9c1db04bdc5566bcdafcc3d5159199089c00 (Debug)

 
Core was generated by `/test/MD211020-mariadb-10.5.7-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
[Current thread is 1 (Thread 0x150a4c1ad700 (LWP 859941))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
 
#1  0x0000559d913e7869 in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:424
 
#2  0x0000559d90b3cf1f in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#5  0x0000150a61229859 in __GI_abort () at abort.c:79
 
#6  0x0000150a61229729 in __assert_fail_base (fmt=0x150a613bf588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x559d9179b780 "ib_table.n_v_cols", file=0x559d91796998 "/test/10.5_dbg/storage/innobase/handler/handler0alter.cc", line=1467, function=<optimized out>) at assert.c:92
 
#7  0x0000150a6123af36 in __GI___assert_fail (assertion=assertion@entry=0x559d9179b780 "ib_table.n_v_cols", file=file@entry=0x559d91796998 "/test/10.5_dbg/storage/innobase/handler/handler0alter.cc", line=line@entry=1467, function=function@entry=0x559d91796d80 "bool instant_alter_column_possible(const dict_table_t&, const Alter_inplace_info*, const TABLE*, const TABLE*, bool)") at assert.c:101
 
#8  0x0000559d90f683ec in instant_alter_column_possible (ib_table=Python Exception <class 'AttributeError'> 'NoneType' object has no attribute 'pointer': 
Python Exception <class 'AttributeError'> 'NoneType' object has no attribute 'pointer': 
@0x1509f801e848: {id = 20, id_hash = 0x0, name = {m_name = 0x1509f801ce48 "test/t", static part_suffix = "#P#"}, name_hash = 0x0, heap = 0x1509f801e6b8, data_dir_path = 0x0, space = 0x1509f80207f8, space_id = 5, flags = 33, flags2 = 80, skip_alter_undo = 0, file_unreadable = 0, cached = 1, to_be_dropped = 0, n_def = 4, n_cols = 4, n_t_cols = 4, n_t_def = 4, n_v_def = 0, n_v_cols = 0, persistent_autoinc = 0, can_be_evicted = 1, corrupted = 0, drop_aborted = 1, cols = 0x1509f801ec38, v_cols = 0x1509f801ecb8, s_cols = 0x0, instant = 0x0, col_names = 0x1509f801ed10 "a", v_col_names = 0x0, vers_start = 0, vers_end = 0, is_system_db = false, dict_frm_mismatch = DICT_FRM_CONSISTENT, fts_doc_id_index = 0x0, indexes = {count = 2, start = 0x1509f8022158, end = 0x1509f8077d28, node = &dict_index_t::indexes, init = 51966}, freed_indexes = {count = 0, start = 0x0, end = 0x0, node = &dict_index_t::indexes, init = 51966}, foreign_list = {count = 0, start = 0x0, end = 0x0, node = &dict_foreign_t::heap, init = 0}, referenced_list = {count = 0, start = 0x0, end = 0x0, node = &dict_foreign_t::heap, init = 0}, table_LRU = {prev = 0x0, next = 0x150a2c0120c8}, fk_max_recusive_level = 0, n_foreign_key_checks_running = {m_counter = {<std::__atomic_base<int>> = {static _S_alignment = 4, _M_i = 0}, <No data fields>}}, query_cache_inv_trx_id = 30, def_trx_id = 31, foreign_set = std::set with 0 elements, referenced_set = std::set with 0 elements, stats_latch = {<latch_t> = {_vptr.latch_t = 0x559d91c902d8 <vtable for rw_lock_t+16>, m_id = LATCH_ID_INDEX_TREE, m_rw_lock = true}, <ilist_node<void>> = {next = 0x150a0401bb28, prev = 0x1509f80208b0}, created = true, lock_word = {m = {<std::__atomic_base<int>> = {static _S_alignment = 4, _M_i = 536870912}, <No data fields>}}, waiters = {m = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 0}, <No data fields>}}, sx_recursive = 0, writer_thread = 0, event = 0x1509f801f3e8, wait_ex_event = 0x1509f801f478, cfile_name = 0x559d91811650 "/test/10.5_dbg/storage/innobase/dict/dict0mem.cc", last_x_file_name = 0x559d91812398 "/test/10.5_dbg/storage/innobase/dict/dict0stats.cc", cline = 214, is_block_lock = 0, last_x_line = 3262, count_os_wait = 0, pfs_psi = 0x0, debug_list = {count = 0, start = 0x0, end = 0x0, node = &rw_lock_debug_t::list, init = 51966}, level = SYNC_INDEX_TREE}, stats_latch_inited = true, stat_initialized = 1, stats_last_recalc = 0, stat_persistent = 0, stats_auto_recalc = 0, stats_sample_pages = 0, stat_n_rows = 1, stat_clustered_index_size = 1, stat_sum_of_other_index_sizes = 0, stat_modified_counter = 1, stats_bg_flag = 0 '\000', stats_error_printed = false, autoinc_lock = 0x1509f801ecb8, autoinc_mutex = {<std::__mutex_base> = {_M_mutex = pthread_mutex_t = {
 
            Type = Normal,
 
            Status = Not acquired,
 
            Robust = No,
 
            Shared = No,
 
            Protocol = None
 
          }}, <No data fields>}, autoinc = 0, n_waiting_or_granted_auto_inc_locks = 0, autoinc_trx = 0x0, fts = 0x0, quiesce = QUIESCE_NONE, n_rec_locks = 0, n_ref_count = {m_counter = {<std::__atomic_base<unsigned int>> = {static _S_alignment = 4, _M_i = 1}, <No data fields>}}, locks = {count = 0, start = 0x0, end = 0x0, node = &lock_table_t::locks, init = 51966}, update_time = 1604133412, magic_n = 76333786, vc_templ = 0x0}, ha_alter_info=ha_alter_info@entry=0x150a4c1a9740, table=0x1509f8024018, altered_table=altered_table@entry=0x150a4c1a97e0, strict=<optimized out>) at /test/10.5_dbg/storage/innobase/handler/handler0alter.cc:1467
 
#9  0x0000559d90f6fff4 in ha_innobase::check_if_supported_inplace_alter (this=0x1509f8024910, altered_table=0x150a4c1a97e0, ha_alter_info=0x150a4c1a9740) at /test/10.5_dbg/storage/innobase/handler/ha_innodb.h:445
 
#10 0x0000559d90954cc8 in mysql_alter_table (thd=thd@entry=0x1509f8000db8, new_db=new_db@entry=0x1509f8005800, new_name=new_name@entry=0x1509f8005c00, create_info=create_info@entry=0x150a4c1ab470, table_list=<optimized out>, table_list@entry=0x1509f8012a18, alter_info=alter_info@entry=0x150a4c1ab3a0, order_num=0, order=0x0, ignore=false, if_exists=false) at /test/10.5_dbg/sql/sql_table.cc:10526
 
#11 0x0000559d909d9f35 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x1509f8000db8) at /test/10.5_dbg/sql/structs.h:559
 
#12 0x0000559d9087f64b in mysql_execute_command (thd=thd@entry=0x1509f8000db8) at /test/10.5_dbg/sql/sql_parse.cc:5952
 
#13 0x0000559d90865e17 in mysql_parse (thd=thd@entry=0x1509f8000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x150a4c1ac3d0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7994
 
#14 0x0000559d90874133 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1509f8000db8, packet=packet@entry=0x1509f8008f89 "ALTER TABLE t ADD d INT, ALGORITHM=INPLACE", packet_length=packet_length@entry=42, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_class.h:1254
 
#15 0x0000559d9087785e in do_command (thd=0x1509f8000db8) at /test/10.5_dbg/sql/sql_parse.cc:1348
 
#16 0x0000559d909d22c6 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x559d935e6158, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1410
 
#17 0x0000559d909d29cd in handle_one_connection (arg=arg@entry=0x559d935e6158) at /test/10.5_dbg/sql/sql_connect.cc:1312
 
#18 0x0000559d90e87cfd in pfs_spawn_thread (arg=0x559d934ee178) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#19 0x0000150a61737609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#20 0x0000150a61326293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.16 (dbg), 10.5.7 (dbg), 10.6.0 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.48 (dbg), 10.1.48 (opt), 10.2.35 (dbg), 10.2.35 (opt), 10.3.26 (dbg), 10.3.26 (opt), 10.4.16 (opt), 10.5.7 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.50 (dbg), 5.6.50 (opt), 5.7.32 (dbg), 5.7.32 (opt), 8.0.22 (dbg), 8.0.22 (opt)

 Comments   
Comment by Marko Mäkelä [ 2020-10-31 ]

The failing debug assertion is enforcing a consistency check:

#if 1 // MDEV-17468: fix bugs with indexed virtual columns & remove this
 
		for (const dict_index_t* index = ib_table.indexes.start;
 
		     index; index = index->indexes.next) {
 
			if (index->has_virtual()) {
 
				ut_ad(ib_table.n_v_cols);
 
				return false;
 
			}
 
		}
 
#endif

This code is implementing a limitation: you cannot instantly add a column if indexed virtual columns exist.

The interesting question is why the virtual column c is not being counted as one, and when this regression occurred. (I might suspect MDEV-23672, but I cannot repeat the reported failure.)

There is also something else fishy about this test: the expression for coulmn c is flagged invalid. I have to actually disable the strict sql_mode to demote that error into a warning:

--source include/have_innodb.inc
 
CREATE TABLE t (a BLOB) ENGINE=InnoDB;
 
INSERT INTO t VALUES ('a');
 
SET sql_mode='';
 
ALTER TABLE t ADD COLUMN (c INT GENERATED ALWAYS AS (a+1) VIRTUAL), ADD INDEX idx1 (c);
 
SHOW CREATE TABLE t;
 
ALTER TABLE t ADD d INT, ALGORITHM=INPLACE;
 
DROP TABLE t;

With this test, I see the following:

10.4 1fddccf676e213f94923f5efaaa76d9793b19a89

 
CREATE TABLE t (a BLOB) ENGINE=InnoDB;
 
INSERT INTO t VALUES ('a');
 
SET sql_mode='';
 
ALTER TABLE t ADD COLUMN (c INT GENERATED ALWAYS AS (a+1) VIRTUAL), ADD INDEX idx1 (c);
 
Warnings:
 
Warning	1292	Truncated incorrect DOUBLE value: 'a'
 
SHOW CREATE TABLE t;
 
Table	Create Table
 
t	CREATE TABLE `t` (
 
  `a` blob DEFAULT NULL,
 
  `c` int(11) GENERATED ALWAYS AS (`a` + 1) VIRTUAL,
 
  KEY `idx1` (`c`)
 
) ENGINE=InnoDB DEFAULT CHARSET=latin1
 
ALTER TABLE t ADD d INT, ALGORITHM=INPLACE;
 
Warnings:
 
Warning	1292	Truncated incorrect DOUBLE value: 'a'
 
DROP TABLE t;

and

10.5 b0ff791618d97487fb7515d3f785b37f46eba132

 
CREATE TABLE t (a BLOB) ENGINE=InnoDB;
 
INSERT INTO t VALUES ('a');
 
SET sql_mode='';
 
ALTER TABLE t ADD COLUMN (c INT GENERATED ALWAYS AS (a+1) VIRTUAL), ADD INDEX idx1 (c);
 
Warnings:
 
Warning	1292	Truncated incorrect DOUBLE value: 'a'
 
SHOW CREATE TABLE t;
 
Table	Create Table
 
t	CREATE TABLE `t` (
 
  `a` blob DEFAULT NULL,
 
  `c` int(11) GENERATED ALWAYS AS (`a` + 1) VIRTUAL,
 
  KEY `idx1` (`c`)
 
) ENGINE=InnoDB DEFAULT CHARSET=latin1
 
ALTER TABLE t ADD d INT, ALGORITHM=INPLACE;
 
Warnings:
 
Warning	1292	Truncated incorrect DOUBLE value: 'a'
 
DROP TABLE t;

Roel, can you provide the complete steps for repeating this?

Comment by Roel Van de Paar [ 2020-11-02 ]

Directly at the CLI:

/test/MD211020-mariadb-10.5.7-linux-x86_64-dbg/bin/mysql -A -uroot -S/test/MD211020-mariadb-10.5.7-linux-x86_64-dbg/socket.sock --force --prompt="$(/test/MD211020-mariadb-10.5.7-linux-x86_64-dbg/bin/mysqld --version | grep -o 'Ver [\.0-9]\+' | sed 's|[^\.0-9]*||')>" --binary-mode test

10.5.7 e3fc9c1db04bdc5566bcdafcc3d5159199089c00 (Debug)

 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
 
Your MariaDB connection id is 4
 
Server version: 10.5.7-MariaDB-debug MariaDB Server
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
10.5.7>USE test;
 
Database changed
 
10.5.7>CREATE TABLE t (a BLOB) ENGINE=InnoDB;
 
Query OK, 0 rows affected (0.012 sec)
 
10.5.7>INSERT INTO t VALUES ('a');
 
Query OK, 1 row affected (0.004 sec)
 
10.5.7>ALTER TABLE t ADD COLUMN (c INT GENERATED ALWAYS AS (a+1) VIRTUAL), ADD INDEX idx1 (c);
 
ERROR 1292 (22007): Truncated incorrect DOUBLE value: 'a'
 
10.5.7>ALTER TABLE t ADD d INT, ALGORITHM=INPLACE;
 
ERROR 2013 (HY000): Lost connection to MySQL server during query

In case it helps, SQL_MODE in CLI by default is:

10.5.7 e3fc9c1db04bdc5566bcdafcc3d5159199089c00 (Debug)

 
10.5.7>SELECT @@SQL_MODE\G
 
*************************** 1. row ***************************
 
@@SQL_MODE: STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
 
1 row in set (0.000 sec)

Comment by Roel Van de Paar [ 2020-11-02 ]

With many thanks to Elena,

--source include/have_innodb.inc
 
CREATE TABLE t (a BLOB) ENGINE=InnoDB;
 
INSERT INTO t VALUES ('a');
 
--error ER_TRUNCATED_WRONG_VALUE
 
ALTER TABLE t ADD COLUMN (c INT GENERATED ALWAYS AS (a+1) VIRTUAL), ADD INDEX idx1 (c);
 
ALTER TABLE t ADD d INT, ALGORITHM=INPLACE;

This produces the same assertion failure for her.

Comment by Marko Mäkelä [ 2020-11-02 ]

The debug assertion was too strict. The stub for the index on column c (which was not added in the end) was marked as containing virtual columns.

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