MySQL ( [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds.

[moro]

Zabbix 5.0.0 from official docker images.
mysql Ver 15.1 Distrib 10.3.27-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
4cores, 24 GB RAM
zabbix db size = 62GB

I have a problem with the server with the MariaDB database and zabbix in the docker. Almost every day, the server goes down for a while. Log from database during problem.

============================
InnoDB: ###### Diagnostic info printed to the standard error stream
2020-12-31 8:38:12 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
201231 8:38:12 [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.3.27-MariaDB-0+deb10u1
key_buffer_size=1073741824
read_buffer_size=134217728
max_used_connections=52
max_threads=102
thread_count=58
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 14629091 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
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x55bcb328391e]
/usr/sbin/mysqld(handle_fatal_signal+0x54d)[0x55bcb2db22ed]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12730)[0x7f902b5f0730]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x10b)[0x7f902abad7bb]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x121)[0x7f902ab98535]
/usr/sbin/mysqld(+0x4e48c3)[0x55bcb2af68c3]
/usr/sbin/mysqld(+0x4daff0)[0x55bcb2aecff0]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7fa3)[0x7f902b5e5fa3]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f902ac6f4cf]
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 /var/lib/mysql
Resource Limits:
Fatal signal 11 while backtracing
2020-12-31 8:38:41 0 [Note] InnoDB: Using Linux native AIO
2020-12-31 8:38:41 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-12-31 8:38:41 0 [Note] InnoDB: Uses event mutexes
2020-12-31 8:38:41 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-12-31 8:38:41 0 [Note] InnoDB: Number of pools: 1
2020-12-31 8:38:41 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-12-31 8:38:42 0 [Note] InnoDB: Initializing buffer pool, total size = 8G, instances = 8, chunk size = 128M
2020-12-31 8:38:42 0 [Note] InnoDB: Completed initialization of buffer pool
2020-12-31 8:38:42 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-12-31 8:38:43 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4991659277590
2020-12-31 8:38:54 0 [Note] InnoDB: 7 transaction(s) which must be rolled back or cleaned up in total 4265 row operations to undo
2020-12-31 8:38:54 0 [Note] InnoDB: Trx id counter is 1098591064
2020-12-31 8:38:54 0 [Note] InnoDB: Starting final batch to recover 515441 pages from redo log.
2020-12-31 8:38:57 0 [Note] InnoDB: To recover: 508189 pages from log
2020-12-31 8:39:12 0 [Note] InnoDB: To recover: 444712 pages from log
2020-12-31 8:39:27 0 [Note] InnoDB: To recover: 376246 pages from log
2020-12-31 8:39:42 0 [Note] InnoDB: To recover: 307507 pages from log
2020-12-31 8:39:57 0 [Note] InnoDB: To recover: 239674 pages from log
2020-12-31 8:40:12 0 [Note] InnoDB: To recover: 174641 pages from log
2020-12-31 8:40:27 0 [Note] InnoDB: To recover: 101787 pages from log
2020-12-31 8:40:42 0 [Note] InnoDB: To recover: 39271 pages from log
2020-12-31 8:40:57 0 [Note] InnoDB: To recover: 4639 pages from log
2020-12-31 8:41:01 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-12-31 8:41:01 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
2020-12-31 8:41:01 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2020-12-31 8:41:01 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-12-31 8:41:01 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-12-31 8:41:01 0 [Note] InnoDB: Rolled back recovered transaction 1098588590
2020-12-31 8:41:01 0 [Note] InnoDB: Rolled back recovered transaction 1098588486
2020-12-31 8:41:01 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-12-31 8:41:01 0 [Note] InnoDB: 10.3.27 started; log sequence number 4991681670069; transaction id 1098591067
2020-12-31 8:41:01 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2020-12-31 8:41:01 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-12-31 8:41:01 0 [Note] Recovering after a crash using tc.log
2020-12-31 8:41:01 0 [Note] Starting crash recovery...
2020-12-31 8:41:01 0 [Note] Crash recovery finished.
2020-12-31 8:41:01 0 [Note] Server socket created on IP: '192.168.1.150'.
2020-12-31 8:41:01 0 [Note] InnoDB: Rolled back recovered transaction 1098585428
2020-12-31 8:41:01 0 [Note] Reading of all Master_info entries succeeded
2020-12-31 8:41:01 0 [Note] Added new Master_info '' to hash table
2020-12-31 8:41:01 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.27-MariaDB-0+deb10u1' socket: '/run/mysqld/mysqld.sock' port: 3306 Debian 10
2020-12-31 8:41:01 0 [Note] InnoDB: Rolled back recovered transaction 1098585418
2020-12-31 8:41:01 0 [Note] InnoDB: Rolled back recovered transaction 1098585424
2020-12-31 8:41:07 0 [Note] InnoDB: Rolled back recovered transaction 1098590977
2020-12-31 8:41:07 0 [Note] InnoDB: Rolled back recovered transaction 1098585435
2020-12-31 8:41:07 0 [Note] InnoDB: Rollback of non-prepared transactions completed
2020-12-31 8:51:50 0 [Note] InnoDB: Buffer pool(s) load completed at 201231 8:51:50

