Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi Pavel.
Yes, by "binlog filename changes" I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymailhttps://polymail.io/?utm_source=polymail&utm_medium=referral&utm_campaign=signature
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov <mailto:Pavel%20Ivanov%20pivanof@google.com> > wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
Yes, by “binlog filename changes” I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymail https://polymail.io/?utm_source=polymail&utm_medium=referral&utm_campaign=signature
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov <Pavel+Ivanov+%3Cpivanof@google.com%3E>> wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
Hi Pavel.
To describe the setup a little better the master replicates to a semi-sync slave, which then replicates to an async slave. This is to ensure at any point in time both the master and the semi-sync slave have a complete copy of the data. If the master fails the semi-sync is automatically promoted to master and the async switches to replicating with semi-sync replication. If the semi-sync fails then the async remasters itself to the master and switches to semi-sync.
However I don't think the 3rd node has any bearing on the hang, I built a test cluster without it and the hang is still easy to reproduce. I just restore a decent sized dump, in this case a portion of the Wikipedia database and the cluster reliably hangs when the master begins writing to the new binlog.
The dump is here if someone wants to use it to reproduce: https://dumps.wikimedia.org/enwiki/latest/enwiki-latest-category.sql.gz
I have created a gist with the output of `SHOW STATUS LIKE 'Rpl_semi_sync%s'` on both master and slave of the simplified 2 node setup. I have also included the binlogs of both the master and the slave and the relay log on the slave.
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68b
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68bLet me know if there is any other useful information I can provide.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Friday, 29 July 2016 4:31:26 PM To: Joseph Glanville Cc: Will Fong; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville <jpg@jpg.id.aumailto:jpg@jpg.id.au> wrote:
Hi Pavel.
Yes, by "binlog filename changes" I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymailhttps://polymail.io/?utm_source=polymail&utm_medium=referral&utm_campaign=signature
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov mailto:Pavel+Ivanov+%3Cpivanof@google.com%3E > wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
Hi,
Does the problem appear if you set the timeout value to 9223372036854775807?
On Fri, Jul 29, 2016 at 3:24 AM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
To describe the setup a little better the master replicates to a semi-sync slave, which then replicates to an async slave. This is to ensure at any point in time both the master and the semi-sync slave have a complete copy of the data. If the master fails the semi-sync is automatically promoted to master and the async switches to replicating with semi-sync replication. If the semi-sync fails then the async remasters itself to the master and switches to semi-sync.
However I don't think the 3rd node has any bearing on the hang, I built a test cluster without it and the hang is still easy to reproduce. I just restore a decent sized dump, in this case a portion of the Wikipedia database and the cluster reliably hangs when the master begins writing to the new binlog.
The dump is here if someone wants to use it to reproduce: https://dumps.wikimedia.org/enwiki/latest/enwiki-latest-category.sql.gz
I have created a gist with the output of `SHOW STATUS LIKE 'Rpl_semi_sync%s'` on both master and slave of the simplified 2 node setup. I have also included the binlogs of both the master and the slave and the relay log on the slave.
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68b
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68bLet me know if there is any other useful information I can provide.
Joseph. ------------------------------ *From:* Pavel Ivanov pivanof@google.com *Sent:* Friday, 29 July 2016 4:31:26 PM *To:* Joseph Glanville *Cc:* Will Fong; maria-discuss@lists.launchpad.net *Subject:* Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
Yes, by “binlog filename changes” I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymail https://polymail.io/?utm_source=polymail&utm_medium=referral&utm_campaign=signature
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov <Pavel+Ivanov+%3Cpivanof@google.com%3E>> wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~maria-discuss Post to : maria-discuss@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-discuss More help : https://help.launchpad.net/ListHelp
Hi Justin,
Adjusting the timeout doesn't seem to have any effect. Though setting it low enough does cause the master to time out waiting for the slave to acknowledge the write and falls back to async only to immediately re-establish semi-sync replication. It does this every time the master begins writing to a new binlog.
Joseph.
________________________________ From: Justin Swanhart greenlion@gmail.com Sent: Friday, 29 July 2016 6:17:28 PM To: Joseph Glanville Cc: Pavel Ivanov; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi,
Does the problem appear if you set the timeout value to 9223372036854775807?
On Fri, Jul 29, 2016 at 3:24 AM, Joseph Glanville <jpg@jpg.id.aumailto:jpg@jpg.id.au> wrote:
Hi Pavel.
To describe the setup a little better the master replicates to a semi-sync slave, which then replicates to an async slave. This is to ensure at any point in time both the master and the semi-sync slave have a complete copy of the data. If the master fails the semi-sync is automatically promoted to master and the async switches to replicating with semi-sync replication. If the semi-sync fails then the async remasters itself to the master and switches to semi-sync.
However I don't think the 3rd node has any bearing on the hang, I built a test cluster without it and the hang is still easy to reproduce. I just restore a decent sized dump, in this case a portion of the Wikipedia database and the cluster reliably hangs when the master begins writing to the new binlog.
The dump is here if someone wants to use it to reproduce: https://dumps.wikimedia.org/enwiki/latest/enwiki-latest-category.sql.gz
I have created a gist with the output of `SHOW STATUS LIKE 'Rpl_semi_sync%s'` on both master and slave of the simplified 2 node setup. I have also included the binlogs of both the master and the slave and the relay log on the slave.
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68b
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68bLet me know if there is any other useful information I can provide.
Joseph.
________________________________ From: Pavel Ivanov <pivanof@google.commailto:pivanof@google.com> Sent: Friday, 29 July 2016 4:31:26 PM To: Joseph Glanville Cc: Will Fong; maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville <jpg@jpg.id.aumailto:jpg@jpg.id.au> wrote:
Hi Pavel.
Yes, by “binlog filename changes” I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymailhttps://polymail.io/?utm_source=polymail&utm_medium=referral&utm_campaign=signature
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov mailto:Pavel+Ivanov+%3Cpivanof@google.com%3E > wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~maria-discuss Post to : maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-discuss More help : https://help.launchpad.net/ListHelp
All the status variables look sane. But you've uploaded empty binlogs, there's no transaction that is hung in them. So I'd guess it should be in mariadb-bin.000004 (or an earlier file) on master and either it doesn't exist on slave or it's in mariadb-bin.000001 and relay-bin.000004 (or in earlier relay-bin.* file).
On Fri, Jul 29, 2016 at 1:29 AM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Justin,
Adjusting the timeout doesn't seem to have any effect. Though setting it low enough does cause the master to time out waiting for the slave to acknowledge the write and falls back to async only to immediately re-establish semi-sync replication. It does this every time the master begins writing to a new binlog.
Joseph. ------------------------------ *From:* Justin Swanhart greenlion@gmail.com *Sent:* Friday, 29 July 2016 6:17:28 PM *To:* Joseph Glanville *Cc:* Pavel Ivanov; maria-discuss@lists.launchpad.net
*Subject:* Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi,
Does the problem appear if you set the timeout value to 9223372036854775807?
On Fri, Jul 29, 2016 at 3:24 AM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
To describe the setup a little better the master replicates to a semi-sync slave, which then replicates to an async slave. This is to ensure at any point in time both the master and the semi-sync slave have a complete copy of the data. If the master fails the semi-sync is automatically promoted to master and the async switches to replicating with semi-sync replication. If the semi-sync fails then the async remasters itself to the master and switches to semi-sync.
However I don't think the 3rd node has any bearing on the hang, I built a test cluster without it and the hang is still easy to reproduce. I just restore a decent sized dump, in this case a portion of the Wikipedia database and the cluster reliably hangs when the master begins writing to the new binlog.
The dump is here if someone wants to use it to reproduce: https://dumps.wikimedia.org/enwiki/latest/enwiki-latest-category.sql.gz
I have created a gist with the output of `SHOW STATUS LIKE 'Rpl_semi_sync%s'` on both master and slave of the simplified 2 node setup. I have also included the binlogs of both the master and the slave and the relay log on the slave.
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68b
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68bLet me know if there is any other useful information I can provide.
Joseph. ------------------------------ *From:* Pavel Ivanov pivanof@google.com *Sent:* Friday, 29 July 2016 4:31:26 PM *To:* Joseph Glanville *Cc:* Will Fong; maria-discuss@lists.launchpad.net *Subject:* Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
Yes, by “binlog filename changes” I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymail https://polymail.io/?utm_source=polymail&utm_medium=referral&utm_campaign=signature
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov <Pavel+Ivanov+%3Cpivanof@google.com%3E>> wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~maria-discuss Post to : maria-discuss@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-discuss More help : https://help.launchpad.net/ListHelp
I have created a gist with as much information as I could including the server configs: https://gist.github.com/josephglanville/4337240e648e77ce7020ebaa1fb8d6b0
This time I uploaded all of the binlog and relay files from both the master and the slave as I don't really know what I am looking for in them.
Ignore the `read_only` variable, it's switched to read write dynamically, report_host is also empty but this doesn't seem to have any effect anyways.
I have updated to to report the actual IP address for the machine correctly however.
I reduced the binlog size to make the issue faster to reproduce (and make the binlogs a bit smaller for ease of uploading).
Basic steps to reproduce is to:
Create the initial master database.
Seed the slave using xtrabackup.
Update slave GTID position using information returned from xtrabackup
Connect the slave using GTID
Insert some data, check that data is replicating correctly to slave.
Keep inserting data until binlog rolls over.
Note that inserts now hang on waiting for slave ack.
Happy to help anyone with further information on how to reproduce.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Saturday, 30 July 2016 9:07:54 AM To: Joseph Glanville Cc: Justin Swanhart; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
All the status variables look sane. But you've uploaded empty binlogs, there's no transaction that is hung in them. So I'd guess it should be in mariadb-bin.000004 (or an earlier file) on master and either it doesn't exist on slave or it's in mariadb-bin.000001 and relay-bin.000004 (or in earlier relay-bin.* file).
On Fri, Jul 29, 2016 at 1:29 AM, Joseph Glanville <jpg@jpg.id.aumailto:jpg@jpg.id.au> wrote:
Hi Justin,
Adjusting the timeout doesn't seem to have any effect. Though setting it low enough does cause the master to time out waiting for the slave to acknowledge the write and falls back to async only to immediately re-establish semi-sync replication. It does this every time the master begins writing to a new binlog.
Joseph.
________________________________ From: Justin Swanhart <greenlion@gmail.commailto:greenlion@gmail.com> Sent: Friday, 29 July 2016 6:17:28 PM To: Joseph Glanville Cc: Pavel Ivanov; maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi,
Does the problem appear if you set the timeout value to 9223372036854775807?
On Fri, Jul 29, 2016 at 3:24 AM, Joseph Glanville <jpg@jpg.id.aumailto:jpg@jpg.id.au> wrote:
Hi Pavel.
To describe the setup a little better the master replicates to a semi-sync slave, which then replicates to an async slave. This is to ensure at any point in time both the master and the semi-sync slave have a complete copy of the data. If the master fails the semi-sync is automatically promoted to master and the async switches to replicating with semi-sync replication. If the semi-sync fails then the async remasters itself to the master and switches to semi-sync.
However I don't think the 3rd node has any bearing on the hang, I built a test cluster without it and the hang is still easy to reproduce. I just restore a decent sized dump, in this case a portion of the Wikipedia database and the cluster reliably hangs when the master begins writing to the new binlog.
The dump is here if someone wants to use it to reproduce: https://dumps.wikimedia.org/enwiki/latest/enwiki-latest-category.sql.gz
I have created a gist with the output of `SHOW STATUS LIKE 'Rpl_semi_sync%s'` on both master and slave of the simplified 2 node setup. I have also included the binlogs of both the master and the slave and the relay log on the slave.
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68b
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68bLet me know if there is any other useful information I can provide.
Joseph.
________________________________ From: Pavel Ivanov <pivanof@google.commailto:pivanof@google.com> Sent: Friday, 29 July 2016 4:31:26 PM To: Joseph Glanville Cc: Will Fong; maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville <jpg@jpg.id.aumailto:jpg@jpg.id.au> wrote:
Hi Pavel.
Yes, by “binlog filename changes” I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymailhttps://polymail.io/?utm_source=polymail&utm_medium=referral&utm_campaign=signature
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov mailto:Pavel+Ivanov+%3Cpivanof@google.com%3E > wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~maria-discuss Post to : maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-discuss More help : https://help.launchpad.net/ListHelp
Hi,
I have created a set of easy scripts to trigger the hang reliably with 10.1 on Ubuntu 14.04.
https://gist.github.com/josephglanville/c9a69b02de319ee06aef1a8d787bcce3
Hopefully this is just a problem with the way I am configuring the replication or the binlog settings because I don't see how noone else would have hit this if they are actually using semi-sync replication with reasonably large values for the semi-sync timeout.
Joseph.
________________________________ From: Maria-discuss maria-discuss-bounces+jpg=jpg.id.au@lists.launchpad.net on behalf of Joseph Glanville jpg@jpg.id.au Sent: Sunday, 31 July 2016 7:37:51 PM To: maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
I have created a gist with as much information as I could including the server configs: https://gist.github.com/josephglanville/4337240e648e77ce7020ebaa1fb8d6b0
This time I uploaded all of the binlog and relay files from both the master and the slave as I don't really know what I am looking for in them.
Ignore the `read_only` variable, it's switched to read write dynamically, report_host is also empty but this doesn't seem to have any effect anyways.
I have updated to to report the actual IP address for the machine correctly however.
I reduced the binlog size to make the issue faster to reproduce (and make the binlogs a bit smaller for ease of uploading).
Basic steps to reproduce is to:
Create the initial master database.
Seed the slave using xtrabackup.
Update slave GTID position using information returned from xtrabackup
Connect the slave using GTID
Insert some data, check that data is replicating correctly to slave.
Keep inserting data until binlog rolls over.
Note that inserts now hang on waiting for slave ack.
Happy to help anyone with further information on how to reproduce.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Saturday, 30 July 2016 9:07:54 AM To: Joseph Glanville Cc: Justin Swanhart; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
All the status variables look sane. But you've uploaded empty binlogs, there's no transaction that is hung in them. So I'd guess it should be in mariadb-bin.000004 (or an earlier file) on master and either it doesn't exist on slave or it's in mariadb-bin.000001 and relay-bin.000004 (or in earlier relay-bin.* file).
On Fri, Jul 29, 2016 at 1:29 AM, Joseph Glanville <jpg@jpg.id.aumailto:jpg@jpg.id.au> wrote:
Hi Justin,
Adjusting the timeout doesn't seem to have any effect. Though setting it low enough does cause the master to time out waiting for the slave to acknowledge the write and falls back to async only to immediately re-establish semi-sync replication. It does this every time the master begins writing to a new binlog.
Joseph.
________________________________ From: Justin Swanhart <greenlion@gmail.commailto:greenlion@gmail.com> Sent: Friday, 29 July 2016 6:17:28 PM To: Joseph Glanville Cc: Pavel Ivanov; maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi,
Does the problem appear if you set the timeout value to 9223372036854775807?
On Fri, Jul 29, 2016 at 3:24 AM, Joseph Glanville <jpg@jpg.id.aumailto:jpg@jpg.id.au> wrote:
Hi Pavel.
To describe the setup a little better the master replicates to a semi-sync slave, which then replicates to an async slave. This is to ensure at any point in time both the master and the semi-sync slave have a complete copy of the data. If the master fails the semi-sync is automatically promoted to master and the async switches to replicating with semi-sync replication. If the semi-sync fails then the async remasters itself to the master and switches to semi-sync.
However I don't think the 3rd node has any bearing on the hang, I built a test cluster without it and the hang is still easy to reproduce. I just restore a decent sized dump, in this case a portion of the Wikipedia database and the cluster reliably hangs when the master begins writing to the new binlog.
The dump is here if someone wants to use it to reproduce: https://dumps.wikimedia.org/enwiki/latest/enwiki-latest-category.sql.gz
I have created a gist with the output of `SHOW STATUS LIKE 'Rpl_semi_sync%s'` on both master and slave of the simplified 2 node setup. I have also included the binlogs of both the master and the slave and the relay log on the slave.
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68b
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68bLet me know if there is any other useful information I can provide.
Joseph.
________________________________ From: Pavel Ivanov <pivanof@google.commailto:pivanof@google.com> Sent: Friday, 29 July 2016 4:31:26 PM To: Joseph Glanville Cc: Will Fong; maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville <jpg@jpg.id.aumailto:jpg@jpg.id.au> wrote:
Hi Pavel.
Yes, by “binlog filename changes” I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymailhttps://polymail.io/?utm_source=polymail&utm_medium=referral&utm_campaign=signature
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov mailto:Pavel+Ivanov+%3Cpivanof@google.com%3E > wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~maria-discuss Post to : maria-discuss@lists.launchpad.netmailto:maria-discuss@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-discuss More help : https://help.launchpad.net/ListHelp
Sorry, I didn't look at the logs you provided earlier. The error log on the master looks very interesting. Here's the important snippet:
2016-07-30 8:01:27 140604322384640 [Note] ActiveTranx:insert_tranx_node: insert (mariadb-bin.000004, 2039896) in entry(71) ... 2016-07-30 8:01:27 140604322384640 [Note] ReplSemiSyncMaster::commitTrx: init wait position (mariadb-bin.000005, 2039896), 2016-07-30 8:01:27 140604322384640 [Note] ReplSemiSyncMaster::commitTrx: wait 18446744073709551615 ms for binlog sent (mariadb-bin.000005, 2039896) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::readSlaveReply: Got reply (mariadb-bin.000004, 2039896) 2016-07-30 8:01:27 140604322687744 [Note] ActiveTranx::::clear_active_tranx_nodes: cleared all nodes 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::reportReplyBinlog: Got reply at (mariadb-bin.000004, 2039896) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::updateSyncHeader: server(1684287243), (mariadb-bin.000004, 2039941) sync(0), repl(1) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::updateSyncHeader: server(1684287243), (mariadb-bin.000005, 288) sync(0), repl(1) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::updateSyncHeader: server(1684287243), (mariadb-bin.000005, 329) sync(0), repl(1)
It shows that when transaction is getting committed and written into binlog ending at position mariadb-bin.000004:2039896, somehow the function ReplSemiSyncMaster::commitTrx() gets trx_wait_binlog_name = 'mariadb-bin.000005' and trx_wait_binlog_pos = 2039896. I.e. the function gets the position of the transaction to wait semi-sync ack for correctly, but the file name is already the one that is current after rotation. Master starts waiting for that position, but the slave of course cannot send ack for that position because master didn't send binlogs up to mariadb-bin.000005:2039896 yet.
So it looks like there's some kind of race between updating MYSQL_BIN_LOG::log_file_name during rotation and passing the current value of log_file_name to the semi_sync_master plugin through the after_sync hook.
Kristian, do you have any idea what's going on? Is there an inappropriate lock release/re-acquire somewhere?
Joseph, I see you've already filed https://jira.mariadb.org/browse/MDEV-10553. That's a good call. Hopefully it will be picked up soon.
On Fri, Aug 12, 2016 at 8:33 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi,
I have created a set of easy scripts to trigger the hang reliably with 10.1 on Ubuntu 14.04.
https://gist.github.com/josephglanville/c9a69b02de319ee06aef1a8d787bcce3
Hopefully this is just a problem with the way I am configuring the replication or the binlog settings because I don't see how noone else would have hit this if they are actually using semi-sync replication with reasonably large values for the semi-sync timeout.
Joseph.
________________________________ From: Maria-discuss maria-discuss-bounces+jpg=jpg.id.au@lists.launchpad.net on behalf of Joseph Glanville jpg@jpg.id.au Sent: Sunday, 31 July 2016 7:37:51 PM To: maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
I have created a gist with as much information as I could including the server configs: https://gist.github.com/josephglanville/4337240e648e77ce7020ebaa1fb8d6b0
This time I uploaded all of the binlog and relay files from both the master and the slave as I don't really know what I am looking for in them.
Ignore the `read_only` variable, it's switched to read write dynamically, report_host is also empty but this doesn't seem to have any effect anyways.
I have updated to to report the actual IP address for the machine correctly however.
I reduced the binlog size to make the issue faster to reproduce (and make the binlogs a bit smaller for ease of uploading).
Basic steps to reproduce is to:
Create the initial master database.
Seed the slave using xtrabackup.
Update slave GTID position using information returned from xtrabackup
Connect the slave using GTID
Insert some data, check that data is replicating correctly to slave.
Keep inserting data until binlog rolls over.
Note that inserts now hang on waiting for slave ack.
Happy to help anyone with further information on how to reproduce.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Saturday, 30 July 2016 9:07:54 AM To: Joseph Glanville Cc: Justin Swanhart; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
All the status variables look sane. But you've uploaded empty binlogs, there's no transaction that is hung in them. So I'd guess it should be in mariadb-bin.000004 (or an earlier file) on master and either it doesn't exist on slave or it's in mariadb-bin.000001 and relay-bin.000004 (or in earlier relay-bin.* file).
On Fri, Jul 29, 2016 at 1:29 AM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Justin,
Adjusting the timeout doesn't seem to have any effect. Though setting it low enough does cause the master to time out waiting for the slave to acknowledge the write and falls back to async only to immediately re-establish semi-sync replication. It does this every time the master begins writing to a new binlog.
Joseph.
________________________________ From: Justin Swanhart greenlion@gmail.com Sent: Friday, 29 July 2016 6:17:28 PM To: Joseph Glanville Cc: Pavel Ivanov; maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi,
Does the problem appear if you set the timeout value to 9223372036854775807?
On Fri, Jul 29, 2016 at 3:24 AM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
To describe the setup a little better the master replicates to a semi-sync slave, which then replicates to an async slave. This is to ensure at any point in time both the master and the semi-sync slave have a complete copy of the data. If the master fails the semi-sync is automatically promoted to master and the async switches to replicating with semi-sync replication. If the semi-sync fails then the async remasters itself to the master and switches to semi-sync.
However I don't think the 3rd node has any bearing on the hang, I built a test cluster without it and the hang is still easy to reproduce. I just restore a decent sized dump, in this case a portion of the Wikipedia database and the cluster reliably hangs when the master begins writing to the new binlog.
The dump is here if someone wants to use it to reproduce: https://dumps.wikimedia.org/enwiki/latest/enwiki-latest-category.sql.gz
I have created a gist with the output of `SHOW STATUS LIKE 'Rpl_semi_sync%s'` on both master and slave of the simplified 2 node setup. I have also included the binlogs of both the master and the slave and the relay log on the slave.
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68b
Let me know if there is any other useful information I can provide.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Friday, 29 July 2016 4:31:26 PM To: Joseph Glanville Cc: Will Fong; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
Yes, by “binlog filename changes” I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymail
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov > wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~maria-discuss Post to : maria-discuss@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-discuss More help : https://help.launchpad.net/ListHelp
Hi,
The bug isn't reproducible when using AFTER_COMMIT over AFTER_SYNC.
So the race happens somewhere between the after_flush hook and the after_sync hook, likely because rotate is called after after_flush.
Unfortunately I don't have enough knowledge of the binlog code to do much more debugging.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Saturday, 13 August 2016 2:17:39 PM To: Joseph Glanville; Kristian Nielsen Cc: maria-discuss@lists.launchpad.net; Will Fong Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Sorry, I didn't look at the logs you provided earlier. The error log on the master looks very interesting. Here's the important snippet:
2016-07-30 8:01:27 140604322384640 [Note] ActiveTranx:insert_tranx_node: insert (mariadb-bin.000004, 2039896) in entry(71) ... 2016-07-30 8:01:27 140604322384640 [Note] ReplSemiSyncMaster::commitTrx: init wait position (mariadb-bin.000005, 2039896), 2016-07-30 8:01:27 140604322384640 [Note] ReplSemiSyncMaster::commitTrx: wait 18446744073709551615 ms for binlog sent (mariadb-bin.000005, 2039896) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::readSlaveReply: Got reply (mariadb-bin.000004, 2039896) 2016-07-30 8:01:27 140604322687744 [Note] ActiveTranx::::clear_active_tranx_nodes: cleared all nodes 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::reportReplyBinlog: Got reply at (mariadb-bin.000004, 2039896) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::updateSyncHeader: server(1684287243), (mariadb-bin.000004, 2039941) sync(0), repl(1) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::updateSyncHeader: server(1684287243), (mariadb-bin.000005, 288) sync(0), repl(1) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::updateSyncHeader: server(1684287243), (mariadb-bin.000005, 329) sync(0), repl(1)
It shows that when transaction is getting committed and written into binlog ending at position mariadb-bin.000004:2039896, somehow the function ReplSemiSyncMaster::commitTrx() gets trx_wait_binlog_name = 'mariadb-bin.000005' and trx_wait_binlog_pos = 2039896. I.e. the function gets the position of the transaction to wait semi-sync ack for correctly, but the file name is already the one that is current after rotation. Master starts waiting for that position, but the slave of course cannot send ack for that position because master didn't send binlogs up to mariadb-bin.000005:2039896 yet.
So it looks like there's some kind of race between updating MYSQL_BIN_LOG::log_file_name during rotation and passing the current value of log_file_name to the semi_sync_master plugin through the after_sync hook.
Kristian, do you have any idea what's going on? Is there an inappropriate lock release/re-acquire somewhere?
Joseph, I see you've already filed https://jira.mariadb.org/browse/MDEV-10553. That's a good call. Hopefully it will be picked up soon.
On Fri, Aug 12, 2016 at 8:33 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi,
I have created a set of easy scripts to trigger the hang reliably with 10.1 on Ubuntu 14.04.
https://gist.github.com/josephglanville/c9a69b02de319ee06aef1a8d787bcce3
Hopefully this is just a problem with the way I am configuring the replication or the binlog settings because I don't see how noone else would have hit this if they are actually using semi-sync replication with reasonably large values for the semi-sync timeout.
Joseph.
________________________________ From: Maria-discuss maria-discuss-bounces+jpg=jpg.id.au@lists.launchpad.net on behalf of Joseph Glanville jpg@jpg.id.au Sent: Sunday, 31 July 2016 7:37:51 PM To: maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
I have created a gist with as much information as I could including the server configs: https://gist.github.com/josephglanville/4337240e648e77ce7020ebaa1fb8d6b0
This time I uploaded all of the binlog and relay files from both the master and the slave as I don't really know what I am looking for in them.
Ignore the `read_only` variable, it's switched to read write dynamically, report_host is also empty but this doesn't seem to have any effect anyways.
I have updated to to report the actual IP address for the machine correctly however.
I reduced the binlog size to make the issue faster to reproduce (and make the binlogs a bit smaller for ease of uploading).
Basic steps to reproduce is to:
Create the initial master database.
Seed the slave using xtrabackup.
Update slave GTID position using information returned from xtrabackup
Connect the slave using GTID
Insert some data, check that data is replicating correctly to slave.
Keep inserting data until binlog rolls over.
Note that inserts now hang on waiting for slave ack.
Happy to help anyone with further information on how to reproduce.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Saturday, 30 July 2016 9:07:54 AM To: Joseph Glanville Cc: Justin Swanhart; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
All the status variables look sane. But you've uploaded empty binlogs, there's no transaction that is hung in them. So I'd guess it should be in mariadb-bin.000004 (or an earlier file) on master and either it doesn't exist on slave or it's in mariadb-bin.000001 and relay-bin.000004 (or in earlier relay-bin.* file).
On Fri, Jul 29, 2016 at 1:29 AM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Justin,
Adjusting the timeout doesn't seem to have any effect. Though setting it low enough does cause the master to time out waiting for the slave to acknowledge the write and falls back to async only to immediately re-establish semi-sync replication. It does this every time the master begins writing to a new binlog.
Joseph.
________________________________ From: Justin Swanhart greenlion@gmail.com Sent: Friday, 29 July 2016 6:17:28 PM To: Joseph Glanville Cc: Pavel Ivanov; maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi,
Does the problem appear if you set the timeout value to 9223372036854775807?
On Fri, Jul 29, 2016 at 3:24 AM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
To describe the setup a little better the master replicates to a semi-sync slave, which then replicates to an async slave. This is to ensure at any point in time both the master and the semi-sync slave have a complete copy of the data. If the master fails the semi-sync is automatically promoted to master and the async switches to replicating with semi-sync replication. If the semi-sync fails then the async remasters itself to the master and switches to semi-sync.
However I don't think the 3rd node has any bearing on the hang, I built a test cluster without it and the hang is still easy to reproduce. I just restore a decent sized dump, in this case a portion of the Wikipedia database and the cluster reliably hangs when the master begins writing to the new binlog.
The dump is here if someone wants to use it to reproduce: https://dumps.wikimedia.org/enwiki/latest/enwiki-latest-category.sql.gz
I have created a gist with the output of `SHOW STATUS LIKE 'Rpl_semi_sync%s'` on both master and slave of the simplified 2 node setup. I have also included the binlogs of both the master and the slave and the relay log on the slave.
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68b
Let me know if there is any other useful information I can provide.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Friday, 29 July 2016 4:31:26 PM To: Joseph Glanville Cc: Will Fong; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
Yes, by “binlog filename changes” I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist: https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymail
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov > wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~maria-discuss Post to : maria-discuss@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-discuss More help : https://help.launchpad.net/ListHelp
Note that in the AFTER_COMMIT mode waiting for semi-sync ack happens later than in AFTER_SYNC mode. So either this is not a race, or the race is made possible by some semi-sync related code... Sounds pretty strange...
On Sat, Aug 13, 2016 at 4:30 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi,
The bug isn't reproducible when using AFTER_COMMIT over AFTER_SYNC.
So the race happens somewhere between the after_flush hook and the after_sync hook, likely because rotate is called after after_flush.
Unfortunately I don't have enough knowledge of the binlog code to do much more debugging.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Saturday, 13 August 2016 2:17:39 PM To: Joseph Glanville; Kristian Nielsen Cc: maria-discuss@lists.launchpad.net; Will Fong
Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Sorry, I didn't look at the logs you provided earlier. The error log on the master looks very interesting. Here's the important snippet:
2016-07-30 8:01:27 140604322384640 [Note] ActiveTranx:insert_tranx_node: insert (mariadb-bin.000004, 2039896) in entry(71) ... 2016-07-30 8:01:27 140604322384640 [Note] ReplSemiSyncMaster::commitTrx: init wait position (mariadb-bin.000005, 2039896), 2016-07-30 8:01:27 140604322384640 [Note] ReplSemiSyncMaster::commitTrx: wait 18446744073709551615 ms for binlog sent (mariadb-bin.000005, 2039896) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::readSlaveReply: Got reply (mariadb-bin.000004, 2039896) 2016-07-30 8:01:27 140604322687744 [Note] ActiveTranx::::clear_active_tranx_nodes: cleared all nodes 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::reportReplyBinlog: Got reply at (mariadb-bin.000004, 2039896) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::updateSyncHeader: server(1684287243), (mariadb-bin.000004, 2039941) sync(0), repl(1) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::updateSyncHeader: server(1684287243), (mariadb-bin.000005, 288) sync(0), repl(1) 2016-07-30 8:01:27 140604322687744 [Note] ReplSemiSyncMaster::updateSyncHeader: server(1684287243), (mariadb-bin.000005, 329) sync(0), repl(1)
It shows that when transaction is getting committed and written into binlog ending at position mariadb-bin.000004:2039896, somehow the function ReplSemiSyncMaster::commitTrx() gets trx_wait_binlog_name = 'mariadb-bin.000005' and trx_wait_binlog_pos = 2039896. I.e. the function gets the position of the transaction to wait semi-sync ack for correctly, but the file name is already the one that is current after rotation. Master starts waiting for that position, but the slave of course cannot send ack for that position because master didn't send binlogs up to mariadb-bin.000005:2039896 yet.
So it looks like there's some kind of race between updating MYSQL_BIN_LOG::log_file_name during rotation and passing the current value of log_file_name to the semi_sync_master plugin through the after_sync hook.
Kristian, do you have any idea what's going on? Is there an inappropriate lock release/re-acquire somewhere?
Joseph, I see you've already filed https://jira.mariadb.org/browse/MDEV-10553. That's a good call. Hopefully it will be picked up soon.
On Fri, Aug 12, 2016 at 8:33 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi,
I have created a set of easy scripts to trigger the hang reliably with 10.1 on Ubuntu 14.04.
https://gist.github.com/josephglanville/c9a69b02de319ee06aef1a8d787bcce3
Hopefully this is just a problem with the way I am configuring the replication or the binlog settings because I don't see how noone else would have hit this if they are actually using semi-sync replication with reasonably large values for the semi-sync timeout.
Joseph.
________________________________ From: Maria-discuss maria-discuss-bounces+jpg=jpg.id.au@lists.launchpad.net on behalf of Joseph Glanville jpg@jpg.id.au Sent: Sunday, 31 July 2016 7:37:51 PM To: maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
I have created a gist with as much information as I could including the server configs: https://gist.github.com/josephglanville/4337240e648e77ce7020ebaa1fb8d6b0
This time I uploaded all of the binlog and relay files from both the master and the slave as I don't really know what I am looking for in them.
Ignore the `read_only` variable, it's switched to read write dynamically, report_host is also empty but this doesn't seem to have any effect anyways.
I have updated to to report the actual IP address for the machine correctly however.
I reduced the binlog size to make the issue faster to reproduce (and make the binlogs a bit smaller for ease of uploading).
Basic steps to reproduce is to:
Create the initial master database.
Seed the slave using xtrabackup.
Update slave GTID position using information returned from xtrabackup
Connect the slave using GTID
Insert some data, check that data is replicating correctly to slave.
Keep inserting data until binlog rolls over.
Note that inserts now hang on waiting for slave ack.
Happy to help anyone with further information on how to reproduce.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Saturday, 30 July 2016 9:07:54 AM To: Joseph Glanville Cc: Justin Swanhart; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
All the status variables look sane. But you've uploaded empty binlogs, there's no transaction that is hung in them. So I'd guess it should be in mariadb-bin.000004 (or an earlier file) on master and either it doesn't exist on slave or it's in mariadb-bin.000001 and relay-bin.000004 (or in earlier relay-bin.* file).
On Fri, Jul 29, 2016 at 1:29 AM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Justin,
Adjusting the timeout doesn't seem to have any effect. Though setting it low enough does cause the master to time out waiting for the slave to acknowledge the write and falls back to async only to immediately re-establish semi-sync replication. It does this every time the master begins writing to a new binlog.
Joseph.
________________________________ From: Justin Swanhart greenlion@gmail.com Sent: Friday, 29 July 2016 6:17:28 PM To: Joseph Glanville Cc: Pavel Ivanov; maria-discuss@lists.launchpad.net
Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi,
Does the problem appear if you set the timeout value to 9223372036854775807?
On Fri, Jul 29, 2016 at 3:24 AM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
To describe the setup a little better the master replicates to a semi-sync slave, which then replicates to an async slave. This is to ensure at any point in time both the master and the semi-sync slave have a complete copy of the data. If the master fails the semi-sync is automatically promoted to master and the async switches to replicating with semi-sync replication. If the semi-sync fails then the async remasters itself to the master and switches to semi-sync.
However I don't think the 3rd node has any bearing on the hang, I built a test cluster without it and the hang is still easy to reproduce. I just restore a decent sized dump, in this case a portion of the Wikipedia database and the cluster reliably hangs when the master begins writing to the new binlog.
The dump is here if someone wants to use it to reproduce: https://dumps.wikimedia.org/enwiki/latest/enwiki-latest-category.sql.gz
I have created a gist with the output of `SHOW STATUS LIKE 'Rpl_semi_sync%s'` on both master and slave of the simplified 2 node setup. I have also included the binlogs of both the master and the slave and the relay log on the slave.
https://gist.github.com/josephglanville/70789bc9c3744090a17070652cded68b
Let me know if there is any other useful information I can provide.
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Friday, 29 July 2016 4:31:26 PM To: Joseph Glanville Cc: Will Fong; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
This looks pretty weird. If you don't mind more information would be useful to look at: contents of mariadb-bin.000005 on the master, in particular what GTID and binlog position the transaction waiting for semi-sync ack has (confirm that it's 0-1684280839-156 and ends at offset 329); result of "show status like 'rpl_semi_sync_%'" on both master and slave; contents of relay-bin.000005 and binlog on the slave, in particular did it really execute the transaction that is currently hanging on the master? Out of curiosity: it looks like the slave also acts as a master to someone else. Can you also verify that the transaction hanging now on the master made it to that second-level slave?
But to be honest, I don't quite understand how what you show us could happen, so I'm just asking to look at the info that I would look at if I were investigating such problem.
On Thu, Jul 28, 2016 at 10:52 PM, Joseph Glanville jpg@jpg.id.au wrote:
Hi Pavel.
Yes, by “binlog filename changes” I mean the master begins writing to a new binlog file.
Output of all the requested commands are in this gist:
https://gist.github.com/josephglanville/7b96c34bb6e79ace33e56627672b98a5
Joseph Glanville Sent from Polymail
On Fri, 29 Jul 2016 at 3:08 PM Pavel Ivanov <Pavel Ivanov > wrote:
By "binlog filename changes" you mean when master starts writing binlogs into a new file? Can you clarify how the replication stalls? What "show processlist" shows at that time on master and on slave? What does "show slave status" show on the slave? On Thu, Jul 28, 2016 at 10:03 PM, Will Fong wrote: > Hi Joseph, > > On Fri, Jul 29, 2016 at 10:11 AM, Joseph Glanville wrote: >> However whenever the binlog filename changes the replication stalls >> indefinitely. > > Interesting! I may have reproduced this, but it was only a quick test. > Let me (or someone else) dig into this more. > > Thanks for reporting this. > -will > > > -- > Will Fong, Senior Support Engineer > MariaDB Corporation > > _______________________________________________ > Mailing list: https://launchpad.net/~maria-discuss > Post to : maria-discuss@lists.launchpad.net > Unsubscribe : https://launchpad.net/~maria-discuss > More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~maria-discuss Post to : maria-discuss@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-discuss More help : https://help.launchpad.net/ListHelp
Pavel Ivanov pivanof@google.com writes:
binlog ending at position mariadb-bin.000004:2039896, somehow the function ReplSemiSyncMaster::commitTrx() gets trx_wait_binlog_name = 'mariadb-bin.000005' and trx_wait_binlog_pos = 2039896. I.e. the function gets the position of the transaction to wait semi-sync ack for correctly, but the file name is already the one that is current after rotation. Master starts waiting for that position, but the slave
Kristian, do you have any idea what's going on? Is there an inappropriate lock release/re-acquire somewhere?
Hm. Actually, looking into MYSQL_BIN_LOG::trx_group_commit_leader, this looks suspicious:
RUN_HOOK(binlog_storage, after_flush, (current->thd, current->cache_mngr->last_commit_pos_file, current->cache_mngr->last_commit_pos_offset, synced, first, last))
But
RUN_HOOK(binlog_storage, after_sync, (current->thd, log_file_name, current->cache_mngr->last_commit_pos_offset, first, last))
I would have expected that `log_file_name' to be also current->cache_mngr->last_commit_pos_file, like in the first instance. And in fact, it looks like (with my limited knowledge of semi-sync) that this suspicious case is exactly the AFTER_SYNC which fails, while AFTER_COMMIT works...
So maybe try the below patch?
Pavel, what do you think, do you agree that this patch should be better?
- Kristian.
Yes, Kristian. Thanks! This indeed looks like the correct patch. In fact I see that internally we have this changed as part of the same patch where after_flush was changed (i.e. https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed...). I'm not sure why Jonas didn't include it in https://jira.mariadb.org/browse/MDEV-7257.
On Mon, Aug 15, 2016 at 5:05 AM, Kristian Nielsen knielsen@knielsen-hq.org wrote:
Pavel Ivanov pivanof@google.com writes:
binlog ending at position mariadb-bin.000004:2039896, somehow the function ReplSemiSyncMaster::commitTrx() gets trx_wait_binlog_name = 'mariadb-bin.000005' and trx_wait_binlog_pos = 2039896. I.e. the function gets the position of the transaction to wait semi-sync ack for correctly, but the file name is already the one that is current after rotation. Master starts waiting for that position, but the slave
Kristian, do you have any idea what's going on? Is there an inappropriate lock release/re-acquire somewhere?
Hm. Actually, looking into MYSQL_BIN_LOG::trx_group_commit_leader, this looks suspicious:
RUN_HOOK(binlog_storage, after_flush, (current->thd, current->cache_mngr->last_commit_pos_file, current->cache_mngr->last_commit_pos_offset, synced, first, last))
But
RUN_HOOK(binlog_storage, after_sync, (current->thd, log_file_name, current->cache_mngr->last_commit_pos_offset, first, last))
I would have expected that `log_file_name' to be also current->cache_mngr->last_commit_pos_file, like in the first instance. And in fact, it looks like (with my limited knowledge of semi-sync) that this suspicious case is exactly the AFTER_SYNC which fails, while AFTER_COMMIT works...
So maybe try the below patch?
Pavel, what do you think, do you agree that this patch should be better?
- Kristian.
diff --git a/sql/log.cc b/sql/log.cc index 7efec98..b77a6b3 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -7712,7 +7712,7 @@ MYSQL_BIN_LOG::trx_group_commit_leader(group_commit_entry *leader) last= current->next == NULL; if (!current->error && RUN_HOOK(binlog_storage, after_sync, - (current->thd, log_file_name, + (current->thd, current->cache_mngr->last_commit_pos_file, current->cache_mngr->last_commit_pos_offset, first, last))) {
Hi Pavel, Kristian,
This fixes the problem for me. How do we go about getting this into a release?
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Tuesday, 16 August 2016 2:28 AM To: Kristian Nielsen; Jonas Oreland Cc: Joseph Glanville; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Yes, Kristian. Thanks! This indeed looks like the correct patch. In fact I see that internally we have this changed as part of the same patch where after_flush was changed (i.e. https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed...). [https://avatars1.githubusercontent.com/u/12231504?v=3&s=200]https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed8d30e
MDEV-7257: Dump Thread Enhancements · MariaDB/server@4d8b346https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed8d30e github.com Make the binlog dump threads not need to take LOCK_log while sending binlog events to slave. Instead, a new LOCK_binlog_end_pos is used just to coordinate tracking the current end-of-log. This is ...
I'm not sure why Jonas didn't include it in https://jira.mariadb.org/browse/MDEV-7257.
On Mon, Aug 15, 2016 at 5:05 AM, Kristian Nielsen knielsen@knielsen-hq.org wrote:
Pavel Ivanov pivanof@google.com writes:
binlog ending at position mariadb-bin.000004:2039896, somehow the function ReplSemiSyncMaster::commitTrx() gets trx_wait_binlog_name = 'mariadb-bin.000005' and trx_wait_binlog_pos = 2039896. I.e. the function gets the position of the transaction to wait semi-sync ack for correctly, but the file name is already the one that is current after rotation. Master starts waiting for that position, but the slave
Kristian, do you have any idea what's going on? Is there an inappropriate lock release/re-acquire somewhere?
Hm. Actually, looking into MYSQL_BIN_LOG::trx_group_commit_leader, this looks suspicious:
RUN_HOOK(binlog_storage, after_flush, (current->thd, current->cache_mngr->last_commit_pos_file, current->cache_mngr->last_commit_pos_offset, synced, first, last))
But
RUN_HOOK(binlog_storage, after_sync, (current->thd, log_file_name, current->cache_mngr->last_commit_pos_offset, first, last))
I would have expected that `log_file_name' to be also current->cache_mngr->last_commit_pos_file, like in the first instance. And in fact, it looks like (with my limited knowledge of semi-sync) that this suspicious case is exactly the AFTER_SYNC which fails, while AFTER_COMMIT works...
So maybe try the below patch?
Pavel, what do you think, do you agree that this patch should be better?
- Kristian.
diff --git a/sql/log.cc b/sql/log.cc index 7efec98..b77a6b3 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -7712,7 +7712,7 @@ MYSQL_BIN_LOG::trx_group_commit_leader(group_commit_entry *leader) last= current->next == NULL; if (!current->error && RUN_HOOK(binlog_storage, after_sync, - (current->thd, log_file_name, + (current->thd, current->cache_mngr->last_commit_pos_file, current->cache_mngr->last_commit_pos_offset, first, last))) {
May have spoke too soon.. I forgot to set the settings back to AFTER_SYNC.
Will have to test with correct settings again, sorry for the false positive.
________________________________ From: Maria-discuss maria-discuss-bounces+jpg=jpg.id.au@lists.launchpad.net on behalf of Joseph Glanville jpg@jpg.id.au Sent: Tuesday, 16 August 2016 11:38:55 AM To: Pavel Ivanov; Kristian Nielsen; Jonas Oreland Cc: maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi Pavel, Kristian,
This fixes the problem for me. How do we go about getting this into a release?
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Tuesday, 16 August 2016 2:28 AM To: Kristian Nielsen; Jonas Oreland Cc: Joseph Glanville; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Yes, Kristian. Thanks! This indeed looks like the correct patch. In fact I see that internally we have this changed as part of the same patch where after_flush was changed (i.e. https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed...). [https://avatars1.githubusercontent.com/u/12231504?v=3&s=200]https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed8d30e
MDEV-7257: Dump Thread Enhancements · MariaDB/server@4d8b346https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed8d30e github.com Make the binlog dump threads not need to take LOCK_log while sending binlog events to slave. Instead, a new LOCK_binlog_end_pos is used just to coordinate tracking the current end-of-log. This is ...
I'm not sure why Jonas didn't include it in https://jira.mariadb.org/browse/MDEV-7257.
On Mon, Aug 15, 2016 at 5:05 AM, Kristian Nielsen knielsen@knielsen-hq.org wrote:
Pavel Ivanov pivanof@google.com writes:
binlog ending at position mariadb-bin.000004:2039896, somehow the function ReplSemiSyncMaster::commitTrx() gets trx_wait_binlog_name = 'mariadb-bin.000005' and trx_wait_binlog_pos = 2039896. I.e. the function gets the position of the transaction to wait semi-sync ack for correctly, but the file name is already the one that is current after rotation. Master starts waiting for that position, but the slave
Kristian, do you have any idea what's going on? Is there an inappropriate lock release/re-acquire somewhere?
Hm. Actually, looking into MYSQL_BIN_LOG::trx_group_commit_leader, this looks suspicious:
RUN_HOOK(binlog_storage, after_flush, (current->thd, current->cache_mngr->last_commit_pos_file, current->cache_mngr->last_commit_pos_offset, synced, first, last))
But
RUN_HOOK(binlog_storage, after_sync, (current->thd, log_file_name, current->cache_mngr->last_commit_pos_offset, first, last))
I would have expected that `log_file_name' to be also current->cache_mngr->last_commit_pos_file, like in the first instance. And in fact, it looks like (with my limited knowledge of semi-sync) that this suspicious case is exactly the AFTER_SYNC which fails, while AFTER_COMMIT works...
So maybe try the below patch?
Pavel, what do you think, do you agree that this patch should be better?
- Kristian.
diff --git a/sql/log.cc b/sql/log.cc index 7efec98..b77a6b3 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -7712,7 +7712,7 @@ MYSQL_BIN_LOG::trx_group_commit_leader(group_commit_entry *leader) last= current->next == NULL; if (!current->error && RUN_HOOK(binlog_storage, after_sync, - (current->thd, log_file_name, + (current->thd, current->cache_mngr->last_commit_pos_file, current->cache_mngr->last_commit_pos_offset, first, last))) {
Managed to get a build running with the patch and all of the settings correct (including AFTER_SYNC this time!) and seems to work well, no more hangs. ________________________________ From: Maria-discuss maria-discuss-bounces+jpg=jpg.id.au@lists.launchpad.net on behalf of Joseph Glanville jpg@jpg.id.au Sent: Tuesday, 16 August 2016 11:41:34 AM To: Pavel Ivanov; Kristian Nielsen; Jonas Oreland Cc: maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
May have spoke too soon.. I forgot to set the settings back to AFTER_SYNC.
Will have to test with correct settings again, sorry for the false positive.
________________________________ From: Maria-discuss maria-discuss-bounces+jpg=jpg.id.au@lists.launchpad.net on behalf of Joseph Glanville jpg@jpg.id.au Sent: Tuesday, 16 August 2016 11:38:55 AM To: Pavel Ivanov; Kristian Nielsen; Jonas Oreland Cc: maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Hi Pavel, Kristian,
This fixes the problem for me. How do we go about getting this into a release?
Joseph.
________________________________ From: Pavel Ivanov pivanof@google.com Sent: Tuesday, 16 August 2016 2:28 AM To: Kristian Nielsen; Jonas Oreland Cc: Joseph Glanville; maria-discuss@lists.launchpad.net Subject: Re: [Maria-discuss] Semi-sync replication hangs when changing binlog filename.
Yes, Kristian. Thanks! This indeed looks like the correct patch. In fact I see that internally we have this changed as part of the same patch where after_flush was changed (i.e. https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed...). [https://avatars1.githubusercontent.com/u/12231504?v=3&s=200]https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed8d30e
MDEV-7257: Dump Thread Enhancements · MariaDB/server@4d8b346https://github.com/MariaDB/server/commit/4d8b346e079a27960dbe49e4d0ec4364bed8d30e github.com Make the binlog dump threads not need to take LOCK_log while sending binlog events to slave. Instead, a new LOCK_binlog_end_pos is used just to coordinate tracking the current end-of-log. This is ...
I'm not sure why Jonas didn't include it in https://jira.mariadb.org/browse/MDEV-7257.
On Mon, Aug 15, 2016 at 5:05 AM, Kristian Nielsen knielsen@knielsen-hq.org wrote:
Pavel Ivanov pivanof@google.com writes:
binlog ending at position mariadb-bin.000004:2039896, somehow the function ReplSemiSyncMaster::commitTrx() gets trx_wait_binlog_name = 'mariadb-bin.000005' and trx_wait_binlog_pos = 2039896. I.e. the function gets the position of the transaction to wait semi-sync ack for correctly, but the file name is already the one that is current after rotation. Master starts waiting for that position, but the slave
Kristian, do you have any idea what's going on? Is there an inappropriate lock release/re-acquire somewhere?
Hm. Actually, looking into MYSQL_BIN_LOG::trx_group_commit_leader, this looks suspicious:
RUN_HOOK(binlog_storage, after_flush, (current->thd, current->cache_mngr->last_commit_pos_file, current->cache_mngr->last_commit_pos_offset, synced, first, last))
But
RUN_HOOK(binlog_storage, after_sync, (current->thd, log_file_name, current->cache_mngr->last_commit_pos_offset, first, last))
I would have expected that `log_file_name' to be also current->cache_mngr->last_commit_pos_file, like in the first instance. And in fact, it looks like (with my limited knowledge of semi-sync) that this suspicious case is exactly the AFTER_SYNC which fails, while AFTER_COMMIT works...
So maybe try the below patch?
Pavel, what do you think, do you agree that this patch should be better?
- Kristian.
diff --git a/sql/log.cc b/sql/log.cc index 7efec98..b77a6b3 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -7712,7 +7712,7 @@ MYSQL_BIN_LOG::trx_group_commit_leader(group_commit_entry *leader) last= current->next == NULL; if (!current->error && RUN_HOOK(binlog_storage, after_sync, - (current->thd, log_file_name, + (current->thd, current->cache_mngr->last_commit_pos_file, current->cache_mngr->last_commit_pos_offset, first, last))) {
Joseph Glanville jpg@jpg.id.au writes:
This fixes the problem for me. How do we go about getting this into a release?
I can push it. It should go into 10.1, I think (this code is not in 10.0).
Thanks for testing!
- Kristian.
participants (4)
-
Joseph Glanville -
Justin Swanhart -
Kristian Nielsen -
Pavel Ivanov