了解GH-OST输出
GH-OST会尽量让你知道自己在做什么,会输出一些关键详细信息,让你了解整个迁移过程。当然,你可以控制输出级别。
--verbose
:常用,有用的输出,而不是一切。
--debug
:输出所有一切。
当开始执行GH-OST时,初始输出行可能如下所示:
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 |
2016-05-19 17:57:04 INFO starting gh-ost 0.7.14 2016-05-19 17:57:04 INFO Migrating `mydb`.`mytable` 2016-05-19 17:57:04 INFO connection validated on 127.0.0.1:3306 2016-05-19 17:57:04 INFO User has ALL privileges 2016-05-19 17:57:04 INFO binary logs validated on 127.0.0.1:3306 2016-05-19 17:57:04 INFO Restarting replication on 127.0.0.1:3306 to make sure binlog settings apply to replication thread 2016-05-19 17:57:04 INFO Table found. Engine=InnoDB 2016-05-19 17:57:05 INFO As instructed, I'm issuing a SELECT COUNT(*) on the table. This may take a while 2016-05-19 17:57:11 INFO Exact number of rows via COUNT: 4466810 2016-05-19 17:57:11 INFO --test-on-replica given. Will not execute on master the.master:3306 but rather on replica 127.0.0.1:3306 itself 2016-05-19 17:57:11 INFO Master found to be 127.0.0.1:3306 2016-05-19 17:57:11 INFO connection validated on 127.0.0.1:3306 2016-05-19 17:57:11 INFO Registering replica at 127.0.0.1:3306 2016-05-19 17:57:11 INFO Connecting binlog streamer at mysql-bin.002587:348694066 2016-05-19 17:57:11 INFO connection validated on 127.0.0.1:3306 2016-05-19 17:57:11 INFO rotate to next log name: mysql-bin.002587 2016-05-19 17:57:11 INFO connection validated on 127.0.0.1:3306 2016-05-19 17:57:11 INFO Dropping table `mydb`.`_mytable_gst` 2016-05-19 17:57:11 INFO Table dropped 2016-05-19 17:57:11 INFO Dropping table `mydb`.`_mytable_old` 2016-05-19 17:57:11 INFO Table dropped 2016-05-19 17:57:11 INFO Creating ghost table `mydb`.`_mytable_gst` 2016-05-19 17:57:11 INFO Ghost table created 2016-05-19 17:57:11 INFO Altering ghost table `mydb`.`_mytable_gst` 2016-05-19 17:57:11 INFO Ghost table altered 2016-05-19 17:57:11 INFO Dropping table `mydb`.`_mytable_osc` 2016-05-19 17:57:11 INFO Table dropped 2016-05-19 17:57:11 INFO Creating changelog table `mydb`.`_mytable_osc` 2016-05-19 17:57:11 INFO Changelog table created 2016-05-19 17:57:11 INFO Chosen shared unique key is PRIMARY 2016-05-19 17:57:11 INFO Shared columns are id,name,ref,col4,col5,col6 |
这些信息是GH-OST相对自我解释,他们大多表示一切顺利。你将主要关注迁移并了解其是否顺利进行。一旦迁移实际开始,你将看到如下输出。
1 2 3 4 5 6 7 |
Copy: 0/752865 0.0%; Applied: 0; Backlog: 0/100; Time: 29s(total), 0s(copy); streamer: mysql-bin.007068:846528615; ETA: N/A Copy: 0/752865 0.0%; Applied: 0; Backlog: 0/100; Time: 30s(total), 1s(copy); streamer: mysql-bin.007068:846875570; ETA: N/A Copy: 7300/752865 1.0%; Applied: 0; Backlog: 0/100; Time: 31s(total), 2s(copy); streamer: mysql-bin.007068:855439063; ETA: N/A Copy: 14100/752865 1.9%; Applied: 0; Backlog: 0/100; Time: 32s(total), 3s(copy); streamer: mysql-bin.007068:864722759; ETA: 2m37s Copy: 20100/752865 2.7%; Applied: 0; Backlog: 0/100; Time: 33s(total), 4s(copy); streamer: mysql-bin.007068:874346340; ETA: 2m26s Copy: 27000/752865 3.6%; Applied: 0; Backlog: 0/100; Time: 34s(total), 5s(copy); streamer: mysql-bin.007068:886997306; ETA: 2m14s ... |
在上面的一段时间主要花在了统计表格行上,可以看到第一次行输出Time: 29s表示在实际的行复制开始之前已经过了29s。另外,GH-OST在复制行完成1%之前是不会提供ETA信息。
1 2 3 4 5 6 7 8 9 10 |
Copy: 460900/752865 61.2%; Applied: 0; Backlog: 0/100; Time: 2m35s(total), 2m6s(copy); streamer: mysql-bin.007069:596112173; ETA: 1m19s Copy: 466600/752865 62.0%; Applied: 0; Backlog: 0/100; Time: 2m40s(total), 2m11s(copy); streamer: mysql-bin.007069:622646704; ETA: throttled, my.replica-01.com:3306 replica-lag=3.000000s Copy: 478500/752865 63.6%; Applied: 0; Backlog: 0/100; Time: 2m45s(total), 2m16s(copy); streamer: mysql-bin.007069:641258880; ETA: 1m17s Copy: 496900/752865 66.0%; Applied: 0; Backlog: 0/100; Time: 2m50s(total), 2m21s(copy); streamer: mysql-bin.007069:678956577; ETA: throttled, my.replica-01.com:3306 replica-lag=2.000000s Copy: 496900/752865 66.0%; Applied: 0; Backlog: 0/100; Time: 2m55s(total), 2m26s(copy); streamer: mysql-bin.007069:681610879; ETA: throttled, max-load Threads_running=26 >= 25 Copy: 528000/752865 70.1%; Applied: 0; Backlog: 0/100; Time: 3m0s(total), 2m31s(copy); streamer: mysql-bin.007069:711177703; ETA: throttled, lag=2.483039s Copy: 564900/752865 75.0%; Applied: 0; Backlog: 0/100; Time: 3m30s(total), 3m1s(copy); streamer: mysql-bin.007069:795150744; ETA: throttled, lag=3.482914s Copy: 577200/752865 76.7%; Applied: 0; Backlog: 0/100; Time: 3m39s(total), 3m10s(copy); streamer: mysql-bin.007069:819956052; ETA: 57s Copy: 589300/752865 78.3%; Applied: 0; Backlog: 0/100; Time: 3m56s(total), 3m27s(copy); streamer: mysql-bin.007069:858738375; ETA: 57s Copy: 595700/752865 79.1%; Applied: 0; Backlog: 0/100; Time: 3m57s(total), 3m28s(copy); streamer: mysql-bin.007069:860745762; ETA: 54s |
在上述迁移中有时会受到节流(throttled)处理。
- 检测到副本复制有延迟时会触发节流,延迟时间可自定义,支持毫秒。
- 检测到max-load超过定义的值(Threads_running=26 >= 25)。
Progress
Copy: 595700/752865 79.1%,指复制到gh-ost表上的现有表行数,以及百分比。
Applied: 0,指在二进制日志中处理的SQL条目数量,并将其应用到gh-ost表上。在上面的例子中,迁移表没有流量,因此没有被处理SQL条目。
在密集使用的表上迁移,输出信息可能如下所示:
1 2 3 4 5 6 7 8 9 |
Copy: 30713100/43138319 71.2%; Applied: 381910; Backlog: 0/1000; Time: 2h6m30s(total), 2h3m20s(copy); streamer: mysql-bin.006792:1001340307; ETA: 49m53s Copy: 30852500/43138338 71.5%; Applied: 383365; Backlog: 0/1000; Time: 2h7m0s(total), 2h3m50s(copy); streamer: mysql-bin.006792:1050191186; ETA: 49m18s 2016-07-25 03:20:41 INFO rotate to next log name: mysql-bin.006793 2016-07-25 03:20:41 INFO rotate to next log name: mysql-bin.006793 Copy: 30925700/43138360 71.7%; Applied: 384873; Backlog: 0/1000; Time: 2h7m30s(total), 2h4m20s(copy); streamer: mysql-bin.006793:9144080; ETA: 49m5s Copy: 31028800/43138380 71.9%; Applied: 386325; Backlog: 0/1000; Time: 2h8m0s(total), 2h4m50s(copy); streamer: mysql-bin.006793:47984430; ETA: 48m43s Copy: 31165600/43138397 72.2%; Applied: 387787; Backlog: 0/1000; Time: 2h8m30s(total), 2h5m20s(copy); streamer: mysql-bin.006793:96139474; ETA: 48m8s Copy: 31291200/43138418 72.5%; Applied: 389257; Backlog: 7/1000; Time: 2h9m0s(total), 2h5m50s(copy); streamer: mysql-bin.006793:141094700; ETA: 47m38s Copy: 31389700/43138432 72.8%; Applied: 390629; Backlog: 1000/1000; Time: 2h9m30s(total), 2h6m20s(copy); streamer: mysql-bin.006793:179473435; ETA: throttled, lag=1.548707s |
关键信息说明:
Applied: 381910,显示自迁移开始,gh-ost表应用(Applied)binlog event语句的数量,由于是ROW格式,一个event中会有多个SQL语句。这里就是统计所有SQL语句的累积值。
Backlog: 0/1000,表示我们在读取二进制日志方面表现良好,在二进制日志队列中没有任何积压(Backlog)事件。
Backlog: 7/1000,当复制行时,在二进制日志中积压了一些事件,并且需要应用。
Backlog: 1000/1000,表示我们的1000个事件的缓冲区已满(程序写死的1000个事件缓冲区,低版本是100个),此时就可能需要暂停binlog读取,需要优先应用缓冲区的事件。
Copy: 31291200/43138418, Copy: 31389700/43138432,此迁移使用--exact-rowcount
执行, gh-ost在迁移过程中不断地更新预期行副本的总数,因此从43138418变为43138432。
streamer: mysql-bin.006793:179473435,告诉我们此时哪个二进制日志条目是gh-ost正在处理的。
状态提示
此外,每10分钟打印一次友好提醒,格式如下:
1 2 3 4 5 6 7 8 |
# Migrating `mydb`.`mytable`; Ghost table is `mydb`.`_mytable_gst` # Migrating mysql.master-01.com:3306; inspecting mysql.replica-05.com:3306; executing on some.host-17.com # Migration started at Mon Jul 25 01:13:19 2016 # chunk-size: 500; max lag: 1000ms; max-load: Threads_running=25; critical-load: Threads_running=1000; nice-ratio: 0 # throttle-additional-flag-file: /tmp/gh-ost.throttle.flag.file # postpone-cut-over-flag-file: /tmp/gh-ost.postpone.flag.file [set] # panic-flag-file: /tmp/gh-ost.panic.flag.file # Serving on unix socket: /tmp/gh-ost.mydb.mytable.sock |
以上大多打印出当前配置。请记住,你可以动态控制其中的大部分。
GH-OST注意到通过打印postpone-cut-over-flag-file文件实际存在延迟切割标志[set]。