September | 2012 | blog.le-vert.net

Hey,

Like me, you may have experiencied slow-down on your PHP/MySQL website, especially when using a crappy CMS (who said Joomla ? ;-)) and have been told “hey, the linux guy, please fix this”.
To be honest, I won’t fix anything as I’m neither a DBA or a developer, however, in this article we will set up an automatic e-mail reporting of slow queries processed by your MySQL server.

First, you’ll have to remove your old syslog server and replace it with something powerful (I mean: syslog-ng):

aptitude install syslog-ng

1	aptitude install syslog-ng

The default Debian configuration doesn’t log mail system messages into syslog (unlike default rsyslogd), I suggest fixing this first:
In /etc/syslog-ng/syslog-ng.conf, find the line

log { source(s_src); filter(f_mail); destination(d_mail); };

1	log { source(s_src); filter(f_mail); destination(d_mail); };

And add this one:

log { source(s_src); filter(f_mail); destination(d_mail); };
log { source(s_src); filter(f_mail); destination(d_syslog); };

1 2	log { source(s_src); filter(f_mail); destination(d_mail); }; log { source(s_src); filter(f_mail); destination(d_syslog); };

We need to ask MySQL to log slow queries (queries for which processing took more than NN seconds).
Edit /etc/mysql/my.cnf and uncomment the following lines:

log_slow_queries        = /var/log/mysql/mysql-slow.log
long_query_time = 1

1 2	log_slow_queries = /var/log/mysql/mysql-slow.log long_query_time = 1

We started investigating with long_query_time set to 5 seconds, but 1 is a decent value. I haven’t tried yet to use something lower than 1 sec but I guess that should work.

Restart mysql server.

Open /etc/syslog-ng/syslog-ng.conf again and add the following piece of configuration:

# MySQL slow queries
source s_mysql_slow { file("/var/log/mysql/mysql-slow.log"); };

destination d_syslog_mysql_slow { file("/var/log/syslog" template("$DATE $FULLHOST mysql-slow-query: $MESSAGE\n")); };
destination mail-alert-mysql-slow-query { program("/etc/syslog-ng/mail-alert-mysql-slow-query" template("$DATE $FULLHOST mysql-slow-query: $MESSAGE\n")); };

log { 
  source(s_mysql_slow); 
  destination(d_syslog_mysql_slow);
  destination(mail-alert-mysql-slow-query);
};

# MySQL slow queries

source s_mysql_slow { file("/var/log/mysql/mysql-slow.log"); };

destination d_syslog_mysql_slow { file("/var/log/syslog" template("$DATE $FULLHOST mysql-slow-query: $MESSAGE\n")); };

destination mail-alert-mysql-slow-query { program("/etc/syslog-ng/mail-alert-mysql-slow-query" template("$DATE $FULLHOST mysql-slow-query: $MESSAGE\n")); };

log {

source(s_mysql_slow);

destination(d_syslog_mysql_slow);

destination(mail-alert-mysql-slow-query);

};

A little explanation:
First we define a new source of log file. MySQL has its own way of logging and doesn’t rely on syslog, so we need to track its own log file and ask our syslog to merge this logs.
Then we create a new destination similar to the default d_syslog (aka /var/log/syslog file) but with text refactoring (just to make it look like a real syslog entry).
After that, another destination: pipe into an homemade script that will send the lines by email (and text refactoring again).
Finally, associate the sources with the two destinations.

So, yes, we need to create that “mailing” script. Create a new file named /etc/syslog-ng/mail-alert-mysql-slow-query and fill it with:

#!/usr/bin/python

import Queue
import re
import smtplib
import sys
import time
import thread
import os

q = Queue.Queue(0)

def producer():
        tag = re.compile('(.*)')
        while True:
                line = sys.stdin.readline()
                untagged = tag.match(line)
                if untagged:
                        q.put(untagged.group(1) + '\n')
                else:
                        pass

