Posts Tagged “slow query”

15 07 2010

mySQL >= 5.0.37 community profiling SQL queries.

Posted by Buzz in mySQL

Whilst there indeed seems to be a veritable plethora of SQL profiling / benchmarking tools, most of them with insane commercial license fees (>= $400 per annum on most)

I have found it intriguing that as of mySQL community edition >= 5.0.37 mySQL offers an inbuilt method for profiling SQL queries, as can be see here the downside is that this is session based, meaning it can only provide profiling information for the current connection, almost useless for trying to profile a running web app (that is without code modification to set profiling and harvest the data).

However it can be useful if you have a known slow query.

So lets work on the basis that we have a known slow SQL query we’d like profiling information for,

check to see if profiling is enabled:

1
SELECT  @@profiling;

The returned value is generally 0 so lets enable it.

1
2
SET profiling_history_size=100;
SET profiling=1;

This tells mySQL to retain the profile of 100 queries in memory, and to enable profiling.

Now at this point this can also be used to diagnose slow loading datases, simply

1
2
3
USE <dbname>;
SHOW profiles;
SHOW profile FOR 1;

Upon running the above you will now be using your database and will see an output similar to

1
2
3
4
5
6
7
+----------+------------+-------------------+
| Query_ID | Duration   | Query             |
+----------+------------+-------------------+
|        1 | 0.00011400 | SELECT DATABASE() |
|        2 | 0.00048900 | show databases    |
|        3 | 0.00026600 | show tables       |
+----------+------------+-------------------+

Followed by

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000053 |
| checking permissions | 0.000004 |
| Opening tables       | 0.000009 |
| init                 | 0.000011 |
| optimizing           | 0.000004 |
| executing            | 0.000017 |
| end                  | 0.000003 |
| end                  | 0.000002 |
| query end            | 0.000002 |
| freeing items        | 0.000005 |
| logging slow query   | 0.000002 |
| cleaning up          | 0.000002 |
+----------------------+----------+

In my case here nothing really eventful, lets assume for the moment you are using a wordpress database, and you have numerous posts

1
2
SELECT COUNT(*) FROM wp_posts WHERE ID > 100
SELECT COUNT(ID) FROM wp_posts WHERE ID > 100

in my case I got the following results:

1
2
0.00072600 | select count(*) from wp_posts where ID &gt; 100
0.00069900 | select count(ID) from wp_posts where ID &gt; 100

a simple demonstration showing the difference between a count() on an indexed field vs *, in this case the saving is ~4%.

1
2
SHOW profiles;
SHOW profile FOR query <n>;

Will give you an output similar to:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
+--------------------+----------+
| Status             | Duration |
+--------------------+----------+
| starting           | 0.000079 |
| Opening tables     | 0.000014 |
| System lock        | 0.000005 |
| Table lock         | 0.000008 |
| init               | 0.000025 |
| optimizing         | 0.000012 |
| statistics         | 0.000049 |
| preparing          | 0.000012 |
| executing          | 0.000006 |
| Sending data       | 0.000461 |
| end                | 0.000004 |
| end                | 0.000003 |
| query end          | 0.000003 |
| freeing items      | 0.000007 |
| closing tables     | 0.000005 |
| logging slow query | 0.000003 |
| cleaning up        | 0.000003 |
+--------------------+----------+
17 rows in set (0.00 sec)

this is very similar to a stack trace you may run on a problematic script, or xdebug + webgrind, and will gain futher insight into your SQL should EXPLAIN no give you enough of an insight.

I’ll post more information on this as I get time to work with it more, this is still knew to me, and aside from knowing how to use it I know relatively little about this profiling functionality, please feel free to post references / examples in the comments.

Cheers

Buzz, , , , , , ,

Comments No Comments »

16 03 2009

mySQL slow query log rotation

Posted by Buzz in mySQL

One of the issues facing log rotation in mySQL is that mySQL doesn’t seem to have the ability to perform a “reload”.

Meaning standard methods of rotating logs using logrotate leave mySQL logging an error in the syslog saying that the log file could not be found, and refusing to to any logging until the server is restarted, not fun if like me you manage high availability solutions and restarting a service is never the best option.

As such I have written this log rotate script, this does however make some assumptions.

  1. Your mysql user is “mysql”
  2. Your mysql slow query log is /var/log/mysql-slow.log

The script is written to perform the following actions:

  1. Rotate weekly
  2. Retain 3 rotations (3 files + live log)
  3. Compress on rotate (gzip)
  4. Create new logfile with 660 permissions chowned to mysql:mysql
  5. Run: mysqladmin flush-logs

Please be aware that the flush logs command will also rotate any binary logging currently in place, please ensure this will not adversely affect your deployment prior to use

Please ensure you carry out your own testing prior to deploying this script into a live environment.

http://svn.saiweb.co.uk/branches/linux-the-sysadmin-script/branches/logrotate.d/mysql

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
#
# mySQL slow log rotation script by D.Busby
# place this script in /etc/logrotate.d/ or your appropriate logrotate dir.
# http://creativecommons.org/licenses/by-sa/2.0/uk/ CC BY-SA
#
# NOTE: if you are reliant on binlogs i.e. for replication, 'flush logs' closes the current binlog and moves to the next itteration of log files
# You should test this does not cause an issue with your deployment before using this script
#
/var/log/mysql-slow.log {
    weekly
    rotate 3
    compress
    missingok
    notifempty
    sharedscripts
    create 660 mysql mysql
    postrotate
        /usr/bin/mysqladmin flush-logs
    endscript
}

Tags: , ,

Comments 2 Comments »