Take the 2-minute tour ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.

I have a problem with MySQL clustering. My systems consist of:

  • xtrabackup: version 2.0.2
  • MySQL: version 5.5.27
  • Distro: CentOS 5.7 64-bit

my.cnf on the donor:

[mysqld]
binlog_format=ROW

wsrep_provider=/usr/lib64/libgalera_smm.so
wsrep_provider_options="gcache.size=4G;"

wsrep_slave_threads=2
wsrep_cluster_name=trimethylxanthine
wsrep_sst_method=xtrabackup
wsrep_sst_auth=root:x
wsrep_node_name=node1
wsrep_node_address=192.168.5.148

innodb_locks_unsafe_for_binlog=1
innodb_autoinc_lock_mode=2

[mysqld_safe]
wsrep_urls=gcomm://192.168.5.148:4567, gcomm://192.168.5.149:4567, 
    gcomm://192.168.5.197:4567,gcomm://

my.cnf on the joiner:

[mysqld]
binlog_format=ROW

wsrep_provider=/usr/lib64/libgalera_smm.so

wsrep_slave_threads=2
wsrep_cluster_name=trimethylxanthine
wsrep_sst_method=xtrabackup
wsrep_sst_auth=root:x
wsrep_node_name=node2
wsrep_node_address=192.168.5.197

innodb_locks_unsafe_for_binlog=1
innodb_autoinc_lock_mode=2

[mysqld_safe]
wsrep_urls=gcomm://192.168.5.148:4567, gcomm://192.168.5.149:4567, 
    gcomm://192.168.5.197:4567,gcomm://

The backup are performed by running:

innobackupex --galera-info --stream=tar ./ | gzip - | nc 192.168.5.197 9999

grastate.dat on the joiner (sure, take it from the xtrabackup_galera_info)

# GALERA saved state
version: 2.1
uuid:    f68ad1a2-0a4e-11e2-0800-7441f90e56cf
seqno:   6
cert_index:

mysqld.log on the donor:

120930 17:00:49 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 8)
120930 17:00:49 [Note] WSREP: IST request: f68ad1a2-0a4e-11e2-0800-7441f90e56cf:6-8|
    tcp://192.168.5.197:4568
120930 17:00:49 [Note] WSREP: IST first seqno 7 not found from cache, 
    falling back to SST

mysqld.log on the joiner:

120930 17:01:54 [Note] WSREP: Prepared SST request: xtrabackup|192.168.5.197:4444/
    xtrabackup_sst
120930 17:01:54 [Note] WSREP: wsrep_notify_cmd is not defined, skipping 
    notification.
120930 17:01:54 [Note] WSREP: Assign initial position for certification: 8, 
    protocol version: 2
120930 17:01:54 [Note] WSREP: Prepared IST receiver, listening at: 
    tcp://192.168.5.197:4568
120930 17:01:54 [Note] WSREP: Node 2 (SVR282-5197.localdomain) 
    requested state transfer from '*any*'. Selected 0 (x)(SYNCED) as donor.
120930 17:01:54 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 8)
120930 17:01:54 [Note] WSREP: Requesting state transfer: success, donor: 0
120930 17:03:18 [Note] WSREP: 0 (SVR120-27148.localdomain): State transfer to
     2 (SVR282-5197.localdomain) complete.
120930 17:03:18 [Note] WSREP: Member 0 (SVR120-27148.localdomain) synced with
     group.
120930 17:03:29 [Note] WSREP: SST complete, seqno: 8

The second node joined the cluster successfully but it does an SST instead of an IST.

Why doesn't it find the sequence number from the cache?

My database is only ~ 3 GB, there are only a few changes from the time of the backup until the restore is complete.

sst.err on the joiner is empty.

Some lines at the end of innobackup.backup.log on the donor:

...
innobackupex: Resuming ibbackup

xtrabackup: The latest check point (for incremental): '1850952486'
xtrabackup: Stopping log copying thread.
.>> log scanned up to (1850952640)

xtrabackup: Streaming transaction log from a temporary file...
xtrabackup: Done.
xtrabackup: Transaction log of lsn (1850952486) to (1850952640) was copied.
120930 18:52:04 innobackupex: All tables unlocked
120930 18:52:04 innobackupex: Connection to database server closed

innobackupex: Backup created in directory '/tmp'
innobackupex: MySQL binlog position: filename 'mysql-bin.000185', position 107
innobackupex: You must use -i (--ignore-zeros) option for extraction of the tar stream.
120930 18:52:04 innobackupex: completed OK!

UPDATE Tue Oct 2 01:29:50 ICT 2012

I've tried to set Gcache to... 256M:

