[MDEV-24643] Assertion `(l & (WRITER | UPDATER)) == UPDATER' failed in void rw_lock::update_unlock() Created: 2021-01-21  Updated: 2021-02-16  Resolved: 2021-02-12

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

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

Attachments: File TBR-826.yy    
Issue Links:
Problem/Incident
is caused by MDEV-24142 rw_lock_t has unnecessarily complex w... Closed

 Description    

origin/bb-10.6-MDEV-24637 22a15eb42589f98fdc305e04ab297a880f1c39ca 2021-01-21T17:02:13+05:30
 
       Observed on origin/bb-10.6-MDEV-515 bc9bc89b4275fe963d24d90de3c72bb01871f33f 2021-01-21 too
 
 
 
mysqld: /Server/bb-10.6-MDEV-24637/storage/innobase/include/rw_lock.h:141: void rw_lock::update_unlock(): Assertion `(l & (WRITER | UPDATER)) == UPDATER' failed.
 
...
 
Query (0x62b0000a1238): INSERT INTO `table300_innodb_int_autoinc` SELECT * FROM `table200_innodb_int_autoinc`
 
Status: NOT_KILLED
 
 
 
(rr) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x00003a264e80e859 in __GI_abort () at abort.c:79
 
#2  0x00003a264e80e729 in __assert_fail_base (fmt=0x3a264e9a4588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x556ebc134500 "(l & (WRITER | UPDATER)) == UPDATER", file=0x556ebc134220 "/Server/bb-10.6-MDEV-24637/storage/innobase/include/rw_lock.h", 
    line=141, function=<optimized out>) at assert.c:92
 
#3  0x00003a264e81ff36 in __GI___assert_fail (assertion=0x556ebc134500 "(l & (WRITER | UPDATER)) == UPDATER", file=0x556ebc134220 "/Server/bb-10.6-MDEV-24637/storage/innobase/include/rw_lock.h", line=141, function=0x556ebc134560 "void rw_lock::update_unlock()")
 
    at assert.c:101
 
#4  0x0000556ebaa67175 in rw_lock::update_unlock (this=0x78024ae0) at /Server/bb-10.6-MDEV-24637/storage/innobase/include/rw_lock.h:141
 
#5  0x0000556ebaa65dac in ssux_lock_low::u_unlock (this=0x78024ae0) at /Server/bb-10.6-MDEV-24637/storage/innobase/sync/srw_lock.cc:236
 
#6  0x0000556eba80e84c in sux_lock<ssux_lock_low>::u_or_x_unlock (this=0x78024ae0, allow_readers=true, claim_ownership=false) at /Server/bb-10.6-MDEV-24637/storage/innobase/include/sux_lock.h:245
 
#7  0x0000556eba7ffb26 in buf_page_release_latch (block=0x78024a60, rw_latch=4) at /Server/bb-10.6-MDEV-24637/storage/innobase/include/buf0buf.ic:291
 
#8  0x0000556eba7ffeca in memo_slot_release (slot=0x47b01f3531a0) at /Server/bb-10.6-MDEV-24637/storage/innobase/mtr/mtr0mtr.cc:240
 
#9  0x0000556eba80ad6b in ReleaseAll::operator() (this=0x47b01f352e10, slot=0x47b01f3531a0) at /Server/bb-10.6-MDEV-24637/storage/innobase/mtr/mtr0mtr.cc:299
 
#10 0x0000556eba812195 in CIterate<ReleaseAll>::operator() (this=0x47b01f352e10, block=0x47b01f353170) at /Server/bb-10.6-MDEV-24637/storage/innobase/mtr/mtr0mtr.cc:61
 
#11 0x0000556eba80f8eb in mtr_buf_t::for_each_block_in_reverse<CIterate<ReleaseAll> > (this=0x47b01f353148, functor=...) at /Server/bb-10.6-MDEV-24637/storage/innobase/include/dyn0buf.h:379
 
#12 0x0000556eba801752 in mtr_t::commit (this=0x47b01f353130) at /Server/bb-10.6-MDEV-24637/storage/innobase/mtr/mtr0mtr.cc:458
 
#13 0x0000556ebacafa14 in dict_stats_analyze_index (index=0x6160099bb320) at /Server/bb-10.6-MDEV-24637/storage/innobase/dict/dict0stats.cc:1953
 
