October 1, 2014

Rotating MySQL slow logs safely

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. And one more reminder that I’ll be at the Percona Live MySQL Conference and Expo next week in Santa Clara, California so look for me there. You can checkout the sessions I’ll be leading here.

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):

  1. copytruncate – Copies the file to a new name, and then truncates the original file.
  2. 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:

  1. Send a HUP signal to the mysqld process.
  2. 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:

About Peter Boros

Peter joined the European consulting team in May 2012. Before joining Percona, among many other things, he worked at Sun Microsystems, specialized there in performance tuning and was a DBA at Hungary's largest social networking site. He also taught many Oracle University MySQL courses. He has been using and working with open source software from early 2000s. Peter's first and foremost professional interest is performance tuning.

He currently lives in Budapest, Hungary with his wife and son.

Comments

  1. martin.arrieta says:

    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 http://www.percona.com/doc/percona-server/5.1/diagnostics/slow_extended.html#use_global_log_slow_control
    PS 5.5 http://www.percona.com/doc/percona-server/5.5/diagnostics/slow_extended_55.html#slow_query_log_use_global_control

    Martin

    @martinarrietac

  2. Andrew says:

    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.

  3. Peter Boros says:

    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/

  4. ruochen says:

    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.

  5. astrostl says:

    “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.

  6. @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;)

  7. astrostl says:

    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.

  8. braa says:

    Hi!
    is this method usable for schema with replication? What will happen with bin-logs after FLUSH LOGS?

  9. Peter Boros says:

    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.

  10. braa says:

    Thanks for your respond, Peter! It’s just my case!
    I’ll try to use FLUSH SLOW LOGS

  11. braa says:

    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

  12. monty says:

    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?

  13. @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. :)

  14. Valerie Parham-Thompson says:

    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.

  15. @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.

  16. Valerie Parham-Thompson says:

    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.

Speak Your Mind

*