Slow query log logs queries that are fast during testing

Question

My slow query log is full of queries with following query time and rows examined:

# Query_time: 26.370100  Lock_time: 0.000213  Rows_sent: 0  Rows_examined: 30976475

If I copy and paste the exact query from the log into phpmyadmin and run it, result comes instantly, even trying EXPLAIN upon that query reveals no flaws in indexes or bad structure.

As far as I can tell, for some reason a small fraction of queries fail to use indexes and trying to reproduce that event is next to impossible during testing.

How should I prevent these occasional slow queries which in vast majority of cases work as intended?

--- EDIT #1 ---

My create tables are:

CREATE TABLE msgs (
  id bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  sender text NOT NULL,
  receiver text NOT NULL,
  cont blob NOT NULL,
  img text NOT NULL,
  orient text NOT NULL,
  d_t datetime NOT NULL,
  convo text NOT NULL,
  u_code text NOT NULL,
  viewed datetime NOT NULL,
  stat int(11) NOT NULL,
  device text NOT NULL,
  addr text NOT NULL,
  PRIMARY KEY (id),
  KEY msg_u_code (`u_code`(24)),
  KEY receiver (`receiver`(24)),
  KEY sender (`sender`(24)),
  KEY img (`img`(28)),
  KEY convo (`convo`(49))
) ENGINE=InnoDB  DEFAULT CHARSET=utf8;

CREATE TABLE usrs (
  id bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  usr_name text NOT NULL,
  img text NOT NULL,
  orient text NOT NULL,
  `password` text NOT NULL,
  u_code text NOT NULL,
  d_t datetime NOT NULL,
  stat int(11) NOT NULL,
  device text NOT NULL,
  addr text NOT NULL,
  PRIMARY KEY (id),
  KEY img (`img`(28)),
  KEY usr_code (`u_code`(24))
) ENGINE=InnoDB  DEFAULT CHARSET=utf8;

And my slow query log entry is:

 # Time: 171115  6:26:37
 # User@Host: xxx[xxx] @ localhost []
 # Thread_id: 25524888  Schema: xxx  QC_hit: No
 # Query_time: 32.423430  Lock_time: 0.000425  Rows_sent: 1  Rows_examined: 30998008
 # Rows_affected: 0
 use xxx;
 SET timestamp=1510723597;
 select msg_cont, msg_u_code, msg_d_t, msg_viewed, usr_u_code, usr_name from
        (select
            msgs.id as msg_id,
            msgs.cont as msg_cont,
            msgs.u_code as msg_u_code,
            msgs.d_t as msg_d_t,
            msgs.viewed as msg_viewed,
            usrs.u_code as usr_u_code,
            usrs.usr_name as usr_name
            from msgs
            left join usrs on msgs.sender = usrs.u_code
    where  msgs.convo = 'aaaaaaaaaabfbaghdgcigfid_aaaaaaaaaabeiaccjfhjfach'
      and  (msgs.sender = 'aaaaaaaaaabfbaghdgcigfid'
              or  msgs.receiver = 'aaaaaaaaaabfbaghdgcigfid'
           )
      and  msgs.stat = '1'
      and  usrs.stat = '1'
      and  usrs.u_code not in('aaaaaaaaaabfaagfbgggiejh',
                              'aaaaaaaaaabfabgbjdfjigbd',
                ...... !!!!![here go 400 more usr_u_codes]!!!!!
                          )
      and  msgs.id > 30997997
        ) a order by msg_id asc;

Caution, this query shall contain on average 400 elements in the not in function.

--- EDIT #2 ---

looks like is a hardware issue. At the moment you run the query the system was running other queries and couldnt handle the new request. Either for busy disk or low memory. — Juan Carlos Oropeza, Nov 14 '17 at 13:58

score 1 · Accepted Answer · answered Nov 16 '17 at 08:53

While I am unable to explain why MySQL occasionally decided not to use index on a very obvious and very common query, the solution was to simply force the index.

In my particular case:

