0

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;

bumped to the homepage by Community 2 days ago

This question has answers that may be good or bad; the system has marked it active so that they can be reviewed.

  • Is the server running on a mobile phone from 2002? All kidding aside, there are a lot of possible reasons. Have you checked anything? – Max Vernon Jan 13 '17 at 13:33
  • It's a production server with very good characteristics but last weeks we see some anomaly. Normally this queries run very fast (as it should) but from time to time you see this... I am developer and I don't have direct access to production server to make some performance check or troubleshooting but I am very interesting what can most likely cause this. – Pustovalov Dmitry Jan 13 '17 at 13:35
  • Do you use BEGIN...COMMIT and other statements around this CALL? What does SHOW ENGINE INNODB STATUS; say when it happens? I see that the timestamp is identical; how many copies were running at the same time? – Rick James Jan 13 '17 at 19:28
  • It runs with autocommit off with READ COMMITED transaction isolation level. SHOW ENGINE INNODB STATUS shows nothing special. Actually this query is just a one example, I am pretty sure problem is not in this query, I just show it to give an example that most slow queries are very simple. – Pustovalov Dmitry Jan 13 '17 at 19:32
0

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).

  • Query_time: 14.532574 Lock_time: 0.050162 As far as I understand: Lock_time - time that query wait to execute because of other query, it's pretty small here actually I don't understand why it is > 0 because it should be consistent non-locking read so nothing to wait here... And query_time is actual query time and I think problem is here. – Pustovalov Dmitry Jan 13 '17 at 19:42
  • I don't think Lock_time takes transaction locks into account. – Rick James Jan 13 '17 at 19:44
  • Query_time is elapsed time, including all kinds of delays. – Rick James Jan 13 '17 at 19:45
  • According to this: stackoverflow.com/questions/19036176/… Lock time is the time spend before the query starts executing. I.e., time waiting for other threads to give up their locks on the data the current query needs to lock. – Pustovalov Dmitry Jan 13 '17 at 19:47
  • How can I forcefully grab table lock if I just make consistent non-locking read? – Pustovalov Dmitry Jan 13 '17 at 19:51

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.