Posted on 5 Comments

Slow Query Log Rotation

Some time ago, Peter Boros at Percona wrote this post: Rotating MySQL slow logs safely. It contains good info, such as that one should use the rename method for rotation (rather than copytruncate), and then connect to mysqld and issue a FLUSH LOGS (rather than send a SIGHUP signal).

So far so good. What I do not agree with is the additional construct to prevent slow queries from being written during log rotation. The author’s rationale is that if too many items get written while the rotation is in process, this can block threads. I understand this, but let’s review what actually happens.

Indeed, if one were to do lots of writes to the slow query log in a short space of time, a write could block while waiting.

Is the risk of this occurring greater during a logrotate operation? I doubt it. A FLUSH LOGS has to close and open the file. While there is no file open, no writes can occur anyhow and they may be stored in the internal buffer of the lowlevel MySQL code for this.

In any case, if there is such a high write rate, that is an issue in itself: it is not useful to have the slow query log write that fast. Instead, you’d up the long_query_time and min_examined_rows variables to reduce the effectively “flow rate”. It’s always best to resolve an underlying issue rather than its symptom(s).

Posted on 5 Comments

5 thoughts on “Slow Query Log Rotation

  1. The slow log mutex is the issue here. I quote: “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).”

    Sometimes you need to use the slow log as a general log (long_query_time=0) to capture the entire data and use it later for different purpose.

    1. Daniel, the slow log mutex won’t be an issue if the copy/truncate method of log rotation is not used. Use the rename method.

      Using the slow log as general log makes no sense these days. There used to be a reason: it wasn’t possible to turn the general log on/off dynamically. However, that was resolved several major versions ago.

  2. I co-authored the article with Peter. Arjen, you raise some valid concerns.

    At Groupon, we log every query (set long_query_time to 0) because we use the slow log for buffer pool warming on our standby server. (See https://engineering.groupon.com/2013/open-source/mysql-buffer-pool-warming/) If not for that, I agree that reducing the “flow rate” is a great option. In fact, that’s what we did before adding buffer pool warming!

    Our workloads are majority reads. An infrequent write will block waiting for FLUSH LOGS to complete, as you said, but also has to wait for the many SELECT queries to be written to the slow log. Losing those few SELECTs from the slow log wasn’t a big deal to us and allows the write operation to occur more quickly.

    1. Why do you have that many selects getting written to the slow log?

      Are you
      a) misusing the slow log as general log? Solution: the general log can be dynamically turned on/off these days.
      b) logging too many slow queries? Solution: tune the various slow log related settings appropriately to only pick “low-hanging fruit”. When you’ve fixed all those, you tune down further to see new “homework”.

      1. @Arjen, if you look at the blog post I referenced above, you can see that we are using the slow query log mostly like a specialized general log that only contains DML statements. With some filtering / re-formatting, we could use the general log instead. Percona Playback’s Query_log plugin already slurps in the slow log, so it was straightforward choice to use it as the input for our buffer pool warming solution.

Comments are closed.