Details
-
Bug
-
Status: Closed (View Workflow)
-
Blocker
-
Resolution: Fixed
-
10.6.0, 10.5
Description
origin/10.6 92abdcca5a5324f0727112ab2417d10c7a8d5094 2021-01-07T09:08:09+02:00
|
Workflow:
|
1. Start the server
|
2. Run a DDL/DML mix by 9 sessions
|
3. During 2. is ongoing kill the server
|
4. The attempt to restart the server fails with
|
mysqld:storage/innobase/log/log0recv.cc:274: log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const: Assertion `mach_read_from_4(frame + 4U) == block.page.id().page_no()' failed.
|
(rr) bt
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x00007d171d43c859 in __GI_abort () at abort.c:79
|
#2 0x00007d171d43c729 in __assert_fail_base (fmt=0x7d171d5d2588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x564bea837fc0 "mach_read_from_4(frame + 4U) == block.page.id().page_no()",
|
file=0x564bea837960 "/Server/10.6E/storage/innobase/log/log0recv.cc", line=274, function=<optimized out>) at assert.c:92
|
#3 0x00007d171d44df36 in __GI___assert_fail (assertion=0x564bea837fc0 "mach_read_from_4(frame + 4U) == block.page.id().page_no()", file=0x564bea837960 "/Server/10.6E/storage/innobase/log/log0recv.cc", line=274,
|
function=0x564bea837d40 "log_phys_t::apply_status log_phys_t::apply(const buf_block_t&, uint16_t&) const") at assert.c:101
|
#4 0x0000564be906714e in log_phys_t::apply (this=0x6400003b2740, block=..., last_offset=@0x608001af92e4: 0) at /Server/10.6E/storage/innobase/log/log0recv.cc:274
|
#5 0x0000564be905473c in recv_recover_page (block=0x6400000e8360, mtr=..., Traceback (most recent call last):
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1522, in __call__
|
return self.lookup[basename].invoke(val)
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1459, in invoke
|
return self.function(self.name, value)
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 649, in __init__
|
self.link_type = nodetype.pointer()
|
AttributeError: 'NoneType' object has no attribute 'pointer'
|
p=
|
..., space=0x613000000c98, init=0x6070000117f0) at /Server/10.6E/storage/innobase/log/log0recv.cc:2316
|
#6 0x0000564be906f5c6 in recv_sys_t::recover_low (this=0x564bebab2da0 <recv_sys>, page_id=..., Traceback (most recent call last):
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1522, in __call__
|
return self.lookup[basename].invoke(val)
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 1459, in invoke
|
return self.function(self.name, value)
|
File "/lib/x86_64-linux-gnu/../../share/gcc-10/python/libstdcxx/v6/printers.py", line 649, in __init__
|
self.link_type = nodetype.pointer()
|
AttributeError: 'NoneType' object has no attribute 'pointer'
|
p=
|
..., mtr=..., b=0x6400000e8360) at /Server/10.6E/storage/innobase/log/log0recv.cc:2590
|
#7 0x0000564be905753b in recv_sys_t::apply (this=0x564bebab2da0 <recv_sys>, last_batch=true) at /Server/10.6E/storage/innobase/log/log0recv.cc:2705
|
#8 0x0000564be92efde0 in srv_start (create_new_db=false) at /Server/10.6E/storage/innobase/srv/srv0start.cc:1470
|
#9 0x0000564be8e6c164 in innodb_init (p=0x615000002898) at /Server/10.6E/storage/innobase/handler/ha_innodb.cc:3689
|
#10 0x0000564be8350be1 in ha_initialize_handlerton (plugin=0x621000033010) at /Server/10.6E/sql/handler.cc:645
|
#11 0x0000564be7b895b4 in plugin_initialize (tmp_root=0x7ffe97cc90a0, plugin=0x621000033010, argc=0x564bebff7a00 <remaining_argc>, argv=0x615000000e08, options_only=false) at /Server/10.6E/sql/sql_plugin.cc:1459
|
#12 0x0000564be7b8b542 in plugin_init (argc=0x564bebff7a00 <remaining_argc>, argv=0x615000000e08, flags=0) at /Server/10.6E/sql/sql_plugin.cc:1751
|
#13 0x0000564be784466b in init_server_components () at /Server/10.6E/sql/mysqld.cc:4950
|
#14 0x0000564be784665e in mysqld_main (argc=28, argv=0x615000000e08) at /Server/10.6E/sql/mysqld.cc:5539
|
#15 0x0000564be783014d in main (argc=27, argv=0x7ffe97ccb7d8) at /Server/10.6E/sql/main.cc:25
|
(rr)
|
|
|
pluto:/data/Results/1610366087/CR-20/dev/shm/vardir/1610366087/50/1/rr
|
_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-0 # Fate of the server till SIGKILL
|
_RR_TRACE_DIR="." rr replay --mark-stdio # The failing restart
|
|
|
|
|
|
|
RQG
|
====
|
git clone https://github.com/mleich1/rqg --branch experimental RQG
|
|
|
perl rqg.pl \
|
--no-mask \
|
--seed=1610366105 \
|
--duration=300 \
|
--engine=InnoDB \
|
--queries=100000000 \
|
--mysqld=--loose_innodb_use_native_aio=1 \
|
--reporters=Backtrace,ErrorLog,Deadlock1,CrashRecovery1 \
|
--mysqld=--innodb_undo_tablespaces=3 \
|
--mysqld=--innodb_immediate_scrub_data_uncompressed=1 \
|
--mysqld=--innodb_file_per_table=0 \
|
--restart_timeout=600 \
|
--max_gd_duration=1200 \
|
--mysqld=--innodb_page_size=8K \
|
--mysqld=--innodb-buffer-pool-size=8M \
|
--mysqld=--log_output=none \
|
--sqltrace=MarkErrors \
|
--grammar=conf/mariadb/innodb_compression_encryption.yy \
|
--gendata=conf/mariadb/innodb_compression_encryption.zz \
|
--mysqld=--plugin-load-add=file_key_management.so \
|
--mysqld=--loose-file-key-management-filename=$RQG/conf/mariadb/encryption_keys.txt \
|
--threads=9 \
|
--duration=300 \
|
--no_mask \
|
--workdir=<local settings> \
|
--vardir=<local settings> \
|
--mtr-build-thread=<local settings> \
|
--basedir1=<local settings> \
|
--basedir2=<local settings> \
|
--script_debug=_nix_ \
|
--rr=Extended \
|
--rr_options=--chaos
|
|
|
You will need several attempts for replaying the bug once.
|
Attachments
Issue Links
- causes
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
MDEV-18518 Implement atomic multi-table (or multi-partition) CREATE TABLE for InnoDB
-
- Closed
-
-
-
- Closed
-
(2 relates to)
Activity
On the merge to 10.6, I discarded the change to replace the fil_space_t::latch S-latch with SX-latch, because MDEV-24167 replaced that with a plain RW-lock. In 10.6, we will avoid the read-latch acquisition if the current thread is already holding the fil_space_t::latch in exclusive mode.
ssh sdp
|
_RR_TRACE_DIR=/home/mleich/RQG_O/storage/1610563808/tmp1/dev/shm/vardir/1610563808/173/1/rr rr replay
|
That failure should be completely unrelated to this bug. I was first suspecting that it could be fixed by MDEV-20605, but that does not seem to be the case. Here is the assertion failure and the creation of the conflicting lock shortly earlier:
Thread 3 received signal SIGABRT, Aborted.
|
__GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
50 in ../sysdeps/unix/sysv/linux/raise.c
|
(rr) backtrace
|
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
|
#1 0x000028411bded859 in __GI_abort () at abort.c:79
|
#2 0x000028411bded729 in __assert_fail_base (fmt=0x28411bf83588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55a435d77cc0 "!other_lock",
|
file=0x55a435d758e0 "/Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc", line=1775, function=<optimized out>) at assert.c:92
|
#3 0x000028411bdfef36 in __GI___assert_fail (assertion=0x55a435d77cc0 "!other_lock", file=0x55a435d758e0 "/Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc", line=1775,
|
function=0x55a435d77b40 "void lock_rec_add_to_queue(unsigned int, const buf_block_t*, ulint, dict_index_t*, trx_t*, bool)") at assert.c:101
|
#4 0x000055a4344e2a7d in lock_rec_add_to_queue (type_mode=35, block=0x4a3e2d3c1520, heap_no=2, index=0x6170003277a0, trx=0x74905a4644c0, caller_owns_trx_mutex=false)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc:1775
|
#5 0x000055a4344e7ad4 in lock_move_rec_list_end (new_block=0x4a3e2d3c1520, block=0x4a3e2d3c66b0, rec=0x4a3e2d7ce065 "infimum") at /Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc:2710
|
#6 0x000055a4345c6a0e in page_copy_rec_list_end (new_block=0x4a3e2d3c1520, block=0x4a3e2d3c66b0, rec=0x4a3e2d7ce065 "infimum", index=0x6170003277a0, mtr=0x38c21e5e4dc0)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/page/page0page.cc:658
|
#7 0x000055a4348cdc15 in btr_root_raise_and_insert (flags=0, cursor=0x38c21e5e49a0, offsets=0x38c21e5e4920, heap=0x38c21e5e4900, tuple=0x61700047ac20, n_ext=1, mtr=0x38c21e5e4dc0)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0btr.cc:1904
|
#8 0x000055a43491ea43 in btr_cur_pessimistic_insert (flags=0, cursor=0x38c21e5e49a0, offsets=0x38c21e5e4920, heap=0x38c21e5e4900, entry=0x61700047ac20, rec=0x38c21e5e4940, big_rec=0x38c21e5e48e0, n_ext=1,
|
thr=0x621000447ca0, mtr=0x38c21e5e4dc0) at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0cur.cc:3746
|
#9 0x000055a434694e0e in row_ins_clust_index_entry_low (flags=0, mode=33, index=0x6170003277a0, n_uniq=0, entry=0x61700047ac20, n_ext=0, thr=0x621000447ca0)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:2755
|
#10 0x000055a434697980 in row_ins_clust_index_entry (index=0x6170003277a0, entry=0x61700047ac20, thr=0x621000447ca0, n_ext=0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3225
|
#11 0x000055a434698154 in row_ins_index_entry (index=0x6170003277a0, entry=0x61700047ac20, thr=0x621000447ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3333
|
#12 0x000055a4346992c5 in row_ins_index_entry_step (node=0x6210004477c0, thr=0x621000447ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3502
|
#13 0x000055a434699d9e in row_ins (node=0x6210004477c0, thr=0x621000447ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3661
|
#14 0x000055a43469afb9 in row_ins_step (thr=0x621000447ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3807
|
#15 0x000055a4346e4abd in row_insert_for_mysql (mysql_rec=0x61a00086eeb8 "\320\001", prebuilt=0x6210004471a0, ins_mode=ROW_INS_NORMAL) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0mysql.cc:1421
|
#16 0x000055a434343582 in ha_innobase::write_row (this=0x61d000a122b8, record=0x61a00086eeb8 "\320\001") at /Server/bb-10.5-MDEV-24569/storage/innobase/handler/ha_innodb.cc:7545
|
#17 0x000055a433840d51 in handler::ha_write_row (this=0x61d000a122b8, buf=0x61a00086eeb8 "\320\001") at /Server/bb-10.5-MDEV-24569/sql/handler.cc:7151
|
#18 0x000055a432f4c43e in write_record (thd=0x62b00018f218, table=0x61900064d798, info=0x38c21e5e6820, sink=0x0) at /Server/bb-10.5-MDEV-24569/sql/sql_insert.cc:2106
|
#19 0x000055a432f43efb in mysql_insert (thd=0x62b00018f218, table_list=0x62b0001964b8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0)
|
at /Server/bb-10.5-MDEV-24569/sql/sql_insert.cc:1099
|
#20 0x000055a43300c790 in mysql_execute_command (thd=0x62b00018f218) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:4596
|
#21 0x000055a433024c98 in mysql_parse (thd=0x62b00018f218,
|
rawbuf=0x62b000196238 "INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1 - 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread17 QNO 188 C"..., length=211, parser_state=0x38c21e5e77c0, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:8062
|
#22 0x000055a432ffaf91 in dispatch_command (command=COM_QUERY, thd=0x62b00018f218,
|
packet=0x6290007df219 " INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1 - 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread17 QNO 188 "..., packet_length=213, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:1889
|
#23 0x000055a432ff78ba in do_command (thd=0x62b00018f218) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:1370
|
#24 0x000055a433439b71 in do_handle_one_connection (connect=0x60800000d6b8, put_in_cache=true) at /Server/bb-10.5-MDEV-24569/sql/sql_connect.cc:1410
|
#25 0x000055a4334394da in handle_one_connection (arg=0x60800000d6b8) at /Server/bb-10.5-MDEV-24569/sql/sql_connect.cc:1312
|
#26 0x000055a4341442eb in pfs_spawn_thread (arg=0x61500000e918) at /Server/bb-10.5-MDEV-24569/storage/perfschema/pfs.cc:2201
|
#27 0x00007f67f5fef609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#28 0x000028411beea293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr) reverse-continue
|
Continuing.
|
[Switching to Thread 1745825.1798278]
|
|
|
Thread 42 hit Breakpoint 4, lock_rec_create_low (c_lock=0x0, thr=0x0, type_mode=2, page_id=..., page=0x4a3e2d75a000 "", heap_no=2, index=0x617000536e20, trx=0x74905a450810, holds_trx_mutex=false)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc:1332
|
1332 lock->trx = trx;
|
Current event: 361529
|
(rr) thread apply 3 backtrace
|
|
|
Thread 3 (Thread 1745825.1797112):
|
#0 0x0000000070000002 in ?? ()
|
#1 0x00005cd3326bf3b6 in _raw_syscall () at /build/rr-S0CLEN/rr-5.3.0/src/preload/raw_syscall.S:120
|
#2 0x00005cd3326bb2ff in traced_raw_syscall (call=call@entry=0x7f67f06aefa0) at ./src/preload/syscallbuf.c:229
|
#3 0x00005cd3326be37e in sys_futex (call=<optimized out>) at ./src/preload/syscallbuf.c:1355
|
#4 syscall_hook_internal (call=0x7f67f06aefa0) at ./src/preload/syscallbuf.c:2861
|
#5 syscall_hook (call=0x7f67f06aefa0) at ./src/preload/syscallbuf.c:2987
|
#6 0x00005cd3326bb1da in _syscall_hook_trampoline () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:282
|
#7 0x00005cd3326bb20a in __morestack () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:417
|
#8 0x00005cd3326bb225 in _syscall_hook_trampoline_48_3d_00_f0_ff_ff () at /build/rr-S0CLEN/rr-5.3.0/src/preload/syscall_hook.S:428
|
#9 0x00007f67f5ff67b7 in futex_abstimed_wait_cancelable (private=<optimized out>, abstime=0x38c21e5e57a0, clockid=<optimized out>, expected=0, futex_word=0x62b00018f414) at ../sysdeps/nptl/futex-internal.h:320
|
#10 __pthread_cond_wait_common (abstime=0x38c21e5e57a0, clockid=<optimized out>, mutex=0x62b00018f360, cond=0x62b00018f3e8) at pthread_cond_wait.c:520
|
#11 __pthread_cond_timedwait (cond=0x62b00018f3e8, mutex=0x62b00018f360, abstime=0x38c21e5e57a0) at pthread_cond_wait.c:656
|
#12 0x000055a434dd045d in safe_cond_timedwait (cond=0x62b00018f3e8, mp=0x62b00018f338, abstime=0x38c21e5e57a0, file=0x55a43546d340 "/Server/bb-10.5-MDEV-24569/include/mysql/psi/mysql_thread.h", line=1270) at /Server/bb-10.5-MDEV-24569/mysys/thr_mutex.c:546
|
#13 0x000055a43345bdb9 in inline_mysql_cond_timedwait (that=0x62b00018f3e8, mutex=0x62b00018f338, abstime=0x38c21e5e57a0, src_file=0x55a435471200 "/Server/bb-10.5-MDEV-24569/sql/mdl.cc", src_line=1166) at /Server/bb-10.5-MDEV-24569/include/mysql/psi/mysql_thread.h:1270
|
#14 0x000055a43345e72a in MDL_wait::timed_wait (this=0x62b00018f338, owner=0x62b00018f2e8, abs_timeout=0x38c21e5e57a0, set_status_on_timeout=false, wait_state_name=0x55a436a87c70 <MDL_key::m_namespace_to_wait_state_name+48>) at /Server/bb-10.5-MDEV-24569/sql/mdl.cc:1166
|
#15 0x000055a433462d00 in MDL_context::acquire_lock (this=0x62b00018f338, mdl_request=0x62b000196900, lock_wait_timeout=2) at /Server/bb-10.5-MDEV-24569/sql/mdl.cc:2332
|
#16 0x000055a432e62030 in open_table_get_mdl_lock (thd=0x62b00018f218, ot_ctx=0x38c21e5e62b0, mdl_request=0x62b000196900, flags=0, mdl_ticket=0x38c21e5e5c90) at /Server/bb-10.5-MDEV-24569/sql/sql_base.cc:1546
|
#17 0x000055a432e6390d in open_table (thd=0x62b00018f218, table_list=0x62b0001964b8, ot_ctx=0x38c21e5e62b0) at /Server/bb-10.5-MDEV-24569/sql/sql_base.cc:1815
|
#18 0x000055a432e6ea85 in open_and_process_table (thd=0x62b00018f218, tables=0x62b0001964b8, counter=0x38c21e5e63e0, flags=0, prelocking_strategy=0x38c21e5e6510, has_prelocking_list=false, ot_ctx=0x38c21e5e62b0) at /Server/bb-10.5-MDEV-24569/sql/sql_base.cc:3801
|
#19 0x000055a432e7160c in open_tables (thd=0x62b00018f218, options=..., start=0x38c21e5e63f0, counter=0x38c21e5e63e0, flags=0, prelocking_strategy=0x38c21e5e6510) at /Server/bb-10.5-MDEV-24569/sql/sql_base.cc:4275
|
#20 0x000055a432e76750 in open_and_lock_tables (thd=0x62b00018f218, options=..., tables=0x62b0001964b8, derived=true, flags=0, prelocking_strategy=0x38c21e5e6510) at /Server/bb-10.5-MDEV-24569/sql/sql_base.cc:5211
|
#21 0x000055a432dcd964 in open_and_lock_tables (thd=0x62b00018f218, tables=0x62b0001964b8, derived=true, flags=0) at /Server/bb-10.5-MDEV-24569/sql/sql_base.h:507
|
#22 0x000055a432f41bf4 in mysql_insert (thd=0x62b00018f218, table_list=0x62b0001964b8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0) at /Server/bb-10.5-MDEV-24569/sql/sql_insert.cc:756
|
#23 0x000055a43300c790 in mysql_execute_command (thd=0x62b00018f218) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:4596
|
#24 0x000055a433024c98 in mysql_parse (thd=0x62b00018f218, rawbuf=0x62b000196238 "INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1 - 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread17 QNO 188 C"..., length=211, parser_state=0x38c21e5e77c0, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:8062
|
#25 0x000055a432ffaf91 in dispatch_command (command=COM_QUERY, thd=0x62b00018f218, packet=0x6290007df219 " INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1 - 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread17 QNO 188 "..., packet_length=213, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:1889
|
#26 0x000055a432ff78ba in do_command (thd=0x62b00018f218) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:1370
|
#27 0x000055a433439b71 in do_handle_one_connection (connect=0x60800000d6b8, put_in_cache=true) at /Server/bb-10.5-MDEV-24569/sql/sql_connect.cc:1410
|
#28 0x000055a4334394da in handle_one_connection (arg=0x60800000d6b8) at /Server/bb-10.5-MDEV-24569/sql/sql_connect.cc:1312
|
#29 0x000055a4341442eb in pfs_spawn_thread (arg=0x61500000e918) at /Server/bb-10.5-MDEV-24569/storage/perfschema/pfs.cc:2201
|
#30 0x00007f67f5fef609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#31 0x000028411beea293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
(rr) backtrace
|
#0 lock_rec_create_low (c_lock=0x0, thr=0x0, type_mode=2, page_id=..., page=0x4a3e2d75a000 "", heap_no=2, index=0x617000536e20, trx=0x74905a450810, holds_trx_mutex=false)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc:1332
|
#1 0x000055a4344d5e81 in lock_rec_create (c_lock=0x0, thr=0x0, type_mode=2, block=0x4a3e2d3c1520, heap_no=2, index=0x617000536e20, trx=0x74905a450810, caller_owns_trx_mutex=false)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/include/lock0lock.ic:97
|
#2 0x000055a4344e3501 in lock_rec_lock (impl=false, mode=2, block=0x4a3e2d3c1520, heap_no=2, index=0x617000536e20, thr=0x621000122ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc:1938
|
#3 0x000055a4344faa9b in lock_sec_rec_read_check_and_lock (flags=0, block=0x4a3e2d3c1520, rec=0x4a3e2d75a085 "\200", index=0x617000536e20, offsets=0x3bb61b227eb0, mode=LOCK_S, gap_mode=0, thr=0x621000122ca0)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/lock/lock0lock.cc:5597
|
#4 0x000055a43468e52d in row_ins_set_shared_rec_lock (type=0, block=0x4a3e2d3c1520, rec=0x4a3e2d75a085 "\200", index=0x617000536e20, offsets=0x3bb61b227eb0, thr=0x621000122ca0)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:1402
|
#5 0x000055a4346916e3 in row_ins_scan_sec_index_for_duplicate (flags=0, index=0x617000536e20, entry=0x6170000c5038, thr=0x621000122ca0, s_latch=true, mtr=0x3bb61b228660, offsets_heap=0x61a0005bbc98)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:2146
|
#6 0x000055a4346965b3 in row_ins_sec_index_entry_low (flags=0, mode=2, index=0x617000536e20, offsets_heap=0x61a0005bbc98, heap=0x61a0005bb698, entry=0x6170000c5038, trx_id=0, thr=0x621000122ca0)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3015
|
#7 0x000055a434697dfd in row_ins_sec_index_entry (index=0x617000536e20, entry=0x6170000c5038, thr=0x621000122ca0, check_foreign=true) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3288
|
#8 0x000055a43469816f in row_ins_index_entry (index=0x617000536e20, entry=0x6170000c5038, thr=0x621000122ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3335
|
#9 0x000055a4346992c5 in row_ins_index_entry_step (node=0x6210001227c0, thr=0x621000122ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3502
|
#10 0x000055a434699d9e in row_ins (node=0x6210001227c0, thr=0x621000122ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3661
|
#11 0x000055a43469afb9 in row_ins_step (thr=0x621000122ca0) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0ins.cc:3807
|
#12 0x000055a4346e4abd in row_insert_for_mysql (mysql_rec=0x61a0005bc2b8 "\320\001", prebuilt=0x6210001221a0, ins_mode=ROW_INS_NORMAL) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0mysql.cc:1421
|
#13 0x000055a434343582 in ha_innobase::write_row (this=0x61d0009a38b8, record=0x61a0005bc2b8 "\320\001") at /Server/bb-10.5-MDEV-24569/storage/innobase/handler/ha_innodb.cc:7545
|
#14 0x000055a433840d51 in handler::ha_write_row (this=0x61d0009a38b8, buf=0x61a0005bc2b8 "\320\001") at /Server/bb-10.5-MDEV-24569/sql/handler.cc:7151
|
#15 0x000055a432f4c43e in write_record (thd=0x62b00028b218, table=0x619000254498, info=0x3bb61b22a820, sink=0x0) at /Server/bb-10.5-MDEV-24569/sql/sql_insert.cc:2106
|
#16 0x000055a432f43efb in mysql_insert (thd=0x62b00028b218, table_list=0x62b0002924a8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false, result=0x0)
|
at /Server/bb-10.5-MDEV-24569/sql/sql_insert.cc:1099
|
#17 0x000055a43300c790 in mysql_execute_command (thd=0x62b00028b218) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:4596
|
#18 0x000055a433024c98 in mysql_parse (thd=0x62b00028b218,
|
rawbuf=0x62b000292238 "INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread9 QNO 205 CON_ID"..., length=206, parser_state=0x3bb61b22b7c0, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:8062
|
#19 0x000055a432ffaf91 in dispatch_command (command=COM_QUERY, thd=0x62b00028b218,
|
packet=0x629000e6f219 " INSERT INTO t4 (col1,col2, col_int, col_string, col_text) VALUES ( 1, 1, 1, REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), 10), REPEAT(SUBSTR(CAST( 1 AS CHAR),1,1), @fill_amount) ) /* E_R Thread9 QNO 205 CON_I"..., packet_length=208, is_com_multi=false, is_next_command=false) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:1889
|
#20 0x000055a432ff78ba in do_command (thd=0x62b00028b218) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:1370
|
#21 0x000055a433439b71 in do_handle_one_connection (connect=0x60800000e738, put_in_cache=true) at /Server/bb-10.5-MDEV-24569/sql/sql_connect.cc:1410
|
#22 0x000055a4334394da in handle_one_connection (arg=0x60800000dfb8) at /Server/bb-10.5-MDEV-24569/sql/sql_connect.cc:1312
|
#23 0x000055a4341442eb in pfs_spawn_thread (arg=0x615000021798) at /Server/bb-10.5-MDEV-24569/storage/perfschema/pfs.cc:2201
|
#24 0x00007f67f5fef609 in start_thread (arg=<optimized out>) at pthread_create.c:477
|
#25 0x000028411beea293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
mleich, please file a separate report for the !other_lock assertion failure, and try to shrink the RQG grammar, if possible. As you can see, the conflict involves two INSERT INTO t4 (the same table).
I validated my guess. The B-tree is indeed being freed here:
Thread 1 hit Hardware watchpoint 1: -location $1.frame[150+24+116*2/8]
|
|
|
Old value = 234 '\352'
|
New value = 235 '\353'
|
mtr_t::write<1u, (mtr_t::write_type)0, unsigned char> (this=0x33fe310a3230, block=..., ptr=0x6c9d750a00cb, val=235 '\353') at /Server/bb-10.5-MDEV-24569/storage/innobase/include/mtr0log.h:211
|
211 (ut_align_offset(p, srv_page_size)), p, end - p);
|
(rr) when
|
Current event: 1166976
|
(rr) bt
|
#0 0x00005650f61d59b4 in mtr_t::write<1u, (mtr_t::write_type)0, unsigned char> (this=0x33fe310a3230, block=..., ptr=0x6c9d750a00cb, val=235 '\353')
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/include/mtr0log.h:209
|
#1 0x00005650f66e62f7 in xdes_set_free<true> (block=..., descr=0x6c9d750a0096 "", offset=116, mtr=0x33fe310a3230) at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:164
|
#2 0x00005650f66d8c05 in fsp_free_page (space=0x615000003518, offset=116, mtr=0x33fe310a3230) at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:1227
|
#3 0x00005650f66e046c in fseg_free_page_low (seg_inode=0x6c9d7520c032 "", iblock=0x6c9d74f487a0, space=0x615000003518, offset=116, mtr=0x33fe310a3230)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:2468
|
#4 0x00005650f66e22c4 in fseg_free_step (header=0x6c9d753d804a "", mtr=0x33fe310a3230) at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:2708
|
#5 0x00005650f64c309c in btr_free_but_not_root (block=0x6c9d74f5cb10, log_mode=MTR_LOG_ALL) at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0btr.cc:1173
|
#6 0x00005650f64c33ae in btr_free_if_exists (page_id=..., zip_size=0, index_id=98, mtr=0x33fe310a3d10) at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0btr.cc:1221
|
#7 0x00005650f65f6fd4 in dict_drop_index_tree (pcur=0x629000e9a6a8, trx=0x58176ee5b9a8, mtr=0x33fe310a3d10) at /Server/bb-10.5-MDEV-24569/storage/innobase/dict/dict0crea.cc:955
|
#8 0x00005650f639d5b8 in row_upd_clust_step (node=0x629000e99f40, thr=0x625000f7b7a8) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0upd.cc:2819
|
#9 0x00005650f639e866 in row_upd (node=0x629000e99f40, thr=0x625000f7b7a8) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0upd.cc:2992
|
#10 0x00005650f639f7fa in row_upd_step (thr=0x625000f7b7a8) at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0upd.cc:3136
|
#11 0x00005650f62107a5 in que_thr_step (thr=0x625000f7b7a8) at /Server/bb-10.5-MDEV-24569/storage/innobase/que/que0que.cc:928
|
#12 0x00005650f6210cf3 in que_run_threads_low (thr=0x625000f7b7a8) at /Server/bb-10.5-MDEV-24569/storage/innobase/que/que0que.cc:1008
|
#13 0x00005650f6211152 in que_run_threads (thr=0x625000f7b7a8) at /Server/bb-10.5-MDEV-24569/storage/innobase/que/que0que.cc:1048
|
#14 0x00005650f62116cd in que_eval_sql (info=0x6170003151a0,
|
sql=0x5650f7a7f420 "PROCEDURE DROP_TABLE_PROC () IS\ntid CHAR;\niid CHAR;\nDECLARE CURSOR cur_idx IS\nSELECT ID FROM SYS_INDEXES\nWHERE TABLE_ID = tid FOR UPDATE;\nBEGIN\nSELECT ID INTO tid FROM SYS_TABLES\nWHERE NAME = :name FO"..., reserve_dict_mutex=false, trx=0x58176ee5b9a8) at /Server/bb-10.5-MDEV-24569/storage/innobase/que/que0que.cc:1125
|
#15 0x00005650f62f09e4 in row_drop_table_for_mysql (name=0x33fe310a56e0 "test/E", trx=0x58176ee5b9a8, sqlcom=SQLCOM_DROP_TABLE, create_failed=false, nonatomic=true)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0mysql.cc:3676
|
#16 0x00005650f5f97f04 in ha_innobase::delete_table (this=0x62b000142ca8, name=0x33fe310a75b0 "./test/E", sqlcom=SQLCOM_DROP_TABLE) at /Server/bb-10.5-MDEV-24569/storage/innobase/handler/ha_innodb.cc:13206
|
#17 0x00005650f5f62017 in ha_innobase::delete_table (this=0x62b000142ca8, name=0x33fe310a75b0 "./test/E") at /Server/bb-10.5-MDEV-24569/storage/innobase/handler/ha_innodb.cc:13333
|
#18 0x00005650f5408207 in hton_drop_table (hton=0x615000002898, path=0x33fe310a75b0 "./test/E") at /Server/bb-10.5-MDEV-24569/sql/handler.cc:564
|
#19 0x00005650f54152c5 in ha_delete_table (thd=0x62b00013b218, hton=0x615000002898, path=0x33fe310a75b0 "./test/E", db=0x33fe310a6d80, alias=0x33fe310a6da0, generate_warning=true)
|
at /Server/bb-10.5-MDEV-24569/sql/handler.cc:2770
|
#20 0x00005650f4e797b0 in mysql_rm_table_no_locks (thd=0x62b00013b218, tables=0x62b000142368, if_exists=true, drop_temporary=false, drop_view=false, drop_sequence=false, dont_log_query=false,
|
dont_free_locks=false) at /Server/bb-10.5-MDEV-24569/sql/sql_table.cc:2509
|
#21 0x00005650f4e77549 in mysql_rm_table (thd=0x62b00013b218, tables=0x62b000142368, if_exists=true, drop_temporary=false, drop_sequence=false, dont_log_query=false)
|
at /Server/bb-10.5-MDEV-24569/sql/sql_table.cc:2138
|
#22 0x00005650f4c0e086 in mysql_execute_command (thd=0x62b00013b218) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:4980
|
#23 0x00005650f4c22c98 in mysql_parse (thd=0x62b00013b218, rawbuf=0x62b000142238 "DROP TABLE IF EXISTS E /* E_R Thread9 QNO 42 CON_ID 23 */", length=57, parser_state=0x33fe310a87c0, is_com_multi=false,
|
is_next_command=false) at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:8062
|
…
|
(rr) break trx_write_serialisation_history thread 1
|
Breakpoint 2 at 0x5650f648204a: file /Server/bb-10.5-MDEV-24569/storage/innobase/trx/trx0trx.cc, line 1053.
|
(rr) continue
|
Continuing.
|
|
|
Thread 1 hit Breakpoint 2, trx_write_serialisation_history (trx=0x5650f67aaffd <yyrestart(FILE*)+274>, mtr=0x33fe310a3ac0) at /Server/bb-10.5-MDEV-24569/storage/innobase/trx/trx0trx.cc:1053
|
1053 {
|
(rr) when
|
Current event: 1167020
|
(rr) finish
|
Run till exit from #0 trx_write_serialisation_history (trx=0x5650f67aaffd <yyrestart(FILE*)+274>, mtr=0x33fe310a3ac0) at /Server/bb-10.5-MDEV-24569/storage/innobase/trx/trx0trx.cc:1053
|
trx_t::commit_low (this=0x58176ee5b9a8, mtr=0x33fe310a40f0) at /Server/bb-10.5-MDEV-24569/storage/innobase/trx/trx0trx.cc:1543
|
1543 mtr->commit();
|
(rr) next
|
1546 if (debug_sync)
|
(rr) p *mtr
|
$6 = {m_start = true, m_commit = true, …, m_commit_lsn = 78146879, m_freed_space = 0x0, m_freed_pages = 0x0}
|
(rr) continue
|
Continuing.
|
Thread-specific breakpoint 2 deleted - thread 1 no longer in the thread list.
|
|
|
Thread 3 received signal SIGKILL, Killed.
|
[Switching to Thread 3529385.3529624]
|
0x0000000070000002 in ?? ()
|
(rr) p log_sys.lsn
|
$8 = {<std::__atomic_base<unsigned long>> = {static _S_alignment = 8, _M_i = 78228899}, <No data fields>}
|
(rr) p log_sys.flushed_to_disk_lsn
|
$9 = {<std::__atomic_base<unsigned long>> = {static _S_alignment = 8, _M_i = 78144573}, <No data fields>}
|
Even though the DROP TABLE IF EXISTS E happened to finish committing in memory before the SIGKILL was received, the commit was not yet made persistent at the time of the kill. The end LSN of the transaction commit was mtr->m_commit_lsn==78146879, which is a few hundred bytes ahead of log_sys.flushed_to_disk_lsn == 78144573.
We would have had a similar disastrous effect as soon as the first mini-transaction of btr_free_if_exists() had been made durable.
The correct course of action would be to start dropping the B-tree in a purge-like operation, after the DDL transaction was committed, just like I have suggested in MDEV-18518.
The index ID mismatch after recovery could happen because a freed page was still attached to some other table. The key here seems to be innodb_file_per_table=0.
ssh sdp
|
_RR_TRACE_DIR=/home/mleich/RQG_O/storage/1610556037/tmp1/dev/shm/vardir/1610556037/232/1/rr rr replay
|
The PAGE_INDEX_ID was initialized here:
(rr) when
|
Current event: 129184
|
(rr) bt
|
#0 0x00005558f85d14a3 in mtr_t::write<8u, (mtr_t::write_type)0, unsigned long>
|
(this=0x61a0000576a8, block=..., ptr=0x17994ce6a042, val=116)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/include/mtr0log.h:209
|
#1 0x00005558f88e2f1c in PageBulk::init (this=0x61a000057698)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0bulk.cc:101
|
#2 0x00005558f88e6334 in BtrBulk::insert (this=0x607000e851f8,
|
tuple=0x6310000648d0, level=0)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0bulk.cc:1031
|
#3 0x00005558f865053a in BtrBulk::insert (this=0x607000e851f8,
|
tuple=0x6310000648d0)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/include/btr0bulk.h:301
|
#4 0x00005558f86bf0c1 in row_merge_insert_index_tuples (index=0x61700003bca0,
|
…
|
#26 0x00005558f701ec98 in mysql_parse (thd=0x62b00007e218,
|
rawbuf=0x62b000085238 "OPTIMIZE TABLE `test`.`t6`", length=26,
|
parser_state=0x50d457e7a7c0, is_com_multi=false, is_next_command=false)
|
at /Server/bb-10.5-MDEV-24569/sql/sql_parse.cc:8062
|
No earlier contents of this page 116 is available in the buffer pool. Earlier, the memory was used for buffering redo log records during recovery.
The OPTIMIZE TABLE that is rebuilding the table t6 is reusing the page 116 for a PRIMARY key page of the rebuilt table. But, the GEN_CLUST_INDEX of table E is pointing to this page in purge, even though the page was already reused by the OPTIMIZE TABLE of another table:
#6 0x00005558f87461f6 in row_search_on_row_ref (pcur=0x61f000000540, mode=2,
|
table=0x618000040920, ref=0x625001a1fdc0, mtr=0x233825740060)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0row.cc:1213
|
#7 0x00005558f872edfd in row_purge_reposition_pcur (mode=2, node=0x61f0000004a0,
|
mtr=0x233825740060)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/row/row0purge.cc:78
|
In the root page of that clustered index (page 92), we have PAGE_LEVEL=1 and we do have a record (DB_ROW_ID,page)=(69657,116).
We will have to find out when the allocation status of page 116 changed, in the allocation bitmap page (page 0 in the system tablespace):
(rr) find_page_105 0 0
|
$25 = (buf_block_t *) 0x17994c6655e8
|
(rr) display/x $25.frame[150+24+116*2/8]
|
At the end of the last recovery batch, these bits are 0xef. As expected, the least significant bit will be cleared (the byte will first be changed to 0xee) during our OPTIMIZE TABLE:
#0 mtr_t::write<1u, (mtr_t::write_type)0, unsigned char> (this=0x50d457e72280,
|
block=..., ptr=0x17994cccc0cb, val=238 '\356')
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/include/mtr0log.h:211
|
#1 0x00005558f8ae15af in xdes_set_free<false> (block=..., descr=0x17994cccc096 "",
|
offset=116, mtr=0x50d457e72280)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:164
|
#2 0x00005558f8ad3654 in fsp_alloc_from_free_frag (header=0x17994c6655e8,
|
xdes=0x17994c6655e8, descr=0x17994cccc096 "", bit=116, mtr=0x50d457e72280)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:1016
|
#3 0x00005558f8ad432b in fsp_alloc_free_page (space=0x615000003518, hint=0,
|
mtr=0x50d457e72280, init_mtr=0x61a0000576a8)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:1162
|
#4 0x00005558f8ad9fd8 in fseg_alloc_free_page_low (space=0x615000003518,
|
seg_inode=0x17994ce1e172 "", iblock=0x17994c674390, hint=0, direction=111 'o',
|
has_done_reservation=true, mtr=0x50d457e72280, init_mtr=0x61a0000576a8)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:2084
|
#5 0x00005558f8adb0ba in fseg_alloc_free_page_general (seg_header=0x17994c85004a "",
|
hint=0, direction=111 'o', has_done_reservation=true, mtr=0x50d457e72280,
|
init_mtr=0x61a0000576a8)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/fsp/fsp0fsp.cc:2215
|
#6 0x00005558f88bb007 in btr_page_alloc_low (index=0x61700003bca0, hint_page_no=0,
|
file_direction=111 'o', level=0, mtr=0x50d457e72280, init_mtr=0x61a0000576a8)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0btr.cc:536
|
#7 0x00005558f88bb07f in btr_page_alloc (index=0x61700003bca0, hint_page_no=0,
|
file_direction=111 'o', level=0, mtr=0x50d457e72280, init_mtr=0x61a0000576a8)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0btr.cc:569
|
#8 0x00005558f88e2a02 in PageBulk::init (this=0x61a000057698)
|
at /Server/bb-10.5-MDEV-24569/storage/innobase/btr/btr0bulk.cc:73
|
I will have to check when the page was freed before the server was killed, and why it happened while table E still exists. My guess is an old problem: DDL is not actually safe in InnoDB. We would invoke btr_free() already while delete-marking the record in SYS_INDEXES, before that transaction is actually committed (to be fixed in MDEV-18518). Soon we will see if my guess is right.
The
mysqld: /Server/bb-10.5-
MDEV-24569/storage/innobase/lock/lock0lock.cc:1775: void lock_rec_add_to_queue(unsigned int, const buf_block_t*, ulint, dict_index_t*, trx_t*, bool): Assertion `!other_lock' failed.is now https://jira.mariadb.org/browse/MDEV-24590