Thursday, April 9, 2015

Enabling MySQL Query Logging

In a perfect world, I would like to imagine we'd never had to poke around the internals of software systems to debug the side-effects and performance issues caused by applications and users.

I, however, do not live in a perfect world.   I do live in a world where sometimes it's unclear if the problem is a DBA or the application and sometimes neither are any help in telling me what they did and when... Or I just don't trust them.

Also when your dealing with questions about MySQL performance, 'show processlist' is a good start but it fails to show short lived queries that are running a huge number of times per second.

Luckily, I have a few tools that are my 'go to' tools for problem solving.  For example, packet captures rock and they are my typical go to solution for debugging SIP but sometimes there is a solution which is much more elegant. In these cases with MySQL, enabling the general log gives great insight in to what is happening in your MySQL server.

The MySQL general log lets us figure out which clients did what when and how long that query took.

Turning on the Logging

The following statement turns this logging on.  I typically use a 'select now()' statement in alot of my work so that I can quickly copy and paste such things into our issue tracking software.

mysql> select now(); set global log_output="TABLE";SET GLOBAL general_log = 'ON';
| now()               |
2015-04-04 01:04:28 |

If anyone is worried about the impact of the extra logging, check this out:

Since we have setup the general logging to go to a DB table, we can simply truncate this any time during production.

Intro to Using this for Query Analysis 

Now for the fun part.  You can analyse the queries with simple SQL select statements.  Check this table definition on how to structure your queries.

mysql> SHOW CREATE TABLE mysql.general_log;
CREATE TABLE `general_log` (  `event_time` timestamp ,  `user_host` mediumtext NOT NULL,  `thread_id` int(11) NOT NULL,  `server_id` int(10) unsigned NOT NULL,  `command_type` varchar(64) NOT NULL,  `argument` mediumtext NOT NULL)

Now we can start probing into the data, here is an example to get some of the INSERTs into the databases.   

mysql> select event_time, argument from mysql.general_log where command_type ='Query' and argument like 'INSERT%' limit 100;

It should also be possible to turn this on and analyse the frequency of various queries and look for queries that can be improved or even recommended for caching at the application level.

If you don't know about MySQL's 'EXPLAIN' feature,  I highly recommend learning about it.

Turning the Query Log Off

Don't forget to turn the Query log off!  On a busy database, this is going to consume resources and unchecked, it will fill the disk eventually.

mysql>  select now(); set global log_output="TABLE";SET GLOBAL general_log = 'OFF';
| now()               |
| 2015-04-04 09:33:03 |


MySQL's logging features and other analytic tools like 'EXPLAIN' should be used at every stage of a product life cycle to figure out where bottle necks are and to determine a baseline normal.   This can also be used to help track down which database user maybe corrupting data or not following business rules.

No comments: