Re: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
On 10/15/2012 7:15 PM, spameden wrote: 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. First. What are all of your logging settings? SHOW GLOBAL VARIABLES LIKE '%log%'; Next. When you physically look in the slow query log, how long does it say that it took this command to execute? And last, before you can ask MySQL to fix a bug, you must first ensure it's a MySQL bug. Please try to reproduce your results using official binaries, not those constructed by a third party. If the problem exists in our packages, do tell us about it. If the problem is not reproducible using official MySQL products, then please report it to the appropriate channel for the product you are using. MySQL Bugs - http://bugs.mysql.com/ Thanks! -- Shawn Green MySQL Principal Technical Support Engineer Oracle USA, Inc. - Hardware and Software, Engineered to Work Together. Office: Blountville, TN -- MySQL General Mailing List For list archives: http://lists.mysql.com/mysql To unsubscribe:http://lists.mysql.com/mysql
Re: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
Will do. mysql SHOW GLOBAL VARIABLES LIKE '%log%'; +-+-+ | Variable_name | Value | +-+-+ | back_log| 50 | | binlog_cache_size | 32768 | | binlog_direct_non_transactional_updates | OFF | | binlog_format | MIXED | | expire_logs_days| 5 | | general_log | OFF | | general_log_file| /var/run/mysqld/mysqld.log | | innodb_flush_log_at_trx_commit | 2 | | innodb_flush_log_at_trx_commit_session | 3 | | innodb_locks_unsafe_for_binlog | OFF | | innodb_log_block_size | 512 | | innodb_log_buffer_size | 8388608 | | innodb_log_file_size| 2145386496 | | innodb_log_files_in_group | 2 | | innodb_log_group_home_dir | ./ | | innodb_mirrored_log_groups | 1 | | innodb_overwrite_relay_log_info | OFF | | log | OFF | | log_bin | ON | | log_bin_trust_function_creators | ON | | log_bin_trust_routine_creators | ON | | log_error | /var/log/mysql-error.log | | log_output | FILE | | log_queries_not_using_indexes | ON | | log_slave_updates | OFF | | log_slow_admin_statements | OFF | | log_slow_filter | | | log_slow_queries| ON | | log_slow_rate_limit | 1 | | log_slow_slave_statements | OFF | | log_slow_sp_statements | ON | | log_slow_timestamp_every| OFF | | log_slow_verbosity | microtime | | log_warnings| 1 | | max_binlog_cache_size | 18446744073709547520 | | max_binlog_size | 104857600 | | max_relay_log_size | 0 | | relay_log | /var/log/mysql/mysqld-relay-bin | | relay_log_index | | | relay_log_info_file | relay-log.info | | relay_log_purge | ON | | relay_log_space_limit | 0 | | slow_query_log | ON | | slow_query_log_file | /var/log/mysql/mysql-slow.log | | slow_query_log_microseconds_timestamp | OFF | | sql_log_bin | ON | | sql_log_off | OFF | | sql_log_update | ON | | suppress_log_warning_1592 | OFF | | sync_binlog | 0 | | use_global_log_slow_control | none | +-+-+ 51 rows in set (0.01 sec) Here is full output, but writing happens ONLY if log_queries_not_using_indexes turned ON. Query takes: # Query_time: 0.291280 Lock_time: 0.50 Rows_sent: 0 Rows_examined: 133876 Rows_affected: 0 Rows_read: 1 # Bytes_sent: 1775 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0 # InnoDB_trx_id: F229398 SET timestamp=1350389078; SELECT sql_id, momt, sender, receiver, udhdata, msgdata, time, smsc_id, service, account, id, sms_type, mclass, mwi, coding, compress, validity, deferred, dlr_mask, dlr_url, pid, alt_dcs, rpi, charset, boxc_id, binfo, meta_data, task_id, msgid FROM send_sms_test FORCE INDEX (priority_time) WHERE time = UNIX_TIMESTAMP(NOW()) ORDER by priority LIMIT 0,50; 2012/10/16 Shawn Green shawn.l.gr...@oracle.com On 10/15/2012 7:15 PM, spameden wrote: 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. First. What are all of your logging settings? SHOW GLOBAL VARIABLES LIKE '%log%'; Next. When you physically look in the slow query log, how long does it say that it took this command to execute? And last, before you can ask MySQL to fix a bug, you must first ensure it's a MySQL bug. Please try to reproduce your results using official binaries, not those constructed by a third party. If the problem exists in our packages, do tell us about it. If the problem is not reproducible using official MySQL products, then please report it to the appropriate channel for the product you are using. MySQL Bugs - http://bugs.mysql.com/ Thanks! -- Shawn Green MySQL Principal Technical Support Engineer Oracle USA, Inc. - Hardware and Software, Engineered to Work Together. Office: Blountville, TN -- MySQL General Mailing List For list archives: http://lists.mysql.com/mysql To unsubscribe:http://lists.mysql.com/mysql
Re: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
your now() statement is getting executed for every row on the select. try ptting the phrase up front as in: set @ut= unix_timestamp(now()) and then use that in your statement. On 2012-10-16 8:42 AM, spameden spame...@gmail.com wrote: Will do. mysql SHOW GLOBAL VARIABLES LIKE '%log%'; +-+-+ | Variable_name | Value | +-+-+ | back_log| 50 | | binlog_cache_size | 32768 | | binlog_direct_non_transactional_updates | OFF | | binlog_format | MIXED | | expire_logs_days| 5 | | general_log | OFF | | general_log_file| /var/run/mysqld/mysqld.log | | innodb_flush_log_at_trx_commit | 2 | | innodb_flush_log_at_trx_commit_session | 3 | | innodb_locks_unsafe_for_binlog | OFF | | innodb_log_block_size | 512 | | innodb_log_buffer_size | 8388608 | | innodb_log_file_size| 2145386496 | | innodb_log_files_in_group | 2 | | innodb_log_group_home_dir | ./ | | innodb_mirrored_log_groups | 1 | | innodb_overwrite_relay_log_info | OFF | | log | OFF | | log_bin | ON | | log_bin_trust_function_creators | ON | | log_bin_trust_routine_creators | ON | | log_error | /var/log/mysql-error.log | | log_output | FILE | | log_queries_not_using_indexes | ON | | log_slave_updates | OFF | | log_slow_admin_statements | OFF | | log_slow_filter | | | log_slow_queries| ON | | log_slow_rate_limit | 1 | | log_slow_slave_statements | OFF | | log_slow_sp_statements | ON | | log_slow_timestamp_every| OFF | | log_slow_verbosity | microtime | | log_warnings| 1 | | max_binlog_cache_size | 18446744073709547520 | | max_binlog_size | 104857600 | | max_relay_log_size | 0 | | relay_log | /var/log/mysql/mysqld-relay-bin | | relay_log_index | | | relay_log_info_file | relay-log.info | | relay_log_purge | ON | | relay_log_space_limit | 0 | | slow_query_log | ON | | slow_query_log_file | /var/log/mysql/mysql-slow.log | | slow_query_log_microseconds_timestamp | OFF | | sql_log_bin | ON | | sql_log_off | OFF | | sql_log_update | ON | | suppress_log_warning_1592 | OFF | | sync_binlog | 0 | | use_global_log_slow_control | none | +-+-+ 51 rows in set (0.01 sec) Here is full output, but writing happens ONLY if log_queries_not_using_indexes turned ON. Query takes: # Query_time: 0.291280 Lock_time: 0.50 Rows_sent: 0 Rows_examined: 133876 Rows_affected: 0 Rows_read: 1 # Bytes_sent: 1775 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0 # InnoDB_trx_id: F229398 SET timestamp=1350389078; SELECT sql_id, momt, sender, receiver, udhdata, msgdata, time, smsc_id, service, account, id, sms_type, mclass, mwi, coding, compress, validity, deferred, dlr_mask, dlr_url, pid, alt_dcs, rpi, charset, boxc_id, binfo, meta_data, task_id, msgid FROM send_sms_test FORCE INDEX (priority_time) WHERE time = UNIX_TIMESTAMP(NOW()) ORDER by priority LIMIT 0,50; 2012/10/16 Shawn Green shawn.l.gr...@oracle.com On 10/15/2012 7:15 PM, spameden wrote: T...
Re: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
Interesting thought, but I get the same result. # Query_time: 0.001769 Lock_time: 0.001236 Rows_sent: 0 Rows_examined: 0 use kannel; SET timestamp=1350413592; select * from send_sms FORCE INDEX (priority_time) where time=@ut order by priority limit 0,11; the MySQL i'm using is 5.5.28 from dotdeb.org, pretty sure it's close to the original except packaging scripts. I will check this on the release from MySQL site and report back. Thanks to all. 2012/10/16 Michael Dykman mdyk...@gmail.com your now() statement is getting executed for every row on the select. try ptting the phrase up front as in: set @ut= unix_timestamp(now()) and then use that in your statement. On 2012-10-16 8:42 AM, spameden spame...@gmail.com wrote: Will do. mysql SHOW GLOBAL VARIABLES LIKE '%log%'; +-+-+ | Variable_name | Value | +-+-+ | back_log| 50 | | binlog_cache_size | 32768 | | binlog_direct_non_transactional_updates | OFF | | binlog_format | MIXED | | expire_logs_days| 5 | | general_log | OFF | | general_log_file| /var/run/mysqld/mysqld.log | | innodb_flush_log_at_trx_commit | 2 | | innodb_flush_log_at_trx_commit_session | 3 | | innodb_locks_unsafe_for_binlog | OFF | | innodb_log_block_size | 512 | | innodb_log_buffer_size | 8388608 | | innodb_log_file_size| 2145386496 | | innodb_log_files_in_group | 2 | | innodb_log_group_home_dir | ./ | | innodb_mirrored_log_groups | 1 | | innodb_overwrite_relay_log_info | OFF | | log | OFF | | log_bin | ON | | log_bin_trust_function_creators | ON | | log_bin_trust_routine_creators | ON | | log_error | /var/log/mysql-error.log | | log_output | FILE | | log_queries_not_using_indexes | ON | | log_slave_updates | OFF | | log_slow_admin_statements | OFF | | log_slow_filter | | | log_slow_queries| ON | | log_slow_rate_limit | 1 | | log_slow_slave_statements | OFF | | log_slow_sp_statements | ON | | log_slow_timestamp_every| OFF | | log_slow_verbosity | microtime | | log_warnings| 1 | | max_binlog_cache_size | 18446744073709547520 | | max_binlog_size | 104857600 | | max_relay_log_size | 0 | | relay_log | /var/log/mysql/mysqld-relay-bin | | relay_log_index | | | relay_log_info_file | relay-log.info | | relay_log_purge | ON | | relay_log_space_limit | 0 | | slow_query_log | ON | | slow_query_log_file | /var/log/mysql/mysql-slow.log | | slow_query_log_microseconds_timestamp | OFF | | sql_log_bin | ON | | sql_log_off | OFF | | sql_log_update | ON | | suppress_log_warning_1592 | OFF | | sync_binlog | 0 | | use_global_log_slow_control | none | +-+-+ 51 rows in set (0.01 sec) Here is full output, but writing happens ONLY if log_queries_not_using_indexes turned ON. Query takes: # Query_time: 0.291280 Lock_time: 0.50 Rows_sent: 0 Rows_examined: 133876 Rows_affected: 0 Rows_read: 1 # Bytes_sent: 1775 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0 # InnoDB_trx_id: F229398 SET timestamp=1350389078; SELECT sql_id, momt, sender, receiver, udhdata, msgdata, time, smsc_id, service, account, id, sms_type, mclass, mwi, coding, compress, validity, deferred, dlr_mask, dlr_url, pid, alt_dcs, rpi, charset, boxc_id, binfo, meta_data, task_id, msgid FROM send_sms_test FORCE INDEX (priority_time) WHERE time = UNIX_TIMESTAMP(NOW()) ORDER by priority LIMIT 0,50; 2012/10/16 Shawn Green shawn.l.gr...@oracle.com On 10/15/2012 7:15 PM, spameden wrote: T...
Re: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
2012/10/16 12:57 -0400, Michael Dykman your now() statement is getting executed for every row on the select. try ptting the phrase up front as in: set @ut= unix_timestamp(now()) and then use that in your statement. Quote: Functions that return the current date or time each are evaluated only once per query at the start of query execution. This means that multiple references to a function such as file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_nowNOW() within a single query always produce the same result. (For our purposes, a single query also includes a call to a stored program (stored routine, trigger, or event) and all subprograms called by that program.) This principle also applies to file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_curdateCURDATE(), file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_curtimeCURTIME(), file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_utc-dateUTC_DATE(), file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_utc-timeUTC_TIME(), file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/f! unctio ns.html#function_utc-timestampUTC_TIMESTAMP(), and to any of their synonyms. -- MySQL General Mailing List For list archives: http://lists.mysql.com/mysql To unsubscribe:http://lists.mysql.com/mysql
Re: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
That's exactly what I thought when reading Michael's email, but tried anyways, thanks for clarification :) 2012/10/16 h...@tbbs.net 2012/10/16 12:57 -0400, Michael Dykman your now() statement is getting executed for every row on the select. try ptting the phrase up front as in: set @ut= unix_timestamp(now()) and then use that in your statement. Quote: Functions that return the current date or time each are evaluated only once per query at the start of query execution. This means that multiple references to a function such as file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_nowNOW() within a single query always produce the same result. (For our purposes, a single query also includes a call to a stored program (stored routine, trigger, or event) and all subprograms called by that program.) This principle also applies to file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_curdateCURDATE(), file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_curtimeCURTIME(), file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_utc-dateUTC_DATE(), file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/functions.html#function_utc-timeUTC_TIME(), file:///C:/Program%20Files/MySQL/MySQL%20Server%205.5/HELP/f! unctio ns.html#function_utc-timestampUTC_TIMESTAMP(), and to any of their synonyms. -- MySQL General Mailing List For list archives: http://lists.mysql.com/mysql To unsubscribe:http://lists.mysql.com/mysql
Re: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
Hi, I've just checked on MySQL-5.5.28
it acts absolutely same.
I need to use (priority,time) KEY instead of (time, priority) because query
results in better performance.
With first key used there is no need to sort at all, whilst if using latter:
mysql *desc select * from send_sms_test FORCE INDEX (time_priority) where
time=UNIX_TIMESTAMP(NOW()) order by priority limit 0,13;*
++-+---+---+---+---+-+--+---+-+
| 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)
It uses filesort and results in a worser performance...
Any suggestions ? Should I submit a bug?
2012/10/16 spameden spame...@gmail.com
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`
RE: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
* 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',
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.53 | | Opening tables | 0.09 | | System lock| 0.05 | | Table lock | 0.04 | | init | 0.37 | | optimizing | 0.05 | | statistics | 0.07 | | preparing | 0.05 | | executing | 0.01 | | Sorting result | 0.03 | | Sending data | 0.000856 | | end| 0.03 | | query end | 0.01 | | freeing items | 0.15 | | logging slow query | 0.01 | | logging slow query | 0.47 | | cleaning up| 0.02 | ++--+ 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.48 | | Opening tables | 0.09 | | System lock| 0.02 | | Table lock | 0.04 | | init | 0.47 | | optimizing | 0.06 | | statistics | 0.43 | | preparing | 0.18 | | executing | 0.01 | | Sorting result | 0.076725 | | Sending data | 0.001406 | | end| 0.03 | | query end | 0.01 | | freeing items | 0.12 | | logging slow query | 0.01 | | cleaning up| 0.02 | ++--+ 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|
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.00 | +-+---+ 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.53 | | Opening tables | 0.09 | | System lock| 0.05 | | Table lock | 0.04 | | init | 0.37 | | optimizing | 0.05 | | statistics | 0.07 | | preparing | 0.05 | | executing | 0.01 | | Sorting result | 0.03 | | Sending data | 0.000856 | | end| 0.03 | | query end | 0.01 | | freeing items | 0.15 | | logging slow query | 0.01 | | logging slow query | 0.47 | | cleaning up| 0.02 | ++--+ 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.48 | | Opening tables | 0.09 | | System lock| 0.02 | | Table lock | 0.04 | | init | 0.47 | | optimizing | 0.06 | | statistics | 0.43 | | preparing | 0.18 | | executing | 0.01 | | Sorting result | 0.076725 | | Sending data | 0.001406 | | end| 0.03 | | query end | 0.01 | | freeing items | 0.12 | | logging slow query | 0.01 | | cleaning up| 0.02 | ++--+ 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
RE: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
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.53 | | Opening tables | 0.09 | | System lock| 0.05 | | Table lock | 0.04 | | init | 0.37 | | optimizing | 0.05 | | statistics | 0.07 | | preparing | 0.05 | | executing | 0.01 | | Sorting result | 0.03 | | Sending data | 0.000856 | | end| 0.03 | | query end | 0.01 | | freeing items | 0.15 | | logging slow query | 0.01 | | logging slow query | 0.47 | | cleaning up| 0.02 | ++--+ 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.48 | | Opening tables | 0.09 | | System lock| 0.02 | | Table lock | 0.04 | | init | 0.47 | | optimizing | 0.06 | | statistics | 0.43 | | preparing | 0.18 | | executing | 0.01 | | Sorting result | 0.076725 | | Sending data | 0.001406 | | end| 0.03 | | query end | 0.01 | | freeing items | 0.12 | | logging slow query | 0.01 | | cleaning up| 0.02 |
RE: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
Ø 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:spame...@gmail.com] Sent: Monday, October 15, 2012 3:29 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, forgot to say: mysql show variables like 'long_query_time%'; +-+---+ | Variable_name | Value | +-+---+ | long_query_time | 10.00 | +-+---+ 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.commailto: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.53 | | Opening tables | 0.09 | | System lock| 0.05 | | Table lock | 0.04 | | init | 0.37 | | optimizing | 0.05 | | statistics | 0.07 | | preparing | 0.05 | | executing | 0.01 | | Sorting result | 0.03 | | Sending data | 0.000856 | | end| 0.03 | | query end | 0.01 | | freeing items | 0.15 | | logging slow query | 0.01 | | logging slow query | 0.47 | | cleaning up| 0.02 | ++--+ 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.48 | | Opening tables | 0.09 | | System lock| 0.02 | | Table lock
Re: mysql logs query with indexes used to the slow-log and not logging if there is index in reverse order
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 rja...@yahoo-inc.com **Ø **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:spame...@gmail.com] *Sent:* Monday, October 15, 2012 3:29 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, forgot to say: mysql show variables like 'long_query_time%'; +-+---+ | Variable_name | Value | +-+---+ | long_query_time | 10.00 | +-+---+ 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.53 | | Opening tables | 0.09 | | System lock| 0.05 | | Table lock | 0.04 | | init | 0.37 | | optimizing | 0.05 | | statistics | 0.07 | | preparing | 0.05 | | executing | 0.01 | | Sorting result | 0.03 | | Sending data | 0.000856 | | end| 0.03 | | query end | 0.01 | | freeing items | 0.15 | | logging slow query | 0.01 | | logging slow query | 0.47 | | cleaning up| 0.02 | ++--+ 17 rows in set (0.00