#14 0x0000556ebacb1e59 in dict_stats_update_persistent (table=0x6180000db920) at /Server/bb-10.6-MDEV-24637/storage/innobase/dict/dict0stats.cc:2289
 
#15 0x0000556ebacb7224 in dict_stats_update (table=0x6180000db920, stats_upd_option=DICT_STATS_RECALC_PERSISTENT) at /Server/bb-10.6-MDEV-24637/storage/innobase/dict/dict0stats.cc:3223
 
#16 0x0000556ebacb797b in dict_stats_update (table=0x6180000db920, stats_upd_option=DICT_STATS_FETCH_ONLY_IF_NOT_IN_MEMORY) at /Server/bb-10.6-MDEV-24637/storage/innobase/dict/dict0stats.cc:3344
 
#17 0x0000556eba5cd15d in dict_stats_init (table=0x6180000db920) at /Server/bb-10.6-MDEV-24637/storage/innobase/include/dict0stats.ic:165
 
#18 0x0000556eba5e06dd in ha_innobase::open (this=0x61d0004eacb8, name=0x61b00012d670 "./test/table200_innodb_int_autoinc") at /Server/bb-10.6-MDEV-24637/storage/innobase/handler/ha_innodb.cc:5440
 
#19 0x0000556eb9acaa66 in handler::ha_open (this=0x61d0004eacb8, table_arg=0x6190006cfc98, name=0x61b00012d670 "./test/table200_innodb_int_autoinc", mode=2, test_if_locked=18, mem_root=0x0, partitions_to_open=0x0) at /Server/bb-10.6-MDEV-24637/sql/handler.cc:2983
 
#20 0x0000556eb960a7b9 in open_table_from_share (thd=0x62b00009a218, share=0x61b00012d0b8, alias=0x62b0000a2278, db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x6190006cfc98, is_create_table=false, partitions_to_open=0x0)
 
    at /Server/bb-10.6-MDEV-24637/sql/table.cc:4218
 
#21 0x0000556eb91170df in open_table (thd=0x62b00009a218, table_list=0x62b0000a2230, ot_ctx=0x47b01f355790) at /Server/bb-10.6-MDEV-24637/sql/sql_base.cc:2001
 
#22 0x0000556eb9120e7f in open_and_process_table (thd=0x62b00009a218, tables=0x62b0000a2230, counter=0x47b01f3558c0, flags=0, prelocking_strategy=0x47b01f3559f0, has_prelocking_list=false, ot_ctx=0x47b01f355790) at /Server/bb-10.6-MDEV-24637/sql/sql_base.cc:3801
 
#23 0x0000556eb9123a06 in open_tables (thd=0x62b00009a218, options=..., start=0x47b01f3558d0, counter=0x47b01f3558c0, flags=0, prelocking_strategy=0x47b01f3559f0) at /Server/bb-10.6-MDEV-24637/sql/sql_base.cc:4275
 
#24 0x0000556eb9128b4a in open_and_lock_tables (thd=0x62b00009a218, options=..., tables=0x62b0000a1490, derived=true, flags=0, prelocking_strategy=0x47b01f3559f0) at /Server/bb-10.6-MDEV-24637/sql/sql_base.cc:5211
 
#25 0x0000556eb907fd5e in open_and_lock_tables (thd=0x62b00009a218, tables=0x62b0000a1490, derived=true, flags=0) at /Server/bb-10.6-MDEV-24637/sql/sql_base.h:507
 
#26 0x0000556eb92bf555 in mysql_execute_command (thd=0x62b00009a218) at /Server/bb-10.6-MDEV-24637/sql/sql_parse.cc:4532
 
#27 0x0000556eb92d69d7 in mysql_parse (thd=0x62b00009a218, rawbuf=0x62b0000a1238 "INSERT INTO `table300_innodb_int_autoinc` SELECT * FROM `table200_innodb_int_autoinc` /* E_R Thread1 QNO 142 CON_ID 14 */", length=121, parser_state=0x47b01f3567c0)
 
    at /Server/bb-10.6-MDEV-24637/sql/sql_parse.cc:7901
 
#28 0x0000556eb92ad6b5 in dispatch_command (command=COM_QUERY, thd=0x62b00009a218, packet=0x629000190219 "INSERT INTO `table300_innodb_int_autoinc` SELECT * FROM `table200_innodb_int_autoinc` /* E_R Thread1 QNO 142 CON_ID 14 */ ", packet_length=122)
 
    at /Server/bb-10.6-MDEV-24637/sql/sql_parse.cc:1833
 
