Inspecting MySQL slow query log I found out that in certain periods of time there are a bunch of queries in log which are supposed to be very fast but were actually very slow.
For example:
# User@Host: ***[***] @ [***]
# Query_time: 14.532574 Lock_time: 0.050162 Rows_sent: 18 Rows_examined: 18
SET timestamp=1483014348;
CALL get_games();
# User@Host: ***[***] @ [***]
# Query_time: 15.287524 Lock_time: 0.008114 Rows_sent: 18 Rows_examined: 18
SET timestamp=1483014348;
CALL get_games();
# User@Host: ***[***] @ [***]
# Query_time: 15.637633 Lock_time: 0.027461 Rows_sent: 18 Rows_examined: 18
SET timestamp=1483014348;
CALL get_games();
# User@Host: ***[***] @ [***]
# Query_time: 15.070246 Lock_time: 0.050137 Rows_sent: 18 Rows_examined: 18
SET timestamp=1483014348;
CALL get_games();
Where procedure get_games is just a simple SELECT from table with 18 rows and normally executes immediately.
MySQL [db_receipt]> show create table game;
MySQL [db_receipt]> CREATE TABLE `game` (
`id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
`product_id` smallint(5) unsigned NOT NULL COMMENT 'Гейтовый идентификатор игры',
`product_name` varchar(64) COLLATE utf8_unicode_ci NOT NULL COMMENT 'Название игры для печати в квитанции',
`arm_url` varchar(32) COLLATE utf8_unicode_ci DEFAULT NULL COMMENT 'Url в АРМ-е',
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=20 DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci;
MySQL [db_receipt]> show create procedure get_games;
+-----------+----------+----------------------------------------------------------------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
| Procedure | sql_mode | Create Procedure | character_set_client | collation_connection | Database Collation |
+-----------+----------+----------------------------------------------------------------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
| get_games | | CREATE DEFINER=`receipt_adm`@`%` PROCEDURE `get_games`()
l_proc: begin
SELECT `product_id`, `product_name` FROM `game`;
end | utf8 | utf8_unicode_ci | utf8_unicode_ci |
+-----------+----------+----------------------------------------------------------------------------------------------------------------------------------------+----------------------+----------------------+----
There are also a lot of other slow simple queries such select a row by primary key etc.
What can cause such a performance degradation? How can I troubleshoot a problem to find a reason?
EDIT: MySQL Server has very good characteristics and normally queries run fast. It's a production server under high load.
EDIT2: Another slow query example (on another database), also very simple:
# Time: 161230 12:13:39
# User@Host: ***[***] @ *** [***]
# Query_time: 4.780936 Lock_time: 0.000069 Rows_sent: 0 Rows_examined: 1
use ***;
SET timestamp=1483089219;
update ShoppingCart set cartStatus='ACQUIRED' where shoppingCartId=23423;
Best Answer
Probably... Some other transaction hit that table in some locking way. And it took 15+ seconds for it to finish. Meanwhile, all of your 'users' were running this SP, but being held up until the lock was released.
If you can catch it when it happens, do
SHOW PROCESSLIST
, and look for the queries other thanCALL get_games
. One of them is likely to be the villain.Once you have found it, there may be several actionss to consider...
SHOW ENGINE INNODB STATUS
is likely to show the villain, also, but you have to run it during or very soon after the problem.I dislike using
autocommit=0
because I might forget to eventually doCOMMIT
. That is a hard-to-find bug. I prefer to explicitly sayBEGIN
as a reminder that I need to place theCOMMIT
some time really soon. I even insist (for my code) of putting both in the same subroutine.Simply moving the
CALL
to before theBEGIN
may solve it (unless you are also modifying the table in the transaction).