maria-discuss team mailing list archive

[Joseph Glanville <jpg@xxxxxxxxx>]

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
>>>
>>
>