From: Rick James Date: October 15 2012 11:06pm Subject: RE: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order List-Archive: http://lists.mysql.com/mysql/228400 Message-Id: <2E7DD7ADE53B044C8C8BCD9C5829E1EB148D27C02F@SP2-EX07VS01.ds.corp.yahoo.com> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="_000_2E7DD7ADE53B044C8C8BCD9C5829E1EB148D27C02FSP2EX07VS01ds_" --_000_2E7DD7ADE53B044C8C8BCD9C5829E1EB148D27C02FSP2EX07VS01ds_ Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable I don't fully understand Handler numbers, either. But note the vast differ= ence 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=3D12); 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 st= op with the LIMIT. However, if most of the rows failed the WHERE clause, t= his could be the "wrong" choice. That is, it is hard for the optimizer to get a query like this "right" ever= y time. To see what I mean, flip the inequality in WHERE time <=3D ... around; I t= hink the results will be disappointing. If you had more than a million rows, I would bring up PARTITIONing as a ass= ist to this "2-dimensional" type of problem. From: spameden [mailto:spameden@stripped] Sent: Monday, October 15, 2012 3:23 PM To: Rick James Cc: mysql@stripped Subject: Re: mysql logs query with indexes used to the slow-log and not log= ging 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 t= ime<=3DUNIX_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 t= ime<=3DUNIX_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 num= ber of records returned to process. mysql> select * from send_sms_test FORCE INDEX (priority_time) where time<= =3DUNIX_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<= =3DUNIX_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<=3DUNIX_TIMESTAMP(NOW()) order by p= riority 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<= =3DUNIX_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, ba= sed on the results I've posted ? In which case it works better and how it u= ses the index? About BIGINT(20) and INT(3) I will look further into this later, I understa= nd it might be oversized, but my main question is about index why it's usin= g it so weird. Many thanks for your quick answer! 2012/10/16 Rick James > * Rows =3D 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 efficienc= y. (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 =3D 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 tabl= e 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 det= ailed 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:spameden@stripped] > Sent: Monday, October 15, 2012 1:42 PM > To: mysql@stripped > 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=3DInnoDB AUTO_INCREMENT=3D7806318 DEFAULT CHARSET=3Dutf8 > > 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<=3DUNIX_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<=3DUNIX_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<=3DUNIX_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 --_000_2E7DD7ADE53B044C8C8BCD9C5829E1EB148D27C02FSP2EX07VS01ds_--