def consumer(timeout, mail_from, rcpt_to, subject):
        client = smtplib.SMTP()
        body = 'From: %s\nTo: %s\nSubject: %s\n\n' % (mail_from, rcpt_to, subject)
        while True:
                lines = q.get()
                time.sleep(timeout)
                while not q.empty():
                        lines += q.get()

                client.connect('localhost')
                client.sendmail(mail_from, rcpt_to, body+lines)
                client.quit()

thread.start_new_thread(producer, ())
consumer(0.1, 'root', 'root', 'MySQL: slow query detected on '+os.uname()[1])

#!/usr/bin/python

import Queue

import re

import smtplib

import sys

import time

import thread

import os

q = Queue.Queue(0)

def producer():

tag = re.compile('(.*)')

while True:

line = sys.stdin.readline()

untagged = tag.match(line)

if untagged:

q.put(untagged.group(1) + '\n')

else:

pass

def consumer(timeout, mail_from, rcpt_to, subject):

client = smtplib.SMTP()

body = 'From: %s\nTo: %s\nSubject: %s\n\n' % (mail_from, rcpt_to, subject)

while True:

lines = q.get()

time.sleep(timeout)

while not q.empty():

lines += q.get()

client.connect('localhost')

client.sendmail(mail_from, rcpt_to, body+lines)

client.quit()

thread.start_new_thread(producer, ())

consumer(0.1, 'root', 'root', 'MySQL: slow query detected on '+os.uname()[1])

I stole this script somewhere on syslog-ng’s mailing list and tweaked it a bit.
This script is a lot better because it handles a timeout before sending the email (see 0.1 in last line).
A full “slow query log” is written on several line. Thanks to this genius piece of Python script, only one email containing all of them will be send!

Set this file +x (chmod 755) and restart syslog-ng. Run tail -f /var/log/syslog and start a slow mysql query.
You should see something like this:

Sep  4 22:20:44 hostname mysql-slow-query: # Time: 120904 22:20:44
Sep  4 22:20:44 hostname mysql-slow-query: # User@Host: root[root] @ localhost []
Sep  4 22:20:44 hostname mysql-slow-query: # Query_time: 18.409844  Lock_time: 0.000075 Rows_sent: 1  Rows_examined: 8595368
Sep  4 22:20:44 hostname mysql-slow-query: SET timestamp=1346790044;
Sep  4 22:20:44 hostname mysql-slow-query: SELECT  SQL_CALC_FOUND_ROWS  *  FROM  `cdi_news`  as n, log_news as l where n.newsid = l.newsid and n.link like  "%canard%" LIMIT 1;
Sep  4 22:20:44 hostname postfix/smtpd[11597]: connect from localhost.localdomain[127.0.0.1]
Sep  4 22:20:44 hostname postfix/smtpd[11597]: 65D451013AD: client=localhost.localdomain[127.0.0.1]
Sep  4 22:20:44 hostname postfix/cleanup[10800]: 65D451013AD: message-id=
Sep  4 22:20:44 hostname postfix/qmgr[22208]: 65D451013AD: from=, size=953, nrcpt=1 (queue active)
Sep  4 22:20:44 hostname postfix/smtpd[11597]: disconnect from localhost.localdomain[127.0.0.1]
Sep  4 22:20:44 hostname postfix/cleanup[10800]: 681621013AE: message-id=
Sep  4 22:20:44 hostname postfix/qmgr[22208]: 681621013AE: from=, size=1100, nrcpt=3 (queue active)
Sep  4 22:20:44 hostname postfix/local[11599]: 65D451013AD: to=, orig_to=, relay=local, delay=0.01, delays=0/0.01/0/0, dsn=2.0.0, status=sent (forwarded as 681621013AE)
Sep  4 22:20:44 hostname postfix/qmgr[22208]: 65D451013AD: removed

Sep 4 22:20:44 hostname mysql-slow-query: # Time: 120904 22:20:44

Sep 4 22:20:44 hostname mysql-slow-query: # User@Host: root[root] @ localhost []

Sep 4 22:20:44 hostname mysql-slow-query: # Query_time: 18.409844 Lock_time: 0.000075 Rows_sent: 1 Rows_examined: 8595368