mysql config

[server]

[mysqld]

user = mysql
pid-file = /run/mysqld/mysqld.pid
socket = /run/mysqld/mysqld.sock
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
lc-messages-dir = /usr/share/mysql
innodb_log_file_size = 1G

innodb_strict_mode = 0
bind-address = 111.222.111.222

key_buffer_size = 1024M
max_allowed_packet = 512M
max_connections = 100
table_cache = 256M
innodb_buffer_pool_size = 8096M
innodb_buffer_pool_instances = 8
innodb_flush_method = O_DIRECT
join_buffer_size = 1M
wait_timeout = 86400
table_definition_cache = -1
skip-name-resolve
read_buffer_size = 128M
query_cache_limit = 0
query_cache_size = 0

general_log_file = /var/log/mysql/mysql.log
general_log = 3
log_error = /var/log/mysql/error.log
slow_query_log_file = /var/log/mysql/mariadb-slow.log
long_query_time = 10
expire_logs_days = 10
max_binlog_size = 100M


character-set-server = utf8mb4
collation-server = utf8mb4_general_ci



[embedded]

[mariadb]

[mariadb-10.3]

[barnettd]

I ran into the same issue on a Debian 10 install. Downgrading mariadb to 10.3.25 seems to have resolved the issue.

[[email protected]]

Same problem on FreeBSD after upgrading do mariadb 10.4.17 (from 10.4.15), didn't try to downgrade yet.

[moro]

Yesterday I upgraded to

mysql --version mysql Ver 15.1 Distrib 10.5.8-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

and I will test.

[Damir]

Same problem after upgrade to 5.2.3 and mariadb 10.3.27 from 10.3.22.
Give feedback please how its works with mariadb 10.5.8

[moro]

I still have a problem. Now there's another bug in the logs.

InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 1, writes 0
InnoDB: ###### Diagnostic info printed to the standard error stream
2021-01-19 6:20:49 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139918274991872 has waited at btr0cur.cc line 1480 for 290.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969
2021-01-19 6:20:49 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139918279599872 has waited at btr0cur.cc line 1480 for 290.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969
2021-01-19 6:20:49 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139918280828672 has waited at btr0cur.cc line 1480 for 290.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969
2021-01-19 6:20:49 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139928491443968 has waited at btr0cur.cc line 1480 for 290.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969
2021-01-19 6:20:49 0 [Note] InnoDB: A semaphore wait:
--Thread 139918274991872 has waited at btr0cur.cc line 1480 for 290.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969
2021-01-19 6:20:49 0 [Note] InnoDB: A semaphore wait:
--Thread 139918279599872 has waited at btr0cur.cc line 1480 for 290.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969
2021-01-19 6:20:49 0 [Note] InnoDB: A semaphore wait:
--Thread 139918280828672 has waited at btr0cur.cc line 1480 for 290.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969
2021-01-19 6:20:49 0 [Note] InnoDB: A semaphore wait:
--Thread 139928491443968 has waited at btr0cur.cc line 1480 for 290.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending reads 1, writes 0
InnoDB: ###### Diagnostic info printed to the standard error stream
2021-01-19 6:20:50 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139918274991872 has waited at btr0cur.cc line 1480 for 291.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969
2021-01-19 6:20:50 0 [Warning] InnoDB: A long semaphore wait:
--Thread 139918279599872 has waited at btr0cur.cc line 1480 for 291.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f4125ad3270 created in file dict0dict.cc line 2161
a writer (thread id 139918248584960) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time write locked in file dict0stats.cc line 1969

[barnettd]

I can verify that rolling back MariaDB to 10.3.25 has completely resolved the issue for us. We are currently on Zabbix version 5.0.7 which is unchanged.

[Hitman]

I also have the same problem with zabbix 5.0.8 and MariaDB 10.3.27, I will try to downgrade MariaDB to 10.3.25 to confirm if it works.

[Hitman]

I can confirm, that after downgrading MariaDB to 10.3.25 problem is resolved, no issues for over 2 weeks now.

[martin89]

Привет ребята, а есть какая то инструкция по понижению МарияДБ с 10.3.27 на 10.2.25.
Спасибо.

[pizzulicchio]

Привет ребята, а есть какая то инструкция по понижению МарияДБ с 10.3.27 на 10.2.25.
Спасибо.

apt install mariadb-server-10.3=1:10.3.25-0+deb10u1
apt install mariadb-server-core-10.3=1:10.3.25-0+deb10u1
apt install mariadb-server=1:10.3.25-0+deb10u1