MySQL Bugs: #86829: Slave IO Disconnects and binlog transfer slowed down on sync_master

Bug #86829	Slave IO Disconnects and binlog transfer slowed down on sync_master_info
Submitted:	26 Jun 2017 17:42	Modified:	1 Sep 2017 12:13
Reporter:	Srinivasa Krishna Mamillapalli	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.6.36/5.6.37	OS:	Linux
Assigned to:	MySQL Verification Team	CPU Architecture:	Any
Tags:	Lost connection, server_errno=2013, Slave IO failed, System lock

Description:
We have had MySQL replication on Azure and noticed replication slave IO thread slowing down on network packet transfers and even dropping connections frequently.
MySQL replication IO threads reports lost connections and the corresponding binlog dump thread on the master gets disconnected on enabling sync_master_info to 1.

2017-06-23 12:33:48 [ERROR] Error reading packet from server: Lost connection to MySQL server during query (server_errno=2013)
2017-06-23 12:33:48 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'mysql-bin.0xxxxx' at position xxxxx.

How to repeat:
1.setup replication b/w 2 servers.
2.set sync_master_info =0.
3.Enable log_warnings=4.
4.start slave to notice slave IO is sending the binlogs from master to slave relay log.
slave received the data to relaylogs in full.(1.1G similar to master)
5. now, set sync_master_info=1 and start noticing the relay log status .
notice the errors in mysql logs related to slave IO thread disconnects and reconnects.
6. notice that binlog dump thread on the master disappers for some time and then reconnects.
7. on the slave,notice the relay log switch happen due to the disconnects and packet trasnfer to slow down.
8.No issues with disk IO on the slave and master. disk IO is not stressed at all.
Please note that there are no packet drops on the n/w later and connectivity is just good.
Enabling this parameter triggers the packet drop and slowes down the binlog transfer from master to slave.

Suggested fix:
What would be the impact on the n/w packet by enabling sync_master_info on the salve IO thread.
Why does the timings on the disconnects match with the timings on enabling the parameter and slowdown on binlog transfer.

according to the documentation, sync_maste_info would impact on the binlog information from master to sync on local disk(either to a file or table) on slave and should impact the DISK IO performance.

Also,if those are related, the errorlog entries for slave IO disconnects should have more descriptive info of the issues.

Hi!

You have specified your OS as Linux, while you are describing your problems as occurring  on Azure, which is Microsoft product.

Can you be more precise ?????

Thanks for the ack.
This is a cloud server hosted in Azure with the guest OS as RHEL6/7.

few more info on the actual replication issue..
Documentation states that "in order to have a crash safe slave, it is recommended to enable these parameters.

Settings for making the slave crash safe:
--relay-log-info-repository=TABLE
--master-info-repository=TABLE
--relay_log_recovery=ON
--sync_relay_log_info=1 
--sync_master_info=1

However, sync_master_info=1 seems to be causing performance issues for slave IO_thread to disconnect from the master and slowdown the binlog dump transfer from master to slave.. even when the salve SQL_thread is stopped to avoid the contention of reading/writing from the same log.

Hi,

> 5. now, set sync_master_info=1 and start noticing the relay log status .

This is not a bug, it is a problem with your VM. You do not have enough IOPS available to handle all the writes to the disk. (I assume master_info_repository = FILE)

If the value of sync_master_info is greater than 0, the slave synchronizes its master.info file to disk (using fdatasync()) after every sync_master_info events. 

If it is 0, the MySQL server performs no synchronization of the master.info file to disk; instead, the server relies on the operating system to flush its contents periodically as with any other file. 

So, first you had value of 0, the system was not forcing OS to sync the file and your VM was flushing it only from time to time and your IO use was not high. When you changed it to 1 your IO usage jumps as you are constantly flushing this to disk. Since you don't have a disk but some shared storage N layers below your VM your VM gets stuck and everything slows down.

all best
Bogdan

>> 5. now, set sync_master_info=1 and start noticing the relay log status .
> This is not a bug, it is a problem with your VM. You do not have enough IOPS available to handle all the writes to the disk. (I assume master_info_repository = FILE)

Hi Bogdan,
my master_info_repository is set to TABLE, and anyway experience the same issue.
Do you think that also in this case it may depend on IOPS? Cause the usage of disks, as a whole, is very low.

To give you an idea of how much performance may change, consider that having a "regular" usage, with sync_master_info = 1 the system takes a day to recover 1000 "seconds_behind_master" (at night, when traffic goes down). With sync_master_info = 0, instead, I saw it recover a 50.000 "seconds_behind_master" in 10 minutes at peak time.
I'm not an expert, but looks like it cannot depend only on IOPS.

All the best,

Fabrizio

Thanks Bogdan and Fabrizio.
yes, I do have the repository as TABLE(InnoDB) . not FILE.

The reason we wanted to have sync_master_info=1 is to ensure we have all the data from the master even in the event of a crash,to ensure a crash safe replication setup.
Iam aware of the IOPS issue it has on the system and the sync_master_info setting. Also,here the VM is not stressed at all on the disk IO. 
but it doenst really explain why it would slow down the slave IO thread to send the binlog events from master to slave.

