MySQL 5.7 reads all your binlog files more often than you think

After upgrading some of our slaves to latest 5.7, I have found  what looks like a serious regression introduced in MySQL 5.7.
A couple weeks ago I noticed that the error log file of one of our clusters, where I had implemented my in place transparent compression of binary logs,  was literally flooded by the following error:

[ERROR] Binlog has bad magic number;  It's not a binary log file that can be used by this version of MySQL

In the above setup this is  an harmless error, and it should only happen at server startup, where mysqld opens and reads all available binary log files.  The error is due to the fact that since files are now compressed, mysqld doesn't recognize them as valid - not an issue, as only older files are compressed, and only after ensuring all slaves already got them.

But I couldn't understand why the error was now hitting every minute or so, after upgrading from 5.6 to 5.7.

After a short investigation I was able to relate the errors to the exact moment where a binary log was closed and a new one created, this normally happens when the binary log file size reaches the value you have set in max_binlog_size variable. But this indicated that mysqld was continuously trying to open and read all the available binary logs, each time a file was rotated.

Ouch! This wasn't a nice finding.

On this server we have in excess of 3,500 binary log files, and I know about installations which have much more (mind you, we have a retention of 4 days only here). We like to keep binlog files small, we have them sized at 100 MB as this makes easier to peruse them when troubleshooting with mysqlbinlog. Anyways this wouldn't change anything, I mean, having 3,500 100M files or 350 1G files would generate exactly the same amount of I/O when you wanted to read them all....

Anyways, I had just found that every time a binary log is rotated, mysqld needs to open all of the files. What a waste of I/O and performances, I thought.  So I decided to have a look at the code to understand what mysqld was actually trying to do with those binlogs.

It wasn't too difficult to narrow down the binlog scan with the function  purge_logs_before_date()
that expires logs based on time, as set by the expire_logs_days variable.
But reading the binary log files shouldn't be really needed when you're only looking to expire them, so this looked weird to me.

Further digging into the source code shows that mysqld is actually looking for "lost GTIDs" in the binlog files, and does it every time a binary log is closed for rotation. I haven't looked deeper into what a "lost" GTID means in the code, however whatever the reason for this search is, for sure it shouldn't be done repeatedly at every binlog rotation.

The weird thing is, we aren't even using GTIDs!
But still mysqld opens and reads ALL the available binary log files all the time. This is a serious regression compared to 5.6 where this wasn't happening, and it can hit you hard when you have a large number of binary log files. Caveat emptor.

I have raised a bug for the above, and really hope Oracle gives it the needed attention.

In place transparent compression of MySQL binary logs

Any DBA who has administered a busy master knows how fast the disk space occupied by binary logs may grow.  DBAs have no control on this: the growth depends on the workload, and the workload depends on many factors, e.g.:

- application changes (the applications start writing more due to code changes)

- traffic changes (the peak season arrive, your workload doubles in size)

- infrastructure changes (the devops add more servers)

- business changes (new business flows adds to existing workload)

So either you have being thoughtful and have planned in advance for a large enough storage space (to handle the increase in number of binary logs), or,  sooner or later, you will face the usual dilemma - how many retention days dare you give up to accommodate for the binlog growth?

In my case, I was very thoughtful, but the boss didn't listen and gave me servers with very limited binlog storage space and, more important, using internal disks so no way to add more disk space on demand. Pity, as I had previously found a way to move binlogs to a different filesystem without downtime. But unfortunately, there is no "different filesystem" this time. I'm stuck with what I have.

So, the obvious answer at first was to reduce the retention of binary logs via the
expire_logs_days variable. Not the ideal option, as in my situation, I had to reduce it to a mere 2 days, not even enough to survive a weekend. At the same time I didn't like the idea to keep more days and be waken up at 3am by a filesystem full alert.

So the idea of compressing the binary logs came to my mind, but I wanted to do it in a transparent way, preserving the existing binlog retention mechanisms (expire_logs_days variable and PURGE BINARY LOGS command should continue to work as before) and without breaking the MySQL server and/or replication. Ideally, the timestamps of the files themselves should also preserved.

I decided to try and compress the binary logs in place. In place means that when you look at your binlogs folder, you don't notice anything unusual.  Here's (a part of ) the listing of one of our servers with compression active:

-rw-rw---- 1 mysql mysql  13631245 Dec 14 14:17 dbmd01.079826

-rw-rw---- 1 mysql mysql  13909321 Dec 14 14:23 dbmd01.079827

-rw-rw---- 1 mysql mysql  13656948 Dec 14 14:30 dbmd01.079828

-rw-rw---- 1 mysql mysql  13915222 Dec 14 14:37 dbmd01.079829

-rw-rw---- 1 mysql mysql 104883640 Dec 14 14:44 dbmd01.079830

-rw-rw---- 1 mysql mysql 104898032 Dec 14 14:50 dbmd01.079831

-rw-rw---- 1 mysql mysql 104861122 Dec 14 14:57 dbmd01.079832

You can spot which files are compressed by looking at the file size, but everything else is preserved. Looking with file, here's what's in each of them:

dbmd01.079826: gzip compressed data

dbmd01.079827: gzip compressed data

dbmd01.079828: gzip compressed data

dbmd01.079829: gzip compressed data

dbmd01.079830: MySQL replication log

dbmd01.079831: MySQL replication log

dbmd01.079832: MySQL replication log

Basically, after compression, the compressed file retains the original file name. This is to keep MySQL happy - you know, these files are tracked in the index file and read when mysqld starts.