121002  1:12:26 [Note] WSREP: Passing config to GCS: base_host = 192.168.5.148; gcache.dir = /data/var/lib/mysql/; gcache.ke
ep_pages_size = 0; gcache.mem_size = 0; gcache.name = /data/var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.siz
e = 256M; gcs.fc_debug = 0; gcs.fc_factor = 0.5; gcs.fc_limit = 16; gcs.fc_master_slave = NO; gcs.max_packet_size = 64500; g
cs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = NO; repl
icator.causal_read_timeout = PT30S; replicator.commit_order = 3

and got the same error:

121002  1:16:52 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 12)
121002  1:16:52 [Note] WSREP: IST request: f68ad1a2-0a4e-11e2-0800-7441f90e56cf:6-12|tcp://192.168.5.197:4568
121002  1:16:52 [Note] WSREP: IST first seqno 7 not found from cache, falling back to SST

UPDATE Tue Oct 2 02:12:46 ICT 2012

Here's what I have tried again:

  • Deleted the datadir on the joiner
  • Do another backup on the donor
  • Restored the backup on the joiner
  • Create the grastate.dat file
  • Start MySQL

It seems that IST is used. By seems, I mean it takes only ~ 10 seconds to start MySQL (instead of ~ 2 minutes for SST), but there's no evidence in the logs:

joiner:

