[MDEV-14240] sync0rw.ic:285 Assertion `!rw_lock_own(lock, RW_LOCK_X)' failed Created: 2017-11-01  Updated: 2023-11-02  Resolved: 2023-11-02

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

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Marko Mäkelä
Resolution: Cannot Reproduce Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-11816 Disallow CREATE TEMPORARY TABLE…ROW_F... Closed
relates to MDEV-13626 Merge InnoDB test cases from MySQL 5.7 Closed
relates to MDEV-16779 Assertion `!rw_lock_own(lock, RW_LOCK... Closed

 Description   

innodb_zip.wl6470_1 failed with 4k, (test merged from mysql 5.7) https://github.com/MariaDB/server/blob/mdev-13626/mysql-test/suite/innodb_zip/t/wl6470_1.test

innodb_zip.wl6470_1 '16k,innodb'         [ pass ]    724
innodb_zip.wl6470_1 '4k,innodb'          [ fail ]
        Test ended at 2017-11-01 15:19:40
 
CURRENT_TEST: innodb_zip.wl6470_1
mysqltest: In included file "./suite/innodb_zip/include/innodb_dml_ops.inc": 
included from /10.2/mysql-test/suite/innodb_zip/t/wl6470_1.test at line 25:
At line 62: query 'rollback' failed: 2013: Lost connection to MySQL server during query
 
The result from queries just before the failure was:
< snip >
9	c	d
10	c	d
begin;
call populate_t1_small2();
select count(*) from t1;
count(*)
181
select * from t1 where keyc > 30 limit 10;
keyc	c1	c2
31	e	f
32	e	f
33	e	f
34	e	f
35	e	f
36	e	f
37	e	f
38	e	f
39	e	f
40	e	f
rollback;
 
More results from queries before failure can be found in /10.2/mysql-test/var/log/wl6470_1.log

Version: '10.2.10-MariaDB-debug-log'  socket: '/10.2/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
mysqld: /10.2/storage/innobase/include/sync0rw.ic:285: void rw_lock_s_lock_func(rw_lock_t*, ulint, const char*, unsigned int): Assertion `!rw_lock_own(lock, RW_LOCK_X)' failed.
171101 15:19:39 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.2.10-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=7
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63152 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7fc7ac000a98
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7fc7f45f5e70 thread_stack 0x49000
/10.2/sql/mysqld(my_print_stacktrace+0x38)[0x559d8e64e4df]
/10.2/sql/mysqld(handle_fatal_signal+0x3a3)[0x559d8dedfd62]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fc80374b390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7fc802b04428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fc802b0602a]
mysys/stacktrace.c:267(my_print_stacktrace)[0x7fc802afcbd7]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7fc802afcc82]
include/sync0rw.ic:287(rw_lock_s_lock_func(rw_lock_t*, unsigned long, char const*, unsigned int))[0x559d8e39df02]
include/sync0rw.ic:640(pfs_rw_lock_s_lock_func(rw_lock_t*, unsigned long, char const*, unsigned int))[0x559d8e39e8e0]
buf/buf0buf.cc:4759(buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*))[0x559d8e3ae8d0]
include/trx0undo.ic:179(trx_undo_page_get_s_latched(page_id_t const&, mtr_t*))[0x559d8e31ffae]
trx/trx0rec.cc:2094(trx_undo_get_undo_rec_low(unsigned long, bool, mem_block_info_t*))[0x559d8e324fe1]
trx/trx0rec.cc:2132(trx_undo_get_undo_rec(unsigned long, bool, mem_block_info_t*, unsigned long, table_name_t const&, unsigned char**))[0x559d8e325107]
trx/trx0rec.cc:2216(trx_undo_prev_version_build(unsigned char const*, mtr_t*, unsigned char const*, dict_index_t*, unsigned long*, mem_block_info_t*, unsigned char**, mem_block_info_t*, dtuple_t const**, unsigned long))[0x559d8e32532f]
row/row0vers.cc:1019(row_vers_old_has_index_entry(unsigned long, unsigned char const*, mtr_t*, dict_index_t*, dtuple_t const*, unsigned long, unsigned long))[0x559d8e2db4ca]
row/row0umod.cc:512(row_undo_mod_del_mark_or_remove_sec_low(undo_node_t*, que_thr_t*, dict_index_t*, dtuple_t*, unsigned long))[0x559d8e4bc58c]
row/row0umod.cc:584(row_undo_mod_del_mark_or_remove_sec(undo_node_t*, que_thr_t*, dict_index_t*, dtuple_t*))[0x559d8e4bc8a5]
row/row0umod.cc:889(row_undo_mod_upd_del_sec(undo_node_t*, que_thr_t*))[0x559d8e4bd604]
row/row0umod.cc:1254(row_undo_mod(undo_node_t*, que_thr_t*))[0x559d8e4be34f]
row/row0undo.cc:301(row_undo(undo_node_t*, que_thr_t*))[0x559d8e2c5344]
row/row0undo.cc:342(row_undo_step(que_thr_t*))[0x559d8e2c5451]
que/que0que.cc:1051(que_thr_step(que_thr_t*))[0x559d8e224e1a]
que/que0que.cc:1115(que_run_threads_low(que_thr_t*))[0x559d8e225034]
que/que0que.cc:1157(que_run_threads(que_thr_t*))[0x559d8e2251dd]
trx/trx0roll.cc:122(trx_rollback_to_savepoint_low(trx_t*, trx_savept_t*))[0x559d8e327f57]
trx/trx0roll.cc:182(trx_rollback_for_mysql_low(trx_t*))[0x559d8e3282c2]
trx/trx0roll.cc:212(trx_rollback_low(trx_t*))[0x559d8e3285b9]
trx/trx0roll.cc:288(trx_rollback_for_mysql(trx_t*))[0x559d8e3288f0]
handler/ha_innodb.cc:4865(innobase_rollback(handlerton*, THD*, bool))[0x559d8e12c347]
sql/handler.cc:1670(ha_rollback_trans(THD*, bool))[0x559d8dee3df8]
sql/transaction.cc:415(trans_rollback(THD*))[0x559d8ddce750]
sql/sql_parse.cc:5578(mysql_execute_command(THD*))[0x559d8dc782b0]
sql/sql_parse.cc:7861(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x559d8dc7eee5]
sql/sql_parse.cc:1807(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x559d8dc6cbb2]
sql/sql_parse.cc:1360(do_command(THD*))[0x559d8dc6b509]
sql/sql_connect.cc:1354(do_handle_one_connection(CONNECT*))[0x559d8ddb897e]
sql/sql_connect.cc:1261(handle_one_connection)[0x559d8ddb86fe]
perfschema/pfs.cc:1865(pfs_spawn_thread)[0x559d8e114256]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fc8037416ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fc802bd63dd]
 
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fc7ac034210): rollback
Connection ID (thread ID): 9
Status: NOT_KILLED
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
Writing a core file

Thread 1 (Thread 0x7fc7f45f6700 (LWP 1970)):
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1  0x0000559d8e64e5d1 in my_write_core (sig=6) at /10.2/mysys/stacktrace.c:477
#2  0x0000559d8dee010e in handle_fatal_signal (sig=6) at /10.2/sql/signal_handler.cc:303
#3  <signal handler called>
#4  0x00007fc802b04428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#5  0x00007fc802b0602a in __GI_abort () at abort.c:89
#6  0x00007fc802afcbd7 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x559d8e9151d2 "!rw_lock_own(lock, RW_LOCK_X)", file=file@entry=0x559d8e915160 "/10.2/storage/innobase/include/sync0rw.ic", line=line@entry=285, function=function@entry=0x559d8e91b720 <_ZZL19rw_lock_s_lock_funcP9rw_lock_tmPKcjE19__PRETTY_FUNCTION__> "void rw_lock_s_lock_func(rw_lock_t*, ulint, const char*, unsigned int)") at assert.c:92
#7  0x00007fc802afcc82 in __GI___assert_fail (assertion=0x559d8e9151d2 "!rw_lock_own(lock, RW_LOCK_X)", file=0x559d8e915160 "/10.2/storage/innobase/include/sync0rw.ic", line=285, function=0x559d8e91b720 <_ZZL19rw_lock_s_lock_funcP9rw_lock_tmPKcjE19__PRETTY_FUNCTION__> "void rw_lock_s_lock_func(rw_lock_t*, ulint, const char*, unsigned int)") at assert.c:101
#8  0x0000559d8e39df02 in rw_lock_s_lock_func (lock=0x7fc7fc13a0c8, pass=0, file_name=0x559d8e8e0be8 "/10.2/storage/innobase/include/trx0undo.ic", line=180) at /10.2/storage/innobase/include/sync0rw.ic:285
#9  0x0000559d8e39e8e0 in pfs_rw_lock_s_lock_func (lock=0x7fc7fc13a0c8, pass=0, file_name=0x559d8e8e0be8 "/10.2/storage/innobase/include/trx0undo.ic", line=180) at /10.2/storage/innobase/include/sync0rw.ic:638
#10 0x0000559d8e3ae8d0 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=1, guess=0x0, mode=10, file=0x559d8e8e0be8 "/10.2/storage/innobase/include/trx0undo.ic", line=180, mtr=0x7fc7f45f1ca0, err=0x0) at /10.2/storage/innobase/buf/buf0buf.cc:4757
#11 0x0000559d8e31ffae in trx_undo_page_get_s_latched (page_id=..., mtr=0x7fc7f45f1ca0) at /10.2/storage/innobase/include/trx0undo.ic:179
#12 0x0000559d8e324fe1 in trx_undo_get_undo_rec_low (roll_ptr=26458647831776232, is_temp=true, heap=0x7fc7ac04acb0) at /10.2/storage/innobase/trx/trx0rec.cc:2094
#13 0x0000559d8e325107 in trx_undo_get_undo_rec (roll_ptr=26458647831776232, is_temp=true, heap=0x7fc7ac04acb0, trx_id=1506, name=..., undo_rec=0x7fc7f45f2270) at /10.2/storage/innobase/trx/trx0rec.cc:2132
#14 0x0000559d8e32532f in trx_undo_prev_version_build (index_rec=0x7fc7fc417855 "\200", index_mtr=0x7fc7f45f2bf0, rec=0x7fc7ac04b3b6 "\200", index=0x7fc7ac066828, offsets=0x7fc7ac04b4e0, heap=0x7fc7ac04acb0, old_vers=0x7fc7f45f2360, v_heap=0x0, vrow=0x0, v_status=0) at /10.2/storage/innobase/trx/trx0rec.cc:2216
#15 0x0000559d8e2db4ca in row_vers_old_has_index_entry (also_curr=0, rec=0x7fc7fc417855 "\200", mtr=0x7fc7f45f2bf0, index=0x7fc7ac17d328, ientry=0x7fc7ac04a8a8, roll_ptr=0, trx_id=0) at /10.2/storage/innobase/row/row0vers.cc:1019
#16 0x0000559d8e4bc58c in row_undo_mod_del_mark_or_remove_sec_low (node=0x7fc7ac04d5f8, thr=0x7fc7ac04e2c0, index=0x7fc7ac17d328, entry=0x7fc7ac04a8a8, mode=2) at /10.2/storage/innobase/row/row0umod.cc:512
#17 0x0000559d8e4bc8a5 in row_undo_mod_del_mark_or_remove_sec (node=0x7fc7ac04d5f8, thr=0x7fc7ac04e2c0, index=0x7fc7ac17d328, entry=0x7fc7ac04a8a8) at /10.2/storage/innobase/row/row0umod.cc:584
#18 0x0000559d8e4bd604 in row_undo_mod_upd_del_sec (node=0x7fc7ac04d5f8, thr=0x7fc7ac04e2c0) at /10.2/storage/innobase/row/row0umod.cc:889
#19 0x0000559d8e4be34f in row_undo_mod (node=0x7fc7ac04d5f8, thr=0x7fc7ac04e2c0) at /10.2/storage/innobase/row/row0umod.cc:1254
#20 0x0000559d8e2c5344 in row_undo (node=0x7fc7ac04d5f8, thr=0x7fc7ac04e2c0) at /10.2/storage/innobase/row/row0undo.cc:301
#21 0x0000559d8e2c5451 in row_undo_step (thr=0x7fc7ac04e2c0) at /10.2/storage/innobase/row/row0undo.cc:342
#22 0x0000559d8e224e1a in que_thr_step (thr=0x7fc7ac04e2c0) at /10.2/storage/innobase/que/que0que.cc:1051
#23 0x0000559d8e225034 in que_run_threads_low (thr=0x7fc7ac04e2c0) at /10.2/storage/innobase/que/que0que.cc:1115
#24 0x0000559d8e2251dd in que_run_threads (thr=0x7fc7ac04e2c0) at /10.2/storage/innobase/que/que0que.cc:1155
#25 0x0000559d8e327f57 in trx_rollback_to_savepoint_low (trx=0x7fc7fca6b888, savept=0x0) at /10.2/storage/innobase/trx/trx0roll.cc:118
#26 0x0000559d8e3282c2 in trx_rollback_for_mysql_low (trx=0x7fc7fca6b888) at /10.2/storage/innobase/trx/trx0roll.cc:180
#27 0x0000559d8e3285b9 in trx_rollback_low (trx=0x7fc7fca6b888) at /10.2/storage/innobase/trx/trx0roll.cc:212
#28 0x0000559d8e3288f0 in trx_rollback_for_mysql (trx=0x7fc7fca6b888) at /10.2/storage/innobase/trx/trx0roll.cc:288
#29 0x0000559d8e12c347 in innobase_rollback (hton=0x559d904b7608, thd=0x7fc7ac000a98, rollback_trx=true) at /10.2/storage/innobase/handler/ha_innodb.cc:4865
#30 0x0000559d8dee3df8 in ha_rollback_trans (thd=0x7fc7ac000a98, all=true) at /10.2/sql/handler.cc:1670
#31 0x0000559d8ddce750 in trans_rollback (thd=0x7fc7ac000a98) at /10.2/sql/transaction.cc:415
#32 0x0000559d8dc782b0 in mysql_execute_command (thd=0x7fc7ac000a98) at /10.2/sql/sql_parse.cc:5578
#33 0x0000559d8dc7eee5 in mysql_parse (thd=0x7fc7ac000a98, rawbuf=0x7fc7ac034210 "rollback", length=8, parser_state=0x7fc7f45f51f0, is_com_multi=false, is_next_command=false) at /10.2/sql/sql_parse.cc:7861
#34 0x0000559d8dc6cbb2 in dispatch_command (command=COM_QUERY, thd=0x7fc7ac000a98, packet=0x7fc7ac007f49 "rollback", packet_length=8, is_com_multi=false, is_next_command=false) at /10.2/sql/sql_parse.cc:1805
#35 0x0000559d8dc6b509 in do_command (thd=0x7fc7ac000a98) at /10.2/sql/sql_parse.cc:1360
#36 0x0000559d8ddb897e in do_handle_one_connection (connect=0x559d90a75d98) at /10.2/sql/sql_connect.cc:1354
#37 0x0000559d8ddb86fe in handle_one_connection (arg=0x559d90a75d98) at /10.2/sql/sql_connect.cc:1260
#38 0x0000559d8e114256 in pfs_spawn_thread (arg=0x559d90a2ae08) at /10.2/storage/perfschema/pfs.cc:1863
#39 0x00007fc8037416ba in start_thread (arg=0x7fc7f45f6700) at pthread_create.c:333
#40 0x00007fc802bd63dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109



 Comments   
Comment by Marko Mäkelä [ 2023-11-02 ]

I can’t reproduce this failure on a recent 10.4 where I ported the test. The original purpose of the test was to test CREATE TEMPORARY TABLE…ENGINE=InnoDB ROW_FORMAT=COMPRESSED, but MariaDB never allowed the creation of any compressed temporary tables.

The reported assertion failure indicates an attempt to acquire a shared latch on an undo page on which the current thread (executing ROLLBACK) already held an exclusive latch. If the assertion failure were reproducible, it would look in 10.6 and later major releases due to MDEV-24142. In MDEV-32050 (MariaDB Server 10.6.16), this code was changed further so that rollback would mainly hold a buffer fix on the undo log pages that it is processing.

Comment by Marko Mäkelä [ 2023-11-02 ]

MDEV-11816 disallowed compressed temporary tables in MariaDB Server.

Generated at Thu Feb 08 08:12:01 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.