Speaking of which, here's what happens when you start mysqld  with in-place compression:

2016-10-26 03:06:13 0 [Note] /usr/sbin/mysqld (mysqld 5.6.34-79.1-log) starting as process 1407 ...

[ ... ]

2016-10-26 03:06:13 1407 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 2722915

2016-10-26 03:06:13 1407 [ERROR] Binlog has bad magic number;  It's not a binary log file that can be used by this version of MySQL

2016-10-26 03:06:13 1407 [ERROR] Binlog has bad magic number;  It's not a binary log file that can be used by this version of MySQL

2016-10-26 03:06:13 1407 [ERROR] Binlog has bad magic number;  It's not a binary log file that can be used by this version of MySQL

2016-10-26 03:06:13 1407 [ERROR] Binlog has bad magic number;  It's not a binary log file that can be used by this version of MySQL

Although these entries are flagged as ERROR, actually mysqld just ignores the compressed files, and more importantly, does not touch them.  

This way, compressed binlog files can be managed exactly like uncompressed, standard ones. Of course, I need to remember that if I need to peruse their content, I have to uncompress them before feeding them to the mysqlbinlog utility.

Last but not least, in order to ensure that we do not inadvertently compress binlogs that haven't been downloaded by all slaves yet,  the following extra safety rules are enforced:

- do not compress any binlog which is not at least 1 hour old 

- only compress binlogs that have a sequence number which is less than the current sequence number  of the most lagging slave

The script runs every 10 minutes, extracts the list of the binary logs which aren't compressed yet, applies the above rules, then it proceeds to compress them.

I have set expire_logs_days back to 7 days and have plenty of disk space for extra growth now....

You can find the  compress_binlog.sh which I crafted for the above on my GitHub page.

One caveat  - script hasn't been tested with binlog sequence numbers greater than 999,999. I am actually curious to see what happens to the binlog file name when we reach one million - need to either be very patient, or have a look at the source code... :-)

Enjoy!

Rick

Moving binary logs to a different filesystem without downtime

Another day at the office...

"Whoa, the write workload on our statistical cluster has  suddendly increased by 20% and the filesystem that holds the binary logs is no longer large enough".

Of course, I had warned the boss about this possibility when I received those servers with that tiny 250G filesystem for binlogs, but my red flag was just ignored as usual.

So here we are, presto I get this new shiny 600G LUN, but we need to stop the damn MySQL server in order to repoint the log_bin variable to the new storage area.

Dunno about you, but the idea of waking up at 2am to just perform a variable change is not something that makes me particularly happy. Not to mention the maintenance period that is needed around it....

So, I decided to investigate a bit about the possibilities to do such change without stopping the service.

As we all know, the log_bin variable is read-only and to change it, you need to restart mysqld.  So I wanted to check whether there was a way to actually swap the current binlog directory with another without making the server mad and/or lose data and/or causing downtime.

First and foremost I wanted  to check how the server would react with a rename of the binary logs folder. So I just issued the following:

mv /db/binlog /db/binlog_orig

I was very happy to find out that mysqld kept  running, and writing to the currently open file without any complaints.  I decided then to push the test further by actually linking a new folder to the old path and then switching to the next binlog.

So I created a symlink to the new binlog area first:

mkdir /db/binlog2
ln -s /db/binlog2 /db/binlog

I then connected to MySQL and issued a FLUSH BINARY LOGS. To my surprise, MySQL happily closed the current binary log (still being written in the original folder) and started a new one in the new folder. Oh,  and the index file was recreated there automatically too.  Cool :-)

Still something was not good, as the operation resulted in the binary log file number being reset to 1. Not cool if you have slaves (which you likely have, since you have binary logging enabled).

So I had to  guess how mysqld decides what the  number of the next binlog file should be.  My  first guess was that it should be looking at other files already in place. So  I repeated the steps above, but before actually issuing the flush logs command, I created an empty file in the new binary log folder with the same number as the one currently being written to in the old folder.
Voilà, that did the trick!  The new binlog file was now correctly numbered :-)

But what about slaves?  I did all these tests with no slave connected.
So I quickly set up a slave instance and set up replication, then I retried my binary logs path exchange trick.

Right after the binary log file switch, the slave stopped, complaining that it couldn't read the next file. Basically, it had finished reading the log written in the old path, but could not "see" the next one written in the new path. I was able to verify that the old log was entirely read, and just the switch to the next one had failed:

[ERROR] Error reading packet from server: could not find next log; the first event 'dbstat01.014676' at 103351600, the last event read from '/storage/binlog/dbstat01.016653' at 136744026, the last byte read from '/storage/binlog/dbstat01.016653' at 136744026. (server_errno=1236)

That position was exactly where the file, in the old path, was closed due to the flush:

-rw-rw---- 1 mysql mysql 136744026 Sep 23 14:30 dbstat01.016653

Okay I thought, I can just repoint the slave to next binlog, position 4. 

But if the slave complained, that means the IO_Thread is probably just still looking in the old path.  What if I just stop the slave and start it again?  

Pronto, STOP SLAVE; START SLAVE ...and the slave resumed replication from the new binlog  file in the new path just fine!

So happy that I have saved myself a nightly maint!

This was tested on Percona 5.6.31-77.0-log and previous versions, but I don't see why it shouldn't work on stock Oracle's or even on Maria.

If you are lazy like me, you can use the simple script that I have crafted for this test, you can find it on my GitHub page .