List:General Discussion« Previous MessageNext Message »
From:Rick James Date:October 15 2012 11:11pm
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  
Ø  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<mailto: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<mailto: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<mailto:spameden@stripped>]
> Sent: Monday, October 15, 2012 1:42 PM
> To: mysql@stripped<mailto: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