Search code examples
mysqlperformancemysql-slow-query-log

Slow query log logs queries that are fast during testing


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

Explain of the query


Solution

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