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 <j...@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 <piva...@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 <j...@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...@lists.launchpad.net> on behalf of >> Joseph Glanville <j...@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 <piva...@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 <j...@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 <greenl...@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 <j...@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 <piva...@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 <j...@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 >>>> >>> >> _______________________________________________ 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
