slow-query-log = 1
slow-query-log-file = /var/log/mysql/localhost-slow.log
long_query_time = 5
log-queries-not-using-indexes
Ever wondered why some queries from the MySQL database seems to be slow. I have been into a situation when I restart a process (particularly Snort/Barnyard) I end up waiting up why the MySQL process takes ages sometimes 5 to 15 minutes waiting. As such, I ended up enabling debugging MySQL queries and checked how long each query is being process. This is called the Slow Query Log.
To enable this debugging, we need to modify the MySQL configuration file (normally my.cnf). Below are settings working for MySQL version 5.6.21 on Debian 7.7 environment.
To enable this debugging, we need to modify the MySQL configuration file (normally my.cnf). Below are settings working for MySQL version 5.6.21 on Debian 7.7 environment.
The slow-query-log-file can be any filename as long with a log extension name and preferred to be located in the MySQL logs directory. Then restart the MySQL process
# /etc/init.d/mysql restart
Stopping MySQL database server: mysqld .
Starting MySQL database server: mysqld ..
Checking for tables which need an upgrade, are corrupt or were
not closed cleanly..
Now, you can view ALL queries to the database both preceding queries and actives queries. Below is a sample of logs from my Snort/Barnyard/BASE platform.
# tail /var/log/mysql/localhost-slow.log
# User@Host: snort[snort] @ localhost [] Id: 154
# Query_time: 0.000824 Lock_time: 0.000022 Rows_sent: 1 Rows_examined: 1815
SET timestamp=1421036399;
SELECT count(*) FROM acid_event;
# User@Host: snort[snort] @ localhost [] Id: 154
# Query_time: 0.001872 Lock_time: 0.000029 Rows_sent: 1 Rows_examined: 1815
SET timestamp=1421036399;
SELECT COUNT(DISTINCT acid_event.ip_src), COUNT(DISTINCT acid_event.ip_dst) FROM acid_event;
# User@Host: snort[snort] @ localhost [] Id: 154
# Query_time: 0.001689 Lock_time: 0.000031 Rows_sent: 1 Rows_examined: 1815
SET timestamp=1421036399;
SELECT COUNT(DISTINCT acid_event.ip_src, acid_event.ip_dst, acid_event.ip_proto) FROM acid_event;
# User@Host: snort[snort] @ localhost [] Id: 154
# Query_time: 0.002063 Lock_time: 0.000031 Rows_sent: 1 Rows_examined: 1815
SET timestamp=1421036399;
SELECT COUNT(DISTINCT layer4_sport), COUNT(DISTINCT layer4_dport) FROM acid_event;
# User@Host: snort[snort] @ localhost [] Id: 154
# Query_time: 0.001989 Lock_time: 0.000039 Rows_sent: 1 Rows_examined: 1815
SET timestamp=1421036399;
SELECT COUNT(DISTINCT acid_event.layer4_sport), COUNT(DISTINCT acid_event.layer4_dport) FROM acid_event WHERE ip_proto='6';
Note that each SQL queries has a "Query_time" and a "Lock_time" which gives an indication how long these statements where executed on the database.