MySQL Bugs: #97379: Semaphore wait has lasted > 600 seconds,then server crash

Bug #97379	Semaphore wait has lasted > 600 seconds,then server crash
Submitted:	25 Oct 2019 8:03	Modified:	25 Oct 2019 12:14
Reporter:	1 1	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	8.0.18	OS:	CentOS (7.0)
Assigned to:		CPU Architecture:	x86 (x86_64)
Tags:	crash, Semaphore

Description:
my mysql server alawys crash, so i see the log.like this :

InnoDB: ###### Diagnostic info printed to the standard error stream
2019-10-24T20:34:02.493026Z 0 [ERROR] [MY-012872] [InnoDB] [FATAL] Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2019-10-24T20:34:02.493066Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: ut0ut.cc:532 thread 140640003274496
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
20:34:02 UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
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 = 0 thread_stack 0x46000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x3d) [0x1f104dd]
/usr/sbin/mysqld(handle_fatal_signal+0x333) [0xf8b933]
/usr/lib64/libpthread.so.0(+0xf5e0) [0x7fe9add5d5e0]
/usr/lib64/libc.so.6(gsignal+0x37) [0x7fe9abe1d1f7]
/usr/lib64/libc.so.6(abort+0x148) [0x7fe9abe1e8e8]
/usr/sbin/mysqld() [0xcf7214]
/usr/sbin/mysqld(ib::fatal::~fatal()+0xa4) [0x21bc824]
/usr/sbin/mysqld(srv_error_monitor_thread()+0x882) [0x215ede2]
/usr/sbin/mysqld(std::thread::_State_impl<std::thread::_Invoker<std::tuple<Runnable, void (*)()> > >::_M_run()+0xb5) [0x2072995]
/usr/sbin/mysqld() [0x263cf3f]
/usr/lib64/libpthread.so.0(+0x7e25) [0x7fe9add55e25]
/usr/lib64/libc.so.6(clone+0x6d) [0x7fe9abee034d]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2019-10-24T20:34:03.217866Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 10000 (requested 10010)
2019-10-24T20:34:03.217877Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 3995 (requested 4000)
2019-10-24T20:34:03.480761Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2019-10-24T20:34:03.482389Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.18) starting as process 30995
2019-10-24T20:34:05.361786Z 0 [System] [MY-010229] [Server] Starting crash recovery...
2019-10-24T20:34:05.368817Z 0 [System] [MY-010232] [Server] Crash recovery finished.
2019-10-24T20:34:05.993814Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.

please help me,thanks

How to repeat:
InnoDB: ###### Diagnostic info printed to the standard error stream
2019-10-24T20:34:02.493026Z 0 [ERROR] [MY-012872] [InnoDB] [FATAL] Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2019-10-24T20:34:02.493066Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: ut0ut.cc:532 thread 140640003274496
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
20:34:02 UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
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 = 0 thread_stack 0x46000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x3d) [0x1f104dd]
/usr/sbin/mysqld(handle_fatal_signal+0x333) [0xf8b933]
/usr/lib64/libpthread.so.0(+0xf5e0) [0x7fe9add5d5e0]
/usr/lib64/libc.so.6(gsignal+0x37) [0x7fe9abe1d1f7]
/usr/lib64/libc.so.6(abort+0x148) [0x7fe9abe1e8e8]
/usr/sbin/mysqld() [0xcf7214]
/usr/sbin/mysqld(ib::fatal::~fatal()+0xa4) [0x21bc824]
/usr/sbin/mysqld(srv_error_monitor_thread()+0x882) [0x215ede2]
/usr/sbin/mysqld(std::thread::_State_impl<std::thread::_Invoker<std::tuple<Runnable, void (*)()> > >::_M_run()+0xb5) [0x2072995]
/usr/sbin/mysqld() [0x263cf3f]
/usr/lib64/libpthread.so.0(+0x7e25) [0x7fe9add55e25]
/usr/lib64/libc.so.6(clone+0x6d) [0x7fe9abee034d]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2019-10-24T20:34:03.217866Z 0 [Warning] [MY-010139] [Server] Changed limits: max_open_files: 10000 (requested 10010)
2019-10-24T20:34:03.217877Z 0 [Warning] [MY-010142] [Server] Changed limits: table_open_cache: 3995 (requested 4000)
2019-10-24T20:34:03.480761Z 0 [Warning] [MY-011070] [Server] 'Disabling symbolic links using --skip-symbolic-links (or equivalent) is the default. Consider not using this option as it' is deprecated and will be removed in a future release.
2019-10-24T20:34:03.482389Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.18) starting as process 30995
2019-10-24T20:34:05.361786Z 0 [System] [MY-010229] [Server] Starting crash recovery...
2019-10-24T20:34:05.368817Z 0 [System] [MY-010232] [Server] Crash recovery finished.
2019-10-24T20:34:05.993814Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.

Hi Mr. 1,

Thank you for your bug report.

However, this is not a bug. Long semaphore waits, in your case, are a consequence of the badly written application. Application starts transaction and then waits on something, being end user's input, processing, network or anything else.

In short, you have to change your application in order to avoid semaphore waits longer then 10 minutes. No transaction should last more then a minute, much less 10 minutes.

Not a bug.

What caused the hang. People who love InnoDB would love to know. In the past this has been caused by InnoDB bugs or flaky HW (stuck storage). It isn't clear from the report that this was flaky HW.

The cause of the semaphore wait is unknown. This is, however, what is known .......

Thread ABC waits in function trx_rsegf_get        on line 50  :  block = buf_page_get(page_id_t(space, page_no), page_size, RW_X_LATCH, mtr);
Thread FGH waits in function trx_undo_assign_undo on line 1663:  mutex_enter(&rseg->mutex);
Thread XYZ is unknown from the outputs given, probably a background thread.

Thread FGH is a user's UPDATE statement executing, but it hasn't done much work and is stuck now.
  "mysql tables in use 1, locked 1
  2 lock struct(s), heap size 1136, 1 row lock(s)"

I guess it is conceivable that whoever called trx_rsegf_get had already locked &rseg->mutex
InnoDB sometimes calls mutex_enter(&(rseg->mutex));   and sometimes  mutex_enter(&rseg->mutex);   so take note when searching the code.

We'd need to know stack traces of threads to figure out the deadlock scenario.

Even then, it is probably not a bug, but expected behaviour. 

We find so many long running transactions that wait on end-user input, network, some processing etc ....