Long node resync after SST then strange behaviour ?

[Laurent MINOST]

Hi,

I'm wondering if this behaviour below is normal or not ? This occurs just after a node's restart :

node1 - which is receiver/recovering in this case :

...

120514 15:22:17  InnoDB: Starting an apply batch of log records to the database...

InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 

InnoDB: Apply batch completed

InnoDB: Last MySQL binlog file position 0 662842, file name /opt/mysql-galera/data/mysql-binary-log.000012

120514 15:22:18  InnoDB: Waiting for the background threads to start

120514 15:22:19 [Note] WSREP: Member 0 (vmfedora1) synced with group.

120514 15:22:19 InnoDB: 1.1.8 started; log sequence number 21283250872

120514 15:22:19 [Note] Event Scheduler: Loaded 0 events

120514 15:22:20 [Note] WSREP: Signalling provider to continue.

120514 15:22:20 [Note] WSREP: Received SST: 6cd33b89-9dc2-11e1-0800-c938ffc57dd8:58242

120514 15:22:20 [Note] /opt/mysql-galera/bin/mysqld: ready for connections.

Version: '5.5.23-log'  socket: '/opt/mysql-galera/data/mysql.sock'  port: 3306  Source distribution, wsrep_23.5.r3743

120514 15:22:20 [Note] WSREP: SST received: 6cd33b89-9dc2-11e1-0800-c938ffc57dd8:58242

120514 15:22:20 [Note] WSREP: 1 (cygnus.lolomin.net): State transfer from 0 (vmfedora1) complete.

120514 15:22:20 [Note] WSREP: Shifting JOINER -> JOINED (TO: 61286)

120514 15:37:46 [Note] WSREP: Member 1 (cygnus.lolomin.net) synced with group.

120514 15:37:46 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 84744)

120514 15:37:46 [Note] WSREP: Synchronized with group, ready for connections

node3 - which is donor :

120514 15:20:47 [Note] WSREP: Flushing tables for SST...

120514 15:20:47 [Note] WSREP: Provider paused at 6cd33b89-9dc2-11e1-0800-c938ffc57dd8:58242

120514 15:20:47 [Note] WSREP: Tables flushed.

120514 15:22:07 [Note] WSREP: Provider resumed.

120514 15:22:07 [Note] WSREP: 0 (vmfedora1): State transfer to 1 (cygnus.lolomin.net) complete.

120514 15:22:07 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 60917)

120514 15:22:19 [Note] WSREP: Member 0 (vmfedora1) synced with group.

120514 15:22:19 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 61251)

120514 15:22:19 [Note] WSREP: Synchronized with group, ready for connections

120514 15:22:20 [Note] WSREP: 1 (cygnus.lolomin.net): State transfer from 0 (vmfedora1) complete.

120514 15:23:01 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows

: 1

120514 15:25:02 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows

: 1

120514 15:26:04 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows

: 1

120514 15:27:03 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows: 1

120514 15:30:02 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows: 1

120514 15:31:02 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows: 1

120514 15:35:00 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows: 1

120514 15:36:02 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows: 1

120514 15:37:02 [Warning] WSREP: empty rbr buffer, query: UPDATE `instance` SET `instance_name` = 'Nagios Cygnus' WHERE `instance_id` = '1' LIMIT 1, affected rows: 1

120514 15:37:45 [Note] WSREP: Member 1 (cygnus.lolomin.net) synced with group.

WSREP: BF lock wait long

WSREP: BF lock wait long

WSREP: BF lock wait long

WSREP: BF lock wait long

=====================================

120514 15:38:18 INNODB MONITOR OUTPUT

=====================================

Per second averages calculated from the last 23 seconds

-----------------

BACKGROUND THREAD

-----------------

srv_master_thread loops: 1963 1_second, 1955 sleeps, 196 10_second, 3 background, 3 flush

srv_master_thread log flush and writes: 1972

----------

SEMAPHORES

----------

OS WAIT ARRAY INFO: reservation count 1846, signal count 1917

Mutex spin waits 8003, rounds 67248, OS waits 1211

RW-shared spins 302, rounds 7518, OS waits 237

RW-excl spins 570, rounds 13084, OS waits 257

Spin rounds per wait: 8.40 mutex, 24.89 RW-shared, 22.95 RW-excl

------------

TRANSACTIONS

------------

Trx id counter 19E249B0

Purge done for trx's n:o < 19E24648 undo n:o < 0

History list length 1829

LIST OF TRANSACTIONS FOR EACH SESSION:

---TRANSACTION 19E246A1, ACTIVE 55 sec setting auto-inc lock

mysql tables in use 1, locked 1

LOCK WAIT 2 lock struct(s), heap size 320, 0 row lock(s), undo log entries 1

MySQL thread id 2, OS thread handle 0xaa849b40, query id 159485 Write_rows_log_event::write_row(84707)

------- TRX HAS BEEN WAITING 55 SEC FOR THIS LOCK TO BE GRANTED:

TABLE LOCK table `centstorage`.`log` trx id 19E246A1 lock mode AUTO-INC waiting

------------------

TABLE LOCK table `centstorage`.`log` trx id 19E246A1 lock mode IX

...


