maria-discuss team mailing list archive

[Pavel Ivanov <pivanof@xxxxxxxxxx>]

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@xxxxxxxxx> 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@xxxxxxxxxx>
> Sent: Saturday, 13 August 2016 2:17:39 PM
> To: Joseph Glanville; Kristian Nielsen
> Cc: maria-discuss@xxxxxxxxxxxxxxxxxxx; 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@xxxxxxxxx> 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@xxxxxxxxxxxxxxxxxxx> on behalf of
>> Joseph Glanville <jpg@xxxxxxxxx>
>> Sent: Sunday, 31 July 2016 7:37:51 PM
>> To: maria-discuss@xxxxxxxxxxxxxxxxxxx
>>
>> 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@xxxxxxxxxx>
>> Sent: Saturday, 30 July 2016 9:07:54 AM
>> To: Joseph Glanville
>> Cc: Justin Swanhart; maria-discuss@xxxxxxxxxxxxxxxxxxx
>> 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@xxxxxxxxx> 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@xxxxxxxxx>
>>> Sent: Friday, 29 July 2016 6:17:28 PM
>>> To: Joseph Glanville
>>> Cc: Pavel Ivanov; maria-discuss@xxxxxxxxxxxxxxxxxxx
>>>
>>> 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@xxxxxxxxx> 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@xxxxxxxxxx>
>>>> Sent: Friday, 29 July 2016 4:31:26 PM
>>>> To: Joseph Glanville
>>>> Cc: Will Fong; maria-discuss@xxxxxxxxxxxxxxxxxxx
>>>> 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@xxxxxxxxx>
>>>> 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@xxxxxxxxxxxxxxxxxxx > Unsubscribe :
>>>>>> https://launchpad.net/~maria-discuss > More help :
>>>>>> https://help.launchpad.net/ListHelp
>>>>>
>>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> Mailing list: https://launchpad.net/~maria-discuss
>>>> Post to     : maria-discuss@xxxxxxxxxxxxxxxxxxx
>>>> Unsubscribe : https://launchpad.net/~maria-discuss
>>>> More help   : https://help.launchpad.net/ListHelp
>>>>
>>>
>>