MySQL Bugs: #88757: convert trx_search_latch_release_if_reserved to a debug assertion/log message

Bug #88757	convert trx_search_latch_release_if_reserved to a debug assertion/log message
Submitted:	5 Dec 2017 10:43	Modified:	1 Aug 2019 4:58
Reporter:	Shane Bester (Platinum Quality Contributor)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.7.26, 5.7.30	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
We're seeing this occurring in the wild on 5.7.20:

InnoDB: Assertion failure in thread x in file trx0trx.ic line 213
InnoDB: Failing assertion: !trx->has_search_latch

Look at the code for that:

/**
Releases the search latch if trx has reserved it.
@param[in,out] trx		Transaction that may own the AHI latch */
UNIV_INLINE
void
trx_search_latch_release_if_reserved(trx_t* trx)
{
	ut_a(!trx->has_search_latch);
}

How to repeat:
Read the code.

The comments are all wrong whenever this is called.
This function releases nothing!

Secondly, the assertion is not needed as far as I can tell, 
and it only caused unnecessary downtime on customer's production.

Suggested fix:
Make it a debug assertion instead, like:
ut_ad(!trx->has_search_latch);

Add a message to the error log with detailed info (like print out the trx)
so the underlying bug can one day still be solved.

Also heavily affected by this one (currently around 2 to 3 crashes a day), however, not able to fully reproduce: Seems to happen around the same few queries which sometimes also generate a deadlock that's normally handled, but every now and then (potentially timing related) it results in this crash:

InnoDB: Assertion failure in thread ... in file trx0trx.ic line 213

We're running 5.7.22 (package on Ubuntu 16.04). I'll add the crash log here, but I agree with Shane Bester that instead of trying to fix the source of the bug right away, a less drastic reaction and helpful log output might be the fastest strategy here. I see that the NOP-function trx_search_latch_release_if_reserved() is called from quite a few other places as well...

InnoDB: Failing assertion: !trx->has_search_latch
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/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
09:41:19 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=1073741824
read_buffer_size=4194304
max_used_connections=153
max_threads=301
thread_count=68
connection_count=68
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3518393 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fb92851b650
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 = 7fb9e8784e70 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xe907ab]
/usr/sbin/mysqld(handle_fatal_signal+0x489)[0x789b49]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fbc6e36f390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7fbc6d728428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fbc6d72a02a]
/usr/sbin/mysqld[0x75f3e0]
/usr/sbin/mysqld[0xf95e18]
/usr/sbin/mysqld(_ZN11ha_innobase8end_stmtEv+0x64)[0xf86294]
/usr/sbin/mysqld(_Z18close_thread_tableP3THDPP5TABLE+0x2b1)[0xbf0ad1]
/usr/sbin/mysqld(_Z19close_thread_tablesP3THD+0x31b)[0xbf11bb]
/usr/sbin/mysqld(_ZN18Prepared_statement7prepareEPKcm+0x724)[0xc7d854]
/usr/sbin/mysqld(_Z19mysqld_stmt_prepareP3THDPKcj+0xf0)[0xc7e9b0]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x1886)[0xc544d6]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1c7)[0xc55137]
/usr/sbin/mysqld(handle_connection+0x288)[0xd16788]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0xec9294]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fbc6e3656ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fbc6d7fa41d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fb9285d9cc0): is an invalid pointer
Connection ID (thread ID): 1274017
Status: NOT_KILLED

this needs rechecking once fix is pushed:

Bug 27325898 - INNODB: ASSERTION FAILURE IN THREAD 139686919030528 IN FILE TRX0TRX.IC LINE 213

We are also being affected by this issue. We are running MySQL through AWS RDS, and their support team is directing us to this issue saying there is nothing they can do. Running version 5.7.21.

Everybody hitting this bug needs to wait for
Fixed as of the upcoming 5.7.24, 8.0.13 release, and here's the changelog
entry:

We just experienced a crash related to this issue over the weekend. Error log attached. We are on 5.7.21.

assertion failure crash error log

Attachment: mysql-bug-assertionFailure.txt (text/plain), 13.91 KiB.

Having The Same Issue in Version 5.7.23.

Anybody hitting this assertion needs to upgrade to 5.7.24+ or 8.0.13+

https://dev.mysql.com/doc/relnotes/mysql/5.7/en/news-5-7-24.html

---
InnoDB: In a function called before the execution of a statement in a stored procedure, a read and write operation on trx->lock.start_stmt was not protected by a mutex. (Bug #27325898)
---

closing as duplicate of the underlying bug that was fixed as noted above.

We are still seeing this issue with 5.7.25:

2019-06-18 10:15:32 0x7f009c321700  InnoDB: Assertion failure in thread 139640597255936 in file trx0trx.ic line 213
InnoDB: Failing assertion: !trx->has_search_latch
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/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
10:15:32 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=1073741824
read_buffer_size=4194304
max_used_connections=239
max_threads=301
thread_count=70
connection_count=70
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3518396 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f00947c4be0
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 = 7f009c320e70 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xe94a9b]
/usr/sbin/mysqld(handle_fatal_signal+0x489)[0x78a9c9]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f0320747390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f031fb00428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f031fb0202a]
/usr/sbin/mysqld[0x760280]
/usr/sbin/mysqld(_Z21innobase_rename_tableP3THDP5trx_tPKcS4_+0x0)[0xed0e50]
/usr/sbin/mysqld(_ZN11ha_innobase8end_stmtEv+0xf7)[0xec1897]
/usr/sbin/mysqld(_Z18close_thread_tableP3THDPP5TABLE+0x2b1)[0xbf1db1]
/usr/sbin/mysqld(_Z19close_thread_tablesP3THD+0x31b)[0xbf249b]
/usr/sbin/mysqld(_ZN18Prepared_statement7prepareEPKcm+0x724)[0xc7f3d4]
/usr/sbin/mysqld(_Z19mysqld_stmt_prepareP3THDPKcj+0xf0)[0xc80530]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x190c)[0xc55e9c]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1c7)[0xc56a77]
/usr/sbin/mysqld(handle_connection+0x290)[0xd18fc0]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x11fd844]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f032073d6ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f031fbd241d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f0094169498): is an invalid pointer
Connection ID (thread ID): 8446430
Status: NOT_KILLED

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.

https://bugs.mysql.com/bug.php?id=96384

I think the fix for 
Bug 30594501 - QUERY STALLS IN "QUERY END" STATUS FOR LONG TIME

might also solve this too.  Have no evidence for it,  just a suspicion.

also seen this on 5.7.30 when using prepared statements

This assertion has been seen again on 5.7.31.   However,  Bug 30594501 is fixed in 5.7.32, so it might be possible solution to wait for that.  We'll have to see, as it is very hard to repeat.