List:General Discussion« Previous MessageNext Message »
From:spameden Date:October 15 2012 11:15pm
Subject:Re: mysql logs query with indexes used to the slow-log and not
logging if there is index in reverse order
View as plain text  
Thanks a lot for all your comments!

I did disable Query cache before testing with

set query_cache_type=OFF

for the current session.

I will report this to the MySQL bugs site later.



2012/10/16 Rick James <rjames@stripped>

> **Ø  **My initial question was why MySQL logs it in the slow log if the
> query uses an INDEX?
>
> ****
>
> That _may_ be worth a bug report.****
>
> ** **
>
> A _possible_ answer...  EXPLAIN presents what the optimizer is in the mood
> for at that moment.  It does not necessarily reflect what it was in the
> mood for when it ran the query.****
>
> ** **
>
> When timing things, run them twice (and be sure not to hit the Query
> cache).  The first time freshens the cache (buffer_pool, etc); the second
> time gives you a 'reproducible' time.  I believe (without proof) that the
> cache contents can affect the optimizer's choice.****
>
> ** **
>
> *From:* spameden [mailto:spameden@stripped]
> *Sent:* Monday, October 15, 2012 3:29 PM
>
> *To:* Rick James
> *Cc:* mysql@stripped
> *Subject:* Re: mysql logs query with indexes used to the slow-log and not
> logging if there is index in reverse order****
>
> ** **
>
> 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 <spameden@stripped>****
>
> 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 <rjames@stripped>****
>
> * 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: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=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****
>
> ** **
>
> ** **
>

Thread
mysql logs query with indexes used to the slow-log and not logging ifthere is index in reverse orderspameden15 Oct
  • Re: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderspameden15 Oct
  • RE: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderRick James15 Oct
    • Re: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderspameden15 Oct
      • Re: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderspameden15 Oct
        • RE: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderRick James15 Oct
          • Re: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderspameden15 Oct
            • Re: mysql logs query with indexes used to the slow-log and not loggingif there is index in reverse orderShawn Green16 Oct
              • Re: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderspameden16 Oct
                • Re: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderMichael Dykman16 Oct
                  • Re: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderspameden16 Oct
                  • Re: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderhsv16 Oct
                    • Re: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderspameden16 Oct
      • RE: mysql logs query with indexes used to the slow-log and notlogging if there is index in reverse orderRick James15 Oct