This blog post is part two of two. Like part one, published Wednesday, this is a cross-post from Groupon’s engineering blog. Thanks again to Kyle Oppenheim at Groupon.
In my last post, I described a solution for keeping the caches of a MySQL standby server hot using MySQL slow logs with long_query_time set to 0. Here are a some lessons we learned when logging a high volume of queries to the slow log.
Do not use copytruncate
Logrotate offers two techniques for log rotation (your log rotation scheme likely offers similar options with a different name):
- copytruncate – Copies the file to a new name, and then truncates the original file.
- no copytruncate – Uses the rename() system call to move the file to a new name, and then expects the daemon to be signaled to reopen its log file.
MySQL has a mutex for slow log writes. Truncation can block MySQL because the OS serializes access to the inode during the truncate operation. This problem is particularly evident when using the ext3 file system (instead of xfs).
Use FLUSH LOGS instead of sending SIGHUP
When copytruncate is disabled, MySQL must be told to reopen the slow log file. There are two options for signaling:
- Send a HUP signal to the mysqld process.
- Use the mysql console or mysqladmin utility to FLUSH LOGS;
These options should be equivalent, but MySQL bug 65481 explains that the HUP signal also flushes tables in addition to logs. Flushing tables can impact running queries.
Disable MySQL slow logs during rotation
Flushing logs takes time. Meanwhile, queries are still being executed. To prevent MySQL from filling the slow log buffer, we disable the MySQL slow logs temporarily during log rotation.
Putting it all together
Here is a logrotate configuration file for a slow log that illustrates these best practices:
1 2 3 4 5 6 7 8 9 10 11 12 | /var/mysql/slow_query.log { nocompress create 660 mysql mysql size 1G dateext missingok notifempty sharedscripts postrotate /usr/local/bin/mysql -e 'select @@global.long_query_time into @lqt_save; set global long_query_time=2000; select sleep(2); FLUSH LOGS; select sleep(2); set global long_query_time=@lqt_save;' endscript rotate 150 |
Hi!
One important thing to check is if you are using persistent-connections.
The global variable long_query_time is checked when the connection is created, so if you are using a connection pool or persistent connections this will not be useful because it will not affect to the connections that were already opened.
There is a Percona Server feature to solve this issue.
You can set the “slow_query_log_use_global_control” in 5.5 or “use_global_log_slow_control” in 5.1 in 1 and the server will use the global variable long_query_time instead the local one.
PS 5.1 https://www.percona.com/doc/percona-server/5.1/diagnostics/slow_extended.html#use_global_log_slow_control
PS 5.5 https://www.percona.com/doc/percona-server/5.5/diagnostics/slow_extended_55.html#slow_query_log_use_global_control
Martin
@martinarrietac
On MySQL 5.5+ I would think its preferable to use FLUSH /*!50503 SLOW */ LOGS, rather than a general FLUSH LOGS which will touch a lot of other (likely more expensive) log files as well.
Hi,
Martin, Andrew, you are right on these. You can also use SET GLOBAL slow_query_log = on|off to turn slow log on and off, like Bill does in his tool here.
http://www.mysqlperformanceblog.com/2012/11/22/get-me-some-query-logs/
Hi,Peter Boros
Thanks for your good idea !
I have a security misgivings with use mysql -e,which need user and password because procedure box must be setted.
“To prevent MySQL from filling the slow log buffer, we disable the MySQL slow logs temporarily during log rotation.”
Wouldn’t that be in the prerotate section? I don’t see one in the stanza provided.
@astrostl, the slow logs are disabled in the postrotate stanza. The order of operations is:
1. logrotate renames the log file. MySQL continues to write to the renamed file because it has not yet reopened the file.
2. logrotate runs the postrotate stanza
2a. Slow logging is paused (set global long_query_time=2000;)
2b. There is a small wait for buffered logs to be flushed (select sleep(2);)
2c. File handles are reopened (FLUSH LOGS;)
2d. Slow logging resumed (set global long_query_time=@lqt_save;)
Roger that. It was “during log rotation” that threw me. Since there are only pre and post methods, I would consider “during” to imply started in pre, and stopped in post.
Hi!
is this method usable for schema with replication? What will happen with bin-logs after FLUSH LOGS?
Hi braa,
The current binary log will be closed, and a new will be opened on FLUSH LOGS, regardless of max_binlog_size. This won’t cause you any replication trouble. If you are on MySQL 5.5 or above, you can use FLUSH SLOW LOGS to rotate only the slow logs.
Thanks for your respond, Peter! It’s just my case!
I’ll try to use FLUSH SLOW LOGS
Peter, I’ve got the task of benchmark testing my MySQL with some queries. And I’ve not got a clue from which point to begin!
Please, give me direction to dig
The sample logrotate configuration file use sharedscripts even though it is used to rotate a single file.
Are similar considerations needed to safely rotate the MySQL general and error logs? Can they be merged into a single logrotate configuration file with the slow log?
@monty, it appears that I cargo-culted the sharedscripts option from our standard config. You are correct that it makes little difference in this case.
You raised a good question regarding the general and error logs. At Groupon we use the same recipe for rotating error logs. I suspect that using copytruncate without a postrotate command would likely be fine unless you have large error logs. (Our error logs are on the order of 100 bytes per hour.) Honestly, I never tried the alternative. 🙂
I agree with ruochen about security misgivings. Looking for slash working on a way to rotate slow logs without requiring a super user. Wondering if there’s a way to do this within mysql as event.
@Valerie, you could create a new MySQL user for log rotation. That user would need the RELOAD privilege (http://dev.mysql.com/doc/refman/5.5/en/privileges-provided.html#priv_reload). You won’t be able to use the part of the recipe that changes the long query time as SET GLOBAL requires the SUPER privilege. I haven’t tried this, but I imagine you could put the SET GLOBAL calls in a stored procedure that executes as user that has the SUPER privilege and call it from an unprivileged user.
Thanks, Kyle. I’ll give that a try. For now, I’ve got it working via a MySQL event, but it doesn’t do the archive/gzip like I want.
Please format the content.
can u please tell how we need to do in windows for the same situtation
I encountered an issue on a server which has a root password. Logrotate apparently does not read .my.cnf in the home folder. Thus it cannot log in to the MySQL server and execute the postrotate statement. The result is that the file is never released.
I worked around that by creating a user with SUPER and RELOAD privilege. Since the password has to be passed on the command line, it is advisable to make the logrotate config exclusively readable for root.
@Fabian Groffen – This can also be addressed by storing the credentials in /root/.my.cnf (600 permissions), and then referring to the file in the mysql command:
/usr/local/bin/mysql –defaults-extra-file=/root/.my.cnf -e “….
Where is copytruncate in the script provided ?