Slow Query Log showing query with Query_time: 0.000000

[vineet khanna]

HI,

I am using Percona Server 5.5.22 with below slow query options:

+------------------------------------+-------------------------------+
| Variable_name | Value |
+------------------------------------+-------------------------------+
| log_slow_admin_statements | OFF |
| log_slow_filter | |
| log_slow_queries | ON |
| log_slow_rate_limit | 1 |
| log_slow_rate_type | session |
| log_slow_slave_statements | OFF |
| log_slow_sp_statements | ON |
| log_slow_verbosity | microtime,query_plan,innodb |
| slow_launch_time | 2 |
| slow_query_log | ON |
| slow_query_log_file | /var/log/mysql/mysql-slow.log |
| slow_query_log_timestamp_always | ON |
| slow_query_log_timestamp_precision | second |
| slow_query_log_use_global_control | |
+------------------------------------+-------------------------------+

+---------------------------------------------------+-----------+
| Variable_name | Value |
+---------------------------------------------------+-----------+
| long_query_time | 10.000000 |
+---------------------------------------------------+-----------+

+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF |
+-------------------------------+-------+

Slow Query Log showing query with Query_time: 0.000000

# Time: 130205 10:03:48
# User@Host: webuser[webuser] @ [192.168.56.200]
# Thread_id: 40979754 Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.000000 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 5 Rows_affected: 2 Rows_read: 0
# Bytes_sent: 11 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 9CAEA097
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 35
SET timestamp=1360029828;
select count(*) from foo;

Query even not showing any impact on server like filesort or tmp usage.

** Above SELECT query is sample query i have lots of queries which are showing zero time in slow log. Do let me know if you require any exact query and other variable information.

[Valerii Kravchuk (valerii-kravchuk)]

long_query_time can be set per session. Are you 100% sure that these problematic queries are NOT coming from sessions where long_query_time is set to 0?

Also, please, check if the problem is repeatable with recent PS version, 5.5.30-30.2.

[vineet khanna (khannavin)]

Yes, i am very sure, we are not setting long_query_time at session level.
About new version we haven't upgraded our system so can't say anything on that.

[Valerii Kravchuk (valerii-kravchuk)]

Please, send the output of:

show create table foo\G
show table status like 'foo'\G

for any of the tables used in queries logged (while they should not be).

I can not reproduce it so far on PS 5.5.31.

What exact OS is this? The output of:

uname -a
cat /etc/issue

may be useful.

[vineet khanna (khannavin)]

mysql> show create table foo\G
*************************** 1. row ***************************
       Table: foo
Create Table: CREATE TABLE `foo` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `type_code` char(5) COLLATE utf8_unicode_ci NOT NULL,
  `sub_type_code` char(5) COLLATE utf8_unicode_ci DEFAULT NULL,
  `name` varchar(100) COLLATE utf8_unicode_ci NOT NULL,
  `postcode` char(10) COLLATE utf8_unicode_ci DEFAULT NULL,
  `streetname` varchar(50) COLLATE utf8_unicode_ci DEFAULT NULL,
  `streetname2` varchar(100) COLLATE utf8_unicode_ci DEFAULT NULL,
  `streetnumber` varchar(20) COLLATE utf8_unicode_ci DEFAULT NULL,
  `region` char(2) COLLATE utf8_unicode_ci DEFAULT NULL,
  `longitude` double DEFAULT NULL,
  `latitude` double DEFAULT NULL,
  `location_id` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `FI_ftype` (`type_code`),
  KEY `indx_location_id` (`location_id`),
  KEY `indx_lat_long_type` (`latitude`,`longitude`,`type_code`)
) ENGINE=InnoDB AUTO_INCREMENT=21360 DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci
1 row in set (0.00 sec)

mysql> show table status like 'foo'\G
*************************** 1. row ***************************
           Name: foo
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 13463
 Avg_row_length: 118
    Data_length: 1589248
Max_data_length: 0
   Index_length: 1949696
      Data_free: 16847470592
 Auto_increment: 21362
    Create_time: 2012-10-11 18:02:34
    Update_time: NULL
     Check_time: NULL
      Collation: utf8_unicode_ci
       Checksum: NULL
 Create_options:
        Comment:
1 row in set (0.00 sec)

Explain Output:
+----+-------------+------------------------+------+-----------------------------+----------+---------+-------+------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+------------------------+------+-----------------------------+----------+---------+-------+------+-------------+
| 1 | SIMPLE | foo | ref | FI_ftype,indx_lat_long_type | FI_ftype | 15 | const | 2658 | Using where |
+----+-------------+------------------------+------+-----------------------------+----------+---------+-------+------+-------------+

Slow log:

# Time: 130603 21:27:25
# User@Host: webuser[webuser] @ [192.168.56.200]
# Thread_id: 123523436 Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.000000 Lock_time: 0.000112 Rows_sent: 339 Rows_examined: 2659 Rows_affected: 0 Rows_read: 339
# Bytes_sent: 25765 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: FE2525C0
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 36

uname -a:
Linux dbbox 2.6.16.33-xenU #2 SMP Wed Aug 15 17:27:36 SAST 2007 x86_64 x86_64 x86_64 GNU/Linux

cat /etc/issue:
CentOS release 5.5 (Final)
Kernel \r on an \m

Do let me know if you require any other information.

[Valerii Kravchuk (valerii-kravchuk)]

I am still not able to reproduce this with Percona Server 5.5.31 with your table having random data, with different kind of queries including "select count(*) from foo;" executed concurrently.

Had you ever seen this problem with recent Percona Server version, 5.5.31+?

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.6 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.5 because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-2888