Month: December 2014

MySQL Plugin for Oracle Enterprise Manager on VirtualBox: installation gotchas

At the last OOW MySQL Plugin for Oracle Enterprise Manager (OEM) was recognized as most popular MySQL product. If you don’t have OEM installed, but want to test the plugin you can download OEM virtual box template. But, althought this is the easiest way to get started, you still need to make few additions. At least I had to do them when deployed such installation for MySQL Support Team.Here they are. I prefer to use command line when possible.0. Import virtual machine image and change network adapter to working one, then allow to connections via rdesktop:sudo vboxmanage import VBox_EM12cR4.ova –vsys 0 –vmname  myhost-vbox04 \–vsys 0 –unit 17 –disk  /data0/vbox/myhost-vbox04/myhost-vbox04.vmdk sudo vboxmanage modifyvm myhost-vbox04 –bridgeadapter1 ‘eth0’sudo vboxmanage modifyvm myhost-vbox04 –vrdeaddress myhost –vrde on –vrdeport 90041. The machine comes with 3G RAM which is not enough. Better to increase up to 8::sudo vboxmanage modifyvm myhost-vbox04 –memory 81922. Also 40G of disk space will be used completely right after you start OEM. Therefore it is better to don’t follow me and don’t reach this point, but increase it right after installing the machine. I increased mine up to 100G. The machines comes with vmdk disk format which does not support dynamic size change. Therefore you need to convert it to vdi format first, then resize.sudo vboxmanage clonehd myhost-vbox04.vmdk myhost-vbox04.vdi –format vdisudo vboxmanage modifyhd myhost-vbox04.vdi –resize 1024003. Then convert it back to vmdk and replace old disk with new one:sudo vboxmanage clonehd myhost-vbox04.vdi myhost-vbox04-01.vmdk –format vmdksudo vboxmanage storageattach myhost-vbox04 –storagectl “SATA” –device 0  \
–port 0 –type hdd –medium /data0/vbox/myhost-vbox04/myhost-vbox04-01.vmdk4. We are not done yet: 60G will stay invisible unless we change disk partitions. I did it with help of utility GParted, but you can use any, including system’s.5. Turn machine off and eject GParted CD:sudo vboxmanage storageattach myhost-vbox04 –storagectl “IDE” –port 0 \
–device 0 –medium emptydrive6. Boot the machine, login as root user (password is welcome1) and confirm that although OS ecognizes extended disk, but partition which holds OEM installation still full:$ /sbin/fdisk -lDisk /dev/sda: 107.3 GB, 107374182400 bytes255 heads, 63 sectors/track, 13054 cylindersUnits = cylinders of 16065 * 512 = 8225280 bytes   Device Boot      Start         End      Blocks   Id  System/dev/sda1   *           1          13      104391   83  Linux/dev/sda2              14       13055   104753177+  8e  Linux LVMDisk /dev/dm-0: 36.5 GB, 36574330880 bytes255 heads, 63 sectors/track, 4446 cylindersUnits = cylinders of 16065 * 512 = 8225280 bytesDisk /dev/dm-0 doesn’t contain a valid partition tableDisk /dev/dm-1: 7314 MB, 7314866176 bytes255 heads, 63 sectors/track, 889 cylindersUnits = cylinders of 16065 * 512 = 8225280 bytesDisk /dev/dm-1 doesn’t contain a valid partition table$ df -hFilesystem            Size  Used Avail Use% Mounted on/dev/mapper/VolGroup00-LogVol00                       33G   32G     0 100% //dev/sda1              99M   23M   71M  25% /boottmpfs                 4.0G     0  4.0G   0% /dev/shmThis happens, because OEM is on LVM partition and we need to fix it too:$ /sbin/lvmlvm> pvresize /dev/sda2lvm> lvextend -L+55G /dev/mapper/VolGroup00-LogVol00  Extending logical volume LogVol00 to 89.06 GB  Logical volume LogVol00 successfully resizedlvm> quit  Exiting. $ /sbin/resize2fs /dev/mapper/VolGroup00-LogVol00resize2fs 1.39 (29-May-2006)Filesystem at /dev/mapper/VolGroup00-LogVol00 is mounted on /; on-line resizing requiredPerforming an on-line resize of /dev/mapper/VolGroup00-LogVol00 to 23347200 (4k) blocks.The filesystem on /dev/mapper/VolGroup00-LogVol00 is now 23347200 blocks long.$ df -hFilesystem            Size  Used Avail Use% Mounted on/dev/mapper/VolGroup00-LogVol00                       87G   32G   51G  39% //dev/sda1              99M   23M   71M  25% /boottmpfs                 4.0G     0  4.0G   0% /dev/shmVoi-la! Now we can logout from root account and start OEM.7. But not yet if you need to connect to this virtual machine via ssh and cannot tune your network in such a way that emcc.example.com will be resolved to the virtual machine. In my case I had to connect to this machine via ssh and I cannot tune my network, only virtual machine’s options. So I set network options as usual (GUI can be used) and changed ORACLE_HOSTNAME from emcc.example.com to appropriate value in .bashrc and ./start_agent.sh files.Unfortunately this change does not instruct WebLogic to listen remote port even after I disabled machine’s firewall, so I still have to use rdesktop to be able to see OEM GUI.8. Finally we can start OEM as described in the README file, provided at edelivery.oracle.com for this virtual machine: do not use ./start_all.sh, but start each part separately:./start_db.sh/u01/OracleHomes/Middleware/oms/bin/emctl start oms./start_agent.shAnd, last but not least, it is better to perform OEM setup wearing such a t-shirt:I would not describe how to setup MySQL Plugin, because MySQL User Reference Manual contains detailed and clear instructions. I’d better show few screenshots how you can monitor both remote and local servers.Just connected with a server on remote machine:
And on local one:
After test load with help of mysqlslap utility:
And this strange chart show how MySQL works on virtual machine:

2014 review: the year by the numbers

The last post of the year! It’s been a really excellent year all round and time for my traditional post counting down some of the numbers that have been my life this year. 10068445 (roughly): the number of page views across my blog according to Google (up around 9% from 2013) 105881: the number of miles […]

uhesse.com in 2014 – a Review

Better than ever 2014 brought a new high water mark with 282,000 hits! Meanwhile, uhesse.com gets over 1,000 hits per day on average. Who are the referrers? The vast majority of visitors came to uhesse.com via google searches: 163,000 On a distant second place is Twitter: 2,500 visitors came from there Facebook and LinkedIn each […]

只对某个特定的SQL语句开启10046 trace

最近碰到了这样一个有趣的问题: 有一条SQL语句,大部分时间它的执行时间是几十个毫秒; 但是偶尔某次的执行时间会长于2秒钟。因为应用对这个语句的执行时间非常的敏感,我们必须诊断是因为什么原因导致它偶尔执行时间长于2秒。

这个问题为什么会有挑战性呢?因为我们很难收集慢的时候的10046 trace:首先我们不知道这个问题什么时候会发生,也不知道会在哪个session里发生。如果对所有的session全天开启10046 trace, 会产生很多比较大的trace并影响数据库整体的性能。

好在这个数据库是11g的,在11gevent++的特性允许我们只对某个特定的SQL收集10046 trace. 即在运行这条SQL时开启10046 trace,在这条SQL运行完之后关闭10046 trace.这样可以显著的降低生成的trace的大小。但是因为我们无法确定哪个session会产生问题,所以只要运行过这个SQLsession都会产生一个trace文件。

开启的步骤是(要把下面的awsh60c8mpfu1替换成那条SQLSQL_ID)

