[MDEV-23994] InnoDB: Table test/t4 contains 4 indexes inside InnoDB, which is different from the number of indexes 3 defined in the MariaDB Created: 2020-10-20  Updated: 2021-04-13  Resolved: 2021-04-13

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3.26
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Thirunarayanan Balathandayuthapani
Resolution: Duplicate Votes: 0
Labels: rr-profile

Attachments: File rqg.log    
Issue Links:
Duplicate
is duplicated by MDEV-25200 Index count mismatch due to aborted F... Closed

 Description    

Workflow:
 
1. Start the server and create some initial data
 
2. Nine sessions run some concurrent DDL/DML mix
 
3. During 2. one session harvests for CHECK TABLE t4
 
    Warning InnoDB: Table test/t4 contains 4 indexes inside InnoDB, which is different
 
    from the number of indexes 3 defined in the MariaDB.
 
    Initiated by that the RQG runner "reacts" by sending SIGABRT to the DB server process.
 
The table t4 is most probably with InnoDB Page_format = redundant.
 
But its not known if that property is important at all.
 
 
 
origin/bb-10.3-MDEV-23072 36f5ea8b1092099e7ad96251bdefd43142bbe6c3 2020-10-19T22:18:29+05:30 compiled with debug+ASAN+Og
 
 
 
RQG
 
====
 
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
 
 
perl rqg.pl \ 
--grammar=conf/mariadb/table_stress_innodb.yy \
 
--gendata=conf/mariadb/table_stress.zz \
 
--gendata_sql=conf/mariadb/table_stress.sql \
 
--mysqld=--innodb_use_native_aio=1 \
 
--mysqld=--innodb_lock_schedule_algorithm=fcfs \
 
--mysqld=--loose-idle_write_transaction_timeout=0 \
 
--mysqld=--loose-idle_transaction_timeout=0 \
 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
--mysqld=--connect_timeout=60 \
 
--mysqld=--interactive_timeout=28800 \
 
--mysqld=--slave_net_timeout=60 \
 
--mysqld=--net_read_timeout=30 \
 
--mysqld=--net_write_timeout=60 \
 
--mysqld=--loose-table_lock_wait_timeout=50 \
 
--mysqld=--wait_timeout=28800 \
 
--mysqld=--lock-wait-timeout=86400 \
 
--mysqld=--innodb-lock-wait-timeout=50 \
 
--no-mask \
 
--queries=10000000 \
 
--seed=random \
 
--reporters=Backtrace \
 
--reporters=ErrorLog \
 
--reporters=Deadlock1 \
 
--validators=None \
 
--mysqld=--log_output=none \
 
--mysqld=--log-bin \
 
--mysqld=--log_bin_trust_function_creators=1 \
 
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
--engine=InnoDB \
 
--restart_timeout=120 \
 
--duration=400 \
 
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=400 \
 
--mysqld=--innodb_stats_persistent=off \
 
--mysqld=--loose-max-statement-time=30 \
 
--threads=9 \
 
--mysqld=--innodb_page_size=32K \
 
--mysqld=--innodb-buffer-pool-size=24M \
 
--duration=400 \
 
--no_mask \
 
--workdir=<local settings> \
 
--vardir=<local settings> \
 
--mtr-build-thread=<local settings> \
 
--basedir1=<local settings> \
 
--script_debug=_nix_ \
 
--rr=Server \
 
--rr_options=--chaos
 
 



 Comments   
Comment by Matthias Leich [ 2020-10-20 ] 

rr:/home/mleich/RQG/storage/1603134390/006423.tgz -- Archive with remains of the test including rr trace
 
/home/mleich/RQG/storage/1603134390/006423.log -- RQG log (its also uploaded)
 
 
 
cd /home/mleich/RQG/storage/1603134390/TBR-710/dev/shm/vardir/1603134390/36/1/rr
 
_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0
 
Please be aware that the RQG runner sends SIGABRT to the DB server process after
 
detecting the problem.
 
 
 
Error tagging in RQG
 
[ 'CATCH-0001' , 'indexes inside InnoDB, which is different from the number of indexes' ],

Comment by Matthias Leich [ 2021-01-27 ] 

Problem hit again on origin/bb-10.5-MDEV-24695 5232be80c279d0418392f6ac2ca5dd37e5ad86ca 2021-01-27T16:27:53+05:30
 