#29 0x0000556eb92aa57b in do_command (thd=0x62b00009a218) at /Server/bb-10.6-MDEV-24637/sql/sql_parse.cc:1365
 
#30 0x0000556eb96ebbc3 in do_handle_one_connection (connect=0x608000002f38, put_in_cache=true) at /Server/bb-10.6-MDEV-24637/sql/sql_connect.cc:1410
 
#31 0x0000556eb96eb52c in handle_one_connection (arg=0x608000002ab8) at /Server/bb-10.6-MDEV-24637/sql/sql_connect.cc:1312
 
#32 0x0000556eba3eedaf in pfs_spawn_thread (arg=0x61500000ad18) at /Server/bb-10.6-MDEV-24637/storage/perfschema/pfs.cc:2201
 
#33 0x000024d51c2b3609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#34 0x00003a264e90b293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
(rr)
 
pluto:/data/Results/1611230368/tmp2/dev/shm/vardir/1611230368/186/1/rr
 
_RR_TRACE_DIR="." rr replay --mark-stdio
 
 
 
RQG
 
====
 
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
 
 
perl rqg.pl \              
--gendata=conf/engines/innodb/full_text_search.zz \
 
--max_gd_duration=1200 \
 
--short_column_names \
 
--grammar=conf/engines/innodb/full_text_search.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/foreign_keys.yy \
 
--redefine=conf/mariadb/modules/locks.yy \
 
--redefine=conf/mariadb/modules/sql_mode.yy \
 
--redefine=conf/mariadb/redefine_temporary_tables.yy \
 
--redefine=conf/mariadb/versioning.yy \
 
--redefine=conf/mariadb/sequences.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/RQG_O/conf/mariadb/encryption_keys.txt \
 
--duration=300 \
 
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
 
--mysqld=--innodb_stats_persistent=on \
 
--mysqld=--innodb_adaptive_hash_index=on \
 
--mysqld=--loose-max-statement-time=30 \
 
--threads=1 \
 
--mysqld=--innodb_page_size=8K \
 
--mysqld=--innodb-buffer-pool-size=256M \
 
--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 [ 2021-02-09 ]

The automatic test simplifier is just running and seems to make good progress.

Comment by Matthias Leich [ 2021-02-10 ] 

The uploaded RQG grammar TBR-826.yy is a simplified version of the test.
 
rqg.pl \ 
--duration=300 \
 
--queries=10000000 \
 
--no_mask \
 
--seed=random \
 
--gendata=conf/mariadb/table_stress.zz \
 
--engine=InnoDB \
 
--rpl_mode=none \
 
--mysqld=--innodb_adaptive_hash_index=on \
 
--mysqld=--log-output=none \
 
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
 
--mysqld=--innodb_page_size=4K \
 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
--mysqld=--log-bin \
 
--mysqld=--loose-table_lock_wait_timeout=50 \
 
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
 
--mysqld=--lock-wait-timeout=86400 \
 
--mysqld=--innodb-lock-wait-timeout=50 \
 
--mysqld=--loose-idle_write_transaction_timeout=0 \
 
--mysqld=--loose-max-statement-time=30 \
 
--mysqld=--net_read_timeout=30 \
 
--mysqld=--net_write_timeout=60 \
 
--mysqld=--connect_timeout=60 \
 
--mysqld=--innodb_stats_persistent=off \
 
--mysqld=--interactive_timeout=28800 \
 
--mysqld=--wait_timeout=28800 \
 
--mysqld=--loose-idle_transaction_timeout=0 \
 
--mysqld=--slave_net_timeout=60 \
 
--mysqld=--log_bin_trust_function_creators=1 \
 
--mysqld=--innodb-buffer-pool-size=256M \
 
--reporters=Backtrace,Deadlock1,ErrorLog \
 
--validators=None \
 
--grammar=TBR.826.yy \
 
--threads=2 \
 
--rr \
 
--workdir=<local settings> \
 
--vardir=<local settings> \
 
--mtr-build-thread=<local settings> \
 
--basedir1=<local settings> 
 
 
The bug is also in
 
origin/10.6 commit bfb4761ca04704d68dba51f76d7c9967f880a6ee

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