Bug #73988 find_all_keys spams server error log with deadlock/lock wait errors
Submitted: 20 Sep 2014 20:26 Modified: 30 Oct 2014 18:11
Reporter: Shane Bester (Platinum Quality Contributor) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: DML Severity:S3 (Non-critical)
Version:5.7.6 OS:Any
Assigned to: CPU Architecture:Any
Tags: deadlock, lock wait timeout, SPAM

[20 Sep 2014 20:26] Shane Bester
Description:
The server error log gets littered with client-side error messages:

Deadlock found when trying to get lock; try restarting transaction
Deadlock found when trying to get lock; try restarting transaction

The issues are:

o) It is incorrect to log this to the server error log.

o) It is logged as [ERROR].  A deadlock or lock wait timeout is NOT an error, but a normal occurrence in a transactional database.

o) Why doesn't --log-error-verbosity work to disable this?

How to repeat:
make deadlocks, watch error log.

Suggested fix:
=== modified file 'sql/filesort.cc'
--- sql/filesort.cc     2014-09-04 11:03:17 +0000
+++ sql/filesort.cc     2014-09-20 20:20:06 +0000
@@ -927,7 +927,8 @@
   DBUG_PRINT("test",("error: %d  indexpos: %d",error,indexpos));
   if (error != HA_ERR_END_OF_FILE)
   {
-    file->print_error(error,MYF(ME_ERROR | ME_WAITTANG)); // purecov: inspected
+    if (error != HA_ERR_LOCK_DEADLOCK && error != HA_ERR_LOCK_WAIT_TIMEOUT)
+      file->print_error(error,MYF(ME_ERROR | ME_WAITTANG)); // purecov: inspected
     num_records= HA_POS_ERROR;                            // purecov: inspected
     goto cleanup;
   }
[20 Sep 2014 20:37] MySQL Verification Team
For reference, the call stack that wrote to error log was:

8	mysqld.exe	_write_nolock
9	mysqld.exe	_write + 0x8f, .\lowio\write.c(72)
10	mysqld.exe	_flsbuf + 0x167, .\stdio\_flsbuf.c(186)
11	mysqld.exe	write_char + 0x35, .\stdio\output.c(2425)
12	mysqld.exe	write_string + 0x55, .\stdio\output.c(2568)
13	mysqld.exe	_output_l + 0x788, .\stdio\output.c(2247)
14	mysqld.exe	fprintf + 0x107, .\stdio\fprintf.c(69)
15	mysqld.exe	print_buffer_to_file + 0x106, .\sql\log.cc(1875)
16	mysqld.exe	error_log_print + 0x49, .\sql\log.cc(1893)
17	mysqld.exe	sql_print_error + 0x27, .\sql\log.cc(1916)
18	mysqld.exe	my_message_sql + 0x8e, .\sql\mysqld.cc(2311)
19	mysqld.exe	my_error + 0x8b, .\mysys\my_error.c(206)
20	mysqld.exe	handler::print_error + 0x572, .\sql\handler.cc(3888)
21	mysqld.exe	find_all_keys + 0x492, .\sql\filesort.cc(930)
22	mysqld.exe	filesort + 0x4ef, .\sql\filesort.cc(375)
23	mysqld.exe	mysql_update + 0xaeb, .\sql\sql_update.cc(617)
24	mysqld.exe	mysql_execute_command + 0x1646, .\sql\sql_parse.cc(3160)
25	mysqld.exe	mysql_parse + 0x22c, .\sql\sql_parse.cc(5399)
26	mysqld.exe	dispatch_command + 0x707, .\sql\sql_parse.cc(1250)
27	mysqld.exe	do_command + 0x13e, .\sql\sql_parse.cc(840)
28	mysqld.exe	handle_connection + 0x114, .\sql\conn_handler\connection_handler_per_thread.cc(297)
29	mysqld.exe	pfs_spawn_thread + 0xf3, .\storage\perfschema\pfs.cc(2137)
30	mysqld.exe	pthread_start + 0x1b, .\mysys\my_winthread.c(72)
[30 Oct 2014 18:11] Paul Dubois
Noted in 5.7.6 changelog.

The server incorrectly wrote client-side error messages to the error
log: Deadlock found when trying to get lock; try restarting
transaction.