Slow query log logs queries that are fast during testing

Gordon Casper

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

Gordon Casper

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.

Collected from the Internet

Please contact [email protected] to delete if infringement.

edited at
0

Comments

0 comments
Login to comment

Related

Mysql slow query log not honoring long_query_time variable, logs really quick queries

Slow query with join - works fast as individual queries

PgAdmin Queries fast but Django orm query very slow

Filter AuroraMysql slow query log file by specific queries

mysql 5.7: Why are 38% of queries missing from the slow query log?

How to print logs during jest tests when I need to mock console.log as part of testing?

MySQL queries on two different indexes fast, but combined into one query slow. Why?

AWS Cloudwatch Log Insights query using Regex does not extract columns for MySql Slow Query Logs

postgresql 9.3 log slow queries

Two fast queries, slow when combined

Query slow in SSRS but fast in SSMS

mysql 5.7 log-slow-queries error

SQL query on large tables fast at first then slow

Slow MySQL query in Laravel, but very fast in phpMyAdmin

Slow query at one DB, but fast at his copy

Extremely slow Postgres query that runs fast in Oracle

SQL Server: Query fast, but slow from procedure

Why slow java app query but fast in PgAdmin?

Elasticsearch first query is slow, rest of them are fast

Query slow in Web App, but fast in command line

why is my first query slow but then it is fast?

Combining two fast indexed queries makes the result slow

2 very fast and simple queries are terribly slow when merged together

Query extremely slow because of sub-queries

Parse IIS logs in Azure Log Analytics' Query

Disabling Log4J logs during maven test phase

Still can't enable the slow query log

Why does not .show queries work in Azure App Insights logs query?

Why is this query slow over certain ranges of data and fast over others?