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
| Field | Original Value | New Value |
|---|---|---|
| Priority | Major [ 3 ] | Blocker [ 1 ] |
| Description |
{noformat} 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. {noformat} |
{noformat}
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). No replay within ~ 2500 RQG tests on mariadb-10.6.8. {noformat} |
| Description |
{noformat}
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). No replay within ~ 2500 RQG tests on mariadb-10.6.8. {noformat} |
{noformat}
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). 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> {noformat} |
| Description |
{noformat}
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). 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> {noformat} |
{noformat}
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). No replay within ~ 1500 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> {noformat} |
| Description |
{noformat}
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). No replay within ~ 1500 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> {noformat} |
{noformat}
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). 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> {noformat} |
| Description |
{noformat}
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). 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> {noformat} |
{noformat}
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). 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> {noformat} |
| Description |
{noformat}
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). 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> {noformat} |
{noformat}
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.10 fd0bdd3180a7d5f4b9804d372d6a63b6a202818c 2022-09-13T08:40:05+03: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> {noformat} |
| Description |
{noformat}
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.10 fd0bdd3180a7d5f4b9804d372d6a63b6a202818c 2022-09-13T08:40:05+03: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> {noformat} |
{noformat}
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> {noformat} |
This needs to be tested by both mleich (to see if it fixes the hang) and axel (to assess the performance impact):
diff --git a/storage/innobase/btr/btr0cur.cc b/storage/innobase/btr/btr0cur.cc
|
index d52f061827f..f4860510e0e 100644
|
--- a/storage/innobase/btr/btr0cur.cc
|
+++ b/storage/innobase/btr/btr0cur.cc
|
@@ -1420,13 +1420,7 @@ dberr_t btr_cur_search_to_nth_level(dict_index_t *index, ulint level,
|
|
switch (latch_mode) {
|
case BTR_MODIFY_TREE:
|
- /* Most of delete-intended operations are purging.
|
- Free blocks and read IO bandwidth should be prior
|
- for them, when the history list is glowing huge. */
|
- if (lock_intention == BTR_INTENTION_DELETE
|
- && buf_pool.n_pend_reads
|
- && trx_sys.history_size_approx()
|
- > BTR_CUR_FINE_HISTORY_LENGTH) {
|
+ if (lock_intention == BTR_INTENTION_DELETE) {
|
x_latch_index:
|
mtr_x_lock_index(index, mtr);
|
} else if (index->is_spatial()
|
diff --git a/storage/innobase/row/row0purge.cc b/storage/innobase/row/row0purge.cc
|
index 434ea7cfd20..fbfddd2f5ff 100644
|
--- a/storage/innobase/row/row0purge.cc
|
+++ b/storage/innobase/row/row0purge.cc
|
@@ -349,10 +349,8 @@ row_purge_remove_sec_if_poss_tree(
|
mtr.start();
|
index->set_modified(mtr);
|
|
- search_result = row_search_index_entry(
|
- index, entry,
|
- BTR_MODIFY_TREE | BTR_LATCH_FOR_DELETE,
|
- &pcur, &mtr);
|
+ search_result = row_search_index_entry(index, entry, BTR_PURGE_TREE,
|
+ &pcur, &mtr);
|
|
switch (search_result) {
|
case ROW_NOT_FOUND: |
The second hunk is non-functional cleanup, and indicating the call site that I believe requested an exclusive latch, which the "optimization" in the first hunk disregarded, acquiring only an SX-latch (which MDEV-24142 renamed to U latch) instead. Only the exclusive latch grants a permission to revisit upper layers of the index tree, which is what the relatively rare btr_compress() operation in btr_cur_pessimistic_delete() is doing.
If this is the reason of the hang, it should affect all versions since MariaDB 10.2.2, inherited from MySQL 5.7.
| Link |
This issue relates to |
Also the earlier core dump that was produced for a working tree of MDEV-24402 matches these symptoms. One thread is executing ha_innobase::records_in_range(), holding an index S-latch while waiting for a leaf page latch, and another one is violating the protocol (only holding index SX-latch), doing a double btr_compress() within purge:
#4 0x000055776ccf8747 in sux_lock<ssux_lock_impl<true> >::x_lock_upgraded (this=0x7fc11e424528) at /usr/include/c++/9/bits/atomic_base.h:413
|
#5 buf_page_get_low (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=2, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7fc0e6c5d5d0, err=<optimized out>, allow_ibuf_merge=<optimized out>) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/buf/buf0buf.cc:2842
|
#6 0x000055776ccf9244 in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=rw_latch@entry=2, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7fc0e6c5d5d0, err=0x7fc0e6c5b260, allow_ibuf_merge=false) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/buf/buf0buf.cc:2962
|
#7 0x000055776cc00b88 in btr_block_get (index=..., page=page@entry=1018, mode=mode@entry=2, merge=<optimized out>, mtr=mtr@entry=0x7fc0e6c5d5d0, err=0x7fc0e6c5b260, err@entry=0x0) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/include/buf0types.h:95
|
#8 0x000055776cc0f501 in btr_can_merge_with_page (cursor=cursor@entry=0x7fc0e6c5c5f0, page_no=page_no@entry=1018, merge_block=merge_block@entry=0x7fc0e6c5b420, mtr=mtr@entry=0x7fc0e6c5d5d0) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/btr/btr0btr.cc:5335
|
#9 0x000055776cc23836 in btr_compress (cursor=cursor@entry=0x7fc0e6c5c5f0, adjust=adjust@entry=false, mtr=mtr@entry=0x7fc0e6c5d5d0) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/btr/btr0btr.cc:3640
|
#10 0x000055776cc64021 in btr_cur_compress_if_useful (cursor=cursor@entry=0x7fc0e6c5c5f0, adjust=adjust@entry=false, mtr=mtr@entry=0x7fc0e6c5d5d0) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/include/page0page.inl:303
|
#11 0x000055776cc85218 in btr_cur_pessimistic_delete (err=err@entry=0x7fc0e6c5c2c0, has_reserved_extents=has_reserved_extents@entry=1, cursor=cursor@entry=0x7fc0e6c5c5f0, flags=flags@entry=16, rollback=rollback@entry=false, mtr=mtr@entry=0x7fc0e6c5d5d0) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/btr/btr0cur.cc:5842
|
#12 0x000055776cc241d9 in btr_compress (cursor=cursor@entry=0x61a00000a9a8, adjust=adjust@entry=false, mtr=mtr@entry=0x7fc0e6c5d5d0) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/btr/btr0btr.cc:3909
|
#13 0x000055776cc64021 in btr_cur_compress_if_useful (cursor=cursor@entry=0x61a00000a9a8, adjust=adjust@entry=false, mtr=mtr@entry=0x7fc0e6c5d5d0) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/include/page0page.inl:303
|
#14 0x000055776cc85218 in btr_cur_pessimistic_delete (err=err@entry=0x7fc0e6c5d120, has_reserved_extents=has_reserved_extents@entry=0, cursor=cursor@entry=0x61a00000a9a8, flags=flags@entry=0, rollback=rollback@entry=false, mtr=mtr@entry=0x7fc0e6c5d5d0) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/btr/btr0cur.cc:5842
|
#15 0x000055776ca3ee70 in row_purge_remove_clust_if_poss_low (node=node@entry=0x61a00000a908, mode=mode@entry=522) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/row/row0purge.cc:220
|
#16 0x000055776ca3f8bf in row_purge_remove_clust_if_poss (node=node@entry=0x61a00000a908) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/row/row0purge.cc:260
|
#17 0x000055776ca5153a in row_purge_del_mark (node=node@entry=0x61a00000a908) at /data/Server/bb-10.6-MDEV-24402-2/storage/innobase/row/row0purge.cc:630
|
origin/bb-10.6-MDEV-29835 6598d9e1edd3597de84c5f4d17c68a0a571638a6 2022-10-21T17:03:40+03:00
|
There is again a case where RQG means to have caught a partial server freeze because certain sessions are longer than 240s making no progress.
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': Content of processlist ---------- begin
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': ID -- COMMAND -- TIME -- INFO -- state
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 15 -- Sleep -- 272 -- <undef> -- ok
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 16 -- Killed -- 243 -- SELECT `col_longtext_ucs2` FROM `table100_innodb_key_pk_parts_2_int_autoinc` /* E_R Thread1 QNO 498 CON_ID 16 */ -- stalled?
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 17 -- Killed -- 213 -- SELECT `pk` FROM `table100_innodb_key_pk_parts_2_int_autoinc` /* E_R Thread2 QNO 511 CON_ID 17 */ -- ok
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 18 -- Killed -- 213 -- SELECT `col_enum_utf8_key` FROM `table100_innodb_key_pk_parts_2_int_autoinc` /* E_R Thread7 QNO 450 CON_ID 18 */ -- ok
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 19 -- Killed -- 213 -- SELECT `col_varchar_255_utf8_key` FROM `table100_innodb_key_pk_parts_2_int_autoinc` /* E_R Thread5 QNO 485 CON_ID 19 */ -- ok
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 20 -- Killed -- 213 -- SELECT `col_longtext_ucs2` FROM `table100_innodb_key_pk_parts_2_int_autoinc` /* E_R Thread4 QNO 486 CON_ID 20 */ -- ok
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 21 -- Killed -- 243 -- UPDATE `table100_innodb_key_pk_parts_2_int_autoinc` SET `col_char_255_ucs2_key` = CONVERT( 'bee' USING UTF8 ) WHERE `col_varchar_255_ucs2` <> CONVERT( 'zixpowauicvkzyujqdoydmkpoaahgnhkobvegbauwsfdnuwizsonkphsmealkmpivvddwaezmigtks' USING ASCII ) /* E_R Thread6 QNO 483 CON_ID 21 */ -- stalled?
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 22 -- Killed -- 243 -- DELETE FROM `table100_innodb_key_pk_parts_2_int_autoinc` WHERE `col_varchar_255_utf8_key` LIKE CONCAT( REPEAT( _UTF8 0x6, 76 ), '%' ) ORDER BY `pk` LIMIT 1 /* E_R Thread3 QNO 452 CON_ID 22 */ -- stalled?
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 23 -- Killed -- 243 -- DELETE FROM `table100_innodb_key_pk_parts_2_int_autoinc` WHERE `col_char_255_ucs2_key` IS NOT NULL ORDER BY `pk` LIMIT 1 /* E_R Thread8 QNO 487 CON_ID 23 */ -- stalled?
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 24 -- Killed -- 213 -- SELECT `col_longtext_utf8_key` FROM `table100_innodb_key_pk_parts_2_int_autoinc` /* E_R Thread9 QNO 430 CON_ID 24 */ -- ok
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': 52 -- Query -- 0 -- SHOW FULL PROCESSLIST -- ok
|
# 2022-10-21T16:27:32 [1782511] Reporter 'Deadlock': Content of processlist ---------- end
|
|
|
pluto:/data/results/1666361930/Freeze$ gdb -c ./1/data/core /data/Server_bin/bb-10.6-MDEV-29835_asan_Og/bin/mysqld
|
|
|
pluto:/data/results/1666361930/Freeze/rqg.log shows
|
~ line 871 the processlist content
|
~ line 1022 SHOW ENGINE INNODB STATUS
|
RQG sends SIGHUP and SIGSEGV to the server process
|
~ line 1341 is the backtrace
|
|
|
pluto:/data/results/1666361930/Freeze$ gdb -c ./1/data/core /data/Server_bin/bb-10.6-MDEV-29835_asan_Og/bin/mysqld
|
| Assignee | Matthias Leich [ mleich ] | Marko Mäkelä [ marko ] |
| Summary | Draft: Server freeze | Partial server freeze |
In the core dump, Thread 13 is trying to acquire a parent page latch while holding the child page latch in exclusive mode while only holding the index latch in SX a.k.a. U a.k.a. Update mode. Thread 14 (inside ha_innobase::records_in_range()) is holding a shared index latch and parent page latch and waiting for a child page latch in shared mode. Here is the call stack of the culprit:
Thread 13 (Thread 0x7f459fd34700 (LWP 1782559)):
|
#0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
|
#1 0x0000563cf4664162 in ssux_lock_impl<true>::wait (lk=2147483649, this=0x7f45c4103f98) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/sync/srw_lock.cc:244
|
#2 ssux_lock_impl<true>::wr_wait (this=this@entry=0x7f45c4103f98, lk=2147483649) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/sync/srw_lock.cc:378
|
#3 0x0000563cf480ca75 in ssux_lock_impl<true>::wr_lock (this=0x7f45c4103f98) at /usr/include/c++/9/bits/atomic_base.h:539
|
#4 0x0000563cf483f671 in sux_lock<ssux_lock_impl<true> >::x_lock_upgraded (this=0x7f45c4103f98) at /usr/include/c++/9/bits/atomic_base.h:413
|
#5 buf_page_get_low (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=2, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7f459fd2eb50, err=<optimized out>, allow_ibuf_merge=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/buf/buf0buf.cc:2842
|
#6 0x0000563cf484016e in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=rw_latch@entry=2, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7f459fd2eb50, err=0x7f459fd2ce70, allow_ibuf_merge=false) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/buf/buf0buf.cc:2962
|
#7 0x0000563cf4748424 in btr_block_get (index=..., page=page@entry=17, mode=mode@entry=2, merge=merge@entry=false, mtr=mtr@entry=0x7f459fd2eb50, err=0x7f459fd2ce70, err@entry=0x0) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/include/buf0types.h:95
|
#8 0x0000563cf475293b in btr_attach_half_pages (flags=flags@entry=7, index=<optimized out>, block=block@entry=0x7f45c4104120, split_rec=split_rec@entry=0x7f45c421107e "", new_block=new_block@entry=0x7f45c41109d0, direction=direction@entry=112, mtr=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/btr/btr0btr.cc:2486
|
#9 0x0000563cf4763a52 in btr_page_split_and_insert (flags=flags@entry=7, cursor=cursor@entry=0x7f459fd2d4e0, offsets=offsets@entry=0x7f459fd2d4c0, heap=heap@entry=0x7f459fd2d4a0, tuple=tuple@entry=0x6190008ee008, n_ext=<optimized out>, mtr=<optimized out>, err=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/btr/btr0btr.cc:3016
|
#10 0x0000563cf47a9ad2 in btr_cur_pessimistic_insert (flags=flags@entry=7, cursor=cursor@entry=0x7f459fd2d4e0, offsets=offsets@entry=0x7f459fd2d4c0, heap=heap@entry=0x7f459fd2d4a0, entry=entry@entry=0x6190008ee008, rec=rec@entry=0x7f459fd2d480, big_rec=<optimized out>, n_ext=0, thr=<optimized out>, mtr=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/include/buf0types.h:135
|
#11 0x0000563cf474f159 in btr_insert_on_non_leaf_level (flags=7, flags@entry=0, index=index@entry=0x616000d3db08, level=level@entry=1, tuple=<optimized out>, mtr=mtr@entry=0x7f459fd2eb50) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/btr/btr0btr.cc:2396
|
#12 0x0000563cf4752228 in btr_attach_half_pages (flags=flags@entry=0, index=<optimized out>, block=block@entry=0x7f45c412d270, split_rec=split_rec@entry=0x616006419786 "", new_block=new_block@entry=0x7f45c4123190, direction=direction@entry=111, mtr=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/btr/btr0btr.cc:2504
|
#13 0x0000563cf4763a52 in btr_page_split_and_insert (flags=flags@entry=0, cursor=cursor@entry=0x7f459fd2e790, offsets=offsets@entry=0x7f459fd2e690, heap=heap@entry=0x7f459fd2e770, tuple=tuple@entry=0x61900102b708, n_ext=<optimized out>, mtr=<optimized out>, err=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/btr/btr0btr.cc:3016
|
#14 0x0000563cf47a9ad2 in btr_cur_pessimistic_insert (flags=flags@entry=0, cursor=cursor@entry=0x7f459fd2e790, offsets=offsets@entry=0x7f459fd2e690, heap=heap@entry=0x7f459fd2e770, entry=entry@entry=0x61900102b708, rec=rec@entry=0x7f459fd2e6b0, big_rec=<optimized out>, n_ext=0, thr=<optimized out>, mtr=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/include/buf0types.h:135
|
#15 0x0000563cf44e73e0 in row_ins_sec_index_entry_low (flags=flags@entry=0, mode=<optimized out>, mode@entry=10, index=index@entry=0x616000d3db08, offsets_heap=offsets_heap@entry=0x619001029d80, heap=heap@entry=0x61900102a280, entry=entry@entry=0x61900102b708, trx_id=<optimized out>, thr=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/row/row0ins.cc:3055
|
#16 0x0000563cf44e83f2 in row_ins_sec_index_entry (index=index@entry=0x616000d3db08, entry=0x61900102b708, thr=thr@entry=0x6210005e6c08, check_foreign=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/row/row0ins.cc:3245
|
#17 0x0000563cf4619e48 in row_upd_sec_index_entry (node=node@entry=0x6210005e6568, thr=thr@entry=0x6210005e6c08) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/row/row0upd.cc:2028
|
#18 0x0000563cf461a164 in row_upd_sec_step (node=node@entry=0x6210005e6568, thr=thr@entry=0x6210005e6c08) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/row/row0upd.cc:2055
|
#19 0x0000563cf461d123 in row_upd (node=node@entry=0x6210005e6568, thr=thr@entry=0x6210005e6c08) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/row/row0upd.cc:2779
|
#20 0x0000563cf461dad4 in row_upd_step (thr=thr@entry=0x6210005e6c08) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/row/row0upd.cc:2894
|
#21 0x0000563cf45412a0 in row_update_for_mysql (prebuilt=0x623000063d88) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/row/row0mysql.cc:1690
|
#22 0x0000563cf4155c66 in ha_innobase::update_row (this=0x61d0002e36b8, old_row=<optimized out>, new_row=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/storage/innobase/handler/ha_innodb.cc:8662
|
#23 0x0000563cf3794fe4 in handler::ha_update_row (this=0x61d0002e36b8, old_data=old_data@entry=0x626000052578 "D", <incomplete sequence \370>, new_data=new_data@entry=0x626000051138 "D", <incomplete sequence \370>) at /data/Server/bb-10.6-MDEV-29835/sql/handler.cc:7634
|
#24 0x0000563cf40510e6 in ha_partition::update_row (this=0x61d0002e2cb8, old_data=<optimized out>, new_data=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/sql/ha_partition.cc:4661
|
#25 0x0000563cf3794fe4 in handler::ha_update_row (this=0x61d0002e2cb8, old_data=0x626000052578 "D", <incomplete sequence \370>, new_data=0x626000051138 "D", <incomplete sequence \370>) at /data/Server/bb-10.6-MDEV-29835/sql/handler.cc:7634
|
#26 0x0000563cf32259e7 in mysql_update (thd=thd@entry=0x62b00019d218, table_list=<optimized out>, fields=..., values=..., conds=<optimized out>, order_num=<optimized out>, order=<optimized out>, limit=18446744073709551609, ignore=<optimized out>, found_return=<optimized out>, updated_return=<optimized out>) at /data/Server/bb-10.6-MDEV-29835/sql/sql_update.cc:1087
|
My fix so far was only for the DELETE (or purge or rollback) code path, while this involves INSERT.
A conservative fix that would cover also INSERT would be something like the following if BTR_LATCH_FOR_INSERT had been specified instead of BTR_INSERT:
diff --git a/storage/innobase/btr/btr0cur.cc b/storage/innobase/btr/btr0cur.cc
|
index d52f061827f..169c2a539a9 100644
|
--- a/storage/innobase/btr/btr0cur.cc
|
+++ b/storage/innobase/btr/btr0cur.cc
|
@@ -1420,21 +1420,8 @@ dberr_t btr_cur_search_to_nth_level(dict_index_t *index, ulint level,
|
|
switch (latch_mode) {
|
case BTR_MODIFY_TREE:
|
- /* Most of delete-intended operations are purging.
|
- Free blocks and read IO bandwidth should be prior
|
- for them, when the history list is glowing huge. */
|
- if (lock_intention == BTR_INTENTION_DELETE
|
- && buf_pool.n_pend_reads
|
- && trx_sys.history_size_approx()
|
- > BTR_CUR_FINE_HISTORY_LENGTH) {
|
-x_latch_index:
|
+ if (lock_intention) {
|
mtr_x_lock_index(index, mtr);
|
- } else if (index->is_spatial()
|
- && lock_intention <= BTR_INTENTION_BOTH) {
|
- /* X lock the if there is possibility of
|
- pessimistic delete on spatial index. As we could
|
- lock upward for the tree */
|
- goto x_latch_index;
|
} else {
|
mtr_sx_lock_index(index, mtr);
|
} |
I see that the conservative fix that had I proposed in MDEV-14637 skips even the if condition and always acquires an X latch. Hopefully this fix will not destroy performance as badly.
I was thinking of an alternative fix that would skip btr_compress() if the U latches cannot be upgraded to X. Obviously, it would not help in the INSERT case. I am afraid that even my fix above may seriously degrade the INSERT performance when page splits occur frequently.
If I understood it correctly, the idea that was implemented in MySQL 5.7 is to have btr_cur_search_to_nth_level() predict which subtree may need to be accessed during the operation. This prediction seems to fail in both INSERT and DELETE operations, that is, some subtree pages are being prematurely released and then reacquired in a deadlock-prone fashion.
| Link | This issue relates to MDEV-15275 [ MDEV-15275 ] |
MDEV-15275 (hangs of the test innodb_gis.rtree_purge) is very similar to this but needs to be fixed separately.
The flag BTR_LATCH_FOR_INSERT was introduced in MySQL 5.7.2 and was initially only used in two places: ibuf_insert() and the native CREATE INDEX code where it actually was unnecessary, because only one thread at a time was accessing the being-created index. The latter code was removed in MySQL 5.7.5.
This means that the vast majority of pessimistic INSERT operations (which may potentially split index pages) only use the BTR_MODIFY_TREE flag. To protect the rare use of ibuf_insert(), we could simply hold an exclusive ibuf.index->latch.
The flag BTR_INSERT has nothing to do with index tree splits or merges. It requests an insert into a secondary index leaf page to be buffered if the change buffer has been enabled (MDEV-27734 disabled it by default).
On a related note, the flag BTR_MODIFY_EXTERNAL is only being specified in btr_blob_log_check_t::check(). I think that we can remove that flag and let that single caller explicitly acquire index->lock upfront.
To significantly improve the chances, we can add a debug assertion to report potential hang:
diff --git a/storage/innobase/btr/btr0btr.cc b/storage/innobase/btr/btr0btr.cc
|
index e503215e05b..02adf8439dd 100644
|
--- a/storage/innobase/btr/btr0btr.cc
|
+++ b/storage/innobase/btr/btr0btr.cc
|
@@ -3604,6 +3604,8 @@ btr_compress(
|
} else {
|
offsets = btr_page_get_father_block(
|
NULL, heap, index, block, mtr, &father_cursor);
|
+ ut_ad(!father_cursor.page_cur.block->page.lock.not_recursive()
|
+ || mtr->memo_contains(index->lock, MTR_MEMO_X_LOCK));
|
}
|
|
if (adjust) { |
Without the condition about index->lock, the assertion would fail in the test innodb.innodb_defrag_concurrent. I expect that this assertion would fail relatively easily in basically any 10.6 version that includes the necessary API (MDEV-24142).
Here is a 10.3 version of the instrumentation patch:
diff --git a/storage/innobase/btr/btr0btr.cc b/storage/innobase/btr/btr0btr.cc
|
index f041e35e501..740e92598f5 100644
|
--- a/storage/innobase/btr/btr0btr.cc
|
+++ b/storage/innobase/btr/btr0btr.cc
|
@@ -3609,6 +3609,10 @@ btr_compress(
|
} else {
|
offsets = btr_page_get_father_block(
|
NULL, heap, index, block, mtr, &father_cursor);
|
+ ut_ad(my_atomic_load32_explicit(&father_cursor.page_cur.block
|
+ ->lock.lock_word,
|
+ MY_MEMORY_ORDER_RELAXED)
|
+ || mtr_memo_contains(mtr, &index->lock, MTR_MEMO_X_LOCK));
|
}
|
|
if (adjust) { |
I added some instrumentation to btr_attach_half_pages() and got it to fail in a number of tests on 10.6:
mariabackup.xb_compressed_encrypted '4k,innodb' w34 [ fail ]
|
Test ended at 2022-10-25 16:17:34
|
|
|
CURRENT_TEST: mariabackup.xb_compressed_encrypted
|
mysqltest: At line 16: query 'INSERT INTO t1
|
VALUES($n-$i, concat('$u', $n-$i, repeat('ab', floor(rand()*100)), '$u'))' failed: <Unknown> (2013): Lost connection to server during query
|
…
|
innodb_zip.wl5522_debug_zip '4k,innodb' w27 [ fail ]
|
Test ended at 2022-10-25 16:18:34
|
|
|
CURRENT_TEST: innodb_zip.wl5522_debug_zip
|
mysqltest: At line 331: query 'UPDATE t1 SET c3 = REPEAT("c2", 1024)' failed: <Unknown> (2013): Lost connection to server during query
|
…
|
innodb_gis.multi_pk 'innodb' w5 [ fail ]
|
Test ended at 2022-10-25 16:19:45
|
|
|
CURRENT_TEST: innodb_gis.multi_pk
|
mysqltest: At line 74: query 'CALL insert_t1(30000)' failed: <Unknown> (2013): Lost connection to server during query
|
…
|
innodb.insert_debug 'innodb' w42 [ fail ]
|
Test ended at 2022-10-25 16:20:00
|
|
|
CURRENT_TEST: innodb.insert_debug
|
mysqltest: At line 28: query 'CREATE TABLE t2(col1 INT PRIMARY KEY, col2 INT NOT NULL,
|
FOREIGN KEY(col2) REFERENCES t1(col1)) ENGINE=INNODB' failed: <Unknown> (2013): Lost connection to server during query
|
(The last failure obviously requires that some previous tests have run enough DDL statements, because the failure occurs while updating the InnoDB data dictionary tables.)
I was able to reproduce one failure in rr:
./mtr --rr innodb_zip.wl5522_debug_zip,4k
|
rr replay var/log/mysqld.1.rr/latest-trace
|
I confirmed that the mini-transaction is only holding an index U-latch while attempting to acquire an explicit latch on next_block for the first time, while already having holding a leaf page latch:
#3 0x0000562b35a25d64 in btr_attach_half_pages (flags=7,
|
index=0x7f65640b2df0, block=0x7f658d9854f0,
|
split_rec=0x7f65640df9b8 "c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2"...,
|
new_block=0x7f658d9a7bd0, mtr=0x7f658405b968, direction=<optimized out>)
|
at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:2492
|
#4 btr_page_split_and_insert (flags=7, flags@entry=375767,
|
cursor=cursor@entry=0x7f658405a9f8, offsets=0x7f658405a9e0,
|
offsets@entry=0x7f658405a9d8, heap=0x7f658405a9d8, heap@entry=0x7,
|
tuple=tuple@entry=0x7f65640dea90, n_ext=0, mtr=<optimized out>,
|
err=<optimized out>) at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:3020
|
#5 0x0000562b359f8814 in btr_cur_pessimistic_insert (flags=<optimized out>,
|
flags@entry=7, cursor=cursor@entry=0x7f658405a9f8,
|
offsets=<optimized out>, offsets@entry=0x7f658405a9e0,
|
heap=<optimized out>, heap@entry=0x7f658405a9d8,
|
entry=entry@entry=0x7f65640dea90, rec=<optimized out>,
|
rec@entry=0x7f658405a9e8, big_rec=<optimized out>, n_ext=140073447063648,
|
thr=<optimized out>, mtr=<optimized out>)
|
at /mariadb/10.6m/storage/innobase/btr/btr0cur.cc:3675
|
#6 0x0000562b35a28cd5 in btr_insert_on_non_leaf_level (flags=7,
|
flags@entry=0, index=index@entry=0x7f65640b2df0, level=level@entry=1,
|
tuple=0x7f65640dea90, mtr=mtr@entry=0x7f658405b968)
|
at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:2396
|
#7 0x0000562b35a25e16 in btr_attach_half_pages (flags=0,
|
index=0x7f65640b2df0, block=0x7f658d9a7480,
|
split_rec=0x7f65640f5c38 "c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2"...,
|
new_block=0x7f658d9a7960, mtr=0x7f658405b968, direction=<optimized out>)
|
at /mariadb/10.6m/storage/innobase/btr/btr0btr.cc:2508
|
…
|
#22 0x0000562b35690a66 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f65640020d8, packet=packet@entry=0x7f65640242f9 "UPDATE t1 SET c3 = REPEAT(\"c2\", 1024)", packet_length=packet_length@entry=37, blocking=true) at /mariadb/10.6m/sql/sql_parse.cc:1896
|
The instrumentation that I used was as follows:
diff --git a/storage/innobase/btr/btr0btr.cc b/storage/innobase/btr/btr0btr.cc
|
index e503215e05b..166422fce92 100644
|
--- a/storage/innobase/btr/btr0btr.cc
|
+++ b/storage/innobase/btr/btr0btr.cc
|
@@ -2485,10 +2485,14 @@ btr_attach_half_pages(
|
if (prev_page_no != FIL_NULL && direction == FSP_DOWN) {
|
prev_block = btr_block_get(*index, prev_page_no, RW_X_LATCH,
|
!level, mtr);
|
+ ut_ad(!prev_block->page.lock.not_recursive()
|
+ || mtr->memo_contains(index->lock, MTR_MEMO_X_LOCK));
|
}
|
if (next_page_no != FIL_NULL && direction != FSP_DOWN) {
|
next_block = btr_block_get(*index, next_page_no, RW_X_LATCH,
|
!level, mtr);
|
+ ut_ad(!next_block->page.lock.not_recursive()
|
+ || mtr->memo_contains(index->lock, MTR_MEMO_X_LOCK));
|
}
|
|
/* Build the node pointer (= node key and page address) for the upper
|
@@ -3604,6 +3608,8 @@ btr_compress(
|
} else {
|
offsets = btr_page_get_father_block(
|
NULL, heap, index, block, mtr, &father_cursor);
|
+ ut_ad(!father_cursor.page_cur.block->page.lock.not_recursive()
|
+ || mtr->memo_contains(index->lock, MTR_MEMO_X_LOCK));
|
}
|
|
if (adjust) { |
I believe that this constitutes a design violation.
Also in 10.3, I can repeat the failure of innodb_zip.wl5522_debug_zip,4k when adding the equivalent assertion, this time on prev_block, which is an even more blatant design violation:
diff --git a/storage/innobase/btr/btr0btr.cc b/storage/innobase/btr/btr0btr.cc
|
index f041e35e501..31896a70273 100644
|
--- a/storage/innobase/btr/btr0btr.cc
|
+++ b/storage/innobase/btr/btr0btr.cc
|
@@ -2519,11 +2519,17 @@ btr_attach_half_pages(
|
prev_block = btr_block_get(
|
page_id_t(space, prev_page_no), block->page.size,
|
RW_X_LATCH, index, mtr);
|
+ ut_ad(my_atomic_load32_explicit(&prev_block->lock.lock_word,
|
+ MY_MEMORY_ORDER_RELAXED)
|
+ || mtr_memo_contains(mtr, &index->lock, MTR_MEMO_X_LOCK));
|
}
|
if (next_page_no != FIL_NULL && direction != FSP_DOWN) {
|
next_block = btr_block_get(
|
page_id_t(space, next_page_no), block->page.size,
|
RW_X_LATCH, index, mtr);
|
+ ut_ad(my_atomic_load32_explicit(&next_block->lock.lock_word,
|
+ MY_MEMORY_ORDER_RELAXED)
|
+ || mtr_memo_contains(mtr, &index->lock, MTR_MEMO_X_LOCK));
|
}
|
|
/* Get the level of the split pages */
|
@@ -3609,6 +3615,10 @@ btr_compress(
|
} else {
|
offsets = btr_page_get_father_block(
|
NULL, heap, index, block, mtr, &father_cursor);
|
+ ut_ad(my_atomic_load32_explicit(&father_cursor.page_cur.block
|
+ ->lock.lock_word,
|
+ MY_MEMORY_ORDER_RELAXED)
|
+ || mtr_memo_contains(mtr, &index->lock, MTR_MEMO_X_LOCK));
|
}
|
|
if (adjust) { |
This proves to me that these hangs are likely possible starting with MariaDB 10.2.2.
| Link |
This issue is blocked by |
The observed hangs started to reproduce with the commit of MDEV-21136.
|
Tested was
|
mariadb-10.6.9 commit 222e800e24c
|
+ a patch (Assert in btr_compress()) provided by Marko.
|
The assert in btr_compress() did not show up during the replay of the hang.
|
|
|
Preliminary result of MDEV-29883 testing based on
|
origin/10.6 79dc3989fdc3bdcfc4eb5e17ac87fa501039ebba 2022-10-26T14:53:06+03:00
|
No replay of the hangs and also no new bad effects.
|
Thank you, mleich. I believe that the observed hangs may be explained MDEV-29886 (I did not recheck any core dumps), but we have not tested it long enough to really claim so.
Due to my findings in this ticket, I think that some hang during INSERT is possible. I will continue to play with some instrumentation and analyze the validity of the scenarios.
Like MDEV-29886 proved, there is a huge gap between a potential hang and an actual hang. MDEV-21136 did not do anything wrong, but it improved the chances of the scenario of MDEV-29886 in your testing. My observed scenario of MDEV-29886 was actually something else than your ha_innobase::records_in_range(), which ‘benefited’ from MDEV-21136. That hang should have been out there ever since MariaDB 10.2 was released, and we never got reports of that with usable stack traces of the hung threads. It is possible that some reports of MDEV-15020 were actually due to that hang.
| Link |
This issue relates to |
| Affects Version/s | 10.6 [ 24028 ] | |
| Affects Version/s | 10.6.11 [ 28441 ] | |
| Priority | Blocker [ 1 ] | Critical [ 2 ] |
origin/10.6 79dc3989fdc3bdcfc4eb5e17ac87fa501039ebba 2022-10-26T14:53:06+03:00 without additional patches.
|
Scenario:
|
(same RQG grammar like on top)
|
1. Start the server and generate some initial data.
|
2. Two concurrent sessions run a DML stream
|
3. During 2. is ongoing some third session detects
|
Reporter 'Deadlock': Content of processlist ---------- begin
|
Reporter 'Deadlock': ID -- COMMAND -- TIME -- INFO -- state
|
Reporter 'Deadlock': 15 -- Killed -- 250 -- DELETE FROM `table100_innodb_key_pk_parts_2_int_autoinc` WHERE `col_longtext_ucs2_key` <> CONVERT( 'changing' USING UCS2 ) ORDER BY `pk` LIMIT 1 /* E_R Thread2 QNO 2925 CON_ID 15 */ -- stalled?
|
Reporter 'Deadlock': 16 -- Sleep -- 270 -- <undef> -- ok
|
Reporter 'Deadlock': 17 -- Killed -- 249 -- UPDATE `table100_innodb_key_pk_parts_2_int_autoinc` SET `col_longtext_ucs2` = CONVERT( 'fcbbkrwhvlcynylazskhhdxexskexciqwbyzgflvdblvcrqtmpdptubaevkfytqffjminilgtnwyyjcehjnakexfxpchseseriqdhnanpjxzjvcsuucxwlmug' USING ASCII ) WHERE `col_varchar_255_utf8` IS NOT NULL /* E_R Thread1 QNO 2971 CON_ID 17 */ -- stalled?
|
Reporter 'Deadlock': 45 -- Query -- 0 -- SHOW FULL PROCESSLIST -- ok
|
Reporter 'Deadlock': Content of processlist ---------- end
|
4. RQG reacts with SHOW ENGINE InnoDB STATUS
|
SIGHUP
|
SIGSEGV
|
sdp:/data/results/1666797019/Freeze$ gdb -c dev/shm/rqg/1666797019/262/1/data/core /data/Server_bin/10.6_asan_Og/bin/mysqld
|
|
|
sdp:/data/results/1666797019/Freeze/rqg.log
|
~ line 932 the SHOW ENGINE INNODB STATUS
|
~ line 1257 Backtrace
|
|
|
sdp:/data/results/1666797019/Freeze/dev/shm/rqg/1666797019/262/1/data Data directory of the server
|
|
I checked that core dump. Thread 6 is executing btr_estimate_n_rows_in_range_on_level() as part of ha_innobase::records_in_range(), this time for preparing to execute a DELETE statement. It is holding a shared latch on the index col_longtext_ucs2_key and a shared latch on the index non-leaf page 0x2a. The index root page is 4. It is waiting for a shared latch on the index leaf page 0xbb.
Thread 8 is holding a U latch on the index and an exclusive latch on the leaf page, and it is waiting for a latch on the non-leaf page. This is another clear latching order violation. I think that my instrumentation patch for btr_compress() should have caught this, but that patch was not present in the build. I hope that we can run more tests where the patch is present. Here is the relevant part of the stack trace of that thread:
|
10.6 79dc3989fdc3bdcfc4eb5e17ac87fa501039ebba |
#6 0x000055a87a6b5086 in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=rw_latch@entry=2, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7f29702ee080, err=0x7f29702ebcb0, allow_ibuf_merge=false) at /data/Server/10.6/storage/innobase/buf/buf0buf.cc:2962
|
#7 0x000055a87a5bc654 in btr_block_get (index=..., page=page@entry=42, mode=mode@entry=2, merge=<optimized out>, mtr=mtr@entry=0x7f29702ee080, err=0x7f29702ebcb0, err@entry=0x0) at /data/Server/10.6/storage/innobase/include/buf0types.h:95
|
#8 0x000055a87a5cafcd in btr_can_merge_with_page (cursor=cursor@entry=0x7f29702ecf30, page_no=page_no@entry=42, merge_block=merge_block@entry=0x7f29702ebe70, mtr=mtr@entry=0x7f29702ee080) at /data/Server/10.6/storage/innobase/btr/btr0btr.cc:5336
|
#9 0x000055a87a5dfa97 in btr_compress (cursor=cursor@entry=0x7f29702ecf30, adjust=adjust@entry=false, mtr=mtr@entry=0x7f29702ee080) at /data/Server/10.6/storage/innobase/btr/btr0btr.cc:3641
|
#10 0x000055a87a61fe35 in btr_cur_compress_if_useful (cursor=cursor@entry=0x7f29702ecf30, adjust=adjust@entry=false, mtr=mtr@entry=0x7f29702ee080) at /data/Server/10.6/storage/innobase/include/page0page.inl:303
|
#11 0x000055a87a64102c in btr_cur_pessimistic_delete (err=err@entry=0x7f29702ecc80, has_reserved_extents=has_reserved_extents@entry=1, cursor=cursor@entry=0x7f29702ecf30, flags=flags@entry=16, rollback=rollback@entry=false, mtr=mtr@entry=0x7f29702ee080) at /data/Server/10.6/storage/innobase/btr/btr0cur.cc:5842
|
#12 0x000055a87a6415b6 in btr_cur_node_ptr_delete (parent=parent@entry=0x7f29702ecf30, mtr=mtr@entry=0x7f29702ee080) at /data/Server/10.6/storage/innobase/btr/btr0cur.cc:5882
|
#13 0x000055a87a5dedb2 in btr_compress (cursor=cursor@entry=0x7f29702edd90, adjust=adjust@entry=false, mtr=mtr@entry=0x7f29702ee080) at /data/Server/10.6/storage/innobase/btr/btr0btr.cc:3753
|
#14 0x000055a87a61fe35 in btr_cur_compress_if_useful (cursor=cursor@entry=0x7f29702edd90, adjust=adjust@entry=false, mtr=mtr@entry=0x7f29702ee080) at /data/Server/10.6/storage/innobase/include/page0page.inl:303
|
#15 0x000055a87a64102c in btr_cur_pessimistic_delete (err=err@entry=0x7f29702edbe0, has_reserved_extents=has_reserved_extents@entry=0, cursor=cursor@entry=0x7f29702edd90, flags=flags@entry=0, rollback=rollback@entry=false, mtr=mtr@entry=0x7f29702ee080) at /data/Server/10.6/storage/innobase/btr/btr0cur.cc:5842
|
#16 0x000055a87a402efe in row_purge_remove_sec_if_poss_tree (node=node@entry=0x61a00000a908, index=index@entry=0x616000cdff08, entry=entry@entry=0x619000865c08) at /data/Server/10.6/storage/innobase/row/row0purge.cc:408
|
#17 0x000055a87a407b29 in row_purge_remove_sec_if_poss (entry=0x619000865c08, index=0x616000cdff08, node=0x61a00000a908) at /data/Server/10.6/storage/innobase/row/row0purge.cc:590
|
#18 row_purge_upd_exist_or_extern_func (thr=thr@entry=0x61600005adc0, node=node@entry=0x61a00000a908, undo_rec=undo_rec@entry=0x62100a934588 "\005k\214.\023") at /data/Server/10.6/storage/innobase/row/row0purge.cc:774
|
#19 0x000055a87a40d20c in row_purge_record_func (node=node@entry=0x61a00000a908, undo_rec=undo_rec@entry=0x62100a934588 "\005k\214.\023", thr=thr@entry=0x61600005adc0, updated_extern=<optimized out>) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1214
|
#20 0x000055a87a40e610 in row_purge (node=node@entry=0x61a00000a908, undo_rec=undo_rec@entry=0x62100a934588 "\005k\214.\023", thr=thr@entry=0x61600005adc0) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1253
|
#21 0x000055a87a40ef2c in row_purge_step (thr=thr@entry=0x61600005adc0) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1316
|
It may be worth noting that there are two calls to btr_compress() in the stack trace. Maybe the prediction logic in btr_cur_search_to_nth_level() is incorrect when several btr_compress() operations are needed.
| Status | Open [ 1 ] | In Progress [ 3 ] |
I debugged the case of ./mtr --rr innodb_zip.wl5522_debug_zip,4k further.
The distance from the leaf B-tree level of the root page of INDEX idx2(c3) is 2. In the problematic mini-transaction, when row_ins_sec_index_entry_low() is being invoked with BTR_MODIFY_TREE, all pages will initially be requested with a buffer-fix only. The upper_rw_latch=RW_X_LATCH does not have any effect. The first time any page latch is being acquired is in btr_cur_latch_leaves(). After I modified some code so that the flag BTR_LATCH_FOR_INSERT will be set and handled in any tree-modifying INSERT}, I would still get an assertion failure a bit further along the way:
#0 btr_cur_search_to_nth_level (index=index@entry=0x7f2a300b2df0, level=level@entry=1, tuple=tuple@entry=0x7f2a300de950, mode=PAGE_CUR_LE, latch_mode=latch_mode@entry=14, cursor=cursor@entry=0x7f2a4075b9f8,
|
mtr=0x7f2a4075d388, autoinc=0) at /mariadb/10.6/storage/innobase/btr/btr0cur.cc:1251
|
#1 0x000055a835735b35 in btr_insert_on_non_leaf_level (flags=<optimized out>, flags@entry=0, index=index@entry=0x7f2a300b2df0, level=level@entry=1, tuple=0x7f2a300de950, mtr=mtr@entry=0x7f2a4075d388)
|
at /mariadb/10.6/storage/innobase/btr/btr0btr.cc:2384
|
#2 0x000055a835732d06 in btr_attach_half_pages (flags=0, index=0x7f2a300b2df0, block=0x7f2a520a7480,
|
split_rec=0x7f2a300f5c38 "c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2"..., new_block=0x7f2a520a7960, mtr=0x7f2a4075d388, direction=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0btr.cc:2509
|
#3 btr_page_split_and_insert (flags=0, flags@entry=139819171393008, cursor=cursor@entry=0x7f2a4075c7c8, offsets=0x7f2a4075c780, offsets@entry=0x7f2a4075c790, heap=0x7f2a4075c790, heap@entry=0x0,
|
tuple=tuple@entry=0x7f2a300d94c0, n_ext=0, mtr=<optimized out>, err=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0btr.cc:3021
|
#4 0x000055a835705254 in btr_cur_pessimistic_insert (flags=<optimized out>, flags@entry=0, cursor=0x7f2a4075c7c8, cursor@entry=0x7f2a4075c7a8, offsets=<optimized out>, offsets@entry=0x7f2a4075c760,
|
heap=<optimized out>, heap@entry=0x7f2a4075c770, entry=0x7f2a300d94c0, entry@entry=0x7f2a300f3528, rec=<optimized out>, rec@entry=0x7f2a4075d820, big_rec=<optimized out>, n_ext=139819446811128,
|
thr=<optimized out>, mtr=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0cur.cc:3627
|
#5 0x000055a83591a9b6 in row_ins_sec_index_entry_low (flags=flags@entry=0, mode=<optimized out>, mode@entry=1034, index=index@entry=0x7f2a300b2df0, offsets_heap=<optimized out>,
|
offsets_heap@entry=0x7f2a300d98d0, heap=<optimized out>, heap@entry=0x7f2a300de440, entry=<optimized out>, entry@entry=0x7f2a300d94c0, trx_id=0, thr=0x7f2a300f3528)
|
at /mariadb/10.6/storage/innobase/row/row0ins.cc:3054
|
At this point, the mini-transaction is holding an index SX-latch and likely holding X latches on all pages from the root to the leaf page. Because we are not holding an exclusive latch on the index tree, we are not allowed to acquire any pages that at a higher level than those that we are already holding. That constraint is being violated here:
#4 0x000055a835732c54 in btr_attach_half_pages (flags=7, index=0x7f2a300b2df0, block=0x7f2a520854f0,
|
split_rec=0x7f2a300d9fb8 "c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2"..., new_block=0x7f2a520a7bd0, mtr=0x7f2a4075d388, direction=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0btr.cc:2493
|
#5 btr_page_split_and_insert (flags=7, flags@entry=375767, cursor=cursor@entry=0x7f2a4075b9f8, offsets=0x7f2a4075b9e0, offsets@entry=0x7f2a4075b9d8, heap=0x7f2a4075b9d8, heap@entry=0x7,
|
tuple=tuple@entry=0x7f2a300de950, n_ext=0, mtr=<optimized out>, err=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0btr.cc:3021
|
#6 0x000055a835705254 in btr_cur_pessimistic_insert (flags=<optimized out>, flags@entry=7, cursor=cursor@entry=0x7f2a4075b9f8, offsets=<optimized out>, offsets@entry=0x7f2a4075b9e0, heap=<optimized out>,
|
heap@entry=0x7f2a4075b9d8, entry=entry@entry=0x7f2a300de950, rec=<optimized out>, rec@entry=0x7f2a4075b9e8, big_rec=<optimized out>, n_ext=139819171576640, thr=<optimized out>, mtr=<optimized out>)
|
at /mariadb/10.6/storage/innobase/btr/btr0cur.cc:3627
|
#7 0x000055a835735bc5 in btr_insert_on_non_leaf_level (flags=7, flags@entry=0, index=index@entry=0x7f2a300b2df0, level=level@entry=1, tuple=0x7f2a300de950, mtr=mtr@entry=0x7f2a4075d388)
|
at /mariadb/10.6/storage/innobase/btr/btr0btr.cc:2397
|
#8 0x000055a835732d06 in btr_attach_half_pages (flags=0, index=0x7f2a300b2df0, block=0x7f2a520a7480,
|
split_rec=0x7f2a300f5c38 "c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2c2"..., new_block=0x7f2a520a7960, mtr=0x7f2a4075d388, direction=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0btr.cc:2509
|
#9 btr_page_split_and_insert (flags=0, flags@entry=139819171393008, cursor=cursor@entry=0x7f2a4075c7c8, offsets=0x7f2a4075c780, offsets@entry=0x7f2a4075c790, heap=0x7f2a4075c790, heap@entry=0x0,
|
tuple=tuple@entry=0x7f2a300d94c0, n_ext=0, mtr=<optimized out>, err=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0btr.cc:3021
|
#10 0x000055a835705254 in btr_cur_pessimistic_insert (flags=<optimized out>, flags@entry=0, cursor=0x7f2a4075c7c8, cursor@entry=0x7f2a4075c7a8, offsets=<optimized out>, offsets@entry=0x7f2a4075c760,
|
heap=<optimized out>, heap@entry=0x7f2a4075c770, entry=0x7f2a300d94c0, entry@entry=0x7f2a300f3528, rec=<optimized out>, rec@entry=0x7f2a4075d820, big_rec=<optimized out>, n_ext=139819171576640,
|
thr=<optimized out>, mtr=<optimized out>) at /mariadb/10.6/storage/innobase/btr/btr0cur.cc:3627
|
#11 0x000055a83591a9b6 in row_ins_sec_index_entry_low (flags=flags@entry=0, mode=<optimized out>, mode@entry=1034, index=index@entry=0x7f2a300b2df0, offsets_heap=<optimized out>,
|
offsets_heap@entry=0x7f2a300d98d0, heap=<optimized out>, heap@entry=0x7f2a300de440, entry=<optimized out>, entry@entry=0x7f2a300d94c0, trx_id=0, thr=0x7f2a300f3528)
|
at /mariadb/10.6/storage/innobase/row/row0ins.cc:3054
|
This is requesting page 0xa4, which is one level above the leaf (0xc8), on which btr_page_split_and_insert() is being invoked. That page latch should really have been acquired already during the initial search that was invoked by row_ins_sec_index_entry_low() before invoking btr_cur_pessimistic_insert(). In fact, a single call to btr_cur_search_to_nth_level() within a single mini-transaction should be sufficient. If we had acquired the necessary non-leaf page latches upfront like the latching order requires us to do, we should find all needed pages in the mtr_t::m_memo.
When it comes to the DELETE code path, here is another hang, for which I will did not yet add a debug assertion to catch potential hangs earlier:
#7 0x000055e8b596be8e in btr_block_get (index=..., page=page@entry=3154, mode=mode@entry=2, merge=merge@entry=true, mtr=mtr@entry=0x7f47e6c935f0, err=err@entry=0x7f47e6c92170) at /data/Server/10.6_freeze/storage/innobase/include/buf0types.h:95
|
#8 0x000055e8b5992ca3 in btr_discard_page (cursor=cursor@entry=0x7f47e6c92a10, mtr=mtr@entry=0x7f47e6c935f0) at /data/Server/10.6_freeze/storage/innobase/btr/btr0btr.cc:4178
|
#9 0x000055e8b59efd04 in btr_cur_pessimistic_delete (err=err@entry=0x7f47e6c928e0, has_reserved_extents=has_reserved_extents@entry=1, cursor=cursor@entry=0x7f47e6c92a10, flags=flags@entry=16, rollback=rollback@entry=false, mtr=mtr@entry=0x7f47e6c935f0) at /data/Server/10.6_freeze/storage/innobase/btr/btr0cur.cc:5739
|
#10 0x000055e8b59f111a in btr_cur_node_ptr_delete (parent=parent@entry=0x7f47e6c92a10, mtr=mtr@entry=0x7f47e6c935f0) at /data/Server/10.6_freeze/storage/innobase/btr/btr0cur.cc:5882
|
#11 0x000055e8b5992e71 in btr_discard_page (cursor=cursor@entry=0x7f47e6c93300, mtr=mtr@entry=0x7f47e6c935f0) at /data/Server/10.6_freeze/storage/innobase/btr/btr0btr.cc:4241
|
#12 0x000055e8b59efd04 in btr_cur_pessimistic_delete (err=err@entry=0x7f47e6c93150, has_reserved_extents=has_reserved_extents@entry=0, cursor=cursor@entry=0x7f47e6c93300, flags=flags@entry=0, rollback=rollback@entry=false, mtr=mtr@entry=0x7f47e6c935f0) at /data/Server/10.6_freeze/storage/innobase/btr/btr0cur.cc:5739
|
This thread is waiting for a level-1 page latch that is being held by ha_innobase::records_in_range(), which is waiting for the level-0 (leaf) page latch that this thread (executing the purge of history) is holding. The tree is 15 levels high. This may be thanks to an innodb_limit_optimistic_insert_debug setting that I suggested.
I think that this change should prevent the hangs. It is obviously unacceptable for performance, just like the one that I initially suggested in MDEV-14637.
At least the debug checks that I added are no longer tripped. Without the work-around, they would fail in about 10 regression tests.
The real fix should be to rewrite the function btr_cur_search_to_nth_level() and a number of its callers, such as btr_page_get_father_block(). All affected non-leaf page latches must be acquired upfront, in the correct order.
| Link |
This issue relates to |
| Link | This issue relates to MDEV-29930 [ MDEV-29930 ] |
We got one more case when testing MDEV-29603, and I double-checked that those changes are innocent. This is a hang between two INSERT. One of them is holding a leaf page latch and waiting for the root page U-latch even though it is not holding index X-latch. This a latching order violation.
#5 sux_lock<ssux_lock_impl<true> >::u_lock (this=this@entry=0x7f8a1b8a7788) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/include/sux_lock.h:378
|
#6 0x00005567e3e24198 in btr_page_alloc_low (index=index@entry=0x61600288c708, hint_page_no=hint_page_no@entry=19, file_direction=file_direction@entry=113 'q', level=level@entry=0,
|
mtr=mtr@entry=0x7f89f504a870, init_mtr=init_mtr@entry=0x7f89f504a870, err=0x7f89f504a6d0) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/btr/btr0btr.cc:531
|
#7 0x00005567e3e24302 in btr_page_alloc (index=index@entry=0x61600288c708, hint_page_no=19, file_direction=file_direction@entry=113 'q', level=level@entry=0, mtr=mtr@entry=0x7f89f504a870,
|
init_mtr=init_mtr@entry=0x7f89f504a870, err=0x7f89f504a6d0) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/btr/btr0btr.cc:566
|
#8 0x00005567e3e75fd4 in btr_store_big_rec_extern_fields (pcur=pcur@entry=0x7f89f504ac60, offsets=offsets@entry=0x6190008e5928, big_rec_vec=big_rec_vec@entry=0x622000435188,
|
btr_mtr=btr_mtr@entry=0x7f89f504ad80, op=op@entry=BTR_STORE_INSERT) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/btr/btr0cur.cc:6871
|
#9 0x00005567e3bd20db in row_ins_index_entry_big_rec (entry=entry@entry=0x61600366af08, big_rec=<optimized out>, offsets=0x6190008e5928, heap=heap@entry=0x7f89f504b1a0, index=index@entry=0x61600288c708,
|
thd=0x62b0001ea218) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/row/row0ins.cc:2493
|
#10 0x00005567e3bee4fc in row_ins_clust_index_entry_low (flags=flags@entry=0, mode=<optimized out>, mode@entry=BTR_MODIFY_TREE, index=index@entry=0x61600288c708, n_uniq=n_uniq@entry=0,
|
entry=entry@entry=0x61600366af08, n_ext=n_ext@entry=0, thr=<optimized out>) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/row/row0ins.cc:2798
|
The function row_ins_clust_index_entry_low() is invoking btr_pcur_open(), which was only subject to minor refactoring in that branch. The function btr_cur_search_to_nth_level() should have been invoked there. This thread is holding the following latches at the time of the hang:
(gdb) p *btr_mtr.m_memo
|
$29 = std::vector of length 3, capacity 4 = {{object = 0x61600288c880, type = MTR_MEMO_SX_LOCK}, {object = 0x0, type = MTR_MEMO_PAGE_S_FIX}, {object = 0x7f8a1b8b0b50, type = MTR_MEMO_PAGE_X_FIX}}
|
(gdb) p *mtr.m_memo
|
$22 = std::vector of length 4, capacity 4 = {{object = 0x7f8a1b8b0b50, type = MTR_MEMO_PAGE_X_FIX}, {object = 0x61200008ca40, type = MTR_MEMO_SPACE_X_LOCK}, {object = 0x7f8a1b8a7500,
|
type = MTR_MEMO_PAGE_SX_MODIFY}, {object = 0x7f8a1b8a7770, type = MTR_MEMO_PAGE_SX_FIX}}
|
That is, the thread is only holding a U-latch on the index (the first item of btr_mtr) and no latch on the root page. The index root page latch is being held by another thread that is waiting for the leaf page latch that the above thread is holding:
#5 sux_lock<ssux_lock_impl<true> >::x_lock_upgraded (this=0x7f8a1b8b0b68) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/include/sux_lock.h:428
|
#6 buf_page_get_low (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=2, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7f89f4371660, err=<optimized out>, allow_ibuf_merge=<optimized out>) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/buf/buf0buf.cc:2842
|
#7 0x00005567e3eea00d in buf_page_get_gen (page_id=..., zip_size=zip_size@entry=0, rw_latch=rw_latch@entry=2, guess=guess@entry=0x0, mode=mode@entry=10, mtr=mtr@entry=0x7f89f4371660, err=0x7f89f43700c0, allow_ibuf_merge=false) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/buf/buf0buf.cc:2962
|
#8 0x00005567e3e88bd7 in btr_cur_search_to_nth_level (level=level@entry=0, tuple=tuple@entry=0x616002dacf08, mode=mode@entry=PAGE_CUR_LE, latch_mode=latch_mode@entry=BTR_MODIFY_LEAF, cursor=cursor@entry=0x7f89f4371260, mtr=mtr@entry=0x7f89f4371660, autoinc=<optimized out>) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/btr/btr0cur.cc:1554
|
#9 0x00005567e3beb3e8 in btr_pcur_open (mtr=0x7f89f4371660, autoinc=0, cursor=0x7f89f4371260, latch_mode=BTR_MODIFY_LEAF, mode=PAGE_CUR_LE, tuple=0x616002dacf08) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/include/btr0pcur.inl:325
|
#10 row_ins_clust_index_entry_low (flags=flags@entry=0, mode=mode@entry=BTR_MODIFY_LEAF, index=index@entry=0x61600288c708, n_uniq=n_uniq@entry=0, entry=entry@entry=0x616002dacf08, n_ext=n_ext@entry=0, thr=<optimized out>) at /data/Server/bb-10.6-MDEV-29603-3/storage/innobase/row/row0ins.cc:2610
|
This thread is holding the following latches:
(gdb) p *mtr.m_memo
|
$19 = std::vector of length 3, capacity 4 = {{object = 0x61600288c880, type = MTR_MEMO_S_LOCK}, {object = 0x0, type = MTR_MEMO_PAGE_S_FIX}, {object = 0x7f8a1b8a7770, type = MTR_MEMO_PAGE_X_FIX}}
|
That is, it is holding the index S-latch and an exclusive latch on the root page 0x7f8a1b8a7770. The same pointer occurs in the first thread’s mtr_t::m_memo, because btr_page_alloc_low() updated it before attempting to acquire the lock:
mtr->u_lock_register(savepoint);
|
root->page.lock.u_lock();
|
I think that if a BLOB operation (freeing or deleting BLOBs) is anticipated, then the root page U-latch needs to be acquired upfront, before releasing the index latch. Currently, we should do that in some cases of BTR_MODIFY_TREE, which frame 10 in the first thread is using. This logic needs to be carefully reviewed when implementing a replacement of btr_cur_search_to_nth_level() as part of fixing the hangs.
In other words: In addition to the hangs related to page splits and merges, MySQL Worklog #6326 seems to have introduced hangs related to BLOB operations. Before that change, this type of a deadlock during a BLOB operation should have been prevented by the fact that the first thread would hold an exclusive latch on the index tree, blocking the second thread before it can acquire any page latches.
| Link |
This issue blocks |
| Link |
This issue relates to |
| Link |
This issue blocks |
I am thinking to push the current state of the fixes as MDEV-30400. That will not fix all hangs but could fix some of them.
The BLOB related deadlock in btr_store_big_rec_extern_fields() is caused by the fact that when btr_blob_log_check_t::check() restarts btr_mtr, it fails to first acquire and hold a latch on the clustered index root page. As a result of that, the call to btr_page_alloc() may end up in a deadlock due to waiting for the root page latch. That will be fixed in MDEV-30400.
With the fix of MDEV-30400, some hangs related to merging or contracting B-trees will remain possible. Also some hangs related to splitting B-trees may remain possible.
In branches where the fix of MDEV-30400 is 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.cc
|
index 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);
|
+#else
|
if (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);
|
else
|
mtr_sx_lock_index(index(), mtr);
|
+#endif
|
break;
|
#ifdef UNIV_DEBUG
|
case BTR_CONT_MODIFY_TREE: |
A number of #if 0 checks that mention MDEV-29835 were added in the MDEV-30400 fix. Those checks will have to be enabled as part of fixing this bug.
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.
| Link |
This issue relates to |
| Link |
This issue relates to |
| Link | This issue blocks MDEV-29930 [ MDEV-29930 ] |
| Link | This issue relates to MDEV-29930 [ MDEV-29930 ] |
| Labels | affects-tests |
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.
| Fix Version/s | 10.6.13 [ 28514 ] | |
| Fix Version/s | 10.8.8 [ 28518 ] | |
| Fix Version/s | 10.9.6 [ 28520 ] | |
| Fix Version/s | 10.10.4 [ 28522 ] | |
| Fix Version/s | 10.11.3 [ 28524 ] | |
| Fix Version/s | 11.0.2 [ 28706 ] | |
| Fix Version/s | 10.6 [ 24028 ] | |
| Resolution | Fixed [ 1 ] | |
| Status | In Progress [ 3 ] | Closed [ 6 ] |
| Link |
This issue relates to |
| Link |
This issue is duplicated by |
| Link |
This issue is duplicated by |
| Link |
This issue relates to |
| Link | This issue is duplicated by MENT-1802 [ MENT-1802 ] |
| Link | This issue relates to TODO-3896 [ TODO-3896 ] |
| Link | This issue causes TODO-3895 [ TODO-3895 ] |
| Link | This issue causes TODO-3899 [ TODO-3899 ] |
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.
| Link | This issue relates to TODO-3902 [ TODO-3902 ] |
| Link |
This issue is duplicated by |
| Link | This issue causes TODO-3909 [ TODO-3909 ] |
| Link | This issue causes TODO-3902 [ TODO-3902 ] |
| Link | This issue relates to TODO-3902 [ TODO-3902 ] |
| Link | This issue causes TODO-3877 [ TODO-3877 ] |
| Link | This issue causes TODO-3890 [ TODO-3890 ] |
| Link | This issue causes TODO-3896 [ TODO-3896 ] |
| Link | This issue relates to TODO-3896 [ TODO-3896 ] |
| Link | This issue relates to TODO-3918 [ TODO-3918 ] |
| Link |
This issue is duplicated by |
| Link | This issue blocks TODO-3922 [ TODO-3922 ] |
| Link |
This issue relates to |
| Link |
This issue is duplicated by |
| Link |
This issue is duplicated by |
| Link |
This issue causes |
| Link |
This issue relates to |
| Link |
This issue is duplicated by |
| Link | This issue relates to MDEV-31815 [ MDEV-31815 ] |
| Link |
This issue is duplicated by |
| Link |
This issue relates to |
| Zendesk Related Tickets | 202343 132524 154165 179767 171654 |
One core dump that I am debugging looks like a violation of the latching protocol described in the https://dev.mysql.com/worklog/task/?id=6326 High Level Architure. Note: That description is missing a line before (2.1). It should read as follows:
I am seeing a deadlock between two threads. One is holding a shared index->lock and waiting for a leaf page latch. The other is holding an index SX-latch (U-latch) and a leaf page latch, and attempting to acquire a latch on the parent page. Tree traversal towards the root is only allowed while holding an exclusive latch on the index. Here is part of the problematic call stack:
10.6 c92c1615852ecd4be2d04203600efd3eba578a02
#10 0x0000557c305a7d3f in btr_page_get_father (index=index@entry=0x7fca4c28f090, block=<optimized out>, mtr=mtr@entry=0x7fcb017e8c20, cursor=cursor@entry=0x7fcb017e8430) at /data/Server/10.6C/storage/innobase/btr/btr0btr.cc:825#11 0x0000557c305b426c in btr_compress (cursor=cursor@entry=0x7fcb017e89b0, adjust=adjust@entry=false, mtr=mtr@entry=0x7fcb017e8c20) at /data/Server/10.6C/storage/innobase/btr/btr0btr.cc:3797#12 0x0000557c305d336d in btr_cur_compress_if_useful (cursor=cursor@entry=0x7fcb017e89b0, adjust=adjust@entry=false, mtr=mtr@entry=0x7fcb017e8c20) at /data/Server/10.6C/storage/innobase/include/page0page.inl:303#13 0x0000557c305e30ac in btr_cur_pessimistic_delete (err=err@entry=0x7fcb017e89a0, has_reserved_extents=has_reserved_extents@entry=0, cursor=cursor@entry=0x7fcb017e89b0, flags=flags@entry=0, rollback=rollback@entry=false, mtr=mtr@entry=0x7fcb017e8c20) at /data/Server/10.6C/storage/innobase/btr/btr0cur.cc:5842#14 0x0000557c304f7a2b in row_purge_remove_sec_if_poss_tree (node=node@entry=0x557c331201c0, index=index@entry=0x7fca4c28f090, entry=entry@entry=0x7fca680055e0) at /data/Server/10.6C/storage/innobase/row/row0purge.cc:408#15 0x0000557c304f9226 in row_purge_remove_sec_if_poss (entry=0x7fca680055e0, index=0x7fca4c28f090, node=0x557c331201c0) at /data/Server/10.6C/storage/innobase/row/row0purge.cc:579#16 row_purge_upd_exist_or_extern_func (thr=thr@entry=0x557c33120120, node=node@entry=0x557c331201c0, undo_rec=undo_rec@entry=0x7fca60025160 "\003[\f\006\022") at /data/Server/10.6C/storage/innobase/row/row0purge.cc:774This feels like a repeat of
MDEV-14637. The index in question is defined on a CHAR(255) CHARACTER SET ucs2 column, and the PRIMARY KEY is a 32-bit column. I am investigating it further.