Maatkit & Slow Query Log strangeness

[John Rogers]

Hi,

I'm using Percona Server 5.1. I have slow query log enabled:

mysql> show variables;

| long_query_time | 2.000000
| slow_query_log |
ON
|
| slow_query_log_file | /var/log/mysql-slow-
queries.log

I set long query time to be 2 seconds. So I'd expect only queries
taking longer than 2 seconds would end up in slow query log.

But when I use Maatkit to analyze slow query log:

~ >> perl mk-query-digest --type slowlog /var/log/mysql-slow-
queries.log

# Overall: 2.62M total, 209 unique, 34.30 QPS, 3.68x concurrency
_________
# Time range: 2011-02-27 04:39:39 to 2011-02-28 01:51:06
# Attribute total min max avg 95% stddev
median
# ============ ======= ======= ======= ======= ======= =======
=======
# Exec time 280658s 0 30s 107ms 266ms 138ms
95ms
# Lock time 94425s 0 29s 36ms 134ms 107ms
1ms
# Rows sent 12.10M 0 3.10M 4.85 0.99
3.02k 0
# Rows examine 16.75G 0 3.10M 6.71k 112.33k 27.89k
563.87
# Query size 1.87G 23 1.42k 767.08 1.33k 587.98
719.66

As you can see the average exec time for the queries are only 107ms,
95% is 266ms. They are both far less than the 2s lower limit I set for
slow queries. So why do they end up in the slow query log?

An example of the queries:

# Query 7: 1.77 QPS, 0.06x concurrency, ID 0xE5823E9DC3B07191 at byte
125323801
# Scores: Apdex = 1.00 [1.0], V/M = 0.04
# Query_time sparkline: | ^ _ |
# Time range: 2011-02-27 04:39:40 to 2011-02-28 01:51:04
# Attribute pct total min max avg 95% stddev
median
# ============ === ======= ======= ======= ======= ======= =======
=======
# Count 5 135234
# Exec time 1 4490s 0 1s 33ms 42ms 35ms
34ms
# Lock time 0 19s 0 1s 141us 185us 3ms
125us
# Rows sent 1 124.99k 0 1 0.95 0.99 0.22
0.99
# Rows examine 89 14.98G 12.52k 116.18k 116.18k 112.33k 277.99
112.33k
# Query size 0 10.45M 81 81 81 81
0 81
# String:
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
################################################################
# 100ms
# 1s #
# 10s+

Again most queries take less than 2s.

The next part of the output is:

# Tables
# SHOW TABLE STATUS FROM `db` LIKE 't1'\G
# SHOW CREATE TABLE `db`.`t1`\G
# EXPLAIN /*!50100 PARTITIONS*/
select x from t1 where a <= '3170445458' and b >= '3170445458'\G

What does the "/*!50100 PARTITIONS*/" after EXPLAIN mean?

Thanks.

[petya]

Hi,

Most likely you have log-queries-not-using-indexes enabled, and this
way, relatively fast queries can make it to the slow log (for example a
full table scan on a table containing only 5 records is fast, but it
won't use indexes). The /*!50100 PARTITIONS*/ is a version specific
statement. If you are on version 5.1 or above, this statement will
execute explain partitions, if you are below 5.0, it will be just
explain (partitioning is available from mysql 5.1).

Peter Boros

[Baron Schwartz]

Hi John,

> I set long query time to be 2 seconds. So I'd expect only queries
> taking longer than 2 seconds would end up in slow query log.

If you have log_queries_not_using_indexes set, that can happen. Also,
check that you are looking at SHOW GLOBAL VARIABLES, and note that this
variable is both local and global, and changes don't take effect for
threads that are currently connected; only new threads see the change
in the global setting. (You can set use_global_long_query_time=1 to
force it to take effect for all threads.)

> The next part of the output is:
>
> # Tables
> # SHOW TABLE STATUS FROM `db` LIKE 't1'\G
> # SHOW CREATE TABLE `db`.`t1`\G
> # EXPLAIN /*!50100 PARTITIONS*/
> select x from t1 where a <= '3170445458' and b >= '3170445458'\G
>
> What does the "/*!50100 PARTITIONS*/" after EXPLAIN mean?

It is a conditional comment that is ignored on 5.0 and earlier. It
makes the EXPLAIN statement copy-paste ready for all versions of MySQL,
including those that don't support partitions.

[John Rogers]

Ah thank you petya and Baron.