to add further, I have no issues with salve dealy as the slave SQL_thread seems to be fast enough to apply the event locally on the slave. its just an issue with the slave_IO thread that was unable to keep up in sending the data from master.

Hi Fabrizio,

> Do you think that also in this case it may depend on IOPS? 
> Cause the usage of disks, as a whole, is very low.

That is bit unexpected with TABLE as on VM systems fsync is the expensive thing that eats up the performance (especially as in most systems it does nothing really). Anyhow even with TABLE you have table updates compared to with 0 you have no writes to table at all... from documentation:
".. the slave updates its master info repository table after every sync_master_info events. If it is 0, the table is never updated." so it def. takes more iops to write to table then not to, anyhow no fdatasync here so the VM "should" be able to handle it.

Now I guess this has something to do with Azure as I am running test for 6 hours already with high load on both PROXMOX (qemu-kvm) and on VMware ESXi and I see zero difference in performance / lagging between sync_master_info=1 and sync_master_info=0 when master_info_repository = TABLE; unfortunately my experience with Azure is not that great and I'm not even sure it's in the list of supported platforms.

all best
Bogdan

Hi Srinivasa,

> The reason we wanted to have sync_master_info=1 is to ensure we have
> all the data from the master even in the event of a crash,to ensure 
> a crash safe replication setup.

- have you tried using FILE? especially if you have the "in the event of crash.." in the event of crash data from file is usually more accessible then data from table, with sync_master_info=1

- have you considered running semisync: https://dev.mysql.com/doc/refman/5.7/en/replication-semisync.html it is way more useful then sync_master_info :D

All in all I don't believe this is a bug. Maybe there's some slight incompatibility between mysqld binary and azure system that's causing this but since Azure is not on the supported env. list there's not much I can do wrt "bug status". I'd try latest 5.7 to compare changes but I don't have access to Azure. 

Now if you have support contract with Oracle I urge you to create an SR there as my colleagues from support would help you design the system that will work acceptably on Azure.

all best
Bogdan

Thanks, As per the docs, it is best to have TABLE repository than FILE for crash safe slave.

I don't believe there is any references  in source code, to throttle the n/w packets or transfer of binlog events from master to slave if we set sync_master_info=1. in Which case, we could rule out that is not a bug in mysql.
I might be wrong. could you check and confirm the same to rule that one out.

I had a detailed discussion with Azure team and they claims that it is a mysql issue and nothing related to the Azure server config.

if Azure is not listed as one of the supported platforms for MySQL yet..then Iam surprised how MS is integrating MySQL with in their IAAS for Production support. Obviously thats for MS Azure team to answer :)

Thank you
Krishna.

Hi,

Discussed with our engineering team and we have some questions.

Regarding frequent disconnections, What is the setting of slave-net-timeout? 
Could it be that it is too low and this one extra transaction (updating sync_master_info table) on every event is causing some delay (because of some reason/bug) and heart beat period was not sent in that less "slave-net-timeout" frame, so Master is thinking that Slave is dead ?

https://dev.mysql.com/doc/refman/5.7/en/replication-options-slave.html#option_mysqld_slave...

Are able to reproduce without azure or on azure but setting a good (reasonable value of slave-net-timeout)?

thanks
Bogdan

Hi Krishna, lemme answer few questions I missed,

> Thanks, As per the docs, it is best to have TABLE repository 
> than FILE for crash safe slave.

That's undisputed! FILE is remnant of the old times. I just wanted you to try using FILE to get more data about what's going on (would be very interesting if for e.g. with FILE you do not have this problem any more), not as any type of solution. Sorry if I was not clear about that. TABLE is a way to go that's for sure.

> I don't believe there is any references  in source code,
> to throttle the n/w packets or transfer of binlog events 
> from master to slave if we set sync_master_info=1. in 
> Which case, we could rule out that is not a bug in mysql.

No throttling that's for sure :)

What is happening is there's one transaction more for every event (write the master info into table) and maybe this causes some delay as I wrote in previous note. It's unlikely but I don't have experience with Azure, no clue how the network latency is nor I really know how you configured timeouts (as I asked in previous note) so that's the direction to explore further.

> if Azure is not listed as one of the supported platforms
> for MySQL yet..then Iam surprised how MS is integrating
> MySQL with in their IAAS for Production support.

I would really restrain myself from commenting about MS plans and execution details, even if I had any opinion on it it would not be worth the time it took to write them down :D .. They know what and why they are doing and if they need help with that I'm sure they know how to contact our support & consulting teams :D

all best
Bogdan

p.s. any reason you are running this on 5.6 instead on 5.7?

Hi,

One other thing, can you please upload the full config for both master and slave

all best
Bogdan

Hi,
thanks for the config. 

Can you try, on the same env.
latest 5.7
your 5.6

but configure slave-net-timeout to 60sec

Thanks
Bogdan

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

slave_net_timeout is default to 3600sec.
all these issues were stopped once we disable sync_master_info .

slave disconnects were stopped, binlog pkt trasnfer speed from master to slave is increased.
No packet loss observed.

Sorry I can't reproduce this with your config on bare metal nor or proxmox either way.

all best
Bogdan