select msg_cont, msg_u_code, msg_d_t, msg_viewed, usr_u_code, usr_name from
        (select
            msgs.id as msg_id,
            msgs.cont as msg_cont,
            msgs.u_code as msg_u_code,
            msgs.d_t as msg_d_t,
            msgs.viewed as msg_viewed,
            usrs.u_code as usr_u_code,
            usrs.usr_name as usr_name
            from msgs FORCE INDEX (convo)
            left join usrs FORCE INDEX (u_code) on msgs.sender = usrs.u_code
    where  msgs.convo = 'aaaaaaaaaabfbaghdgcigfid_aaaaaaaaaabeiaccjfhjfach'
      and  (msgs.sender = 'aaaaaaaaaabfbaghdgcigfid'
              or  msgs.receiver = 'aaaaaaaaaabfbaghdgcigfid'
           )
      and  msgs.stat = '1'
      and  usrs.stat = '1'
      and  usrs.u_code not in('aaaaaaaaaabfaagfbgggiejh',
                              'aaaaaaaaaabfabgbjdfjigbd',
                ...... !!!!![here go 400 more usr_u_codes]!!!!!
                          )
      and  msgs.id > 30997997
        ) a order by msg_id asc;

Slow query log proved this solution to be effective as no new slow entries emerge.

Rick James · Answer 2 · 2017-11-15T18:08:25.973

0

You probably have the "Query cache" turned on. It captures queries and their resultsets. When you run exactly the same query again, it simply echos the saved resultset, instead of re-evaluating it.

The QC can be avoided by adding as little as a single space in the statement, or by saying SELECT SQL_NO_CACHE ....

To further discuss why the query needs to look at 31M rows, let's see the query and SHOW CREATE TABLE.

After seing query

I want to start by focusing on ON msgs.sender = usrs.u_code and the "prefix" indexes.

Based on the sample values, it seems that sender, u_code and several other columns might always be under some small length? If this is true, then

Change from TEXT to VARCHAR(nn) where nn is some realistic limit;
Get rid of the prefixing (eg: KEY sender (sender(24)) --> KEY (sender).

These changes should make the JOIN much more efficient, thereby improving performance. If that is not adequate, come back for more advice.

edited Nov 15 '17 at 18:08

answered Nov 14 '17 at 14:07

Rick James

135,179
13
127
222

Thank you for your suggestion. This would be true if the table was not constantly INSERTed to and UPDATEd. The 31M row table gets several INSERTs, UPDATEs as well as slightly variable SELECTs per second. Hence cache can be ruled out as the issue here. Also only very few queries behave in this wrong manner. If all queries of this type behaved like this, it would crash the server within 1 minute. – John Doe Nov 14 '17 at 15:40
@ahojvole Please share your query, SHOW CREATE TABLE table_name and SHOW INDEX FROM table_name. – Wilson Hauck Nov 14 '17 at 22:01
@ahojvole - How many per second? And, let's see some examples of the ones that are much slower. – Rick James Nov 14 '17 at 22:44
@WilsonHauck Create table with indexes and slow log entry added. – John Doe Nov 15 '17 at 10:47
@RickJames rough estimate is 10 queries per second average during entire day. Peaking at 100 queries per second during highest traffic. Example added. – John Doe Nov 15 '17 at 10:49
@RickJames thank you for the pointers, I shall look into performance as well. Anyway the problem may or may not be solved with enhanced performance since majority of queries do use indexes properly while a small fraction of the same queries do not. Why is this happening is the real issue? – John Doe Nov 15 '17 at 18:26
30M rows "examined". Possibly because the `JOIN` could not be done with an index -- hence my Answer. Please provide `EXPLAIN SELECT ...` to confirm it. – Rick James Nov 15 '17 at 18:40
Also,... There is no need for the outer `SELECT`. Remove it and `msgs.id as msg_id,`. – Rick James Nov 15 '17 at 18:42
@RickJames explain added – John Doe Nov 15 '17 at 21:54
@RickJames could the issue be the lack of limit? My slow query log does not contain any queries that have limit set. – John Doe Nov 15 '17 at 22:24
What is the value of `long_query_time`? It defaults to 10 seconds; recommend 2. The presence or absence of `LIMIT` does not matter. – Rick James Nov 16 '17 at 02:54
Alas, the `EXPLAIN` did not shed any light. I am guessing that the prefix indexes are the villains. – Rick James Nov 16 '17 at 03:10
@RickJames please see my solution, it turns out forcing the index does the trick. Thank you for help. – John Doe Nov 16 '17 at 08:57

Slow query log logs queries that are fast during testing

2 Answers2