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 |
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); }; |
And add this one:
|
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 |
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); }; |
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:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37
|
#!/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 |
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:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22
|
--- /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:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49
|
#!/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); }; |