1

I have a primary MySQL DB with a secondary replica which, apparently, works perfectly.

The replica is connected through a VPN, which reports no problems.

SHOW SLAVE STATUS reports zero seconds behind master (except on slow query updates and so on, when lag is expected).

After hours, the load on the primary drops, and the replica stops updating. That is, I have a single table that is periodically updated even after hours, with a DATETIME timestamp, so it's very easy to check the MAX() of the recorded datetime; and by doing this, I can see lags that slowly grow, up to one hour. Suspiciously exactly one hour at most, actually.

Experimentally, I have created a dummy table and started writing to it. And, as I suspected, after a few (well, many) updates, abruptly the replica catches up... and immediately starts lagging again.

So, I conclude that the master sends updates only when a certain threshold is met. A size threshold? Say, every megabyte or so? And there must also be some timeout that expires after one hour, when the resync is forced come Hell or high water.

STOP SLAVE followed by START SLAVE also syncs the replication, every time, in a few seconds.

I would very much either lower the data threshold, if it exists, or (waaay better!) decrease the "forced update" timeout threshold to one minute so that the slave keeps in sync.

What I've checked:

  • innodb_flush_log_at_trx_commit = 0 (shouldn't matter. Tried 1 with no effect)
  • innodb_flush_log_at_timeout = 1
  • sync_binlog = 1 (again, should not matter)
  • binlog format is okay (I have other replicas that work - actually, this one, the only one behind a VPN, is an exact clone - except for the actual MySQL database - of another replica that works on a different database, flawlessly. Both are Ubuntu 20.04-LTS).
  • The primary reports all OK.

Replica process list is also good:

| 840 | system user | | NULL | Connect | 38 | Waiting for master to send event | NULL | | 841 | system user | | NULL | Connect | 8 | Slave has read all relay log; waiting for more updates | NULL |

IDs (as in this other question) are correct.

This... well, this looks as if someone was playing an abort-slave-event-count on me:

When this option is set to some positive integer value other than 0 (the default) it affects replication behavior as follows: After the replication SQL thread has started, value log events are permitted to be executed; after that, the replication SQL thread does not receive any more events, just as if the network connection from the source were cut. The replication SQL thread continues to run, and the output from SHOW SLAVE STATUS displays Yes in both the Slave_IO_Running and the Slave_SQL_Running columns, but no further events are read from the relay log.

Except, of course, that no one could have conceivably done it.

Other checks or clarifications thanks to Rick James's contribution:

  • Timezone problems: nope, both servers use the same configuration. And in that case I ought to see a constant lag, not a slowly growing one.
  • Transactions are committed eventually (they may run up to five minutes depending on what they're doing, but never more than that).
  • Nothing else is running either on the primary or the replica.
  • Timestamp/Datetime: the table receives a datetime that's externally generated, so the TZ of the machine or MySQL's don't enter into the matter.
  • I already did the trick of entering data into an expendable table (created ad hoc). I entered row after row, in autocommit mode, and ran a SELECT COUNT on the slave. The count remains frozen (while rows are entered into the master, where the COUNT goes up as expected), then after some time, bang!, the data arrives at the replica and the COUNT goes to the expected value... and stops there for another not-so-little time.

Checks I should have done and didn't, will do tomorrow:

  • log both the COUNT and the data size estimate, with rows of different size (e.g. slowly incrementing TEXT field), and the time intervals, when the sync happens when the almost only thing running is my fake "insert rows into expendable table" routine. See whether the critical factor is really the data size, or the time, or the number of rows. This would allow to determine whether the critical factor is a timeout, a data threshold, or a row threshold.

An interesting and useful observation by @RickJames:

Transactions are sent to the Replicas immediately after COMMIT.

I thought as much, and now I am sure. So, TRXs are sent to the replica immediately. Well, they aren't. So this is not a misconfiguration (I know I could do delayed replication, but I didn't); so if MySQL wouldn't ordinarily wait for replication, something must be positively borked here, something that is interfering with MySQL.

I'm more and more suspecting the VPN, somehow. Possibly a logical fallacy of post hoc ergo propter hoc, but this is the only VPN connection I have and the only connection that gives me headaches.

Other checks, with this in mind:

  • Network connectivity. Perfect.
  • Packet loss rate. Negligible on the copper, zero on the VPN.
  • Routing. Copacetic. But of course that would have been noticeable, as in "nothing works".
  • MTU. 1500 at both ends, an intentionally naive netcat block transfer of 200 MB of /dev/zero went from primary to replica, and vice versa, with no issues.

Whatever (else) could I be missing?

3
  • MASTER information request, please. Any SSD or NVME devices on MySQL Host server? Post on pastebin.com and share the links. From your SSH login root, Text results of: A) SELECT COUNT(*) FROM information_schema.tables; B) SHOW GLOBAL STATUS; after minimum 24 hours UPTIME C) SHOW GLOBAL VARIABLES; D) SHOW FULL PROCESSLIST; AND Optional very helpful information, if available includes - htop OR top for most active apps, ulimit -a for a Linux/Unix list of limits, iostat -xm 5 3 for stats info, for server workload tuning analysis to provide suggestions. Oct 28, 2021 at 13:12
  • @WilsonHauck hi, the problem has been traced down to the VPN being "flaky", going more-or-less-down on prolonged inactivity (see Bill Karwin's answer). The connection has been rebuilt on the other end, and the problem has gone away, at least for now.
    – LSerni
    Oct 28, 2021 at 14:50
  • 1
    Great News. Workload analysis is still available to you to provide suggestions to improve performance. Thanks Oct 28, 2021 at 19:31

2 Answers 2

1

SHOW SLAVE STATUS reports zero seconds behind master (except on slow query updates and so on, when lag is expected).

The Seconds_behind_master (aka `Seconds_behind_source on 8.0) only shows the difference between the timestamp of the last binlog entry it has executed on the replica and the timestamp of the last binlog entry it has downloaded. But it doesn't know if more binlogs are waiting to be downloaded on its source.

STOP SLAVE followed by START SLAVE also syncs the replication, every time, in a few seconds.

I think this is the most relevant clue. At least I've seen this before, and I was told why stopping and starting replication fixes it.

If MySQL's replication connection experiences packet loss from an unreliable connection, it uses exponential backoff when retrying transmission. This is done to avoid network congestion from retry packets. But it means that networks that are especially flaky cause long-lived TCP connections to become progressively slower and slower, as more pauses are inserted in between retries.

Stopping and starting replication starts a new TCP connection, which naturally has no pauses. But if it's a persistently flaky network, soon that connection also becomes slower.

Your deduction that something is wrong with your network or your VPN is probably correct.

Transactions are sent to the Replicas immediately after COMMIT.

This is not exactly true. Binlogs are written on the source instance immediately after the COMMIT. There they sit, waiting for a replica to download them. If the replica runs STOP SLAVE (aka STOP REPLICA), or if the replica itself is stopped, or if the network connection is broken for any reason, then no binlogs are fetched.

If the network is very slow, then binlogs continue to be fetched, but at such a slow rate that the replica may become further and further behind, even though it has executed all events in the binlog it has downloaded so far.

I have a single table that is periodically updated even after hours, with a DATETIME timestamp, so it's very easy to check the MAX() of the recorded datetime

This is the principle of the "heartbeat" feature introduced in MySQL 8.0. It sends a timestamp through the replication channel at a regular interval, so you can compare the latest timestamp it has processed to the current system time on the replica, and that gives a more accurate measure of replication lag than Seconds_behind_source.

If you're using a version of MySQL earlier than 8.0, you can use the free tool pt-heartbeat to achieve the same thing.

2
  • 1
    You hit the nail on the head. When running through the "backup" connection via SSH tunnel, no problem appeared even when stopping all tasks on the primary: the replica synced and stayed synced. When running a continuous PING on the VPN connection, again no problem. Stopping IP traffic through the VPN, for 2 minutes, and the replica found itself unable to sync, and started backing off. Sent all the notes to the VPN guys, and what do you know, they fixed things :-) .
    – LSerni
    Oct 28, 2021 at 14:53
  • @LSerni I'm glad it got fixed! Always be kind and patient with the VPN staff. They have to deal with a lot of complaints. For every one genuine fault, there are probably 99 complaints that turn out to be user error. :-( Oct 28, 2021 at 14:57
1
  • Timezone problems? Use TIMESTAMP instead of DATETIME for monitoring. Also compare SHOW VARIABLES LIKE '%zone%' between the servers.

  • Transactions are sent to the Replicas immediately after COMMIT. Check that you either run with autocommit=ON or explicitly use COMMIT. (There is no megabyte threshold.)

  • Backups using mysqldump (or similar tool) can clog things up.

  • ALTERs can clog the replication stream.

  • What version of MySQL? Any "clustering" technique being used? Is GTID in use?

  • innodb_flush_log_at_trx_commit -- "2" is similar to "0", but probably better in all situations. Change that.

  • Does STOP/START always fix the issue?

  • Is any big query running at night (ETL / UPDATE / DELETE / etc.)?

3
  • Yes, STOP/START consistently fixes the issue. I'm now suspecting something's going awry in the connection... except that if that were the case, eg if the VPN hung, START/STOP would avail nothing until I restarted the VPN, which I never needed to do. I guess if necessary I can play with the heartbeat function, hoping that whatever clogs the connection also stops the heartbeat signal... or if I find myself really lost, I might use a shorter heartbeat watch than the actual HB frequency, to forcibly issue a reconnect. It would be butchery, but needs must, I guess.
    – LSerni
    Oct 22, 2021 at 22:51
  • Insert the timestamp every minute; that should not hurt performance. Separately, write a simple test case that fails and file a bug report: bugs.mysql.com
    – Rick James
    Oct 22, 2021 at 22:57
  • I never thought this was a MySQL problem. Before, I just believed I must have botched the config somehow. Now... won't enter in details, but let's just say that there already have been issues with the network guys in this setup. I'm playing with the idea of bringing up a fake interface and opening a SSH tunnel via the public Internet to run through for a few hours (the replica isn't critical, fortunately, it's an off-site last-ditch backup) to see what happens. Maybe I'll file a report for the MySQL guys to maybe allow MySQL to detect the issue, once I've confirmed what it is.
    – LSerni
    Oct 22, 2021 at 23:12

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.