| 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: | |
| 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: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.
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; }