pluto:/data/Results/1611748398/CATCH-001/dev/shm/vardir/1611748398/260/1/rr
 
_RR_TRACE_DIR="." rr replay --mark-stdio
 
rqg.pl \
 
--grammar=conf/mariadb/table_stress_innodb.yy \
 
--gendata=conf/mariadb/table_stress.zz \
 
--gendata_sql=conf/mariadb/table_stress.sql \
 
--reporters=CrashRecovery1 \
 
--mysqld=--innodb_use_native_aio=1 \
 
--mysqld=--innodb_lock_schedule_algorithm=fcfs \
 
--mysqld=--loose-idle_write_transaction_timeout=0 \
 
--mysqld=--loose-idle_transaction_timeout=0 \
 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
--mysqld=--connect_timeout=60 \
 
--mysqld=--interactive_timeout=28800 \
 
--mysqld=--slave_net_timeout=60 \
 
--mysqld=--net_read_timeout=30 \
 
--mysqld=--net_write_timeout=60 \
 
--mysqld=--loose-table_lock_wait_timeout=50 \
 
--mysqld=--wait_timeout=28800 \
 
--mysqld=--lock-wait-timeout=86400 \
 
--mysqld=--innodb-lock-wait-timeout=50 \
 
--no-mask \
 
--queries=10000000 \
 
--seed=random \
 
--reporters=Backtrace \
 
--reporters=ErrorLog \
 
--reporters=Deadlock1 \
 
--validators=None \
 
--mysqld=--log_output=none \
 
--mysqld=--log-bin \
 
--mysqld=--log_bin_trust_function_creators=1 \
 
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
--engine=InnoDB \
 
--restart_timeout=240 \
 
--mysqld=--plugin-load-add=file_key_management.so \
 
--mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
 
--duration=300 \
 
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
 
--mysqld=--innodb_stats_persistent=off \
 
--mysqld=--innodb_adaptive_hash_index=off \
 
--mysqld=--loose-max-statement-time=30 \
 
--threads=33 \
 
--mysqld=--innodb_page_size=16K \
 
--mysqld=--innodb-buffer-pool-size=256M \
 
--duration=300 \
 
--no_mask \
 
--workdir=/data/Results/1611748398/260 \
 
--vardir=/dev/shm/vardir/1611748398/260 \
 
--mtr-build-thread=989 \
 
--basedir1=/Server_bin/bb-10.5-MDEV-24695_asan \
 
--basedir2=/Server_bin/bb-10.5-MDEV-24695_asan \
 
--script_debug=_nix_ \
 
--rr=Extended \
 
--rr_options=--chaos

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

Initially, I suspected that we simply have a case of the .frm file being out of sync with the InnoDB dictionary (which should hopefully eventually be fixed by MDEV-17567), but it is not the case.

The extra index was created a little earlier:

10.5 0565d199737a8412d592c32f315eced33efac7e4 with an unrelated change

 
#5  0x000056388ad15901 in dict_mem_index_create (table=0x618000242120, index_name=0x61b0002c7e20 "\377ftidx3", type=32, n_fields=1) at /Server/bb-10.5-MDEV-24695/storage/innobase/dict/dict0mem.cc:786
 
#6  0x000056388acd60df in dict_index_build_internal_fts (index=0x6170003572a0) at /Server/bb-10.5-MDEV-24695/storage/innobase/dict/dict0dict.cc:2785
 
#7  0x000056388acd07cd in dict_index_add_to_cache (index=@0x7ff2ecc91b20: 0x6170003572a0, page_no=4294967295, add_v=0x0) at /Server/bb-10.5-MDEV-24695/storage/innobase/dict/dict0dict.cc:2077
 
#8  0x000056388ad03e28 in dict_load_indexes (table=0x618000242120, heap=0x62c000410218, ignore_err=DICT_ERR_IGNORE_FK_NOKEY) at /Server/bb-10.5-MDEV-24695/storage/innobase/dict/dict0load.cc:2568
 
#9  0x000056388ad07527 in dict_load_table_one (name=..., ignore_err=DICT_ERR_IGNORE_FK_NOKEY, fk_tables=std::deque with 0 elements) at /Server/bb-10.5-MDEV-24695/storage/innobase/dict/dict0load.cc:2956
 
#10 0x000056388ad056c9 in dict_load_table (name=0x602000020050 "test/t1", ignore_err=DICT_ERR_IGNORE_FK_NOKEY) at /Server/bb-10.5-MDEV-24695/storage/innobase/dict/dict0load.cc:2739
 