Why is the first node is taking more than 15 mins to go in state Synced ? (which make it unavailable for serving requests in my L/B system because I'm checking if node is in status Synced)
Why do I have a lot of BF Lock wait long messages and InnoDB informations after node1's resync which are appearing on node3's error log only ?

Thks !
Regards,

Laurent

[Laurent MINOST]

Did a new test :

120514 17:27:44 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 126349)

120514 17:27:48 [Note] WSREP: 0 (vmfedora1): State transfer from 1 (cygnus.lolomin.net) complete.

120514 17:27:57 [Note] WSREP: Member 0 (vmfedora1) synced with group.

120514 17:37:41 [Note] WSREP: Member 1 (cygnus.lolomin.net) synced with group.

120514 17:37:41 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 138485)

120514 17:37:42 [Note] WSREP: Synchronized with group, ready for connections

This time it needed 10 mins ?! but is it normal ?

Regards,

Laurent 

[Alex Yurchenko]

On 2012-05-14 17:07, Laurent MINOST wrote:

>
> Why is the first node is taking more than 15 mins to go in state
> Synced ?
> (which make it unavailable for serving requests in my L/B system
> because
> I'm checking if node is in status Synced)
> Why do I have a lot of BF Lock wait long messages and InnoDB
> informations
> after node1's resync which are appearing on node3's error log only ?

Are you running this test on individual hardware nodes or in 3 VMs on
one host competing for a single drive? In the latter case I won't be
surprised. Your joiner must be cold and keeps everybody slow. And crappy
VM IO does not help it at all. And several VMs competition for IO makes
it even harder. A bit harder to say about the donor (if it is really
specific to donor), but I won't be surprised as long as it is an
isolated incident.

In other words, if you're running your database servers in VMs, you
can't expect stellar performance. And if those VMs share a host machine,
then you can't make any assumptions about performance at all. The only
thing that can be expected under such conditions is databases
consistency in the end.

Regards,
Alex

> Thks !
> Regards,
>
> Laurent

--
Alexey Yurchenko,
Codership Oy, www.codership.com
Skype: alexey.yurchenko, Phone: +358-400-516-011

[Laurent MINOST]

Hi Alexey,

Le lundi 14 mai 2012 21:23:40 UTC+2, Alexey Yurchenko a écrit :

On 2012-05-14 17:07, Laurent MINOST wrote:

>
> Why is the first node is taking more than 15 mins to go in state
> Synced ?
> (which make it unavailable for serving requests in my L/B system
> because
> I'm checking if node is in status Synced)
> Why do I have a lot of BF Lock wait long messages and InnoDB
> informations
> after node1's resync which are appearing on node3's error log only ?

Are you running this test on individual hardware nodes or in 3 VMs on
one host competing for a single drive? In the latter case I won't be
surprised. Your joiner must be cold and keeps everybody slow. And crappy
VM IO does not help it at all. And several VMs competition for IO makes
it even harder. A bit harder to say about the donor (if it is really
specific to donor), but I won't be surprised as long as it is an
isolated incident.

One of the node (vmfedora1) is a virtual machine hosted on the first galera node (cygnus), that's true.

 

In other words, if you're running your database servers in VMs, you
can't expect stellar performance. And if those VMs share a host machine,
then you can't make any assumptions about performance at all. The only
thing that can be expected under such conditions is databases
consistency in the end.

Ok so we have the answer about this behaviour even if it seems to me pretty long to take several minutes for the node to be available and marked only as synced (datas are already there normally at this moment) ?! The hosting machine is having 8GB RAM and a 4 core Intel I3 CPU, no load at all at these moments.

There is one virtual machine above all the three nodes which is for sure not good to achieve best performance, we are agree with this. 

[Laurent MINOST]

Hi again,

Sorry, I forgot to ask if messages that are found on the log of the second node (beginning with the lines  WSREP: BF lock wait long  ...) are related or if this is another problem ?
I do not remember seeing this message before on any of the nodes and so am wondering why these messages are appearing now ?

Thks.

Regards,

Laurent

[Alexey Yurchenko]

Hi Laurent,

Performance depends on many factors, some of which may avoid your attention. It could be a change in load profile, small buffer pool, or some other misconfiguration or condition that was not present previously. And figuring that out is a full-time job. But here's some VERY CRUDE math

donor

120514 15:20:47 [Note] WSREP: Tables flushed.

120514 15:22:07 [Note] WSREP: Provider resumed.

joiner

120514 15:22:20 [Note] WSREP: Received SST: 6cd33b89-9dc2-11e1-0800-c938ffc57dd8:58242

120514 15:22:20 [Note] WSREP: Shifting JOINER -> JOINED (TO: 61286)

120514 15:37:46 [Note] WSREP: Member 1 (cygnus.lolomin.net) synced with group.

120514 15:37:46 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 84744)

 
It took 80 seconds for SST to complete, at that time the third node apparently managed to churn out 61286-58242=3044 transactions, so one node is capable of ~38 trx/sec unencumbered by flow control.
It took 926 seconds to catch up where the joiner node replayed 26502 trxs at an average rate of 28.6 trx/sec, which is not that bad considering it was cold and trashing the disk that it had to share with another node like crazy.

Regards,
Alex