[MDEV-24101] innodb_random_read_ahead=ON causes hang on DDL or shutdown Created: 2020-11-03  Updated: 2020-11-05  Resolved: 2020-11-03

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.5
Fix Version/s: 10.5.7

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: hang, regression-10.5

Issue Links:
Blocks
Problem/Incident
is caused by MDEV-23855 InnoDB log checkpointing causes regre... Closed

 Description   

10.5 440d4b282d

 
Version: '10.5.7-MariaDB-debug-log'  socket: '/home/mariadb/MDEV-24101/10.5/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
 
2020-11-03  1:43:49 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:43:59 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:44:09 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:44:19 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:44:29 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:44:39 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:44:49 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:44:59 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:45:10 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:45:20 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:45:30 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:45:40 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:45:50 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:46:00 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:46:10 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:46:20 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:46:30 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:46:41 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:46:51 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:47:01 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:47:11 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:47:21 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:47:31 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:47:41 9 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-backup-8cbd-9' but there are 3 pending operations on it.
 
2020-11-03  1:47:49 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635575420672 has waited at dict0dict.cc line 943 for 241.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:47:49 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635056432896 has waited at dict0dict.cc line 943 for 241.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:47:49 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635091044096 has waited at dict0dict.cc line 943 for 241.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
 
 
<...>
 
 
 
2020-11-03  1:48:56 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635595351808 has waited at dict0stats_bg.cc line 348 for 299.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:56 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635575420672 has waited at dict0dict.cc line 943 for 308.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:56 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635056432896 has waited at dict0dict.cc line 943 for 308.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:56 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635091044096 has waited at dict0dict.cc line 943 for 308.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:56 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635080554240 has waited at dict0dict.cc line 943 for 308.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:56 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635583813376 has waited at srv0srv.cc line 1603 for 307.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5642ff699478 created in file dict0dict.cc line 1041
 
a writer (thread id 139635024963328) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3314
 
2020-11-03  1:48:56 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635595351808 has waited at dict0stats_bg.cc line 348 for 299.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
 
InnoDB: Pending reads 0, writes 0
 
InnoDB: ###### Diagnostic info printed to the standard error stream
 
2020-11-03  1:48:57 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635575420672 has waited at dict0dict.cc line 943 for 309.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635056432896 has waited at dict0dict.cc line 943 for 309.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635091044096 has waited at dict0dict.cc line 943 for 309.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635080554240 has waited at dict0dict.cc line 943 for 309.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635583813376 has waited at srv0srv.cc line 1603 for 308.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5642ff699478 created in file dict0dict.cc line 1041
 
a writer (thread id 139635024963328) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635595351808 has waited at dict0stats_bg.cc line 348 for 300.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635575420672 has waited at dict0dict.cc line 943 for 309.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635056432896 has waited at dict0dict.cc line 943 for 309.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635091044096 has waited at dict0dict.cc line 943 for 309.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635080554240 has waited at dict0dict.cc line 943 for 309.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635583813376 has waited at srv0srv.cc line 1603 for 308.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5642ff699478 created in file dict0dict.cc line 1041
 
a writer (thread id 139635024963328) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3314
 
2020-11-03  1:48:57 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635595351808 has waited at dict0stats_bg.cc line 348 for 300.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
 
InnoDB: Pending reads 0, writes 0
 
InnoDB: ###### Diagnostic info printed to the standard error stream
 
2020-11-03  1:48:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635575420672 has waited at dict0dict.cc line 943 for 310.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635056432896 has waited at dict0dict.cc line 943 for 310.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635091044096 has waited at dict0dict.cc line 943 for 310.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635080554240 has waited at dict0dict.cc line 943 for 310.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635583813376 has waited at srv0srv.cc line 1603 for 309.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5642ff699478 created in file dict0dict.cc line 1041
 
a writer (thread id 139635024963328) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635595351808 has waited at dict0stats_bg.cc line 348 for 301.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635575420672 has waited at dict0dict.cc line 943 for 310.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635056432896 has waited at dict0dict.cc line 943 for 310.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635091044096 has waited at dict0dict.cc line 943 for 310.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635080554240 has waited at dict0dict.cc line 943 for 310.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635583813376 has waited at srv0srv.cc line 1603 for 309.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5642ff699478 created in file dict0dict.cc line 1041
 
