Details
-
Bug
-
Status: In Testing (View Workflow)
-
Major
-
Resolution: Unresolved
-
10.11.12
Description
origin/10.11-MDEV-29445 4afd83b99d0a161d698f234427f9dbb2a670ff2f 2025-02-28T17:05:09+02:00
Per Marko the problem is not caused by his modifications within 10.11-MDEV-29445.
[rr 643603 30431]mariadbd: /data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc:401: void dict_table_t::prepare_instant(const[rr 643603 30434] dict_table_t&, const ulint*, unsigned int&): Assertion `n_fields - (i - j) == index.n_fields' failed.
|
(rr) bt
|
#0 __pthread_kill_implementation (no_tid=0, signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:44
|
#1 __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
|
#2 __GI___pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
|
#3 0x000033b20b73e26e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
|
#4 0x000033b20b7218ff in __GI_abort () at ./stdlib/abort.c:79
|
#5 0x000033b20b72181b in __assert_fail_base (fmt=0x33b20b8c91e8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x651a33dd8980 "n_fields - (i - j) == index.n_fields",
|
file=file@entry=0x651a33dce9b0 "/data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc", line=line@entry=401,
|
function=function@entry=0x651a33dd8650 "void dict_table_t::prepare_instant(const dict_table_t&, const ulint*, unsigned int&)") at ./assert/assert.c:94
|
#6 0x000033b20b734507 in __assert_fail (assertion=0x651a33dd8980 "n_fields - (i - j) == index.n_fields", file=0x651a33dce9b0 "/data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc", line=401,
|
function=0x651a33dd8650 "void dict_table_t::prepare_instant(const dict_table_t&, const ulint*, unsigned int&)") at ./assert/assert.c:103
|
#7 0x0000651a33960886 in dict_table_t::prepare_instant (this=0x204f14036de0, old=..., col_map=<optimized out>, first_alter_pos=@0x204f14014fb8: 2)
|
at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc:401
|
#8 0x0000651a33960e87 in ha_innobase_inplace_ctx::prepare_instant (this=this@entry=0x204f14014e58) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc:1218
|
#9 0x0000651a3394756f in prepare_inplace_alter_table_dict (ha_alter_info=ha_alter_info@entry=0x64fe140e3120, altered_table=altered_table@entry=0x64fe140e31e0, old_table=<optimized out>,
|
table_name=<optimized out>, flags=<optimized out>, flags2=<optimized out>, fts_doc_id_col=<optimized out>, add_fts_doc_id=<optimized out>, add_fts_doc_id_idx=<optimized out>)
|
at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc:7129
|
#10 0x0000651a3394c5ff in ha_innobase::prepare_inplace_alter_table (this=0x204f140320a8, altered_table=<optimized out>, ha_alter_info=<optimized out>)
|
at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc:8764
|
#11 0x0000651a336f2af3 in handler::ha_prepare_inplace_alter_table (this=0x204f140320a8, altered_table=altered_table@entry=0x64fe140e31e0, ha_alter_info=ha_alter_info@entry=0x64fe140e3120)
|
at /data/Server/10.11-MDEV-29445F/sql/handler.cc:5368
|
#12 0x0000651a33533388 in mysql_inplace_alter_table (thd=thd@entry=0x204f14000d58, table_list=0x204f140137b0, table=table@entry=0x204f14030048, altered_table=altered_table@entry=0x64fe140e31e0,
|
ha_alter_info=ha_alter_info@entry=0x64fe140e3120, target_mdl_request=target_mdl_request@entry=0x64fe140e3a40, ddl_log_state=0x64fe140e30e0, trigger_param=0x64fe140e35e0, alter_ctx=0x64fe140e4610,
|
partial_alter=@0x64fe140e307f: false, start_alter_id=@0x64fe140e3088: 0, if_exists=false) at /data/Server/10.11-MDEV-29445F/sql/sql_table.cc:8012
|
#13 0x0000651a335448db in mysql_alter_table (thd=thd@entry=0x204f14000d58, new_db=new_db@entry=0x204f140058e8, new_name=<optimized out>, create_info=create_info@entry=0x64fe140e54b0, table_list=<optimized out>,
|
table_list@entry=0x204f140137b0, recreate_info=recreate_info@entry=0x64fe140e5300, alter_info=<optimized out>, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>,
|
if_exists=<optimized out>) at /data/Server/10.11-MDEV-29445F/sql/sql_table.cc:11348
|
#14 0x0000651a335b2c85 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x204f14000d58) at /data/Server/10.11-MDEV-29445F/sql/sql_alter.cc:688
|
#15 0x0000651a334865a3 in mysql_execute_command (thd=thd@entry=0x204f14000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:6167
|
#16 0x0000651a33487131 in mysql_parse (thd=thd@entry=0x204f14000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x64fe140e6400)
|
at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:8188
|
#17 0x0000651a3348879d in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x204f14000d58,
|
packet=packet@entry=0x204f1400b0c9 " ALTER TABLE t7 DROP COLUMN col_string /* E_R Thread2 QNO 30 CON_ID 16 */ ", packet_length=packet_length@entry=74, blocking=blocking@entry=true)
|
at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:1905
|
#18 0x0000651a33489c3b in do_command (thd=thd@entry=0x204f14000d58, blocking=blocking@entry=true) at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:1418
|
#19 0x0000651a335ab9af in do_handle_one_connection (connect=<optimized out>, connect@entry=0x651a36582fb8, put_in_cache=put_in_cache@entry=true) at /data/Server/10.11-MDEV-29445F/sql/sql_connect.cc:1386
|
#20 0x0000651a335abbc0 in handle_one_connection (arg=0x651a36582fb8) at /data/Server/10.11-MDEV-29445F/sql/sql_connect.cc:1298
|
#21 0x000033b20b795a94 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
|
#22 0x000033b20b822a34 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
|
(rr)
|
sdp:/data/results/1741269400/TBR-1983--TBR-1788$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio
|
|
|
RQG
|
====
|
# git clone https://github.com/mleich1/rqg RQG
|
#
|
# GIT_SHOW: HEAD -> master, origin/master, origin/HEAD be3b5d9200c1ee3980b5deecb9856b078ba7ed00 2025-02-28T21:46:24+01:00
|
# rqg.pl : Version 4.5.0 (2023-12)
|
#
|
# $RQG_HOME/rqg.pl \
|
# --duration=300 \
|
# --queries=10000000 \
|
# --no_mask \
|
# --seed=random \
|
# --vardir_type=fast \
|
# --rpl_mode=none \
|
# --engine=InnoDB \
|
# --max_gd_duration=1200 \
|
# --gendata_sql=conf/mariadb/table_stress.sql \
|
# --gendata=conf/mariadb/table_stress.zz \
|
# --mysqld=--loose-idle_readonly_transaction_timeout=0 \
|
# --mysqld=--sync-binlog=1 \
|
# --mysqld=--loose-table_lock_wait_timeout=50 \
|
# --mysqld=--net_read_timeout=30 \
|
# --mysqld=--log-output=none \
|
# --mysqld=--log_bin_trust_function_creators=1 \
|
# --mysqld=--slave_net_timeout=60 \
|
# --mysqld=--innodb-lock-wait-timeout=10 \
|
# --mysqld=--innodb_page_size=64K \
|
# --mysqld=--interactive_timeout=28800 \
|
# --mysqld=--log-bin \
|
# --mysqld=--loose-plugin-load-add=provider_lz4.so \
|
# --mysqld=--loose-max-statement-time=30 \
|
# --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
|
# --mysqld=--wait_timeout=28800 \
|
# --mysqld=--file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
|
# --mysqld=--lock-wait-timeout=15 \
|
# --mysqld=--plugin-load-add=file_key_management.so \
|
# --mysqld=--innodb-buffer-pool-size=256M \
|
# --mysqld=--loose-innodb_read_only_compressed=OFF \
|
# --mysqld=--loose-innodb_evict_tables_on_commit_debug=on \
|
# --mysqld=--net_write_timeout=60 \
|
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
|
# --mysqld=--connect_timeout=60 \
|
# --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
|
# --mysqld=--loose-idle_transaction_timeout=0 \
|
# --mysqld=--sql_mode=STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION \
|
# --mysqld=--loose-idle_write_transaction_timeout=0 \
|
# --reporters=Deadlock,None \
|
# --validators=None \
|
# --grammar=TBR-1983--TBR-1788.yy \
|
# --threads=2 \
|
# <local settings>
|
|
|
How to replay the problem faster?
|
./REPLAY_SIMP.sh TBR-1983--TBR-1788.cfg <path to MariaDB install>
|
|
|
|
Attachments
Activity
We got another failure where an UPDATE statement fails with DB_LOCK_TABLE_FULL:
#0 buf_pool_t::running_out (this=0x5a3eb9d32c80 <buf_pool>) at /data/Server/10.11-MDEV-29445H/storage/innobase/buf/buf0flu.cc:2429
|
#1 0x00005a3eb909696b in row_upd_clust_rec (flags=flags@entry=0x0, node=node@entry=0x6a07440da920, index=index@entry=0x42c32409efb0, offsets=<optimized out>, offsets@entry=0x3c7f2d1dc250, offsets_heap=offsets_heap@entry=0x3c7f2d1dc248, thr=thr@entry=0x6a07440dae30, mtr=0x3c7f2d1dc4b0) at /data/Server/10.11-MDEV-29445H/storage/innobase/row/row0upd.cc:2407
|
#2 0x00005a3eb9098e23 in row_upd_clust_step (node=node@entry=0x6a07440da920, thr=thr@entry=0x6a07440dae30) at /data/Server/10.11-MDEV-29445H/storage/innobase/row/row0upd.cc:2678
|
#3 0x00005a3eb909915c in row_upd (node=node@entry=0x6a07440da920, thr=thr@entry=0x6a07440dae30) at /data/Server/10.11-MDEV-29445H/storage/innobase/row/row0upd.cc:2779
|
#4 0x00005a3eb9099450 in row_upd_step (thr=thr@entry=0x6a07440dae30) at /data/Server/10.11-MDEV-29445H/storage/innobase/row/row0upd.cc:2921
|
#5 0x00005a3eb9059bba in row_update_for_mysql (prebuilt=0x6a07440da0b0) at /data/Server/10.11-MDEV-29445H/storage/innobase/row/row0mysql.cc:1663
|
#6 0x00005a3eb8f18ac4 in ha_innobase::update_row (this=0x6a07440d8068, old_row=0x6a07440d8aa0 "\3064444444444 ", new_row=0x6a07440d8868 "\3044444444444 \004") at /data/Server/10.11-MDEV-29445H/storage/innobase/handler/ha_innodb.cc:8629
|
#7 0x00005a3eb8cebad7 in handler::ha_update_row (this=0x6a07440d8068, old_data=0x6a07440d8aa0 "\3064444444444 ", new_data=0x6a07440d8868 "\3044444444444 \004") at /data/Server/10.11-MDEV-29445H/sql/handler.cc:7812
|
and the same thread subsequently hits an assertion failure on ALTER TABLE…DROP COLUMN:
#6 0x00006a076049e507 in __assert_fail (assertion=0x5a3eb94b5dd2 "d < n_old_drop", file=0x5a3eb93c39d8 "/data/Server/10.11-MDEV-29445H/storage/innobase/handler/handler0alter.cc", line=0x144, function=0x5a3eb93cd678 "void dict_table_t::prepare_instant(const dict_table_t&, const ulint*, unsigned int&)")
|
at ./assert/assert.c:103
|
#7 0x00005a3eb8f55262 in dict_table_t::prepare_instant (this=0xe004bb80, old=..., col_map=0x42c3240580f8, first_alter_pos=@0x42c324016380: 0x1) at /data/Server/10.11-MDEV-29445H/storage/innobase/handler/handler0alter.cc:324
|
#8 0x00005a3eb8f55ea5 in ha_innobase_inplace_ctx::prepare_instant (this=this@entry=0x42c324016220) at /data/Server/10.11-MDEV-29445H/storage/innobase/handler/handler0alter.cc:1218
|
#9 0x00005a3eb8f3c58d in prepare_inplace_alter_table_dict (ha_alter_info=ha_alter_info@entry=0x3c7f2d1da120, altered_table=altered_table@entry=0x3c7f2d1da1e0, old_table=<optimized out>, table_name=<optimized out>, flags=<optimized out>, flags2=<optimized out>, fts_doc_id_col=<optimized out>,
|
add_fts_doc_id=<optimized out>, add_fts_doc_id_idx=<optimized out>) at /data/Server/10.11-MDEV-29445H/storage/innobase/handler/handler0alter.cc:7129
|
#10 0x00005a3eb8f4161d in ha_innobase::prepare_inplace_alter_table (this=0x15a66c0d7d68, altered_table=<optimized out>, ha_alter_info=<optimized out>) at /data/Server/10.11-MDEV-29445H/storage/innobase/handler/handler0alter.cc:8764
|
Please check if the current fix should address this one as well, or if some further changes would be needed.
ssh sdp
|
rr replay /data/results/1742824191/TBR-2263/1/rr/latest-trace
|
mleich, the executable for the rr replay trace was changed. There is a chance that the error was caused by incorrect error handling in an earlier ALTER TABLE operation, but we can’t check that anymore. I would suggest to test the fix in a 10.11 branch where your current test setup can easily reproduce it (by modifying innodb_buffer_pool_size during the workload):
git fetch origin
|
git checkout origin/10.11
|
git cherry-pick --no-commit origin/10.6-MDEV-36236
|
I debugged an rr replay trace of this. The actual root cause of this failure turns out to be that some test parameters for
MDEV-29445are increasing the rate of DB_LOCK_TABLE_FULL. In the trace that I debugged, there will be 3 statements that executed native ALTER TABLE:The second statement is failing, because a call to que_eval_sql() will fail with DB_LOCK_TABLE_FULL:
10.11-MDEV-29445 4afd83b99d0a161d698f234427f9dbb2a670ff2f
#0 0x0000651a33a19676 in que_eval_sql (info=info@entry=0x204f14038e40,sql=sql@entry=0x651a33dd29e0 "PROCEDURE ADD_COL () IS\nBEGIN\nINSERT INTO SYS_COLUMNS VALUES(:id,:pos,:name,:mtype,:prtype,:len,:base);\nEND;\n", trx=trx@entry=0x33704aad3e80)at /data/Server/10.11-MDEV-29445F/storage/innobase/que/que0que.cc:673#1 0x0000651a3394ff73 in innodb_insert_sys_columns (table_id=24, pos=pos@entry=1, field_name=0x204f1403b8a9 "col_text", mtype=5, prtype=524540, len=10, n_base=0, trx=0x33704aad3e80, update=false)at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc:5528#2 0x0000651a33961fe4 in innobase_instant_try (ha_alter_info=ha_alter_info@entry=0x64fe140e3120, ctx=ctx@entry=0x204f14014e58, altered_table=altered_table@entry=0x64fe140e31e0,table=table@entry=0x204f1402f008, trx=trx@entry=0x33704aad3e80) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc:6099#3 0x0000651a33964f4c in commit_try_norebuild (ha_alter_info=ha_alter_info@entry=0x64fe140e3120, ctx=ctx@entry=0x204f14014e58, altered_table=altered_table@entry=0x64fe140e31e0, old_table=0x204f1402f008,statistics_exist=true, trx=trx@entry=0x33704aad3e80, table_name=0x204f1402a59d "t7") at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc:10892The error handling here seems to be inadequate, because the subsequent attempt to drop the column will fail due to a column number mismatch. I didn’t quite debug the reason for that.
This bug should be easy to reproduce by tweaking the following call of buf_pool_t::running_out():
10.11-MDEV-29445 4afd83b99d0a161d698f234427f9dbb2a670ff2f
#0 buf_pool_t::running_out (this=0x651a3473dc40 <buf_pool>) at /data/Server/10.11-MDEV-29445F/storage/innobase/buf/buf0flu.cc:2442#1 0x0000651a33a4266a in row_ins_clust_index_entry_by_modify (pcur=pcur@entry=0x64fe140e1340, flags=flags@entry=0, mode=mode@entry=10, offsets=offsets@entry=0x64fe140e1308,offsets_heap=offsets_heap@entry=0x64fe140e1300, heap=heap@entry=0x204f140527e0, entry=0x204f1403ddf0, thr=0x204f1404f4d0, mtr=0x64fe140e1670)at /data/Server/10.11-MDEV-29445F/storage/innobase/row/row0ins.cc:338#2 0x0000651a33a4b0d7 in row_ins_clust_index_entry_low (flags=flags@entry=0, mode=mode@entry=BTR_MODIFY_TREE, index=index@entry=0x651a36291d40, n_uniq=n_uniq@entry=2, entry=entry@entry=0x204f1403ddf0,n_ext=n_ext@entry=0, thr=<optimized out>) at /data/Server/10.11-MDEV-29445F/storage/innobase/row/row0ins.cc:2918#3 0x0000651a33a4b759 in row_ins_clust_index_entry (index=index@entry=0x651a36291d40, entry=entry@entry=0x204f1403ddf0, thr=thr@entry=0x204f1404f4d0, n_ext=n_ext@entry=0)at /data/Server/10.11-MDEV-29445F/storage/innobase/row/row0ins.cc:3355#4 0x0000651a33a4b929 in row_ins_index_entry (index=0x651a36291d40, entry=0x204f1403ddf0, thr=thr@entry=0x204f1404f4d0) at /data/Server/10.11-MDEV-29445F/storage/innobase/row/row0ins.cc:3483#5 0x0000651a33a4b9da in row_ins_index_entry_step (node=node@entry=0x204f1404f1f0, thr=thr@entry=0x204f1404f4d0) at /data/Server/10.11-MDEV-29445F/storage/innobase/row/row0ins.cc:3649#6 0x0000651a33a4bbfb in row_ins (node=node@entry=0x204f1404f1f0, thr=thr@entry=0x204f1404f4d0) at /data/Server/10.11-MDEV-29445F/storage/innobase/row/row0ins.cc:3774#7 0x0000651a33a4becb in row_ins_step (thr=thr@entry=0x204f1404f4d0) at /data/Server/10.11-MDEV-29445F/storage/innobase/row/row0ins.cc:3903#8 0x0000651a33a18ec2 in que_thr_step (thr=thr@entry=0x204f1404f4d0) at /data/Server/10.11-MDEV-29445F/storage/innobase/que/que0que.cc:532#9 0x0000651a33a19176 in que_run_threads_low (thr=thr@entry=0x204f1404f4d0) at /data/Server/10.11-MDEV-29445F/storage/innobase/que/que0que.cc:609#10 0x0000651a33a19237 in que_run_threads (thr=0x204f1404f4d0) at /data/Server/10.11-MDEV-29445F/storage/innobase/que/que0que.cc:629#11 0x0000651a33a19662 in que_eval_sql (info=info@entry=0x204f14038e40,sql=sql@entry=0x651a33dd29e0 "PROCEDURE ADD_COL () IS\nBEGIN\nINSERT INTO SYS_COLUMNS VALUES(:id,:pos,:name,:mtype,:prtype,:len,:base);\nEND;\n", trx=trx@entry=0x33704aad3e80)at /data/Server/10.11-MDEV-29445F/storage/innobase/que/que0que.cc:668#12 0x0000651a3394ff73 in innodb_insert_sys_columns (table_id=24, pos=pos@entry=1, field_name=0x204f1403b8a9 "col_text", mtype=5, prtype=524540, len=10, n_base=0, trx=0x33704aad3e80, update=false)at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/handler0alter.cc:5528