[MDEV-24379] Assertion `table->stat_initialized' failed in dict0stats_bg.cc Created: 2020-12-09  Updated: 2021-04-12  Resolved: 2021-04-12

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.5.9
Fix Version/s: 10.2.38, 10.3.29, 10.4.19, 10.5.10

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: rr-profile

Issue Links:
Duplicate
duplicates MDEV-18802 Assertion `table->stat_initialized' f... Closed

 Description   

Workflow:
1. Start the server and generate some initial data
2. 33 sessions run concurrent a DDL/DML mix
3. Towards planned test end 30 sessions have disconnected.
4. The server asserts
[rr 465475 380406]mysqld: storage/innobase/dict/dict0stats_bg.cc:149: void dict_stats_update_if_needed(dict_table_t*, const trx_t&): Assertion `table->stat_initialized' failed.
... 
Query (0x62b000292238): LOAD DATA INFILE 'load_table10_innodb_int_autoinc' REPLACE INTO TABLE table10_innodb_int_autoinc /* E_R Thread33 QNO 191 CON_ID 48 */
...
[rr 465475 410611]Status: KILL_TIMEOUT
 
(rr) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00005629278d2859 in __GI_abort () at abort.c:79
#2  0x00005629278d2729 in __assert_fail_base (fmt=0x562927a68588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55c1a58d4f80 "table->stat_initialized", 
    file=0x55c1a58d41c0 "/Server/bb-10.5-MDEV-24369A/storage/innobase/dict/dict0stats_bg.cc", line=149, function=<optimized out>) at assert.c:92
#3  0x00005629278e3f36 in __GI___assert_fail (assertion=assertion@entry=0x55c1a58d4f80 "table->stat_initialized", 
    file=file@entry=0x55c1a58d41c0 "/Server/bb-10.5-MDEV-24369A/storage/innobase/dict/dict0stats_bg.cc", line=line@entry=149, 
    function=function@entry=0x55c1a58d4fc0 "void dict_stats_update_if_needed(dict_table_t*, const trx_t&)") at assert.c:101
#4  0x000055c1a4a86470 in dict_stats_update_if_needed (table=0x618000035120, trx=...) at /Server/bb-10.5-MDEV-24369A/storage/innobase/dict/dict0stats_bg.cc:149
#5  0x000055c1a459230d in row_update_cascade_for_mysql (thr=thr@entry=0x6250000371a0, node=0x61700053cca0, table=<optimized out>)
    at /Server/bb-10.5-MDEV-24369A/storage/innobase/row/row0mysql.cc:2254
#6  0x000055c1a45390d2 in row_ins_foreign_check_on_constraint (thr=thr@entry=0x6250000371a0, foreign=foreign@entry=0x616009d64820, pcur=pcur@entry=0x17c201994790, 
    entry=entry@entry=0x61700053c948, mtr=mtr@entry=0x17c201994c30) at /Server/bb-10.5-MDEV-24369A/storage/innobase/row/row0ins.cc:1337
#7  0x000055c1a453bbbb in row_ins_check_foreign_constraint (check_ref=check_ref@entry=0, foreign=foreign@entry=0x616009d64820, table=table@entry=0x618000034520, 
    entry=entry@entry=0x61700053c948, thr=thr@entry=0x6250000371a0) at /Server/bb-10.5-MDEV-24369A/storage/innobase/row/row0ins.cc:1744
#8  0x000055c1a46752c4 in row_upd_check_references_constraints (node=node@entry=0x621000eda180, pcur=pcur@entry=0x612000276c58, table=0x618000034520, index=index@entry=0x617000131aa0, 
    offsets=offsets@entry=0x17c201995a30, thr=thr@entry=0x6250000371a0, mtr=<optimized out>) at /Server/bb-10.5-MDEV-24369A/storage/innobase/row/row0upd.cc:295
#9  0x000055c1a4676581 in row_upd_del_mark_clust_rec (node=node@entry=0x621000eda180, index=index@entry=0x617000131aa0, offsets=offsets@entry=0x17c201995a30, thr=thr@entry=0x6250000371a0, 
    referenced=referenced@entry=1, foreign=foreign@entry=false, mtr=<optimized out>) at /Server/bb-10.5-MDEV-24369A/storage/innobase/row/row0upd.cc:2691
#10 0x000055c1a4679b52 in row_upd_clust_step (node=node@entry=0x621000eda180, thr=thr@entry=0x6250000371a0) at /Server/bb-10.5-MDEV-24369A/storage/innobase/row/row0upd.cc:2860
#11 0x000055c1a467e67a in row_upd (node=node@entry=0x621000eda180, thr=thr@entry=0x6250000371a0) at /Server/bb-10.5-MDEV-24369A/storage/innobase/row/row0upd.cc:2992
#12 0x000055c1a467f8d5 in row_upd_step (thr=thr@entry=0x6250000371a0) at /Server/bb-10.5-MDEV-24369A/storage/innobase/row/row0upd.cc:3136
#13 0x000055c1a45970a5 in row_update_for_mysql (prebuilt=0x621000ed95a0) at /Server/bb-10.5-MDEV-24369A/storage/innobase/row/row0mysql.cc:1847
#14 0x000055c1a41491ea in ha_innobase::delete_row (this=0x61d0010e46b8, record=<optimized out>) at /Server/bb-10.5-MDEV-24369A/storage/innobase/handler/ha_innodb.cc:8474
#15 0x000055c1a34ea93b in handler::ha_delete_row (this=0x61d0010e46b8, buf=0x6190006faa08 "\256", ' ' <repeats 24 times>) at /Server/bb-10.5-MDEV-24369A/sql/handler.cc:7262
#16 0x000055c1a2ade1ec in write_record (thd=thd@entry=0x62b00028b218, table=table@entry=0x6190006fae98, info=info@entry=0x17c201997040, sink=sink@entry=0x0)
    at /Server/bb-10.5-MDEV-24369A/sql/sql_insert.cc:2055
#17 0x000055c1a2b9732f in read_sep_field (thd=thd@entry=0x62b00028b218, info=..., table_list=table_list@entry=0x62b0002924d0, fields_vars=..., set_fields=..., set_values=..., read_info=..., 
    enclosed=..., skip_lines=0, ignore_check_option_errors=<optimized out>) at /Server/bb-10.5-MDEV-24369A/sql/sql_load.cc:1172
#18 0x000055c1a2ba54af in mysql_load (thd=thd@entry=0x62b00028b218, ex=0x62b0002923f8, table_list=table_list@entry=0x62b0002924d0, fields_vars=..., set_fields=..., set_values=..., 
    handle_duplicates=<optimized out>, ignore=false, read_file_from_client=<optimized out>) at /Server/bb-10.5-MDEV-24369A/sql/sql_load.cc:677
#19 0x000055c1a2bfb9b1 in mysql_execute_command (thd=thd@entry=0x62b00028b218) at /Server/bb-10.5-MDEV-24369A/sql/sql_parse.cc:5045
#20 0x000055c1a2baed6a in mysql_parse (thd=thd@entry=0x62b00028b218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x17c201998ed0, 
    is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /Server/bb-10.5-MDEV-24369A/sql/sql_parse.cc:8042
#21 0x000055c1a2be06a5 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b00028b218, 
    packet=packet@entry=0x62900040b219 " LOAD DATA INFILE 'load_table10_innodb_int_autoinc' REPLACE INTO TABLE table10_innodb_int_autoinc /* E_R Thread33 QNO 191 CON_ID 48 */ ", 
    packet_length=packet_length@entry=135, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /Server/bb-10.5-MDEV-24369A/sql/sql_class.h:1252
#22 0x000055c1a2bebc02 in do_command (thd=0x62b00028b218) at /Server/bb-10.5-MDEV-24369A/sql/sql_parse.cc:1353
#23 0x000055c1a3086c84 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x6080000b42b8, put_in_cache=put_in_cache@entry=true)
    at /Server/bb-10.5-MDEV-24369A/sql/sql_connect.cc:1410
#24 0x000055c1a3087ec4 in handle_one_connection (arg=arg@entry=0x6080000b42b8) at /Server/bb-10.5-MDEV-24369A/sql/sql_connect.cc:1312
#25 0x000055c1a3f1b8fc in pfs_spawn_thread (arg=0x6150000b1398) at /Server/bb-10.5-MDEV-24369A/storage/perfschema/pfs.cc:2201
#26 0x000034b17afee609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#27 0x00005629279cf293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(rr)
 
origin/bb-10.5-MDEV-24369 5eb539555b36a60944eefeb84d5d6d436ba61e63 2020-12-09T09:22:13+02:00     compiled with debug+ASAN+Og
Per Marko: This problem should be in the current 10.5 too.
 
Hitting this problem seems to be quite rare.
196 RQG tests with similar setup made, issue only one time hit.
 
 
RQG
====
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
perl rqg.pl \
--gendata=conf/engines/engine_stress.zz \
--views \
--grammar=conf/engines/engine_stress.yy \
--redefine=conf/mariadb/alter_table.yy \
--redefine=conf/mariadb/instant_add.yy \
--redefine=conf/mariadb/modules/alter_table_columns.yy \
--redefine=conf/mariadb/sp.yy \
--redefine=conf/mariadb/bulk_insert.yy \
--redefine=conf/mariadb/modules/userstat.yy \
--redefine=conf/mariadb/modules/foreign_keys.yy \
--redefine=conf/mariadb/modules/locks.yy \
--redefine=conf/mariadb/modules/sql_mode.yy \
--redefine=conf/mariadb/versioning.yy \
--redefine=conf/mariadb/sequences.yy \
--redefine=conf/mariadb/modules/locks-10.4-extra.yy \
--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 \
--mysqld=--plugin-load-add=file_key_management.so \
--mysqld=--loose-file-key-management-filename=/home/mleich/RQG3/conf/mariadb/encryption_keys.txt \
--duration=300 \
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
--mysqld=--innodb_stats_persistent=on \
--mysqld=--loose-max-statement-time=30 \
--threads=33 \
--mysqld=--innodb_page_size=8K \
--mysqld=--innodb-buffer-pool-size=8M \
--duration=300 \
--no_mask \
--workdir=<local settings> \
--vardir=<local settings> \
--mtr-build-thread=<local settings> \
--basedir1=<local settings> \
--script_debug=_nix_ \
--rr=Extended \
--rr_options=--chaos



 Comments   
Comment by Matthias Leich [ 2020-12-09 ]

pluto:/RQG3/storage/1607516745/TBR-787/dev/shm/vardir/1607516745/193/1/rr
_RR_TRACE_DIR="." rr replay --mark-stdio

Archive: pluto:/RQG3/storage/1607516745/003738.tgz

Comment by Alice Sherepa [ 2021-03-17 ]

probably MDEV-18802

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

Thank you, alice, for pointing out that this is duplicating MDEV-18802. I fixed that one now.

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