a writer (thread id 139635024963328) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3314
 
2020-11-03  1:48:58 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635595351808 has waited at dict0stats_bg.cc line 348 for 301.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
 
InnoDB: Pending reads 0, writes 0
 
InnoDB: ###### Diagnostic info printed to the standard error stream
 
2020-11-03  1:48:59 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635575420672 has waited at dict0dict.cc line 943 for 311.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635056432896 has waited at dict0dict.cc line 943 for 311.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635091044096 has waited at dict0dict.cc line 943 for 311.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635080554240 has waited at dict0dict.cc line 943 for 311.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635583813376 has waited at srv0srv.cc line 1603 for 310.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5642ff699478 created in file dict0dict.cc line 1041
 
a writer (thread id 139635024963328) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Warning] InnoDB: A long semaphore wait:
 
--Thread 139635595351808 has waited at dict0stats_bg.cc line 348 for 302.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635575420672 has waited at dict0dict.cc line 943 for 311.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635056432896 has waited at dict0dict.cc line 943 for 311.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635091044096 has waited at dict0dict.cc line 943 for 311.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635080554240 has waited at dict0dict.cc line 943 for 311.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635583813376 has waited at srv0srv.cc line 1603 for 310.00 seconds the semaphore:
 
X-lock on RW-latch at 0x5642ff699478 created in file dict0dict.cc line 1041
 
a writer (thread id 139635024963328) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time write locked in file row0mysql.cc line 3314
 
2020-11-03  1:48:59 0 [Note] InnoDB: A semaphore wait:
 
--Thread 139635595351808 has waited at dict0stats_bg.cc line 348 for 302.00 seconds the semaphore:
 
Mutex at 0x5642ff6993e0, Mutex DICT_SYS created /home/mariadb/MDEV-24101/10.5/storage/innobase/dict/dict0dict.cc:1032, lock var 2
 
Last time reserved in file /home/mariadb/MDEV-24101/10.5/storage/innobase/row/row0mysql.cc line 3314
 
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
 
InnoDB: Pending reads 0, writes 0
 
InnoDB: ###### Diagnostic info printed to the standard error stream
 
2020-11-03  1:48:59 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 300 seconds. We intentionally crash the server because it appears to be hung.
 
201103  1:48:59 [ERROR] mysqld got signal 6 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.5.7-MariaDB-debug-log
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=3
 
max_threads=153
 
thread_count=4
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 193789 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x0 thread_stack 0x49000
 
/home/mariadb/MDEV-24101/10.5/sql/mariadbd(my_print_stacktrace+0x40)[0x5642fe86b833]
 
mysys/stacktrace.c:212(my_print_stacktrace)[0x5642fdf2979b]
 
??:0(__restore_rt)[0x7eff8205c8a0]
 
linux/raise.c:51(__GI_raise)[0x7eff81154f47]
 
stdlib/abort.c:81(__GI_abort)[0x7eff811568b1]
 
/home/mariadb/MDEV-24101/10.5/sql/mariadbd(+0x1376741)[0x5642fe627741]
 
/home/mariadb/MDEV-24101/10.5/sql/mariadbd(+0x1306b93)[0x5642fe5b7b93]
 
ut/ut0ut.cc:580(ib::fatal::~fatal())[0x5642fe7c858a]
 
srv/srv0srv.cc:1431(srv_error_monitor_task)[0x5642fe7c8678]
 
tpool/tpool_generic.cc:300(tpool::thread_pool_generic::timer_generic::run())[0x5642fe7cd74d]
 
tpool/task.cc:53(tpool::task::execute())[0x5642fe7c6e2e]
 
tpool/tpool_generic.cc:516(tpool::thread_pool_generic::worker_main(tpool::worker_data*))[0x5642fe7ca1d5]
 
bits/invoke.h:73(void std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&))[0x5642fe7c94c1]
 
bits/invoke.h:95(std::__invoke_result<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>::type std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&))[0x5642fe7cd055]
 
7/thread:234(decltype (__invoke((_S_declval<0ul>)(), (_S_declval<1ul>)(), (_S_declval<2ul>)())) std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul>(std::_Index_tuple<0ul, 1ul, 2ul>))[0x5642fe7ccfef]
 
7/thread:243(std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()())[0x5642fe7ccfce]
 
