{"id":41,"date":"2012-09-04T22:24:17","date_gmt":"2012-09-04T20:24:17","guid":{"rendered":"http:\/\/blog.le-vert.net\/?p=41"},"modified":"2015-11-19T11:05:31","modified_gmt":"2015-11-19T10:05:31","slug":"tracking-mysql-slow-queries-with-syslog-ng","status":"publish","type":"post","link":"https:\/\/blog.le-vert.net\/?p=41","title":{"rendered":"Tracking MySQL slow queries with syslog-ng"},"content":{"rendered":"
\n\t\t\t\t\tTweet<\/a>\n\t\t\t\t<\/div><\/div>

Hey,<\/p>\n

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”.
\nTo 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.<\/p>\n

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

aptitude install syslog-ng<\/pre>\n
The default Debian configuration doesn’t log mail system messages into syslog (unlike default rsyslogd), I suggest fixing this first:
\nIn \/etc\/syslog-ng\/syslog-ng.conf<\/em>, find the line<\/p>\n
log { source(s_src); filter(f_mail); destination(d_mail); };<\/pre>\n
And add this one:<\/p>\n
log { source(s_src); filter(f_mail); destination(d_mail); };\r\nlog { source(s_src); filter(f_mail); destination(d_syslog); };<\/pre>\n
We need to ask MySQL to log slow queries (queries for which processing took more than NN seconds).
\nEdit \/etc\/mysql\/my.cnf<\/em> and uncomment the following lines:<\/p>\n
log_slow_queries        = \/var\/log\/mysql\/mysql-slow.log\r\nlong_query_time = 1<\/pre>\n
We started investigating with long_query_time<\/em> 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.<\/p>\n
Restart mysql server.<\/p>\n
Open \/etc\/syslog-ng\/syslog-ng.conf<\/em> again and add the following piece of configuration:<\/p>\n
# MySQL slow queries\r\nsource s_mysql_slow { file(\"\/var\/log\/mysql\/mysql-slow.log\"); };\r\n\r\ndestination d_syslog_mysql_slow { file(\"\/var\/log\/syslog\" template(\"$DATE $FULLHOST mysql-slow-query: $MESSAGE\\n\")); };\r\ndestination mail-alert-mysql-slow-query { program(\"\/etc\/syslog-ng\/mail-alert-mysql-slow-query\" template(\"$DATE $FULLHOST mysql-slow-query: $MESSAGE\\n\")); };\r\n\r\nlog { \r\n  source(s_mysql_slow); \r\n  destination(d_syslog_mysql_slow);\r\n  destination(mail-alert-mysql-slow-query);\r\n};<\/pre>\n
A little explanation:
\nFirst 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.
\nThen we create a new destination similar to the default d_syslog<\/em> (aka \/var\/log\/syslog file) but with text refactoring (just to make it look like a real syslog entry).
\nAfter that, another destination: pipe into an homemade script that will send the lines by email (and text refactoring again).
\nFinally, associate the sources with the two destinations.<\/p>\n
So, yes, we need to create that “mailing” script. Create a new file named \/etc\/syslog-ng\/mail-alert-mysql-slow-query<\/em> and fill it with:<\/p>\n
#!\/usr\/bin\/python\r\n\r\nimport Queue\r\nimport re\r\nimport smtplib\r\nimport sys\r\nimport time\r\nimport thread\r\nimport os\r\n\r\nq = Queue.Queue(0)\r\n\r\ndef producer():\r\n        tag = re.compile('(.*)')\r\n        while True:\r\n                line = sys.stdin.readline()\r\n                untagged = tag.match(line)\r\n                if untagged:\r\n                        q.put(untagged.group(1) + '\\n')\r\n                else:\r\n                        pass\r\n\r\ndef consumer(timeout, mail_from, rcpt_to, subject):\r\n        client = smtplib.SMTP()\r\n        body = 'From: %s\\nTo: %s\\nSubject: %s\\n\\n' % (mail_from, rcpt_to, subject)\r\n        while True:\r\n                lines = q.get()\r\n                time.sleep(timeout)\r\n                while not q.empty():\r\n                        lines += q.get()\r\n\r\n                client.connect('localhost')\r\n                client.sendmail(mail_from, rcpt_to, body+lines)\r\n                client.quit()\r\n\r\nthread.start_new_thread(producer, ())\r\nconsumer(0.1, 'root', 'root', 'MySQL: slow query detected on '+os.uname()[1])<\/pre>\n
I stole this script somewhere on syslog-ng’s mailing list and tweaked it a bit.
\nThis script is a lot better because it handles a timeout before sending the email (see 0.1<\/em> in last line).
\nA 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!<\/p>\n
Set this file +x (chmod 755) and restart syslog-ng. Run tail -f \/var\/log\/syslog<\/em> and start a slow mysql query.
\nYou should see something like this:<\/p>\n
Sep  4 22:20:44 hostname mysql-slow-query: # Time: 120904 22:20:44\r\nSep  4 22:20:44 hostname mysql-slow-query: # User@Host: root[root] @ localhost []\r\nSep  4 22:20:44 hostname mysql-slow-query: # Query_time: 18.409844  Lock_time: 0.000075 Rows_sent: 1  Rows_examined: 8595368\r\nSep  4 22:20:44 hostname mysql-slow-query: SET timestamp=1346790044;\r\nSep  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;\r\nSep  4 22:20:44 hostname postfix\/smtpd[11597]: connect from localhost.localdomain[127.0.0.1]\r\nSep  4 22:20:44 hostname postfix\/smtpd[11597]: 65D451013AD: client=localhost.localdomain[127.0.0.1]\r\nSep  4 22:20:44 hostname postfix\/cleanup[10800]: 65D451013AD: message-id=\r\nSep  4 22:20:44 hostname postfix\/qmgr[22208]: 65D451013AD: from=, size=953, nrcpt=1 (queue active)\r\nSep  4 22:20:44 hostname postfix\/smtpd[11597]: disconnect from localhost.localdomain[127.0.0.1]\r\nSep  4 22:20:44 hostname postfix\/cleanup[10800]: 681621013AE: message-id=\r\nSep  4 22:20:44 hostname postfix\/qmgr[22208]: 681621013AE: from=, size=1100, nrcpt=3 (queue active)\r\nSep  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)\r\nSep  4 22:20:44 hostname postfix\/qmgr[22208]: 65D451013AD: removed<\/pre>\n
Enjoy!<\/p>\n
*UPDATE* 2012-10-22<\/strong><\/p>\n
After using this setup for a while, we discovered that most of alert sent during the night were irrelevant.
\nSo here a quick patch to disable it from midnight to 8am:<\/p>\n
--- \/tmp\/mail-alert-mysql-slow-query    2012-10-22 21:52:52.000000000 +0200                                                                                                                                                                                                    \r\n+++ \/etc\/syslog-ng\/\/mail-alert-mysql-slow-query 2012-09-07 23:45:37.000000000 +0200                                                                                                                                                                                            \r\n@@ -8,6 +8,7 @@                                                                                                                                                                                                                                                                \r\n import time                                                                                                                                                                                                                                                                   \r\n import thread                                                                                                                                                                                                                                                                 \r\n import os                                                                                                                                                                                                                                                                     \r\n+from datetime import datetime                                                                                                                                                                                                                                                 \r\n\r\n q = Queue.Queue(0)                                                                                                                                                                                                                                                            \r\n\r\n@@ -17,7 +18,10 @@\r\n        while True:\r\n                line = sys.stdin.readline()\r\n                untagged = tag.match(line)\r\n-               if untagged:\r\n+               # Avoid sending alerts between midnight and 8 a.m\r\n+               # (not relevant, admin task, backups...)\r\n+               hour_now = getattr(datetime.now(), 'hour')\r\n+               if untagged and hour_now >= 8:\r\n                        q.put(untagged.group(1) + '\\n')\r\n                else:\r\n                        pass<\/pre>\n
*UPDATE* 2015-11-19<\/strong><\/p>\n
I made a slightly better version for another issue at work:<\/p>\n
\r\n#!\/usr\/bin\/python3\r\n\r\nimport queue\r\nimport smtplib\r\nimport sys\r\nimport time\r\nfrom threading import Thread\r\nimport os\r\n\r\nq = queue.Queue()\r\nstab_period = 60\r\nsmtp_server = 'localhost'\r\nmail_from   = 'root'\r\nmail_to     = 'owncloud-admins'\r\nmail_subj   = 'Owncloud: DELETE or MOVE detected on '+os.uname()[1]\r\n\r\n# Thread reading STDin (piped on syslog-ng) and filling a queue\r\ndef producer():\r\n  while True:\r\n    q.put(sys.stdin.readline())\r\n\r\n# Poping the queue and seding an email (with stabilization period)\r\ndef consumer(timeout, mail_from, rcpt_to, subject):\r\n   client = smtplib.SMTP()\r\n   body = 'From: %s\\nTo: %s\\nSubject: %s\\n\\n' % (mail_from, rcpt_to, subject)\r\n   while True:\r\n     lines = q.get()\r\n     time.sleep(timeout)\r\n     while not q.empty():\r\n       lines += q.get()\r\n\r\n     client.connect(smtp_server)\r\n     client.sendmail(mail_from, rcpt_to, body+lines)\r\n     client.quit()\r\n\r\n# Start the produceur queue in a thread, then the consumer loop\r\ndef main():\r\n  th = Thread(target=producer)\r\n  th.daemon = True\r\n  th.start()\r\n  consumer(stab_period, mail_from, mail_to, mail_subj)\r\n\r\n# Proper exit with thread handling\r\nif __name__ == '__main__':\r\n  try:\r\n    main()\r\n  except KeyboardInterrupt:\r\n    print('Interrupted')\r\n    sys.exit(0)\r\n<\/pre>\n
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.<\/p>\n
Here is my configuration file:<\/p>\n
\r\nsource s_owncloud_apache { file(\"\/var\/log\/apache2\/access.log\"); };\r\n\r\nfilter f_owncloud_delete_move { message(\"DELETE \/owncloud\/remote.php\/webdav\/\") or message(\"MOVE \/owncloud\/remote.php\/webdav\/\"); };\r\n\r\ndestination d_owncloud_delete_move { file(\"\/var\/log\/owncloud\/delete-move.log\" template(\"$DATE $FULLHOST: $MESSAGE\\n\")); };\r\ndestination mail-alert-owncloud-delete-move { program(\"\/etc\/syslog-ng\/mail-alert-owncloud-delete-move\" template(\"$MESSAGE\\n\")); };\r\n\r\nlog { \r\n  source(s_owncloud_apache);\r\n  filter(f_owncloud_delete_move);\r\n  destination(d_owncloud_delete_move);\r\n  destination(mail-alert-owncloud-delete-move);\r\n};\r\n<\/pre>\n","protected":false},"excerpt":{"rendered":"
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 … Continue reading →<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[],"_links":{"self":[{"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=\/wp\/v2\/posts\/41"}],"collection":[{"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=41"}],"version-history":[{"count":22,"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=\/wp\/v2\/posts\/41\/revisions"}],"predecessor-version":[{"id":132,"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=\/wp\/v2\/posts\/41\/revisions\/132"}],"wp:attachment":[{"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=41"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=41"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/blog.le-vert.net\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=41"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}