alter system set events ‘sql_trace [sql: awsh60c8mpfu1] level 12’;

而关闭的步骤是(要把下面的awsh60c8mpfu1替换成那条SQLSQL_ID)

alter system set events ‘sql_trace [sql: awsh60c8mpfu1] off’;

在收集到很多10046 trace,并使用tkprof格式化后(需指定AGGREGATE=NO,这样tkprof会对每一次执行都生成汇总报告),我们最后定位到了问题发生时SQL语句读取物理块时花费了更多的时间。

关于这个主题,如果有后续的问题欢迎点击链接参与我们在中文社区的讨论。 

How small changes impact complex systems – MySQL example

If you’ve been studying complex systems you know what minor changes might cause consequences of much greater proportions, sometimes causing some effects that are not easily explained at first. I recently ran across a great illustration of such behavior while doing MySQL benchmarks which I thought would be interesting to share.I’m using a very simple benchmark – Sysbench 0.5 on Percona Server 5.6.21-70.1 just running update queries:sysbench –num-threads=64 –report-interval=10 –max-time=0 –max-requests=0 –rand-type=pareto –oltp-table-size=1000000000 –mysql-user=root –mysql-password= –mysql-db=sbinnodb –test=/usr/share/doc/sysbench/tests/db/update_index.lua runSome people frown upon such benchmarks due to their triviality and being irrelevant to workloads. I like them because they often allow you to study already complex system behavior in a much more controlled environment than “real” workloads – and so you can understand internal dynamics better.For this test I set innodb_purge_threads=8, innodb_max_purge_lag=1000000, innodb_max_purge_lag_delay=5000 as otherwise chances are that the history will just be growing forever not allowing the system to reach the steady state. I wrote about InnoDB history problems in detail recently in a post titled “InnoDB transaction history often hides dangerous ‘debt’.The only change I was looking for is changing innodb_flush_log_at_trx_commit from 1 to 2. I then went back to 1 a few hours later, after the system had reached the steady state. What I would normally expect in such a case is a performance increase because there is less work to do on commit and that is pretty much it. Looking at the graphs however I can see much more changes in the system. Let me go through them and explain the ones which I can:The throughput graph is probably the most interesting here. We can see that indeed the throughput has substantially improved when set innodb_flush_log_at_trx_commit=2 and then went back to the old one after it was set back to 1. We see however in 2 some interesting effects here – a spike of a few minutes and later a dip below the original performance level for a few hours, until finally recovery back to the baseline. I’ll explain this with different graphs.CPU usage is interesting, too. We can see there is user CPU increase correlating to the throughput increase but also a drastic IOWait increase. Why would it increase when we’re actually making workload less IO bound by not flushing log as much? The reason is because there are more threads now that can perform IO concurrently, hence increasing what is reporting IO wait and deceasing idle time.InnoDB writing much more data is expected and it very well matches throughput. Not much of anything unexpected.As we see setting innodb_flush_log_at_trx_commit=2 causes the amount of dirty pages in the buffer pool to go down significantly. It recovers when it is put back. The reason I suspect in this case is the undo space – as we will see in later graph history length spikes quickly – obviously requiring some space in the buffer pool.This is perhaps one of the most interesting graphs here. You can see for some reason when log flush is enabled that purge threads are able to keep up. But if you disable it they cannot, which makes history grow very quickly until the max allowed amount. This is by the way the time we see the spike in the throughput as there is no throttling being done to keep history in check. This also explains why after I set innodb_flush_log_at_trx_commit back to 1 that performance first drops well below original levels – InnoDB needs to go through and purge the history, which takes resources. Another interesting thing you can notice is how uneven history cleanup is. Specifically you can note some 75% percent of the history has been cleaned up almost instantly while initial 25% took a lot of time to work out. I do not have an exact explanation here yet I believe it has to do with the fact initially history purging requires a significant amount of IO while at a certain point in time a purge happens completely in the buffer pool and hence being much faster.Why would purge threads have a hard time keeping up when log flush is disabled? I suspect there are 2 reasons. First, the system can provide much more throughput in such configuration (not keeping purging into account) while purge subsystem is limited and can’t keep up with such a high load. The other reason is – eliminating serialization on the log flush exposes other parts of InnoDB to contention which further suppresses purge system progress.This is another relevant graph to show the throttling done because purging can’t keep up. As you see we got about 2.5ms delay injected for updates to give purging some time to keep up. It is good to watch it to understand if the max delay you specified is enough to prevent purge lag while still avoid having the system grind to a halt. Had I set innodb_max_purge_lag_delay to 1000 it would not be enough to prevent history length growing to infinity, having I set it to 100000 the system could grind to a halt in case there is some long-running transaction causing history length to grow to about 1 million.Lets look at Physical IO – it is also quite interesting. As you can see in the first and last parts of the graph there are more pages flushed than pages read, while when we disable log flushing we get much more reads than writes which only stops after history purging catch up is complete. I find this very interesting – this means that working with even modest history – 1M in this case causes a lot of IO – I assume because due to access pattern to the undo space it is constantly being washed out from the buffer pool. This graph is a very good illustration why large history might be a death spiral, as once it is there the system needs to do much more work.This IO utilization graph might be a bit hard to understand but what it generally shows is that during the time the hard drive has been 100% utilized, there was still at least one outstanding IO to serve. However the concurrency was different with more average IO requests outstanding when we had log flushing disabled. This makes sense. We can also see it was highest when we enabled log flushing back but there was history to go through and catch up.Changes to contention are very curious – we can see there is a lot more spin rounds and specifically shared lock spin rounds when we have log flush disabled. This is what I believe comes from less serialization on the log flushing causes a lot more internal contention.It might not be very easy to see but this graph shows that innodb_row_lock_times spikes 1000x when log flushing is disabled. Why would that be? I suspect the reason is injected delay for purging. I also suspect the design of this throttling so it only is done when an actual change is attempted to be made, this is where update statement already holds some locks, which causes more row lock contention for other statements.InnoDB has something called Server Activity count. As you can see from this graph it is not really a good indicator – for some reason it shows a lower value when the server was doing much more work. I do not understand other than this variable is incremented enough to explain it but find it curious.LRU flushing also is drastically different between enabled and disabled log flushing. We get a lot more calls to search free pages and a lot more scans. I’m not sure why exactly this is happening but I think this has something to do with undo space caching which is constantly washed out from buffer pool which increased IO seems to indicate.Finally lets look at perhaps the most counter-intuitive result – the amount of pending pwrites to the log file – we allowed to cache more log files in the OS cache but the amount of waits on writes to the log files actually increased? I’m not very sure why this is happening – perhaps there is a lot of IO pressure on OS so it does not delay writes to the log files for long time?This is the same graph showing log fsyncs and log pwrites together. We can see when we set innodb_flush_log_at_trx_commit=2 that we see a lot more waits on pwrites, while less waits on fsync (which now should only be happening once per second or so). In general these two graphs tell me in some cases assuming log writes with innodb_flush_log_at_trx_commit=2 will be “free” because the operating system will instantly acknowledge them and put in the cache is not always correct.Summary: The main point I’m looking to illustrate here is what changes you’re doing to the MySQL configuration (same can be said about your application OS configuration, hardware, etc.) can cause much larger changes to system behavior than you would guess. If you have the time it is good to validate whenever there are any other changes to system behavior beyond what you would think. If not at least keep an open mind and assume what any change, even a small one, can cause dramatic system behavior changes.If you want to explore similar graphs check out Percona Cloud Tools – it’s easy to get going and allows you to build graphs like these absolutely free and perform a lot of in depth analyses. Now in free beta, Percona Cloud Tools is a hosted service providing access to query performance insights for all MySQL uses.The post How small changes impact complex systems – MySQL example appeared first on MySQL Performance Blog.