#11 0x000056388acc9788 in dict_table_open_on_name (table_name=0x602000020050 "test/t1", dict_locked=1, try_drop=1, ignore_err=DICT_ERR_IGNORE_FK_NOKEY)
 
    at /Server/bb-10.5-MDEV-24695/storage/innobase/dict/dict0dict.cc:1097
 
#12 0x000056388a6c5b06 in innobase_reload_table (thd=0x62b00028b218, table=0x6180001d1520, table_name=..., ctx=...) at /Server/bb-10.5-MDEV-24695/storage/innobase/handler/handler0alter.cc:10134
 
#13 0x000056388a6cb9f9 in ha_innobase::commit_inplace_alter_table (this=0x61d0009592b8, altered_table=0x7ff2ecc961a0, ha_alter_info=0x7ff2ecc95cc0, commit=true)
 
    at /Server/bb-10.5-MDEV-24695/storage/innobase/handler/handler0alter.cc:11268
 
#14 0x0000563889ae86ee in handler::ha_commit_inplace_alter_table (this=0x61d0009592b8, altered_table=0x7ff2ecc961a0, ha_alter_info=0x7ff2ecc95cc0, commit=true) at /Server/bb-10.5-MDEV-24695/sql/handler.cc:4855
 
#15 0x000056388955f723 in mysql_inplace_alter_table (thd=0x62b00028b218, table_list=0x62b000292418, table=0x619000602c98, altered_table=0x7ff2ecc961a0, ha_alter_info=0x7ff2ecc95cc0, 
    target_mdl_request=0x7ff2ecc95da0, alter_ctx=0x7ff2ecc96c00) at /Server/bb-10.5-MDEV-24695/sql/sql_table.cc:8138
 
#16 0x000056388957255a in mysql_alter_table (thd=0x62b00028b218, new_db=0x62b00028fc60, new_name=0x62b000290060, create_info=0x7ff2ecc97fc0, table_list=0x62b000292418, alter_info=0x7ff2ecc97eb0, order_num=0, 
    order=0x0, ignore=false, if_exists=false) at /Server/bb-10.5-MDEV-24695/sql/sql_table.cc:10683
 
#17 0x00005638897117b0 in Sql_cmd_alter_table::execute (this=0x62b000292c48, thd=0x62b00028b218) at /Server/bb-10.5-MDEV-24695/sql/sql_alter.cc:539
 
#18 0x00005638892d22c7 in mysql_execute_command (thd=0x62b00028b218) at /Server/bb-10.5-MDEV-24695/sql/sql_parse.cc:6023
 
#19 0x00005638892dfd70 in mysql_parse (thd=0x62b00028b218, 
    rawbuf=0x62b000292238 "ALTER TABLE t1 ADD UNIQUE INDEX IF NOT EXISTS `uidx2` ( col1 ), LOCK = NONE, ALGORITHM = NOCOPY  /* E_R Thread30 QNO 66 CON_ID 66 */", length=132, parser_state=0x7ff2ecc997c0, 
    is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24695/sql/sql_parse.cc:8062

thiru, should this index stub be loaded at all? If it has to be loaded, maybe we should skip it in ha_innobase::info_low() when checking for index count mismatch?

Comment by Thirunarayanan Balathandayuthapani [ 2021-04-13 ]

I think this issue should be fixed by the following commit id:

commit b771ab242baf238463837b9d19eb59d544bff475 (origin/st-10.2-MDEV-15527)
 
Author: Thirunarayanan Balathandayuthapani <thiru@mariadb.com>
 
Date:   Mon Mar 29 18:51:36 2021 +0530
 
    MDEV-25200 Index count mismatch due to aborted FULLTEXT INDEX
 
    - Aborting of fulltext index creation fails to remove the
 
    index from sys indexes table. When we try to reload the
 
    table definition, InnoDB fails with index count mismatch
 
    error. InnoDB should remove the index from sys indexes while
 
    rollbacking the secondary index creation.

InnoDB should remove the rollbacked fts index information from dictionary. It is already fixed as MDEV-25200
Testing branch is not based on latest 10.5. 

(rr) p server_version_source_revision
 
$21 = 0x56388b761460 "5232be80c279d0418392f6ac2ca5dd37e5ad86ca"

So closing this issue as duplicate

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