I don't fully understand Handler numbers, either. But note the vast difference in Handler_read_next, as if the second test had to read (sequentially scan) a lot more stuff (in the index or the data).
Summary: INDEX(time, priority) -- slower; bigger Handler numbers; shorter key_len; filesort INDEX(priority, time) -- faster; smaller; seems to use both keys of the index (key_len=12); avoids filesort (because INDEX(priority, ...) agrees with ORDER BY priority). The Optimizer has (at some level) two choices: * Start with the WHERE * Start with the ORDER BY Since the ORDER BY matches one of the indexes, it can avoid the sort and stop with the LIMIT. However, if most of the rows failed the WHERE clause, this could be the "wrong" choice. That is, it is hard for the optimizer to get a query like this "right" every time. To see what I mean, flip the inequality in WHERE time <= ... around; I think the results will be disappointing. If you had more than a million rows, I would bring up PARTITIONing as a assist to this "2-dimensional" type of problem. From: spameden [mailto:spame...@gmail.com] Sent: Monday, October 15, 2012 3:23 PM To: Rick James Cc: mysql@lists.mysql.com Subject: Re: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order 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<mailto: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<mailto:spame...@gmail.com>] > Sent: Monday, October 15, 2012 1:42 PM > To: mysql@lists.mysql.com<mailto: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
