Sorry, forgot to say: mysql> show variables like 'long_query_time%'; +-----------------+-----------+ | Variable_name | Value | +-----------------+-----------+ | long_query_time | 10.000000 | +-----------------+-----------+ 1 row in set (0.00 sec)
It's getting in the log only due: mysql> show variables like '%indexes%'; +-------------------------------+-------+ | Variable_name | Value | +-------------------------------+-------+ | log_queries_not_using_indexes | ON | +-------------------------------+-------+ 1 row in set (0.00 sec) If I turn it off - it's all fine My initial question was why MySQL logs it in the slow log if the query uses an INDEX? And why it's not logging if I create an INDEX (time, priority) (but in the query there is FORCE INDEX (priority,time) specified, so MySQL shouldn't use newly created INDEX (time, priority) at all). 2012/10/16 spameden <spame...@gmail.com> > Sorry, my previous e-mail was a test on MySQL-5.5.28 on an empty table. > > Here is the MySQL-5.1 Percona testing table: > > mysql> select count(*) from send_sms_test; > +----------+ > | count(*) | > +----------+ > | 143879 | > +----------+ > 1 row in set (0.03 sec) > > Without LIMIT: > mysql> desc select * from send_sms_test FORCE INDEX (time_priority) where > time<=UNIX_TIMESTAMP(NOW()) order by priority; > > +----+-------------+---------------+-------+---------------+---------------+---------+------+-------+-----------------------------+ > > | id | select_type | table | type | possible_keys | key > | key_len | ref | rows | Extra | > > +----+-------------+---------------+-------+---------------+---------------+---------+------+-------+-----------------------------+ > | 1 | SIMPLE | send_sms_test | range | time_priority | time_priority > | 8 | NULL | 73920 | Using where; Using filesort | > > +----+-------------+---------------+-------+---------------+---------------+---------+------+-------+-----------------------------+ > 1 row in set (0.00 sec) > > mysql> desc select * from send_sms_test FORCE INDEX (priority_time) where > time<=UNIX_TIMESTAMP(NOW()) order by priority; > > +----+-------------+---------------+-------+---------------+---------------+---------+------+--------+-------------+ > > | id | select_type | table | type | possible_keys | key > | key_len | ref | rows | Extra | > > +----+-------------+---------------+-------+---------------+---------------+---------+------+--------+-------------+ > | 1 | SIMPLE | send_sms_test | index | NULL | priority_time > | 12 | NULL | 147840 | Using where | > > +----+-------------+---------------+-------+---------------+---------------+---------+------+--------+-------------+ > > 1 row in set (0.00 sec) > > But I actually need to use LIMIT, because client uses this to limit the > number of records returned to process. > > mysql> select * from send_sms_test FORCE INDEX (priority_time) where > time<=UNIX_TIMESTAMP(NOW()) order by priority LIMIT 0,100; > 100 rows in set (0.00 sec) > > mysql> show profile; > +--------------------+----------+ > | Status | Duration | > +--------------------+----------+ > | starting | 0.000053 | > | Opening tables | 0.000009 | > | System lock | 0.000005 | > | Table lock | 0.000004 | > | init | 0.000037 | > | optimizing | 0.000005 | > | statistics | 0.000007 | > | preparing | 0.000005 | > | executing | 0.000001 | > | Sorting result | 0.000003 | > | Sending data | 0.000856 | > | end | 0.000003 | > | query end | 0.000001 | > | freeing items | 0.000015 | > | logging slow query | 0.000001 | > | logging slow query | 0.000047 | > | cleaning up | 0.000002 | > +--------------------+----------+ > 17 rows in set (0.00 sec) > > mysql> select * from send_sms_test FORCE INDEX (time_priority) where > time<=UNIX_TIMESTAMP(NOW()) order by priority LIMIT 0,100; > 100 rows in set (0.08 sec) > mysql> show profile; > +--------------------+----------+ > | Status | Duration | > +--------------------+----------+ > | starting | 0.000048 | > | Opening tables | 0.000009 | > | System lock | 0.000002 | > | Table lock | 0.000004 | > | init | 0.000047 | > | optimizing | 0.000006 | > | statistics | 0.000043 | > | preparing | 0.000018 | > | executing | 0.000001 | > | Sorting result | 0.076725 | > | Sending data | 0.001406 | > | end | 0.000003 | > | query end | 0.000001 | > | freeing items | 0.000012 | > | logging slow query | 0.000001 | > | cleaning up | 0.000002 | > +--------------------+----------+ > 16 rows in set (0.00 sec) > > As you can see latter query takes more time, because it's using filesort > as well. > > Now, handler: > mysql> SHOW SESSION STATUS LIKE 'Handler_read%';select * from > send_sms_test FORCE INDEX (priority_time) where time<=UNIX_TIMESTAMP(NOW()) > order by priority LIMIT 0,100;SHOW SESSION STATUS LIKE 'Handler_read%'; > +-----------------------+--------+ > | Variable_name | Value | > +-----------------------+--------+ > | Handler_read_first | 18 | > | Handler_read_key | 244 | > | Handler_read_next | 719969 | > | Handler_read_prev | 0 | > | Handler_read_rnd | 226 | > | Handler_read_rnd_next | 223 | > +-----------------------+--------+ > 6 rows in set (0.00 sec) > .... 100 rows in set (0.00 sec) > +-----------------------+--------+ > | Variable_name | Value | > +-----------------------+--------+ > | Handler_read_first | 19 | > | Handler_read_key | 245 | > | Handler_read_next | 720068 | > | Handler_read_prev | 0 | > | Handler_read_rnd | 226 | > | Handler_read_rnd_next | 223 | > +-----------------------+--------+ > 6 rows in set (0.00 sec) > > > mysql> SHOW SESSION STATUS LIKE 'Handler_read%'; > +-----------------------+--------+ > | Variable_name | Value | > +-----------------------+--------+ > | Handler_read_first | 17 | > | Handler_read_key | 143 | > | Handler_read_next | 576090 | > | Handler_read_prev | 0 | > | Handler_read_rnd | 126 | > | Handler_read_rnd_next | 223 | > +-----------------------+--------+ > 6 rows in set (0.00 sec) > > mysql> select * from send_sms_test FORCE INDEX (time_priority) where > time<=UNIX_TIMESTAMP(NOW()) order by priority LIMIT 0,100; > 100 rows in set (0.09 sec) > > mysql> SHOW SESSION STATUS LIKE 'Handler_read%'; > +-----------------------+--------+ > | Variable_name | Value | > +-----------------------+--------+ > | Handler_read_first | 18 | > | Handler_read_key | 244 | > | Handler_read_next | 719969 | > | Handler_read_prev | 0 | > | Handler_read_rnd | 226 | > | Handler_read_rnd_next | 223 | > +-----------------------+--------+ > 6 rows in set (0.00 sec) > > I don't understand much in Handler thing, could you please explain more, > based on the results I've posted ? In which case it works better and how it > uses the index? > > About BIGINT(20) and INT(3) I will look further into this later, I > understand it might be oversized, but my main question is about index why > it's using it so weird. > > Many thanks for your quick answer! > > 2012/10/16 Rick James <rja...@yahoo-inc.com> > >> * Rows = 11 / 22 -- don't take the numbers too seriously; they are crude >> approximations based on estimated cardinality. >> >> * The 11 comes from the LIMIT -- therefore useless in judging the >> efficiency. (The 22 may be 2*11; I don't know.) >> >> * Run the EXPLAINs without LIMIT -- that will avoid the bogus 11/22. >> >> * If the CREATE INDEX took only 0.67 sec, I surmise that you have very >> few rows in the table?? So this discussion is not necessarily valid in >> general cases. >> >> * What percentage of time values meet the WHERE? This has a big impact >> on the choice of explain plan and performance. >> >> * Set long_query_time = 0; to get it in the slowlog even if it is fast. >> Then look at the various extra values (such as filesort, on disk, temp >> table used, etc). >> >> * Do this (with each index): >> SHOW SESSION STATUS LIKE 'Handler_read%'; >> SELECT ... FORCE INDEX(...) ...; >> SHOW SESSION STATUS LIKE 'Handler_read%'; >> Then take the diffs of the handler counts. This will give you a pretty >> detailed idea of what is going on; better than the SlowLog. >> >> * INT(3) is not a 3-digit integer, it is a full 32-bit integer (4 bytes). >> Perhaps you should have SMALLINT UNSIGNED (2 bytes). >> >> * BIGINT takes 8 bytes -- usually over-sized. >> >> >> > -----Original Message----- >> > From: spameden [mailto:spame...@gmail.com] >> > Sent: Monday, October 15, 2012 1:42 PM >> > To: mysql@lists.mysql.com >> > Subject: mysql logs query with indexes used to the slow-log and not >> > logging if there is index in reverse order >> > >> > Hi, list. >> > >> > Sorry for the long subject, but I'm really interested in solving this >> > and need a help: >> > >> > I've got a table: >> > >> > mysql> show create table send_sms_test; >> > +---------------+------------------------------------------------------ >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > -------------------------------+ >> > | Table | Create >> > Table >> > | >> > +---------------+------------------------------------------------------ >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > ----------------------------------------------------------------------- >> > -------------------------------+ >> > | send_sms_test | CREATE TABLE `send_sms_test` ( >> > `sql_id` bigint(20) NOT NULL AUTO_INCREMENT, >> > `momt` enum('MO','MT') DEFAULT NULL, >> > `sender` varchar(20) DEFAULT NULL, >> > `receiver` varchar(20) DEFAULT NULL, >> > `udhdata` blob, >> > `msgdata` text, >> > `time` bigint(20) NOT NULL, >> > `smsc_id` varchar(255) DEFAULT 'main', >> > `service` varchar(255) DEFAULT NULL, >> > `account` varchar(255) DEFAULT NULL, >> > `id` bigint(20) DEFAULT NULL, >> > `sms_type` tinyint(1) DEFAULT '2', >> > `mclass` bigint(20) DEFAULT NULL, >> > `mwi` bigint(20) DEFAULT NULL, >> > `coding` bigint(20) DEFAULT NULL, >> > `compress` bigint(20) DEFAULT NULL, >> > `validity` bigint(20) DEFAULT NULL, >> > `deferred` bigint(20) DEFAULT NULL, >> > `dlr_mask` bigint(20) DEFAULT NULL, >> > `dlr_url` varchar(255) DEFAULT NULL, >> > `pid` bigint(20) DEFAULT NULL, >> > `alt_dcs` bigint(20) DEFAULT NULL, >> > `rpi` bigint(20) DEFAULT NULL, >> > `charset` varchar(255) DEFAULT NULL, >> > `boxc_id` varchar(255) DEFAULT NULL, >> > `binfo` varchar(255) DEFAULT NULL, >> > `meta_data` text, >> > `task_id` bigint(20) DEFAULT NULL, >> > `msgid` bigint(20) DEFAULT NULL, >> > `priority` int(3) unsigned NOT NULL DEFAULT '500', >> > PRIMARY KEY (`sql_id`), >> > KEY `task_id` (`task_id`), >> > KEY `receiver` (`receiver`), >> > KEY `msgid` (`msgid`), >> > KEY `priority_time` (`priority`,`time`) >> > ) ENGINE=InnoDB AUTO_INCREMENT=7806318 DEFAULT CHARSET=utf8 >> > >> > Slow-queries turned on with an option: >> > | log_queries_not_using_indexes | ON | >> > >> > mysqld --version >> > mysqld Ver 5.1.65-rel14.0 for debian-linux-gnu on x86_64 ((Percona >> > Server (GPL), 14.0, Revision 475)) >> > >> > If I check with EXPLAIN MySQL says it would use the index: >> > mysql> *desc select * from send_sms_test where >> > mysql> time<=UNIX_TIMESTAMP(NOW()) >> > order by priority limit 0,11;* >> > +----+-------------+---------------+-------+---------------+----------- >> > ----+---------+------+------+-------------+ >> > | id | select_type | table | type | possible_keys | key >> > | key_len | ref | rows | Extra | >> > +----+-------------+---------------+-------+---------------+----------- >> > ----+---------+------+------+-------------+ >> > | 1 | SIMPLE | send_sms_test | index | NULL | >> > priority_time >> > | 12 | NULL | * 11* | Using where | >> > +----+-------------+---------------+-------+---------------+----------- >> > ----+---------+------+------+-------------+ >> > 1 row in set (0.00 sec) >> > >> > But If I issue the query I see in the mysql-slow.log: >> > select * from send_sms_test where time<=UNIX_TIMESTAMP(NOW()) order by >> > priority limit 0,11; >> > >> > If I do create INDEX time,priority (in reverse order instead of >> > priority,time) I get still the same usage of priority_time key with the >> > same length, but rows now are doubled): >> > mysql> *create index time_priority ON send_sms_test (time,priority);* >> > Query OK, 0 rows affected (0.67 sec) >> > Records: 0 Duplicates: 0 Warnings: 0 >> > >> > mysql> *desc select * from send_sms_test where >> > mysql> time<=UNIX_TIMESTAMP(NOW()) >> > order by priority limit 0,11;* >> > +----+-------------+---------------+-------+---------------+----------- >> > ----+---------+------+------+-------------+ >> > | id | select_type | table | type | possible_keys | key >> > | key_len | ref | rows | Extra | >> > +----+-------------+---------------+-------+---------------+----------- >> > ----+---------+------+------+-------------+ >> > | 1 | SIMPLE | send_sms_test | index | time_priority | >> > priority_time >> > | 12 | NULL | *22* | Using where | >> > +----+-------------+---------------+-------+---------------+----------- >> > ----+---------+------+------+-------------+ >> > >> > And if both indexes created I do not have anymore this query in the >> > slow-log. >> > >> > Of course If I disable log_queries_not_using_indexes I get none of the >> > queries. >> > >> > So is it a bug inside Percona's implementation or it's generally MySQL >> > behavior? >> > >> > Thanks >> > >