Sep 4 22:20:44 hostname mysql-slow-query: SET timestamp=1346790044;

Sep 4 22:20:44 hostname mysql-slow-query: SELECT SQL_CALC_FOUND_ROWS * FROM `cdi_news` as n, log_news as l where n.newsid = l.newsid and n.link like "%canard%" LIMIT 1;

Sep 4 22:20:44 hostname postfix/smtpd[11597]: connect from localhost.localdomain[127.0.0.1]

Sep 4 22:20:44 hostname postfix/smtpd[11597]: 65D451013AD: client=localhost.localdomain[127.0.0.1]

Sep 4 22:20:44 hostname postfix/cleanup[10800]: 65D451013AD: message-id=

Sep 4 22:20:44 hostname postfix/qmgr[22208]: 65D451013AD: from=, size=953, nrcpt=1 (queue active)

Sep 4 22:20:44 hostname postfix/smtpd[11597]: disconnect from localhost.localdomain[127.0.0.1]

Sep 4 22:20:44 hostname postfix/cleanup[10800]: 681621013AE: message-id=

Sep 4 22:20:44 hostname postfix/qmgr[22208]: 681621013AE: from=, size=1100, nrcpt=3 (queue active)

Sep 4 22:20:44 hostname postfix/local[11599]: 65D451013AD: to=, orig_to=, relay=local, delay=0.01, delays=0/0.01/0/0, dsn=2.0.0, status=sent (forwarded as 681621013AE)

Sep 4 22:20:44 hostname postfix/qmgr[22208]: 65D451013AD: removed

Enjoy!

*UPDATE* 2012-10-22

After using this setup for a while, we discovered that most of alert sent during the night were irrelevant.
So here a quick patch to disable it from midnight to 8am:

--- /tmp/mail-alert-mysql-slow-query    2012-10-22 21:52:52.000000000 +0200                                                                                                                                                                                                    
+++ /etc/syslog-ng//mail-alert-mysql-slow-query 2012-09-07 23:45:37.000000000 +0200                                                                                                                                                                                            
@@ -8,6 +8,7 @@                                                                                                                                                                                                                                                                
 import time                                                                                                                                                                                                                                                                   
 import thread                                                                                                                                                                                                                                                                 
 import os                                                                                                                                                                                                                                                                     
+from datetime import datetime                                                                                                                                                                                                                                                 

 q = Queue.Queue(0)                                                                                                                                                                                                                                                            

@@ -17,7 +18,10 @@
        while True:
                line = sys.stdin.readline()
                untagged = tag.match(line)
-               if untagged:
+               # Avoid sending alerts between midnight and 8 a.m
+               # (not relevant, admin task, backups...)
+               hour_now = getattr(datetime.now(), 'hour')
+               if untagged and hour_now &gt;= 8:
                        q.put(untagged.group(1) + '\n')
                else:
                        pass

--- /tmp/mail-alert-mysql-slow-query 2012-10-22 21:52:52.000000000 +0200

+++ /etc/syslog-ng//mail-alert-mysql-slow-query 2012-09-07 23:45:37.000000000 +0200

@@ -8,6 +8,7 @@

import time

import thread

import os

+from datetime import datetime

q = Queue.Queue(0)

@@ -17,7 +18,10 @@

while True:

line = sys.stdin.readline()

untagged = tag.match(line)

- if untagged:

+ # Avoid sending alerts between midnight and 8 a.m

+ # (not relevant, admin task, backups...)

+ hour_now = getattr(datetime.now(), 'hour')

+ if untagged and hour_now >= 8:

q.put(untagged.group(1) + '\n')

else:

pass

*UPDATE* 2015-11-19

I made a slightly better version for another issue at work:

#!/usr/bin/python3

import queue
import smtplib
import sys
import time
from threading import Thread
import os

q = queue.Queue()
stab_period = 60
smtp_server = 'localhost'
mail_from   = 'root'
mail_to     = 'owncloud-admins'
mail_subj   = 'Owncloud: DELETE or MOVE detected on '+os.uname()[1]

