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.
