Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.6
Description
Workflow of the RQG test:
|
1. Start the server and generate some data
|
2. 9 sessions run concurrent DML
|
3. During 2. is ongoing happens the case that many of these sessions
|
are within the state "killed" since > 240s.
|
4. RQG reacts with running "SHOW ENGINE INNODB STATUS"
|
and than sending SIGHUP and later SIGSEGV to the server process.
|
|
|
Replay on origin/10.6 c92c1615852ecd4be2d04203600efd3eba578a02 2022-10-19T01:02:29+03:00 (10.6.11).
|
Replay on mariadb-10.6.9 b8f6d315fe4fe62ef73f6fb4f45e004fcedec20c 2022-08-10T13:24:31+02:00.
|
No replay within ~ 2000 RQG tests on 10.6 0b47c126e31cddda1e94588799599e138400bcf8 2022-06-06T14:03:22+03:00 (10.6.9)
|
No replay within ~ 3000 RQG tests on 10.6 commit 75096c84b44875b5d226a734fffb08578bc21e96 2022-06-06T11:56:29+03:00 (10.6.9).
|
No replay within ~ 2500 RQG tests on mariadb-10.6.8.
|
|
|
RQG
|
===
|
# git clone https://github.com/mleich1/rqg --branch experimental RQG
|
#
|
# GIT_SHOW: HEAD -> experimental c0cd00de14dd52daa87b155e44a5e4a6f9e67e4d 2022-09-22T16:32:22+02:00
|
# rqg.pl : Version 4.0.6 (2022-09)
|
#
|
# $RQG_HOME/rqg.pl \
|
# --grammar=conf/engines/many_indexes.yy \
|
# --gendata=conf/engines/many_indexes.zz \
|
# --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 \
|
# --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_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 \
|
# --duration=300 \
|
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
|
# --mysqld=--loose-innodb_read_only_compressed=OFF \
|
# --mysqld=--log-bin \
|
# --mysqld=--sync-binlog=1 \
|
# --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
|
# --mysqld=--loose-max-statement-time=30 \
|
# --threads=9 \
|
# --mysqld=--innodb_use_native_aio=1 \
|
# --mysqld=--innodb_rollback_on_timeout=OFF \
|
# --mysqld=--innodb_page_size=4K \
|
# --mysqld=--innodb-buffer-pool-size=5M \
|
# --vardir_type=fast \
|
# <local settings>
|
|
Attachments
Issue Links
- blocks
-
-
- Open
-
- causes
-
-
- Closed
-
- is blocked by
-
-
- Closed
-
- is duplicated by
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Open
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Open
-
(6 is duplicated by, 11 relates to)
Activity
The following deadlock was reproduced with the MDEV-30400 fix. One thread is following the correct latching order (in this case, as part of executing UPDATE…WHERE) when accessing a secondary index tree:
|
10.6 de4030e4d49805a7ded5c0bfee01cc3fd7623522 |
#8 0x000055caae8303a4 in btr_block_get (index=..., page=<optimized out>, mode=mode@entry=1, merge=merge@entry=true, mtr=mtr@entry=0x7f30be16a7b0, err=0x7f30be169fa0, err@entry=0x0) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/include/buf0types.h:95
|
#9 0x000055caae882c71 in btr_estimate_n_rows_in_range_on_level (level=level@entry=0, left_cur=..., right_page_no=<optimized out>, n_rows_on_prev_level=n_rows_on_prev_level@entry=7, is_n_rows_exact=@0x7f30be16a1a0: true, mtr=...) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/include/buf0types.h:135
|
#10 0x000055caae8b8c0a in btr_estimate_n_rows_in_range (index=index@entry=0x616000e11008, range_start=range_start@entry=0x7f30be16ace0, range_end=range_end@entry=0x7f30be16ad20) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/include/buf0types.h:135
|
#11 0x000055caae2577bd in ha_innobase::records_in_range (this=0x61d0008fcab8, keynr=<optimized out>, min_key=<optimized out>, max_key=<optimized out>, pages=<optimized out>) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/handler/ha_innodb.cc:14343
|
Another thread is improperly fetching a parent page while compressing the index tree:
|
10.6 de4030e4d49805a7ded5c0bfee01cc3fd7623522 |
#7 0x000055caae8303a4 in btr_block_get (index=..., page=page@entry=61, mode=mode@entry=2, merge=<optimized out>, mtr=mtr@entry=0x7f30c1f35610, err=0x7f30c1f33770, err@entry=0x0) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/include/buf0types.h:95
|
#8 0x000055caae83b8f7 in btr_can_merge_with_page (cursor=cursor@entry=0x7f30c1f347e0, page_no=page_no@entry=61, merge_block=merge_block@entry=0x7f30c1f33930, mtr=mtr@entry=0x7f30c1f35610) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/btr/btr0btr.cc:5455
|
#9 0x000055caae859e04 in btr_compress (cursor=cursor@entry=0x7f30c1f347e0, adjust=adjust@entry=false, mtr=mtr@entry=0x7f30c1f35610) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/btr/btr0btr.cc:3775
|
#10 0x000055caae893e79 in btr_cur_compress_if_useful (cursor=cursor@entry=0x7f30c1f347e0, adjust=adjust@entry=false, mtr=mtr@entry=0x7f30c1f35610) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/include/btr0cur.h:744
|
#11 0x000055caae8b3407 in btr_cur_pessimistic_delete (err=err@entry=0x7f30c1f34530, has_reserved_extents=has_reserved_extents@entry=1, cursor=cursor@entry=0x7f30c1f347e0, flags=flags@entry=16, rollback=rollback@entry=false, mtr=mtr@entry=0x7f30c1f35610) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/btr/btr0cur.cc:4782
|
#12 0x000055caae8b3997 in btr_cur_node_ptr_delete (parent=parent@entry=0x7f30c1f347e0, mtr=mtr@entry=0x7f30c1f35610) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/btr/btr0cur.cc:4820
|
#13 0x000055caae85a22a in btr_compress (cursor=cursor@entry=0x7f30c1f35330, adjust=adjust@entry=false, mtr=mtr@entry=0x7f30c1f35610) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/btr/btr0btr.cc:3893
|
#14 0x000055caae893e79 in btr_cur_compress_if_useful (cursor=cursor@entry=0x7f30c1f35330, adjust=adjust@entry=false, mtr=mtr@entry=0x7f30c1f35610) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/include/btr0cur.h:744
|
#15 0x000055caae8b3407 in btr_cur_pessimistic_delete (err=err@entry=0x7f30c1f35280, has_reserved_extents=has_reserved_extents@entry=0, cursor=cursor@entry=0x7f30c1f35330, flags=flags@entry=0, rollback=rollback@entry=false, mtr=mtr@entry=0x7f30c1f35610) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/btr/btr0cur.cc:4782
|
#16 0x000055caae68f9f5 in row_purge_remove_sec_if_poss_tree (node=node@entry=0x61a00000a908, index=index@entry=0x616000e11008, entry=entry@entry=0x619000c61708) at /data/Server/bb-10.6-MDEV-30400C/storage/innobase/row/row0purge.cc:410
|
The first thread is holding a Shared latch on the index, and it is following the correct latching order. The first thread is holding the level-1 page that the second thread is waiting for, and the second thread is holding the level-0 (leaf) page that the first thread is waiting for. The second thread is holding an Update latch on the index, which does not give it a permission to wait for a parent page latch while holding a child page latch.
I got stack traces from one hang, but I was not able to analyze the locks held in each thread. The only thread that looked suspicious to me was doing the following:
btr_block_get
|
btr_insert_into_right_sibling
|
btr_page_split_and_insert
|
btr_cur_pessimistic_insert
|
btr_insert_on_non_leaf_level
|
btr_attach_half_pages
|
btr_page_split_and_insert
|
btr_cur_pessimistic_insert
|
row_ins_clust_index_entry_low
|
I think that a recursive call to btr_page_split_and_insert() or btr_compress can potentially lead to this hang.
My current approach is to tweak btr_cur_need_opposite_intention() so that it will return true in case btr_cur_compress_recommendation() would hold later during the operation, or if a page underflow or overflow is possible. If btr_cur_need_opposite_intention() returns true, the caller will escalate to exclusive dict_index_t::lock acquisition. This looks promising so far, both from the correctness and performance point of view.
Side note: It came as a light surprise to me that an operation that is supposed to shrink the tree can cause a page split:
btr_insert_on_non_leaf_level
|
btr_cur_pessimistic_delete
|
btr_cur_node_ptr_delete
|
btr_cur_pessimistic_delete
|
btr_cur_node_ptr_delete
|
btr_compress
|
Once again, https://rr-project.org made it trivial to check what could have been improved earlier during the mini-transaction execution.
For SPATIAL INDEX, some trouble might remain in this area. I just noticed this on the amd64-ubuntu-1804-clang10-asan builder:
|
10.6 3b85e3dcc11e9638c9670a299eccdb77a51c1a19 |
innodb_gis.rtree_purge '64k,innodb' w5 [ fail ] timeout after 900 seconds
|
…
|
#7 sux_lock<ssux_lock>::u_lock (this=0x616007285d98, file=0x32479e0 <.str.13> "/buildbot/amd64-ubuntu-1804-clang10-asan/build/storage/innobase/gis/gis0sea.cc", line=1043) at include/sux_lock.h:321
|
id = 139642136811264
|
#8 0x00000000024bb4b6 in mtr_t::u_lock (this=0x7f00f7f59660, file=0x80 <error: Cannot access memory at address 0x80>, line=1043, lock=0x616007285d98) at include/mtr0mtr.h:287
|
No locals.
|
#9 rtr_search (tuple=0x61a000413520, latch_mode=BTR_MODIFY_LEAF_ALREADY_LATCHED, cursor=0x7f00f7f59a70, mtr=0x7f00f7f59660) at gis/gis0sea.cc:1043
|
btr_cursor = <optimized out>
|
rec = <optimized out>
|
d = <optimized out>
|
#10 0x00000000020a4a14 in row_purge_remove_sec_if_poss_leaf (node=0x61b000003220, index=0x616007285c20, entry=0x61a000413520) at row/row0purge.cc:460
|
mtr = {m_start = true, m_commit = false, m_freeing_tree = false, m_last = 0x0, m_last_offset = 0, m_log_mode = 0, m_modifications = 0, m_made_dirty = 0, m_inside_ibuf = 0, m_trim_pages = 0, m_user_space_id = 7, m_memo = {<small_vector_base> = {BeginX = 0x7f00f7f59688, Size = 0, Capacity = 16}, small = {{object = 0x56b46c0 <log_sys+64>, type = 0}, {object = 0x7f00f7f59968, type = 0}, {object = 0x7f00f7f59988, type = 4160068031}, {object = 0x7f00f7f59ba4, type = 520008497}, {object = 0x8122c8 <__asan_memcpy()+680>, type = 0}, {object = 0x56b46c0 <log_sys+64>, type = 50963552}, {object = 0x99, type = 0}, {object = 0x268c07e <safe_mutex_unlock+414>, type = 4160067944}, {object = 0x1ed05b8 <sux_lock<ssux_lock_impl<true> >::u_or_x_unlock(bool, bool)+56>, type = 4198528296}, {object = 0x7f00f7f59858, type = 520008459}, {object = 0x7f00f7f59860, type = 4160067672}, {object = 0x7f00f7f59840, type = 4160067666}, {object = 0x1edc1ac <mtr_t::commit()+3132>, type = 520008312}, {object = 0x7f00f7f59860, type = 4160067648}, {object = 0xfe01efeb30c, type = 67806101}, {object = 0x7f00f7f59858, type = 0}}}, m_log = {m_heap = 0x0, m_list = {<ilist<mtr_buf_t::block_t, void>> = {sentinel_ = {next = 0x7f00f7f597b0, prev = 0x7f00f7f597b0}}, size_ = 1}, m_size = 0, m_first_block = {<ilist_node<void>> = {next = 0x7f00f7f59790, prev = 0x7f00f7f59790}, m_buf_end = 0, m_magic_n = 375767, m_data = "`\237\365\367\000\177\000\000x~\n\002\000\000\000\000\016\066\340E\000\000\000\000\313D\021\003\000\000\000\000\000k\n\002\000\000\000\000P\226\365\367\000\177\000\000\300\037\000\000\000\000\000\000\060^M\004\000\000\000\000@\237\365\367\000\177\000\000\003\000\000\000\000\000\000\000\003\000\000\000\000\000\000\000`\237\365\367\000\177\000\000\000\000\000\000\000\000\000\000\240\224\365\367\000\177\000\000\001\001", '\000' <repeats 14 times>, "#\000\000\000\000\000\000\000\200\357\a\000@`\000\000#\000\000\000\000\000\000\000\200\357\a\000@`\000\000\000\300\035\372\000\177\000\000`\300\035\372\000\177\000\000\210\aC\004\000\000\000\000S\002z\000\000\000\000\000\340\300\035\372\000\177\000\000"..., m_used = 0}}, m_user_space = 0x6130000c1118, m_commit_lsn = 0, m_freed_space = 0x0, m_freed_pages = 0x0}
|
pcur = {btr_cur = {page_cur = {index = 0x616007285c20, rec = 0x0, offsets = 0x0, block = 0x0}, purge_node = 0x61b000003220, thr = 0x0, flag = 0, tree_height = 0, up_match = 0, up_bytes = 0, low_match = 0, low_bytes = 0, n_fields = 0, n_bytes = 0, fold = 0, path_arr = 0x0, rtr_info = 0x0}, latch_mode = BTR_MODIFY_LEAF, old_rec = 0x0, old_n_core_fields = 0, old_n_fields = 0, rel_pos = 0, block_when_stored = {m_block = 0x0, m_page_id = {m_id = 0}}, modify_clock = 0, pos_state = BTR_PCUR_NOT_POSITIONED, search_mode = PAGE_CUR_RTREE_LOCATE, trx_if_known = 0x0, old_rec_buf = 0x0, buf_size = 0}
|
success = true
|
btr_cur = <optimized out>
|
block = <optimized out>
|
_db_s = <optimized out>
|
Another thread is busy with an insert, holding a conflicting latch on the index tree. Perhaps that thread is just unusually slow. This waiting thread has not acquired any other latches, it is waiting for an index latch on the spatial index.
In branches where the fix of
MDEV-30400is present, the following simple patch should prevent hangs in page splits and merges:diff --git a/storage/innobase/btr/btr0cur.cc b/storage/innobase/btr/btr0cur.ccindex 30432d12afa..97934c7cd4a 100644--- a/storage/innobase/btr/btr0cur.cc+++ b/storage/innobase/btr/btr0cur.cc@@ -1050,6 +1050,9 @@ dberr_t btr_cur_t::search_leaf(const dtuple_t *tuple, page_cur_mode_t mode,ut_ad(mtr->memo_contains_flagged(&index()->lock, MTR_MEMO_X_LOCK));break;}+#if 1 // Work around MDEV-29835 hangs+ mtr_x_lock_index(index(), mtr);+#elseif (lock_intention == BTR_INTENTION_DELETE && buf_pool.n_pend_reads &&trx_sys.history_size_approx() > BTR_CUR_FINE_HISTORY_LENGTH)/* Most delete-intended operations are due to the purge of history.@@ -1057,6 +1060,7 @@ dberr_t btr_cur_t::search_leaf(const dtuple_t *tuple, page_cur_mode_t mode,mtr_x_lock_index(index(), mtr);elsemtr_sx_lock_index(index(), mtr);+#endifbreak;#ifdef UNIV_DEBUGA number of #if 0 checks that mention
MDEV-29835were added in theMDEV-30400fix. Those checks will have to be enabled as part of fixing this bug.