Packt’s $5 eBonanza returns

Packt’s $5 eBonanza returns Following the success of last year’s festive offer, Packt Publishing will be celebrating the holiday season with an even bigger $5 offer. From Thursday 18th December, every eBook and video will be available on the publisher’s website for just $5. Customers are invited to purchase as many as they like before […]

MHA with binlog server

In this post ,we mainly talk about MHA GTID behavior, we test different cases and find something is different from previous versions .
we have four machines for this test.
environment:

master server: 10.0.128.77
slave server : 10.0.128.110/113/114
port : 3306

————————————————————————————–
we first do normal failover .
kill master server
we find MHA outputs:

Tue Dec 30 13:32:14 2014 – [warning] Got error on MySQL connect ping: DBI connect(‘;host=10.0.128.77;port=3306;mysql_connect_timeout=1′,’dbadmin’,…) failed: Lost connection to MySQL server at ‘reading initial communication packet’, system error: 111 at /usr/share/perl5/vendor_perl/MHA/HealthCheck.pm line 97
2013 (Lost connection to MySQL server at ‘reading initial communication packet’, system error: 111)
Tue Dec 30 13:32:14 2014 – [info] Executing secondary network check script: /usr/bin/masterha_secondary_check -s 10.0.128.113 -s 10.0.128.114 –user=root –master_host=10.0.128.77 –master_ip=10.0.128.77 –master_port=3306 –master_user=dbadmin –master_password=NV7yVBpn88cg4WJCVlZd –ping_type=CONNECT
Tue Dec 30 13:32:14 2014 – [info] Executing SSH check script: exit 0
Tue Dec 30 13:32:14 2014 – [info] HealthCheck: SSH to 10.0.128.77 is reachable.
Monitoring server 10.0.128.113 is reachable, Master is not reachable from 10.0.128.113. OK.
Monitoring server 10.0.128.114 is reachable, Master is not reachable from 10.0.128.114. OK.
Tue Dec 30 13:32:14 2014 – [info] Master is not reachable from all other monitoring servers. Failover should start.
Tue Dec 30 13:32:16 2014 – [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at ‘reading initial communication packet’, system error: 111)
Tue Dec 30 13:32:16 2014 – [warning] Connection failed 2 time(s)..
Tue Dec 30 13:32:18 2014 – [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at ‘reading initial communication packet’, system error: 111)
Tue Dec 30 13:32:18 2014 – [warning] Connection failed 3 time(s)..
Tue Dec 30 13:32:20 2014 – [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at ‘reading initial communication packet’, system error: 111)
Tue Dec 30 13:32:20 2014 – [warning] Connection failed 4 time(s)..
Tue Dec 30 13:32:20 2014 – [warning] Master is not reachable from health checker!
Tue Dec 30 13:32:20 2014 – [warning] Master 10.0.128.77(10.0.128.77:3306) is not reachable!
Tue Dec 30 13:32:20 2014 – [warning] SSH is reachable.
Tue Dec 30 13:32:20 2014 – [info] Connecting to a master server failed. Reading configuration file /etc/masterha_default.cnf and /etc/masterha/test.cnf again, and trying to connect to all servers to check server status..
Tue Dec 30 13:32:20 2014 – [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Tue Dec 30 13:32:20 2014 – [info] Reading application default configuration from /etc/masterha/test.cnf..
Tue Dec 30 13:32:20 2014 – [info] Reading server configuration from /etc/masterha/test.cnf..
Tue Dec 30 13:32:20 2014 – [info] GTID failover mode = 1
Tue Dec 30 13:32:20 2014 – [info] Dead Servers:
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] Alive Servers:
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.110(10.0.128.110:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.113(10.0.128.113:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.114(10.0.128.114:3306)
Tue Dec 30 13:32:20 2014 – [info] Alive Slaves:
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.110(10.0.128.110:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.113(10.0.128.113:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.114(10.0.128.114:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] Checking slave configurations..
Tue Dec 30 13:32:20 2014 – [info] read_only=1 is not set on slave 10.0.128.110(10.0.128.110:3306).
Tue Dec 30 13:32:20 2014 – [info] read_only=1 is not set on slave 10.0.128.113(10.0.128.113:3306).
Tue Dec 30 13:32:20 2014 – [info] read_only=1 is not set on slave 10.0.128.114(10.0.128.114:3306).
Tue Dec 30 13:32:20 2014 – [info] Checking replication filtering settings..
Tue Dec 30 13:32:20 2014 – [info] Replication filtering check ok.
Tue Dec 30 13:32:20 2014 – [info] Master is down!
Tue Dec 30 13:32:20 2014 – [info] Terminating monitoring script.
Tue Dec 30 13:32:20 2014 – [info] Got exit code 20 (Master dead).
Tue Dec 30 13:32:20 2014 – [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Tue Dec 30 13:32:20 2014 – [info] Reading application default configuration from /etc/masterha/test.cnf..
Tue Dec 30 13:32:20 2014 – [info] Reading server configuration from /etc/masterha/test.cnf..
Tue Dec 30 13:32:20 2014 – [info] MHA::MasterFailover version 0.56.
Tue Dec 30 13:32:20 2014 – [info] Starting master failover.
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] * Phase 1: Configuration Check Phase..
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] GTID failover mode = 1
Tue Dec 30 13:32:20 2014 – [info] Dead Servers:
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] Checking master reachability via MySQL(double check)…
Tue Dec 30 13:32:20 2014 – [info] ok.
Tue Dec 30 13:32:20 2014 – [info] Alive Servers:
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.110(10.0.128.110:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.113(10.0.128.113:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.114(10.0.128.114:3306)
Tue Dec 30 13:32:20 2014 – [info] Alive Slaves:
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.110(10.0.128.110:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.113(10.0.128.113:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.114(10.0.128.114:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] Starting GTID based failover.
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] ** Phase 1: Configuration Check Phase completed.
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] * Phase 2: Dead Master Shutdown Phase..
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] Forcing shutdown so that applications never connect to the current master..
Tue Dec 30 13:32:20 2014 – [info] Executing master IP deactivation script:
Tue Dec 30 13:32:20 2014 – [info] /usr/local/dbadmin/mhascripts/master_ip_failover_pajk01.pl –orig_master_host=10.0.128.77 –orig_master_ip=10.0.128.77 –orig_master_port=3306 –command=stopssh –ssh_user=root
Disabling the VIP on old master: 10.0.128.77
RTNETLINK answers: Cannot assign requested address
Tue Dec 30 13:32:20 2014 – [info] done.
Tue Dec 30 13:32:20 2014 – [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
Tue Dec 30 13:32:20 2014 – [info] * Phase 2: Dead Master Shutdown Phase completed.
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] * Phase 3: Master Recovery Phase..
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] * Phase 3.1: Getting Latest Slaves Phase..
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] The latest binary log file/position on all slaves is master-bin.000001:3679
Tue Dec 30 13:32:20 2014 – [info] Retrieved Gtid Set: a861ddd1-8f4e-11e4-aeac-86f5fb218bef:1-15
Tue Dec 30 13:32:20 2014 – [info] Latest slaves (Slaves that received relay log files to the latest):
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.110(10.0.128.110:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.113(10.0.128.113:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.114(10.0.128.114:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] The oldest binary log file/position on all slaves is master-bin.000001:3679
Tue Dec 30 13:32:20 2014 – [info] Retrieved Gtid Set: a861ddd1-8f4e-11e4-aeac-86f5fb218bef:1-15
Tue Dec 30 13:32:20 2014 – [info] Oldest slaves:
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.110(10.0.128.110:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.113(10.0.128.113:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info] 10.0.128.114(10.0.128.114:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 13:32:20 2014 – [info] GTID ON
Tue Dec 30 13:32:20 2014 – [info] Replicating from 10.0.128.77(10.0.128.77:3306)
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] * Phase 3.3: Determining New Master Phase..
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] Searching new master from slaves..
Tue Dec 30 13:32:20 2014 – [info] Candidate masters from the configuration file:
Tue Dec 30 13:32:20 2014 – [info] Non-candidate masters:
Tue Dec 30 13:32:20 2014 – [info] New master is 10.0.128.110(10.0.128.110:3306)
Tue Dec 30 13:32:20 2014 – [info] Starting master failover..
Tue Dec 30 13:32:20 2014 – [info]
From:
10.0.128.77(10.0.128.77:3306) (current master)
+–10.0.128.110(10.0.128.110:3306)
+–10.0.128.113(10.0.128.113:3306)
+–10.0.128.114(10.0.128.114:3306)

To:
10.0.128.110(10.0.128.110:3306) (new master)
+–10.0.128.113(10.0.128.113:3306)
+–10.0.128.114(10.0.128.114:3306)
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] * Phase 3.3: New Master Recovery Phase..
Tue Dec 30 13:32:20 2014 – [info]
Tue Dec 30 13:32:20 2014 – [info] Waiting all logs to be applied..
Tue Dec 30 13:32:20 2014 – [info] done.
Tue Dec 30 13:32:20 2014 – [info] Getting new master’s binlog name and position..
Tue Dec 30 13:32:20 2014 – [info] mysql-bin.000001:4142
Tue Dec 30 13:32:20 2014 – [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST=’10.0.128.110′, MASTER_PORT=3306, MASTER_AUTO_POSITION=1, MASTER_USER=’rep’, MASTER_PASSWORD=’xxx’;
Tue Dec 30 13:32:20 2014 – [info] Master Recovery succeeded. File:Pos:Exec_Gtid_Set: mysql-bin.000001, 4142, a861ddd1-8f4e-11e4-aeac-86f5fb218bef:1-15
Tue Dec 30 13:32:20 2014 – [info] Executing master IP activate script:
Tue Dec 30 13:32:20 2014 – [info] /usr/local/dbadmin/mhascripts/master_ip_failover_pajk01.pl –command=start –ssh_user=root –orig_master_host=10.0.128.77 –orig_master_ip=10.0.128.77 –orig_master_port=3306 –new_master_host=10.0.128.110 –new_master_ip=10.0.128.110 –new_master_port=3306 –new_master_user=’dbadmin’ –new_master_password=’NV7yVBpn88cg4WJCVlZd’
Set read_only=0 on the new master.
Enabling the VIP – 10.0.128.35/24 on the new master – 10.0.128.110
Tue Dec 30 13:32:23 2014 – [info] OK.
Tue Dec 30 13:32:23 2014 – [info] ** Finished master recovery successfully.
Tue Dec 30 13:32:23 2014 – [info] * Phase 3: Master Recovery Phase completed.
Tue Dec 30 13:32:23 2014 – [info]
Tue Dec 30 13:32:23 2014 – [info] * Phase 4: Slaves Recovery Phase..
Tue Dec 30 13:32:23 2014 – [info]
Tue Dec 30 13:32:23 2014 – [info]
Tue Dec 30 13:32:23 2014 – [info] * Phase 4.1: Starting Slaves in parallel..
Tue Dec 30 13:32:23 2014 – [info]
Tue Dec 30 13:32:23 2014 – [info] — Slave recovery on host 10.0.128.113(10.0.128.113:3306) started, pid: 31607. Check tmp log /var/log/masterha/test/10.0.128.113_3306_20141230133220.log if it takes time..
Tue Dec 30 13:32:23 2014 – [info] — Slave recovery on host 10.0.128.114(10.0.128.114:3306) started, pid: 31608. Check tmp log /var/log/masterha/test/10.0.128.114_3306_20141230133220.log if it takes time..
Tue Dec 30 13:32:24 2014 – [info]
Tue Dec 30 13:32:24 2014 – [info] Log messages from 10.0.128.113 …
Tue Dec 30 13:32:24 2014 – [info]
Tue Dec 30 13:32:23 2014 – [info] Resetting slave 10.0.128.113(10.0.128.113:3306) and starting replication from the new master 10.0.128.110(10.0.128.110:3306)..
Tue Dec 30 13:32:24 2014 – [info] Executed CHANGE MASTER.
Tue Dec 30 13:32:24 2014 – [info] Slave started.
Tue Dec 30 13:32:24 2014 – [info] gtid_wait(a861ddd1-8f4e-11e4-aeac-86f5fb218bef:1-15) completed on 10.0.128.113(10.0.128.113:3306). Executed 0 events.
Tue Dec 30 13:32:24 2014 – [info] End of log messages from 10.0.128.113.
Tue Dec 30 13:32:24 2014 – [info] — Slave on host 10.0.128.113(10.0.128.113:3306) started.
Tue Dec 30 13:32:24 2014 – [info]
Tue Dec 30 13:32:24 2014 – [info] Log messages from 10.0.128.114 …
Tue Dec 30 13:32:24 2014 – [info]
Tue Dec 30 13:32:23 2014 – [info] Resetting slave 10.0.128.114(10.0.128.114:3306) and starting replication from the new master 10.0.128.110(10.0.128.110:3306)..
Tue Dec 30 13:32:24 2014 – [info] Executed CHANGE MASTER.
Tue Dec 30 13:32:24 2014 – [info] Slave started.
Tue Dec 30 13:32:24 2014 – [info] gtid_wait(a861ddd1-8f4e-11e4-aeac-86f5fb218bef:1-15) completed on 10.0.128.114(10.0.128.114:3306). Executed 0 events.
Tue Dec 30 13:32:24 2014 – [info] End of log messages from 10.0.128.114.
Tue Dec 30 13:32:24 2014 – [info] — Slave on host 10.0.128.114(10.0.128.114:3306) started.
Tue Dec 30 13:32:24 2014 – [info] All new slave servers recovered successfully.
Tue Dec 30 13:32:24 2014 – [info]
Tue Dec 30 13:32:24 2014 – [info] * Phase 5: New master cleanup phase..
Tue Dec 30 13:32:24 2014 – [info]
Tue Dec 30 13:32:24 2014 – [info] Resetting slave info on the new master..
Tue Dec 30 13:32:24 2014 – [info] 10.0.128.110: Resetting slave info succeeded.
Tue Dec 30 13:32:24 2014 – [info] Master failover to 10.0.128.110(10.0.128.110:3306) completed successfully.
Tue Dec 30 13:32:24 2014 – [info]

—– Failover Report —–

test: MySQL Master failover 10.0.128.77(10.0.128.77:3306) to 10.0.128.110(10.0.128.110:3306) succeeded

Master 10.0.128.77(10.0.128.77:3306) is down!

Check MHA Manager logs at a3-relay00.sh for details.

Started automated(non-interactive) failover.
Invalidated master IP address on 10.0.128.77(10.0.128.77:3306)
Selected 10.0.128.110(10.0.128.110:3306) as a new master.
10.0.128.110(10.0.128.110:3306): OK: Applying all logs succeeded.
10.0.128.110(10.0.128.110:3306): OK: Activated master IP address.
10.0.128.113(10.0.128.113:3306): OK: Slave started, replicating from 10.0.128.110(10.0.128.110:3306)
10.0.128.114(10.0.128.114:3306): OK: Slave started, replicating from 10.0.128.110(10.0.128.110:3306)
10.0.128.110(10.0.128.110:3306): Resetting slave info succeeded.
Master failover to 10.0.128.110(10.0.128.110:3306) completed successfully.

failover to new master 10.0.128.110:
create new database liuyang3 on 10.0.128.110:

mysql> show databases;
+——————–+
| Database |
+——————–+
| information_schema |
| liuyang2 |
| mysql |
| performance_schema |
| test |
+——————–+
5 rows in set (0.00 sec)

mysql> create database liuyang3;
Query OK, 1 row affected (0.00 sec)

show all slaves status :

mysql> show slave status\G;
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 10.0.128.110
Master_User: rep
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000001
Read_Master_Log_Pos: 4296
Relay_Log_File: hadoop-vm-datanode3-relay-bin.000002
Relay_Log_Pos: 562
Relay_Master_Log_File: mysql-bin.000001
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 4296
Relay_Log_Space: 780
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 2
Master_UUID: 909ee6b1-8f51-11e4-aebf-00163f00801f
Master_Info_File: mysql.slave_master_info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set: 909ee6b1-8f51-11e4-aebf-00163f00801f:1
Executed_Gtid_Set: 909ee6b1-8f51-11e4-aebf-00163f00801f:1,
a861ddd1-8f4e-11e4-aeac-86f5fb218bef:1-15
Auto_Position: 1
1 row in set (0.00 sec)

start from new GTID — This GTID is new and we can also see old master GTID

#cat /data/mysql/data/auto.cnf
[auto]
server-uuid=909ee6b1-8f51-11e4-aebf-00163f00801f

this GTID was gathered when slave has been started.
start old master 10.0.128.77 again and add it to the cluster.

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.17-log MySQL Community Server (GPL)

Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type ‘help;’ or ‘\h’ for help. Type ‘\c’ to clear the current input statement.

mysql> CHANGE MASTER TO MASTER_HOST=’10.0.128.110′, MASTER_PORT=3306, MASTER_AUTO_POSITION=1, MASTER_USER=’rep’, MASTER_PASSWORD=’rep’;
Query OK, 0 rows affected, 2 warnings (0.32 sec)

mysql> start slave ;
Query OK, 0 rows affected, 1 warning (0.06 sec)

mysql> show databases;
+——————–+
| Database |
+——————–+
| information_schema |
| liuyang2 |
| liuyang3 |
| mysql |
| performance_schema |
| test |
+——————–+
6 rows in set (0.00 sec)

database liuyang3 appeared.
———————————————————————–
initialize cluster:
drop all database;

master: 10.0.128.110
slave: 10.0.128.77/114/113

load data into master. we keep one specific slave has lag and set “sync_binlog=1″ on all slaves.

mysql> delimiter $$
mysql>
mysql> CREATE PROCEDURE myprocedure()
-> BEGIN
-> DECLARE i INT DEFAULT 1;
->
-> CREATE TABLE test
-> (ascii_code int, ascii_char CHAR(1));
->
-> WHILE (i<=10000) DO
-> INSERT INTO test VALUES(i,CHAR(i));
-> SET i=i+1;
-> END WHILE;
->
-> END$$
Query OK, 0 rows affected (0.03 sec)

mysql> delimiter ;
mysql>
mysql> call myprocedure();
Query OK, 1 row affected, 1 warning (5 min 53.61 sec)

mysql> select count(*) from liuyang1.test;
+———-+
| count(*) |
+———-+
| 10000 |
+———-+
1 row in set (0.01 sec)

10.0.128.113/114 are both consistent with master

mysql> select count(*) from liuyang1.test;
+———-+
| count(*) |
+———-+
| 10000 |
+———-+
1 row in set (0.01 sec)

Retrieved_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-10003
Executed_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-10003
Auto_Position: 1

10.0.128.77 has a huge lag:

Retrieved_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-2548
Executed_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-1979
Auto_Position: 1

now kill master server:
oldest slave will change master to 10.0.128.113:

Tue Dec 30 16:36:15 2014 – [info] Retrieved Gtid Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-10003
Tue Dec 30 16:36:15 2014 – [info] Latest slaves (Slaves that received relay log files to the latest):
Tue Dec 30 16:36:15 2014 – [info] 10.0.128.113(10.0.128.113:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 16:36:15 2014 – [info] GTID ON
Tue Dec 30 16:36:15 2014 – [info] Replicating from 10.0.128.110(10.0.128.110:3306)
Tue Dec 30 16:36:15 2014 – [info] 10.0.128.114(10.0.128.114:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 16:36:15 2014 – [info] GTID ON
Tue Dec 30 16:36:15 2014 – [info] Replicating from 10.0.128.110(10.0.128.110:3306)
Tue Dec 30 16:36:15 2014 – [info] The oldest binary log file/position on all slaves is mysql-bin.000001:885010
Tue Dec 30 16:36:15 2014 – [info] Retrieved Gtid Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-2864
Tue Dec 30 16:36:15 2014 – [info] Oldest slaves:
Tue Dec 30 16:36:15 2014 – [info] 10.0.128.77(10.0.128.77:3306) Version=5.6.17-log (oldest major version between slaves) log-bin:enabled
Tue Dec 30 16:36:15 2014 – [info] GTID ON
Tue Dec 30 16:36:15 2014 – [info] Replicating from 10.0.128.110(10.0.128.110:3306)
Tue Dec 30 16:36:15 2014 – [info]
Tue Dec 30 16:36:15 2014 – [info] * Phase 3.3: Determining New Master Phase..
Tue Dec 30 16:36:15 2014 – [info]
Tue Dec 30 16:36:15 2014 – [info] Searching new master from slaves..
Tue Dec 30 16:36:15 2014 – [info] Candidate masters from the configuration file:
Tue Dec 30 16:36:15 2014 – [info] Non-candidate masters:
Tue Dec 30 16:36:15 2014 – [info] New master is 10.0.128.113(10.0.128.113:3306)

and MHA will control 10.0.128.77 to do this command:

SELECT WAIT_UNTIL_SQL_THREAD_AFTER_GTIDS(‘4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-10003’,0) AS Result

</per>

show slave status\G;

<pre class=”brush: text; gutter: false; first-line: 1; highlight: []; html-script: false”>
shows:

Retrieved_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:2786-5067
Executed_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-3929
Auto_Position: 1

this means oldest slave 10.0.128.77 changes to 10.0.128.113 for the new master . Star from transaction id 2785:
Retrieved_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-2785 in old master
Retrieved_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:2786-5067 in current master
wait a long time ……

Retrieved_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:2786-10003
Executed_Gtid_Set: 4f1dfbe6-8ffc-11e4-b318-00163f00801f:1-10003
Auto_Position: 1

mysql> select count(*) from liuyang1.test;
+———-+
| count(*) |
+———-+
| 10000 |
+———-+

oldest slave 10.0.128.77 was OK !
—————————-
TEST more details:
We test two cases:
1. just 10.0.128.77 has lag — make 10.0.128.77 as candidate master
2. all slaves have lag — make 10.0.128.114 as candidate master
initialize environment
all slave should get new GTID:
master: 10.0.128.113
slave: 10.0.128.110/77/114
make all slaves have lag manually .
First rerun procedure to initialize data

mysql> call myprocedure();
Query OK, 1 row affected, 1 warning (1 min 9.98 sec)

kill master MHA will choose a new candidate master and do slave recovery:
10.0.128.110/114 position:

Retrieved_Gtid_Set: f776aa4d-908d-11e4-b6ce-00163f008023:1-10006
Executed_Gtid_Set: f776aa4d-908d-11e4-b6ce-00163f008023:1-10006
Auto_Position: 1

10.0.128.77 position:

Retrieved_Gtid_Set: f776aa4d-908d-11e4-b6ce-00163f008023:1-1269
Executed_Gtid_Set: f776aa4d-908d-11e4-b6ce-00163f008023:1-684
Auto_Position: 1

+–10.0.128.114(10.0.128.114:3306)
Wed Dec 31 10:09:50 2014 – [info]
Wed Dec 31 10:09:50 2014 – [info] * Phase 3.3: New Master Recovery Phase..
Wed Dec 31 10:09:50 2014 – [info]
Wed Dec 31 10:09:50 2014 – [info] Waiting all logs to be applied..
Wed Dec 31 10:10:26 2014 – [info] done.
Wed Dec 31 10:11:28 2014 – [info] Replicating from the latest slave 10.0.128.110(10.0.128.110:3306) and waiting to apply..
Wed Dec 31 10:11:28 2014 – [info] Waiting all logs to be applied on the latest slave..
Wed Dec 31 10:11:28 2014 – [info] Resetting slave 10.0.128.77(10.0.128.77:3306) and starting replication from the new master 10.0.128.110(10.0.128.110:3306)..
Wed Dec 31 10:11:28 2014 – [info] Executed CHANGE MASTER.
Wed Dec 31 10:11:28 2014 – [info] Slave started.
Wed Dec 31 10:11:28 2014 – [info] Waiting to execute all relay logs on 10.0.128.77(10.0.128.77:3306)..

mysql> show slave status\G;
*************************** 1. row ***************************
Slave_IO_State: System lock
Master_Host: 10.0.128.110
Master_User: rep
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000001
Read_Master_Log_Pos: 487380
Relay_Log_File: a3-oracle-128-77-relay-bin.000002
Relay_Log_Pos: 23897
Relay_Master_Log_File: mysql-bin.000001
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 458828
Relay_Log_Space: 52664
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 333
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 2
Master_UUID: 354a7e91-908e-11e4-b6d0-00163f00801f
Master_Info_File: mysql.slave_master_info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Reading event from the relay log
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set: f776aa4d-908d-11e4-b6ce-00163f008023:1539-1722
Executed_Gtid_Set: f776aa4d-908d-11e4-b6ce-00163f008023:1-1622
Auto_Position: 1

MHA will control 77 to change master to 10.0.128.110 (prior is 10.0.128.113)
so 77 start from new transaction (old is 1-1538, new is 1539-1722)
we can wait until reach 10006 on lastest

dbadmin | 10.0.128.25:17331 | NULL | Query | 60 | Waiting for the slave SQL thread to advance position | SELECT MASTER_POS_WAIT(‘mysql-bin.000001′,’2831783′,0) AS Result

in 10.0.128.110 show master status:

| mysql-bin.000001 | 2831783 | | | f776aa4d-908d-11e4-b6ce-00163f008023:1-10006 |

until 77 reached transaction 10006 ,MHA will continue:

Wed Dec 31 10:36:14 2014 – [info] master_pos_wait(mysql-bin.000001:2831783) completed on 10.0.128.77(10.0.128.77:3306). Executed 4229 events.
Wed Dec 31 10:36:14 2014 – [info] done.
Wed Dec 31 10:36:14 2014 – [info] done.
Wed Dec 31 10:36:14 2014 – [info] Getting new master’s binlog name and position..
Wed Dec 31 10:36:14 2014 – [info] master-bin.000001:2831783
Wed Dec 31 10:36:14 2014 – [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST=’10.0.128.77′, MASTER_PORT=3306, MASTER_AUTO_POSITION=1, MASTER_USER=’rep’, MASTER_PASSWORD=’xxx’;
Wed Dec 31 10:36:14 2014 – [info] Master Recovery succeeded. File:Pos:Exec_Gtid_Set: master-bin.000001, 2831783, f776aa4d-908d-11e4-b6ce-00163f008023:1-10006
Wed Dec 31 10:36:14 2014 – [info] Executing master IP activate script:
Wed Dec 31 10:36:14 2014 – [info] /usr/local/dbadmin/mhascripts/master_ip_failover_pajk01.pl –command=start –ssh_user=root –orig_master_host=10.0.128.113 –orig_master_ip=10.0.128.113 –orig_master_port=3306 –new_master_host=10.0.128.77 –new_master_ip=10.0.128.77 –new_master_port=3306 –new_master_user=’dbadmin’ –new_master_password=’NV7yVBpn88cg4WJCVlZd’
Set read_only=0 on the new master.
Enabling the VIP – 10.0.128.35/24 on the new master – 10.0.128.77
sysfs read broadcast value: No such file or directory
falling back to default broadcast value
Wed Dec 31 10:36:17 2014 – [info] OK.
Wed Dec 31 10:36:17 2014 – [info] ** Finished master recovery successfully.
Wed Dec 31 10:36:17 2014 – [info] * Phase 3: Master Recovery Phase completed.
Wed Dec 31 10:36:17 2014 – [info]
Wed Dec 31 10:36:17 2014 – [info] * Phase 4: Slaves Recovery Phase..
Wed Dec 31 10:36:17 2014 – [info]
Wed Dec 31 10:36:17 2014 – [info]
Wed Dec 31 10:36:17 2014 – [info] * Phase 4.1: Starting Slaves in parallel..
Wed Dec 31 10:36:17 2014 – [info]
Wed Dec 31 10:36:17 2014 – [info] — Slave recovery on host 10.0.128.110(10.0.128.110:3306) started, pid: 13177. Check tmp log /var/log/masterha/test/10.0.128.110_3306_20141231100948.log if it takes time..
Wed Dec 31 10:36:17 2014 – [info] — Slave recovery on host 10.0.128.114(10.0.128.114:3306) started, pid: 13178. Check tmp log /var/log/masterha/test/10.0.128.114_3306_20141231100948.log if it takes time..
Wed Dec 31 10:36:18 2014 – [info]
Wed Dec 31 10:36:18 2014 – [info] Log messages from 10.0.128.114 …
Wed Dec 31 10:36:18 2014 – [info]
Wed Dec 31 10:36:17 2014 – [info] Resetting slave 10.0.128.114(10.0.128.114:3306) and starting replication from the new master 10.0.128.77(10.0.128.77:3306)..
Wed Dec 31 10:36:17 2014 – [info] Executed CHANGE MASTER.
Wed Dec 31 10:36:18 2014 – [info] Slave started.
Wed Dec 31 10:36:18 2014 – [info] gtid_wait(f776aa4d-908d-11e4-b6ce-00163f008023:1-10006) completed on 10.0.128.114(10.0.128.114:3306). Executed 0 events.
Wed Dec 31 10:36:18 2014 – [info] End of log messages from 10.0.128.114.
Wed Dec 31 10:36:18 2014 – [info] — Slave on host 10.0.128.114(10.0.128.114:3306) started.
Wed Dec 31 10:36:18 2014 – [info]
Wed Dec 31 10:36:18 2014 – [info] Log messages from 10.0.128.110 …
Wed Dec 31 10:36:18 2014 – [info]
Wed Dec 31 10:36:17 2014 – [info] Resetting slave 10.0.128.110(10.0.128.110:3306) and starting replication from the new master 10.0.128.77(10.0.128.77:3306)..
Wed Dec 31 10:36:18 2014 – [info] Executed CHANGE MASTER.
Wed Dec 31 10:36:18 2014 – [info] Slave started.
Wed Dec 31 10:36:18 2014 – [info] gtid_wait(f776aa4d-908d-11e4-b6ce-00163f008023:1-10006) completed on 10.0.128.110(10.0.128.110:3306). Executed 0 events.
Wed Dec 31 10:36:18 2014 – [info] End of log messages from 10.0.128.110.
Wed Dec 31 10:36:18 2014 – [info] — Slave on host 10.0.128.110(10.0.128.110:3306) started.
Wed Dec 31 10:36:18 2014 – [info] All new slave servers recovered successfully.
Wed Dec 31 10:36:18 2014 – [info]
Wed Dec 31 10:36:18 2014 – [info] * Phase 5: New master cleanup phase..
Wed Dec 31 10:36:18 2014 – [info]
Wed Dec 31 10:36:18 2014 – [info] Resetting slave info on the new master..
Wed Dec 31 10:36:18 2014 – [info] 10.0.128.77: Resetting slave info succeeded.
Wed Dec 31 10:36:18 2014 – [info] Master failover to 10.0.128.77(10.0.128.77:3306) completed successfully.
Wed Dec 31 10:36:18 2014 – [info]

try to recover other slaves but other slave are both newest. So change master to 77 directly.
——————————————————————–
2. all slaves have lag and 114 is candidate master.
slaves will do not merge master’s binlog (I don’t know why)
initialize cluster again:
master : 10.0.128.113
slave : 10.0.128.114(candidate master)/77/110
drop table test ;
Run procedure again:
we got final result .

mysql> select count(*) from liuyang1.test;
+———-+
| count(*) |
+———-+
| 5852 |
+———-+

we lost 4148 records.

Wed Dec 31 10:50:33 2014 – [info] * Phase 3.3: New Master Recovery Phase..
Wed Dec 31 10:50:33 2014 – [info]
Wed Dec 31 10:50:33 2014 – [info] Waiting all logs to be applied..
Wed Dec 31 10:50:33 2014 – [info] done.
Wed Dec 31 10:51:35 2014 – [info] Getting new master’s binlog name and position..
Wed Dec 31 10:51:35 2014 – [info] mysql-bin.000001:4488549
Wed Dec 31 10:51:35 2014 – [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST=’10.0.128.114′, MASTER_PORT=3306, MASTER_AUTO_POSITION=1, MASTER_USER=’rep’, MASTER_PASSWORD=’xxx’;
Wed Dec 31 10:51:35 2014 – [info] Master Recovery succeeded. File:Pos:Exec_Gtid_Set: mysql-bin.000001, 4488549, 5d04dd5c-908e-11e4-b6d1-86f5fb218bef:1,
f776aa4d-908d-11e4-b6ce-00163f008023:1-15861
Wed Dec 31 10:51:35 2014 – [info] Executing master IP activate script:
Wed Dec 31 10:51:35 2014 – [info] /usr/local/dbadmin/mhascripts/master_ip_failover_pajk01.pl –command=start –ssh_user=root –orig_master_host=10.0.128.113 –orig_master_ip=10.0.128.113 –orig_master_port=3306 –new_master_host=10.0.128.114 –new_master_ip=10.0.128.114 –new_master_port=3306 –new_master_user=’dbadmin’ –new_master_password=’NV7yVBpn88cg4WJCVlZd’
Set read_only=0 on the new master.
Enabling the VIP – 10.0.128.35/24 on the new master – 10.0.128.114
Wed Dec 31 10:51:38 2014 – [info] OK.
Wed Dec 31 10:51:38 2014 – [info] ** Finished master recovery successfully.
Wed Dec 31 10:51:38 2014 – [info] * Phase 3: Master Recovery Phase completed.
Wed Dec 31 10:51:38 2014 – [info]
Wed Dec 31 10:51:38 2014 – [info] * Phase 4: Slaves Recovery Phase..
Wed Dec 31 10:51:38 2014 – [info]
Wed Dec 31 10:51:38 2014 – [info]
Wed Dec 31 10:51:38 2014 – [info] * Phase 4.1: Starting Slaves in parallel..
Wed Dec 31 10:51:38 2014 – [info]
Wed Dec 31 10:51:38 2014 – [info] — Slave recovery on host 10.0.128.77(10.0.128.77:3306) started, pid: 13508. Check tmp log /var/log/masterha/test/10.0.128.77_3306_20141231105020.log if it takes time..
Wed Dec 31 10:51:38 2014 – [info] — Slave recovery on host 10.0.128.110(10.0.128.110:3306) started, pid: 13509. Check tmp log /var/log/masterha/test/10.0.128.110_3306_20141231105020.log if it takes time..
Wed Dec 31 11:01:34 2014 – [info]
Wed Dec 31 11:01:34 2014 – [info] Log messages from 10.0.128.77 …
Wed Dec 31 11:01:34 2014 – [info]
Wed Dec 31 10:51:38 2014 – [info] Resetting slave 10.0.128.77(10.0.128.77:3306) and starting replication from the new master 10.0.128.114(10.0.128.114:3306)..
Wed Dec 31 10:52:41 2014 – [info] Executed CHANGE MASTER.
Wed Dec 31 10:52:41 2014 – [info] Slave started.
Wed Dec 31 11:01:34 2014 – [info] gtid_wait(5d04dd5c-908e-11e4-b6d1-86f5fb218bef:1,
f776aa4d-908d-11e4-b6ce-00163f008023:1-15861) completed on 10.0.128.77(10.0.128.77:3306). Executed 855 events.
Wed Dec 31 11:01:34 2014 – [info] End of log messages from 10.0.128.77.
Wed Dec 31 11:01:34 2014 – [info] — Slave on host 10.0.128.77(10.0.128.77:3306) started.
Wed Dec 31 11:02:03 2014 – [info]
Wed Dec 31 11:02:03 2014 – [info] Log messages from 10.0.128.110 …
Wed Dec 31 11:02:03 2014 – [info]
Wed Dec 31 10:51:38 2014 – [info] Resetting slave 10.0.128.110(10.0.128.110:3306) and starting replication from the new master 10.0.128.114(10.0.128.114:3306)..
Wed Dec 31 10:52:41 2014 – [info] Executed CHANGE MASTER.
Wed Dec 31 10:52:41 2014 – [info] Slave started.
Wed Dec 31 11:02:03 2014 – [info] gtid_wait(5d04dd5c-908e-11e4-b6d1-86f5fb218bef:1,
f776aa4d-908d-11e4-b6ce-00163f008023:1-15861) completed on 10.0.128.110(10.0.128.110:3306). Executed 142 events.
Wed Dec 31 11:02:03 2014 – [info] End of log messages from 10.0.128.110.
Wed Dec 31 11:02:03 2014 – [info] — Slave on host 10.0.128.110(10.0.128.110:3306) started.
Wed Dec 31 11:02:03 2014 – [info] All new slave servers recovered successfully.
Wed Dec 31 11:02:03 2014 – [info]
Wed Dec 31 11:02:03 2014 – [info] * Phase 5: New master cleanup phase..
Wed Dec 31 11:02:03 2014 – [info]
Wed Dec 31 11:02:03 2014 – [info] Resetting slave info on the new master..
Wed Dec 31 11:02:03 2014 – [info] 10.0.128.114: Resetting slave info succeeded.
Wed Dec 31 11:02:03 2014 – [info] Master failover to 10.0.128.114(10.0.128.114:3306) completed successfully.
Wed Dec 31 11:02:03 2014 – [info]

10.0.128.114 do not merge newest binlog from 10.0.128.113 (although it can ssh to 113 server )
————————————————————————————-
add binlog server and make 77 server as candidate master

[binlog1]
hostname=10.0.128.252

10.0.128.252 is manager node machine. we set binlog server in this machine.
#ls -l /data/mysql/data/
total 2896
-rw-rw-r– 1 mysql mysql 2960898 Dec 31 13:57 mysql-bin.000001
drop test table
run procedure again
we check lastest slave
10.0.128.114 :

Retrieved_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-3357
Executed_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-3356

10.0.128.77:

Retrieved_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-102
Executed_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-48

10.0.128.110:

Retrieved_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-344
Executed_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-270

and all slaves have lag : 10.0.128.77>10.0.128.110>10.0.128.114 (lastest slave)
now we kill master server:

Waiting to execute all relay logs on 10.0.128.77(10.0.128.77:3306)..
Wed Dec 31 13:59:28 2014 – [info] master_pos_wait(mysql-bin.000001:1219763) completed on 10.0.128.77(10.0.128.77:3306). Executed 37 events.
Wed Dec 31 13:59:28 2014 – [info] done.
Wed Dec 31 13:59:28 2014 – [info] done.
Wed Dec 31 13:59:28 2014 – [info] — Saving binlog from host 10.0.128.252 started, pid: 15893
Wed Dec 31 13:59:29 2014 – [info]
Wed Dec 31 13:59:29 2014 – [info] Log messages from 10.0.128.252 …
Wed Dec 31 13:59:29 2014 – [info]
Wed Dec 31 13:59:28 2014 – [info] Fetching binary logs from binlog server 10.0.128.252..
Wed Dec 31 13:59:28 2014 – [info] Executing binlog save command: save_binary_logs –command=save –start_file=mysql-bin.000001 –start_pos=1275770 –output_file=/var/log/masterha/test/saved_binlog_binlog1_20141231135735.binlog –handle_raw_binlog=0 –skip_filter=1 –disable_log_bin=0 –manager_version=0.56 –oldest_version=5.6.17-log –binlog_dir=/data/mysql/data
Creating /var/log/masterha/test if not exists.. ok.
Concat binary/relay logs from mysql-bin.000001 pos 1275770 to mysql-bin.000001 EOF into /var/log/masterha/test/saved_binlog_binlog1_20141231135735.binlog ..
Concat succeeded.
Wed Dec 31 13:59:29 2014 – [info] scp from root@10.0.128.252:/var/log/masterha/test/saved_binlog_binlog1_20141231135735.binlog to local:/var/log/masterha/test/saved_binlog_10.0.128.252_binlog1_20141231135735.binlog succeeded.
Wed Dec 31 13:59:29 2014 – [info] End of log messages from 10.0.128.252.
Wed Dec 31 13:59:29 2014 – [info] Saved mysqlbinlog size from 10.0.128.252 is 4885833 bytes.
Wed Dec 31 13:59:29 2014 – [info] Applying differential binlog /var/log/masterha/test/saved_binlog_10.0.128.252_binlog1_20141231135735.binlog ..
Wed Dec 31 13:59:39 2014 – [info] Differential log apply from binlog server succeeded.
Wed Dec 31 13:59:39 2014 – [info] Getting new master’s binlog name and position..
Wed Dec 31 13:59:39 2014 – [info] master-bin.000001:3485577

MHA will scp binlog server binlog and Concat binlog, all slaves are consistent in the end. (same with old behavior)
check all slaves:

Retrieved_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:4311-10003
Executed_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-10003
Auto_Position: 1

mysql> select count(*) from liuyang1.test;
+———-+
| count(*) |
+———-+
| 10000 |
+———-+

no data lost. and every slaves got final transaction 10003.
—————————————————————-
add an other binlog server (master server)

[binlog1]
hostname=10.0.128.252

[binlog2]
hostname=10.0.128.113

add 113 to cluster:
master : 10.0.128.113
slave : 10.0.128.77/110/114
run procedure again:

mysql> delimiter ;

mysql> call myprocedure();

10.0.128.77:

Retrieved_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:10004-10327
Executed_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-10151,
cfd90b74-90af-11e4-b7ab-86f5fb218bef:1
Auto_Position: 1

10.0.128.110:

Retrieved_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:10004-10621
Executed_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-10177,
cfd90b74-90af-11e4-b7ab-86f5fb218bef:1
Auto_Position: 1

10.0.128.114:

Retrieved_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:10004-12723
Executed_Gtid_Set: 1cc021e4-90b0-11e4-b7ad-00163f008023:1-12722,
cfd90b74-90af-11e4-b7ab-86f5fb218bef:1
Auto_Position: 1

now we remove binlog on 10.0.128.252 manually and kill master server :
find these messages:

Wed Dec 31 15:26:16 2014 – [info] Executing binlog save command: save_binary_logs –command=save –start_file=mysql-bin.000003 –start_pos=1243184 –output_file=/var/log/masterha/test/saved_binlog_binlog1_20141231152512.binlog –handle_raw_binlog=0 –skip_filter=1 –disable_log_bin=0 –manager_version=0.56 –oldest_version=5.6.17-log –binlog_dir=/data/mysql/data
Failed to save binary log: Binlog not found from /data/mysql/data! If you got this error at MHA Manager, please set “master_binlog_dir=/path/to/binlog_directory_of_the_master” correctly in the MHA Manager’s configuration file and try again.
at /usr/bin/save_binary_logs line 123
eval {…} called at /usr/bin/save_binary_logs line 70
main::main() called at /usr/bin/save_binary_logs line 66
Wed Dec 31 15:26:16 2014 – [error][/usr/share/perl5/vendor_perl/MHA/MasterFailover.pm, ln660] Failed to save binary log events from the binlog server. Maybe disks on binary logs are not accessible or binary log itself is corrupt?
Wed Dec 31 15:26:16 2014 – [info] End of log messages from 10.0.128.252.
Wed Dec 31 15:26:16 2014 – [warning] Got error from 10.0.128.252.
Wed Dec 31 15:26:18 2014 – [info]
Wed Dec 31 15:26:18 2014 – [info] Log messages from 10.0.128.113 …
Wed Dec 31 15:26:18 2014 – [info]
Wed Dec 31 15:26:16 2014 – [info] Fetching binary logs from binlog server 10.0.128.113..
Wed Dec 31 15:26:16 2014 – [info] Executing binlog save command: save_binary_logs –command=save –start_file=mysql-bin.000003 –start_pos=1243184 –output_file=/var/log/masterha/test/saved_binlog_binlog2_20141231152512.binlog –handle_raw_binlog=0 –skip_filter=1 –disable_log_bin=0 –manager_version=0.56 –oldest_version=5.6.17-log –binlog_dir=/data/mysql/data
Creating /var/log/masterha/test if not exists.. ok.

MHA check binlog server 1 and find error with binlog then try to recover from binlog server 2.
With this feature we can add master server as first binlog server to guarantee no binlog loss.If master server crash and can not been reached,binlog server 2 will also provide service.
Final:

MHA has changed failover procedure when turn on GTID.

1.If you want to use binlog server you must open GTID (I don’t know why Yoshi design like this)
2.MHA will not use relay-log to reocver (apply_diff_relay_logs will not be used ,just change master to lastest slave to recover with GTID)
3.if there’s no binlog server setting. MHA will ignore master binlog (even Manager node can ssh to Master server)
4.if you do not set binlog server on MHA, data may lost (MHA just keep all slaves consistent,so if lastest slave has lag data will be lost)
5.you can set multiple binlog server ,MHA will check them orderly,you can even set Master server as binlog server.

TEL/電話+86 13764045638
Email service@parnassusdata.com
QQ 47079569