??:0(std::error_code::default_error_condition() const)[0x7eff81b7a6df]
 
nptl/pthread_create.c:463(start_thread)[0x7eff820516db]
 
x86_64/clone.S:97(clone)[0x7eff81237a3f]
 
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
 
information that should help you find out what is causing the crash.
 
Writing a core file...
 
Working directory at /dev/shm/var_auto_gcO5/mysqld.1/data
 
Resource Limits:
 
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            8388608              unlimited            bytes     
Max core file size        0                    unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             128241               128241               processes 
Max open files            1024                 1024                 files     
Max locked memory         16777216             16777216             bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       128241               128241               signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us        
Core pattern: |/usr/share/apport/apport %p %s %c %d %P %E
 
 
 
----------SERVER LOG END-------------



 Comments   
Comment by Marko Mäkelä [ 2020-11-03 ]

An initial investigation of the shorter trace suggests that read-ahead may be leaking references. The last time when the fil_space_t::n_pending reached 0 was at event 77889. At the time of the crash about 3000 events later, the reference count was 3. It is a little challenging to debug this, because we are submitting asynchronous read requests, and hence the reference count must be nonzero as long as requests are ‘in flight’.

I think that it is safe to say that this hang was introduced by the MDEV-23855 changes that reduce fil_system.mutex contention.

Comment by Marko Mäkelä [ 2020-11-03 ]

I can repeat the hang in various InnoDB tests by simply using a non-default parameter:

./mtr --parallel=auto --mysqld=--loose-innodb-random-read-ahead innodb.101_compatibility

mariadb-10.5.7

 
innodb.101_compatibility '16k,innodb'    w4 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2020-11-03 11:49:37
 
line
 
2020-11-03 11:47:35 0 [ERROR] InnoDB: File './ibdata1' has 1 operations
 
Attempting backtrace. You can use the following information to find out

The parameter innodb_random_read_ahead is OFF by default. That is why we did not catch it earlier.

At the start of the problematic function, we do check for innodb_random_read_ahead:

ulint
 
buf_read_ahead_random(const page_id_t page_id, ulint zip_size, bool ibuf)
 
{
 
  if (!srv_random_read_ahead)
 
    return 0;

So, a perfect work-around should be

SET GLOBAL innodb_random_read_ahead=OFF;

or not setting that parameter in configuration files, because it is disabled by default.

Apparently, buildbot.mariadb.org is running with innodb_random_read_ahead=ON for some reason.

Comment by Elena Stepanova [ 2020-11-05 ]

Test case for the reference (to be run with innodb_fatal_semaphore_wait_threshold=10 on builds with the bug, to get it fail faster; on healthy builds it doesn't matter).

--source include/have_innodb.inc
 
--source include/have_sequence.inc
 
 
 
SET @innodb_random_read_ahead.save= @@innodb_random_read_ahead;
 
 
 
CREATE TABLE t1 (id INT AUTO_INCREMENT, b TEXT, PRIMARY KEY(id,b(14))) ENGINE=InnoDB;
 
 
 
set rand_seed1= 1, rand_seed2= 1;
 
INSERT INTO t1 (b) SELECT 'foo' FROM seq_1_to_900;
 
UPDATE t1 SET b= (SELECT GROUP_CONCAT(CHAR(FLOOR(32 + (RAND() * 90))) SEPARATOR '') FROM seq_1_to_6000);
 
 
 
SET GLOBAL innodb_random_read_ahead= 1;
 
OPTIMIZE TABLE t1;
 
 
 
# Cleanup
 
DROP TABLE t1;
 
SET GLOBAL innodb_random_read_ahead= @innodb_random_read_ahead.save;


2020-11-05 18:44:43 4 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-ib21' but there are 39 pending operations on it.
 
2020-11-05 18:44:53 4 [Warning] InnoDB: Trying to delete tablespace 'test/#sql-ib21' but there are 39 pending operations on it.
 
2020-11-05 18:45:03 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 10 seconds. We intentionally crash the server because it appears to be hung.
 
201105 18:45:03 [ERROR] mysqld got signal 6 ;

The whole deal with GROUP_CONCAT and RAND is unrelated to the bug, it was just the best I could come up with to generate random values. It could be just as well a plain insert or update, but then the test becomes very big in size.

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