121002  1:57:35 [Note] WSREP: Passing config to GCS: base_host = 192.168.5.197; gcache.dir = /var/lib/mysql/; gcache.keep_pa
ges_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.size = 128M; 
gcs.fc_debug = 0; gcs.fc_factor = 0.5; gcs.fc_limit = 16; gcs.fc_master_slave = NO; gcs.max_packet_size = 64500; gcs.max_thr
ottle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = NO; replicator.cau
sal_read_timeout = PT30S; replicator.commit_order = 3
121002  1:57:35 [Note] WSREP: Assign initial position for certification: 12, protocol version: -1
121002  1:57:35 [Note] WSREP: wsrep_sst_grab()
121002  1:57:35 [Note] WSREP: Start replication
121002  1:57:35 [Note] WSREP: Setting initial position to f68ad1a2-0a4e-11e2-0800-7441f90e56cf:12
121002  1:57:35 [Note] WSREP: protonet asio version 0
121002  1:57:35 [Note] WSREP: backend: asio
121002  1:57:35 [Note] WSREP: GMCast version 0
121002  1:57:35 [Note] WSREP: (dd03861e-0bf9-11e2-0800-8dd553174290, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
121002  1:57:35 [Note] WSREP: (dd03861e-0bf9-11e2-0800-8dd553174290, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
121002  1:57:35 [Note] WSREP: EVS version 0
121002  1:57:35 [Note] WSREP: PC version 0
121002  1:57:35 [Note] WSREP: gcomm: connecting to group 'trimethylxanthine', peer '192.168.5.148:4567'
121002  1:57:35 [Note] WSREP: (dd03861e-0bf9-11e2-0800-8dd553174290, 'tcp://0.0.0.0:4567') turning message relay requesting 
on, nonlive peers: tcp://192.168.5.149:4567 
121002  1:57:35 [Note] WSREP: (dd03861e-0bf9-11e2-0800-8dd553174290, 'tcp://0.0.0.0:4567') turning message relay requesting 
off
121002  1:57:35 [Note] WSREP: declaring 8e3322c0-0bf3-11e2-0800-0714e70cf54e stable
121002  1:57:35 [Note] WSREP: declaring 93ab47ba-0acb-11e2-0800-27fb6edb71ea stable
121002  1:57:35 [Note] WSREP: view(view_id(PRIM,8e3322c0-0bf3-11e2-0800-0714e70cf54e,53) memb {
        8e3322c0-0bf3-11e2-0800-0714e70cf54e,
        93ab47ba-0acb-11e2-0800-27fb6edb71ea,
        dd03861e-0bf9-11e2-0800-8dd553174290,
} joined {
} left {
} partitioned {
})
121002  1:57:36 [Note] WSREP: gcomm: connected
121002  1:57:36 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
121002  1:57:36 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
121002  1:57:36 [Note] WSREP: Opened channel 'trimethylxanthine'
121002  1:57:36 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 2, memb_num = 3
121002  1:57:36 [Note] WSREP: Waiting for SST to complete.
121002  1:57:36 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
121002  1:57:36 [Note] WSREP: STATE EXCHANGE: sent state msg: b0b8bcd2-0bf9-11e2-0800-86c3bb133737
121002  1:57:36 [Note] WSREP: STATE EXCHANGE: got state msg: b0b8bcd2-0bf9-11e2-0800-86c3bb133737 from 0 (SVR120-27148.localdomain)
121002  1:57:36 [Note] WSREP: STATE EXCHANGE: got state msg: b0b8bcd2-0bf9-11e2-0800-86c3bb133737 from 1 (svr143-27149.localdomain)
121002  1:57:36 [Note] WSREP: STATE EXCHANGE: got state msg: b0b8bcd2-0bf9-11e2-0800-86c3bb133737 from 2 (SVR282-5197.localdomain)
121002  1:57:36 [Note] WSREP: Quorum results:
        version    = 2,
        component  = PRIMARY,
        conf_id    = 52,
        members    = 3/3 (joined/total),
        act_id     = 12,
        last_appl. = -1,
        protocols  = 0/4/2 (gcs/repl/appl),
        group UUID = f68ad1a2-0a4e-11e2-0800-7441f90e56cf
121002  1:57:36 [Note] WSREP: Flow-control interval: [14, 28]
121002  1:57:36 [Note] WSREP: Restored state OPEN -> JOINED (12)
121002  1:57:36 [Note] WSREP: New cluster view: global state: f68ad1a2-0a4e-11e2-0800-7441f90e56cf:12, view# 53: Primary, number of nodes: 3, my index: 2, protocol version 2
121002  1:57:36 [Note] WSREP: SST complete, seqno: 12
121002  1:57:36 [Note] WSREP: Member 2 (SVR282-5197.localdomain) synced with group.
121002  1:57:36 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 12)

donor:

121002  1:56:21 [Note] WSREP: declaring 93ab47ba-0acb-11e2-0800-27fb6edb71ea stable
121002  1:56:21 [Note] WSREP: declaring dd03861e-0bf9-11e2-0800-8dd553174290 stable
121002  1:56:21 [Note] WSREP: view(view_id(PRIM,8e3322c0-0bf3-11e2-0800-0714e70cf54e,53) memb {
        8e3322c0-0bf3-11e2-0800-0714e70cf54e,
        93ab47ba-0acb-11e2-0800-27fb6edb71ea,
        dd03861e-0bf9-11e2-0800-8dd553174290,
} joined {
} left {
} partitioned {
})
121002  1:56:21 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 3
121002  1:56:21 [Note] WSREP: STATE_EXCHANGE: sent state UUID: b0b8bcd2-0bf9-11e2-0800-86c3bb133737
121002  1:56:21 [Note] WSREP: STATE EXCHANGE: sent state msg: b0b8bcd2-0bf9-11e2-0800-86c3bb133737
121002  1:56:21 [Note] WSREP: STATE EXCHANGE: got state msg: b0b8bcd2-0bf9-11e2-0800-86c3bb133737 from 0 (SVR120-27148.local
domain)
121002  1:56:21 [Note] WSREP: STATE EXCHANGE: got state msg: b0b8bcd2-0bf9-11e2-0800-86c3bb133737 from 1 (svr143-27149.local
domain)
121002  1:56:22 [Note] WSREP: STATE EXCHANGE: got state msg: b0b8bcd2-0bf9-11e2-0800-86c3bb133737 from 2 (SVR282-5197.locald
omain)
121002  1:56:22 [Note] WSREP: Quorum results:
        version    = 2,
        component  = PRIMARY,
        conf_id    = 52,
        members    = 3/3 (joined/total),
        act_id     = 12,
        last_appl. = 0,
        protocols  = 0/4/2 (gcs/repl/appl),
        group UUID = f68ad1a2-0a4e-11e2-0800-7441f90e56cf
121002  1:56:22 [Note] WSREP: Flow-control interval: [14, 28]
121002  1:56:22 [Note] WSREP: New cluster view: global state: f68ad1a2-0a4e-11e2-0800-7441f90e56cf:12, view# 53: Primary, number of nodes: 3, my index: 0, protocol version 2
121002  1:56:22 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
121002  1:56:22 [Note] WSREP: Assign initial position for certification: 12, protocol version: 2
121002  1:56:22 [Note] WSREP: Member 2 (SVR282-5197.localdomain) synced with group.

Don't see something like: WSREP: async IST sender... on the donor or WSREP: Receiving IST... on the joiner.

Still confused about this:

WSREP: Waiting for SST to complete.
share|improve this question

closed as too localized by Jack Douglas Jun 15 '13 at 5:26

This question is unlikely to help any future visitors; it is only relevant to a small geographic area, a specific moment in time, or an extraordinarily narrow situation that is not generally applicable to the worldwide audience of the internet. For help making this question more broadly applicable, visit the help center.If this question can be reworded to fit the rules in the help center, please edit the question.

    
Sorry you got no help with this, I'll close it now as it is unlikely to help anyone else :( –  Jack Douglas Jun 15 '13 at 5:26