# Thread reading STDin (piped on syslog-ng) and filling a queue
def producer():
  while True:
    q.put(sys.stdin.readline())

# Poping the queue and seding an email (with stabilization period)
def consumer(timeout, mail_from, rcpt_to, subject):
   client = smtplib.SMTP()
   body = 'From: %s\nTo: %s\nSubject: %s\n\n' % (mail_from, rcpt_to, subject)
   while True:
     lines = q.get()
     time.sleep(timeout)
     while not q.empty():
       lines += q.get()

     client.connect(smtp_server)
     client.sendmail(mail_from, rcpt_to, body+lines)
     client.quit()

# Start the produceur queue in a thread, then the consumer loop
def main():
  th = Thread(target=producer)
  th.daemon = True
  th.start()
  consumer(stab_period, mail_from, mail_to, mail_subj)

# Proper exit with thread handling
if __name__ == '__main__':
  try:
    main()
  except KeyboardInterrupt:
    print('Interrupted')
    sys.exit(0)

#!/usr/bin/python3

import queue

import smtplib

import sys

import time

from threading import Thread

import os

q = queue.Queue()

stab_period = 60

smtp_server = 'localhost'

mail_from = 'root'

mail_to = 'owncloud-admins'

mail_subj = 'Owncloud: DELETE or MOVE detected on '+os.uname()[1]

# Thread reading STDin (piped on syslog-ng) and filling a queue

def producer():

while True:

q.put(sys.stdin.readline())

# Poping the queue and seding an email (with stabilization period)

def consumer(timeout, mail_from, rcpt_to, subject):

client = smtplib.SMTP()

body = 'From: %s\nTo: %s\nSubject: %s\n\n' % (mail_from, rcpt_to, subject)

while True:

lines = q.get()

time.sleep(timeout)

while not q.empty():

lines += q.get()

client.connect(smtp_server)

client.sendmail(mail_from, rcpt_to, body+lines)

client.quit()

# Start the produceur queue in a thread, then the consumer loop

def main():

th = Thread(target=producer)

th.daemon = True

th.start()

consumer(stab_period, mail_from, mail_to, mail_subj)

# Proper exit with thread handling

if __name__ == '__main__':

try:

main()

except KeyboardInterrupt:

print('Interrupted')

sys.exit(0)

Also, in this case I decided to filter out messages within syslog-ng, which would probably be a lot more efficient than using re module in Python script.

Here is my configuration file:

source s_owncloud_apache { file("/var/log/apache2/access.log"); };

filter f_owncloud_delete_move { message("DELETE /owncloud/remote.php/webdav/") or message("MOVE /owncloud/remote.php/webdav/"); };

destination d_owncloud_delete_move { file("/var/log/owncloud/delete-move.log" template("$DATE $FULLHOST: $MESSAGE\n")); };
destination mail-alert-owncloud-delete-move { program("/etc/syslog-ng/mail-alert-owncloud-delete-move" template("$MESSAGE\n")); };

log { 
  source(s_owncloud_apache);
  filter(f_owncloud_delete_move);
  destination(d_owncloud_delete_move);
  destination(mail-alert-owncloud-delete-move);
};

source s_owncloud_apache { file("/var/log/apache2/access.log"); };

filter f_owncloud_delete_move { message("DELETE /owncloud/remote.php/webdav/") or message("MOVE /owncloud/remote.php/webdav/"); };

destination d_owncloud_delete_move { file("/var/log/owncloud/delete-move.log" template("$DATE $FULLHOST: $MESSAGE\n")); };

destination mail-alert-owncloud-delete-move { program("/etc/syslog-ng/mail-alert-owncloud-delete-move" template("$MESSAGE\n")); };

log {

source(s_owncloud_apache);

filter(f_owncloud_delete_move);

destination(d_owncloud_delete_move);

destination(mail-alert-owncloud-delete-move);

};

blog.le-vert.net

No bullshit, only Linux stuff

Monthly Archives: September 2012

Tracking MySQL slow queries with syslog-ng