Details
-
Bug
-
Status: Closed (View Workflow)
-
Blocker
-
Resolution: Fixed
-
N/A
Description
The assertion was replayed on origin/10.11-MDEV-29445 4afd83b99d0a161d698f234427f9dbb2a670ff2f 2025-02-28T17:05:09+02:00.
|
Per Marko: This problem is not related to the modifications in 10.11-MDEV-29445.
|
|
|
# 2025-03-03T07:20:04 [827446] | mariadbd: 10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:14921: int ha_innobase::info_low(uint, bool): Assertion `ib_table->stat_initialized()' 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 0x00007b987c24526e in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
|
#4 0x00007b987c2288ff in __GI_abort () at ./stdlib/abort.c:79
|
#5 0x00007b987c22881b in __assert_fail_base (fmt=0x7b987c3d01e8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x561de3d83aaf "ib_table->stat_initialized()", file=file@entry=0x561de3c82618 "/data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc", line=line@entry=14921, function=function@entry=0x561de3c87d20 "int ha_innobase::info_low(uint, bool)")
|
at ./assert/assert.c:94
|
#6 0x00007b987c23b507 in __assert_fail (assertion=0x561de3d83aaf "ib_table->stat_initialized()", file=0x561de3c82618 "/data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc", line=14921, function=0x561de3c87d20 "int ha_innobase::info_low(uint, bool)") at ./assert/assert.c:103
|
#7 0x0000561de37e57f9 in ha_innobase::info_low (this=0x7b98580dd618, flag=18, is_analyze=<optimized out>, is_analyze@entry=false) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:14921
|
#8 0x0000561de37e5d38 in ha_innobase::info (this=<optimized out>, flag=<optimized out>) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:15199
|
#9 0x0000561de3439bbd in TABLE_LIST::fetch_number_of_rows (this=this@entry=0x7b9858015b08) at /data/Server/10.11-MDEV-29445F/sql/table.cc:9955
|
#10 0x0000561de33b64c7 in make_join_statistics (join=join@entry=0x7b9858016fc0, tables_list=..., keyuse_array=keyuse_array@entry=0x7b9858017318) at /data/Server/10.11-MDEV-29445F/sql/sql_select.cc:5499
|
#11 0x0000561de33b916d in JOIN::optimize_inner (this=this@entry=0x7b9858016fc0) at /data/Server/10.11-MDEV-29445F/sql/sql_select.cc:2643
|
#12 0x0000561de33b93fb in JOIN::optimize (this=this@entry=0x7b9858016fc0) at /data/Server/10.11-MDEV-29445F/sql/sql_select.cc:1954
|
#13 0x0000561de33b94dd in mysql_select (thd=thd@entry=0x7b9858002568, tables=0x7b9858015b08, fields=..., conds=0x7b9858016400, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=<optimized out>, result=0x7b9858016f98, unit=0x7b9858006828, select_lex=0x7b9858015018) at /data/Server/10.11-MDEV-29445F/sql/sql_select.cc:5218
|
#14 0x0000561de33b98a8 in handle_select (thd=thd@entry=0x7b9858002568, lex=lex@entry=0x7b9858006750, result=result@entry=0x7b9858016f98, setup_tables_done_option=setup_tables_done_option@entry=0) at /data/Server/10.11-MDEV-29445F/sql/sql_select.cc:600
|
#15 0x0000561de333d5f1 in execute_sqlcom_select (thd=thd@entry=0x7b9858002568, all_tables=0x7b9858015b08) at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:6426
|
#16 0x0000561de3346d1b in mysql_execute_command (thd=thd@entry=0x7b9858002568, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:4012
|
#17 0x0000561de334d131 in mysql_parse (thd=thd@entry=0x7b9858002568, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7b98795b3400) at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:8188
|
#18 0x0000561de334e79d in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7b9858002568, packet=packet@entry=0x7b985800c8d9 "SELECT `col_int_nokey` % 10 AS `col_int_nokey`, `col_int_key` % 10 AS `col_int_key` FROM a WHERE `col_int_nokey` <= 6 /* E_R Thread4 QNO 1053 CON_ID 20 */ ", packet_length=packet_length@entry=155, blocking=blocking@entry=true) at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:1905
|
#19 0x0000561de334fc3b in do_command (thd=thd@entry=0x7b9858002568, blocking=blocking@entry=true) at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:1418
|
#20 0x0000561de34719af in do_handle_one_connection (connect=<optimized out>, connect@entry=0x561de6c00898, put_in_cache=put_in_cache@entry=true) at /data/Server/10.11-MDEV-29445F/sql/sql_connect.cc:1386
|
#21 0x0000561de3471bc0 in handle_one_connection (arg=0x561de6c00898) at /data/Server/10.11-MDEV-29445F/sql/sql_connect.cc:1298
|
#22 0x00007b987c29ca94 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:447
|
#23 0x00007b987c329a34 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
|
(rr)
|
|
|
sdp:/data/results/1741001176/TB-2232$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio
|
The test fiddles with partitioned tables and the server starts with innodb_undo_log_truncate=ON.
|
|
|
RQG
|
====
|
# git clone https://github.com/mleich1/rqg --branch <pick the right branch> 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 \
|
# --grammar=conf/mariadb/partitions_innodb.yy \
|
# --mysqld=--loose-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 \
|
# --no_mask \
|
# --queries=10000000 \
|
# --seed=random \
|
# --reporters=None \
|
# --reporters=ErrorLog \
|
# --reporters=Deadlock \
|
# --validators=None \
|
# --mysqld=--log_output=none \
|
# --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 \
|
# --mysqld=--plugin-load-add=provider_lzo.so \
|
# --mysqld=--plugin-load-add=provider_bzip2.so \
|
# --mysqld=--plugin-load-add=provider_lzma.so \
|
# --mysqld=--plugin-load-add=provider_snappy.so \
|
# --mysqld=--plugin-load-add=provider_lz4.so \
|
# --mysqld=--loose-innodb_compression_level=1 \
|
# --duration=300 \
|
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
|
# --mysqld=--lock-wait-timeout=86400 \
|
# --mysqld=--innodb-lock-wait-timeout=50 \
|
# --mysqld=--loose-innodb_fast_shutdown=0 \
|
# --mysqld=--sql_mode=STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION \
|
# --mysqld=--loose-innodb_read_only_compressed=OFF \
|
# --mysqld=--innodb_stats_persistent=on \
|
# --mysqld=--innodb_adaptive_hash_index=off \
|
# --mysqld=--innodb_random_read_ahead=ON \
|
# --mysqld=--innodb_read_ahead_threshold=0 \
|
# --mysqld=--log-bin \
|
# --mysqld=--sync-binlog=1 \
|
# --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
|
# --mysqld=--loose-max-statement-time=30 \
|
# --threads=9 \
|
# --rr=Extended \
|
# --rr_options=--wait \
|
# --mysqld=--innodb_undo_log_truncate=ON \
|
# --mysqld=--innodb_rollback_on_timeout=OFF \
|
# --mysqld=--innodb_page_size=64K \
|
# --mysqld=--innodb-buffer-pool-size=256M \
|
# --vardir_type=fast \
|
# <local settings>
|
|
Attachments
Issue Links
- is caused by
-
-
- Closed
-
Activity
A related finding: We are invoking dict_table_t::stats_mutex_lock() and dict_table_t::stats_mutex_unlock() multiple times during dict_stats_update_persistent(). This may lead to some duplicated work when the same table is accessed "for the first time" in multiple concurrent connections. A possible solution against that would be to set an "in progress" flag in dict_table_t::stat and make the slightly later threads to poll until the first thread has completed.
The statistics were deinitialized by the following:
#3 innodb_copy_stat_flags (table=table@entry=0x561de6d329c0, table_options=<optimized out>, sar=<optimized out>, initialized=initialized@entry=0x0)
|
at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:3009
|
#4 0x0000561de37e6764 in innobase_copy_frm_flags_from_create_info (innodb_table=0x561de6d329c0, create_info=create_info@entry=0x7b987a0cfcf0)
|
at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:3025
|
#5 0x0000561de37e67b6 in ha_innobase::check_if_incompatible_data (this=0x7b9838a06bf8, info=0x7b987a0cfcf0, table_changes=0x1) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:17370
|
#6 0x0000561de33ff673 in mysql_compare_tables (table=table@entry=0x7b983804ff98, alter_info=alter_info@entry=0x7b987a0cf940, create_info=create_info@entry=0x7b987a0cfcf0,
|
metadata_equal=metadata_equal@entry=0x7b987a0cf93f) at /data/Server/10.11-MDEV-29445F/sql/sql_table.cc:7497
|
#7 0x0000561de3472b34 in compare_table_with_partition (thd=thd@entry=0x7b9838002568, table=table@entry=0x7b983804ff98, part_table=part_table@entry=0x7b982c3cd8f8, part_elem=0x7b982c3cbca0, part_id=0x0)
|
at /data/Server/10.11-MDEV-29445F/sql/sql_partition_admin.cc:252
|
#8 0x0000561de3473447 in Sql_cmd_alter_table_exchange_partition::exchange_partition (this=this@entry=0x7b9838015e80, thd=thd@entry=0x7b9838002568, table_list=<optimized out>, table_list@entry=0x7b9838014ff0,
|
alter_info=alter_info@entry=0x7b987a0d1ab0) at /data/Server/10.11-MDEV-29445F/sql/sql_partition_admin.cc:685
|
#9 0x0000561de3473985 in Sql_cmd_alter_table_exchange_partition::execute (this=0x7b9838015e80, thd=0x7b9838002568) at /data/Server/10.11-MDEV-29445F/sql/sql_partition_admin.cc:111
|
#10 0x0000561de334c5a3 in mysql_execute_command (thd=thd@entry=0x7b9838002568, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=0x0) at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:6167
|
#11 0x0000561de334d131 in mysql_parse (thd=thd@entry=0x7b9838002568, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7b987a0d2400)
|
at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:8188
|
#12 0x0000561de334e79d in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7b9838002568,
|
packet=packet@entry=0x7b983800c8d9 "ALTER TABLE w /*!50610 EXCHANGE PARTITION p0 WITH TABLE a */ /* E_R Thread2 QNO 1068 CON_ID 17 */ ", packet_length=packet_length@entry=0x62, blocking=blocking@entry=0x1)
|
at /data/Server/10.11-MDEV-29445F/sql/sql_parse.cc:1905
|
At the time this is executing, we had the following query (which will hit the assertion failure) already executing deep inside InnoDB, committing dict_stats_save():
SELECT `col_int_nokey` % 10 AS `col_int_nokey`, `col_int_key` % 10 AS `col_int_key` FROM a WHERE `col_int_nokey` <= 6 /* E_R Thread4 QNO 1053 CON_ID 20 */ |
#16 trx_t::free (this=this@entry=0x7b987a202300) at /data/Server/10.11-MDEV-29445F/storage/innobase/trx/trx0trx.cc:449
|
#17 0x0000561de3a43ebf in dict_stats_save (table=table@entry=0x561de6d329c0, index_id=index_id@entry=0x0) at /data/Server/10.11-MDEV-29445F/storage/innobase/dict/dict0stats.cc:3005
|
#18 0x0000561de37d9991 in ha_innobase::statistics_init (this=this@entry=0x7b98580dd618, table=table@entry=0x561de6d329c0, recalc=recalc@entry=0x0)
|
at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:5809
|
#19 0x0000561de37e549d in ha_innobase::info_low (this=0x7b98580dd618, flag=0x12, is_analyze=is_analyze@entry=0x0) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:14913
|
#20 0x0000561de37e5d38 in ha_innobase::info (this=<optimized out>, flag=<optimized out>) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:15199
|
#21 0x0000561de3439bbd in TABLE_LIST::fetch_number_of_rows (this=this@entry=0x7b9858015b08) at /data/Server/10.11-MDEV-29445F/sql/table.cc:9955
|
#22 0x0000561de33b64c7 in make_join_statistics (join=join@entry=0x7b9858016fc0,
|
tables_list=@0x7b9858015238: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x7b9858017778, last = 0x7b9858017778, elements = 0x1}, <No data fields>},
|
keyuse_array=keyuse_array@entry=0x7b9858017318) at /data/Server/10.11-MDEV-29445F/sql/sql_select.cc:5499
|
#23 0x0000561de33b916d in JOIN::optimize_inner (this=this@entry=0x7b9858016fc0) at /data/Server/10.11-MDEV-29445F/sql/sql_select.cc:2643
|
#24 0x0000561de33b93fb in JOIN::optimize (this=this@entry=0x7b9858016fc0) at /data/Server/10.11-MDEV-29445F/sql/sql_select.cc:1954
|
#25 0x0000561de33b94dd in mysql_select (thd=thd@entry=0x7b9858002568, tables=0x7b9858015b08,
|
This would seem to be a locking bug related to partitioned tables. I don’t think that the ALTER TABLE…EXCHANGE PARTITION operation is supposed to execute concurrently with a SELECT on the table a that we are trying to exchange a partition with.
I observed that Sql_cmd_alter_table_exchange_partition::exchange_partition() is initially acquiring MDL_SHARED_NO_WRITE on the swap_table and upgrade it to MDL_EXCLUSIVE before starting the actual swap. In compare_table_with_partition() the expectation is that the table metadata does not change.
The problem would seem to be that ha_innobase::check_if_incompatible_data() is invalidating the table statistics.
I was able to write a DEBUG_SYNC test case for this. I think that it addresses this exact scenario for the assertion failure. If there are other scenarios, then those should be found in additional stress testing.
There is a race between two SELECT queries that are initializing statistics for the same table concurrently.
#17 0x0000561de3a43ebf in dict_stats_save (table=table@entry=0x561de6d329c0, index_id=index_id@entry=0x0) at /data/Server/10.11-MDEV-29445F/storage/innobase/dict/dict0stats.cc:3005#18 0x0000561de37d9991 in ha_innobase::statistics_init (this=this@entry=0x7b98580dd618, table=table@entry=0x561de6d329c0, recalc=recalc@entry=0x0) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:5809#19 0x0000561de37e549d in ha_innobase::info_low (this=0x7b98580dd618, flag=0x12, is_analyze=is_analyze@entry=0x0) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:14913#20 0x0000561de37e5d38 in ha_innobase::info (this=<optimized out>, flag=<optimized out>) at /data/Server/10.11-MDEV-29445F/storage/innobase/handler/ha_innodb.cc:15199