Periodically very slow execution of simplest queries

Question

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;

Answer 1

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 than CALL get_games. One of them is likely to be the villain.

Once you have found it, there may be several actionss to consider...

• Not grabbing the table so forcefully; that is, moving it outside its transaction, or otherwise changing the SQL. (This seems like the likely answer.)
• Not having every user always call get_games.
• Other

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 do COMMIT. That is a hard-to-find bug. I prefer to explicitly say BEGIN as a reminder that I need to place the COMMIT some time really soon. I even insist (for my code) of putting both in the same subroutine.

Simply moving the CALL to before the BEGIN may solve it (unless you are also modifying the table in the transaction).