Wednesday, February 20, 2013

Parallel replication and GTID - A tale of two implementations

MySQL 5.6 is probably the version of MySQL with the biggest bundle of new features. You may want to try it soon, since it's now released as GA, and I would like to offer some practical experience on how to use some of the advanced features.

Since replication is my main interest, I will focus on some of the new features in this field, and I will compare what's available in MySQL 5.6 with Tungsten Replicator.

The focus of the comparison is usability, manageability, and some hidden functionality. Parallel replication has been available with Tungsten Replicator for almost two years, and Global Transaction Identifiers for much longer than that. With MySQL 5.6, it seems that the MySQL team wants to close the gap. While the main feature (parallel execution threads) is available and performing well, there are some shocking differences in terms of ease of use, administration handles, and capabilities, that suggest at least poor integration into the server.

To test replication, I have enabled parallel workers and GTID in the slaves, and I ran 5 quick processes on separated databases. I repeated the operation with MySQL 5.6 and Tungsten Replicator. Let's see what I have found.

Monitoring

First of all, there is "SHOW SLAVE STATUS," which has been enhanced to include the GTID. Trouble is, this command was designed for a single replication channel, and when the GTID from several parallel threads are listed, the result is puzzling.

show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: rsandbox
                  Master_Port: 18675
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000002
          Read_Master_Log_Pos: 386003338
               Relay_Log_File: mysql_sandbox18676-relay-bin.000006
                Relay_Log_Pos: 315698722
        Relay_Master_Log_File: mysql-bin.000002
             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: 315698559
              Relay_Log_Space: 386003928
              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: 646
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: 1
                  Master_UUID: f6ea8d94-7147-11e2-a036-6c626da07446
             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: f6ea8d94-7147-11e2-a036-6c626da07446:1-1089548
            Executed_Gtid_Set: f6ea8d94-7147-11e2-
a036-6c626da07446:1-891950:891952-891953:891955-891963:891965-891969:891971-891973:891976-891992:891994-8919
95:891997:891999:892001-892002:892005-892016:892019-892023:892025-892026:892028:892030-892032:892034-892039:
892041-892044:892046:892048-892051:892053-892054:892056-892063:892065-892072:892074-892084:892086-892089:892
091:892094:892096-892111:892113-892122:892124-892137:892139-892142:892144-892146:892148-892150:892152:892154
-892159:892161-892171:892173-892182:892184-892185:892187:892189-892193:892196-892198:892200-892206:892208:89
2210-892211:892213-892216:892218-892219:892222:892224-892226:892228:892230-892249:892251:892255:892257:89225
9-892260:892262-892263:892265:892268:892270-892288:892290:892292:892295-892298:892300-892307:892309:892312:8
92314-892317:892319-892320:892324-892328:892332-892336:892342:892344-892349:892352-892355:892359-892360:8923
62-892363:892369-892372:892376:892378-892384:892387:892390:892392:892394:892396-892397:892399:892401-892403:
892405-892407:892409:892413-892415:892417:892421:892423-892426:892429-892431:892433:892435:892437-892439:892
442:892445:892448
                Auto_Position: 0

After this abundant display of GTID (alas, without any reference to the transactions being processed), I was expecting something from the tables dedicated to replication monitoring. However, what is missing in these tables is any reference to GTIDs, and any context about the transactions. There is no indication of which schema the changes are happening, how well or bad distributed they are, whether there was the need for serialization, or other info.

select * from mysql.slave_worker_info\G
*************************** 1. row ***************************
                        Id: 1
            Relay_log_name: ./mysql_sandbox18676-relay-bin.000006
             Relay_log_pos: 91550519
           Master_log_name: mysql-bin.000002
            Master_log_pos: 91550356
 Checkpoint_relay_log_name: ./mysql_sandbox18676-relay-bin.000006
  Checkpoint_relay_log_pos: 91371802
Checkpoint_master_log_name: mysql-bin.000002
 Checkpoint_master_log_pos: 91371639
          Checkpoint_seqno: 508
     Checkpoint_group_size: 64
   Checkpoint_group_bitmap: #####(unprintable characters replaced)#####
*************************** 2. row ***************************
                        Id: 2
            Relay_log_name: ./mysql_sandbox18676-relay-bin.000006
             Relay_log_pos: 91497101
           Master_log_name: mysql-bin.000002
            Master_log_pos: 91496938
 Checkpoint_relay_log_name: ./mysql_sandbox18676-relay-bin.000006
  Checkpoint_relay_log_pos: 91319665
Checkpoint_master_log_name: mysql-bin.000002
 Checkpoint_master_log_pos: 91319502
          Checkpoint_seqno: 501
     Checkpoint_group_size: 64
  ?! ?AA@oint_group_bitmap:  #####(unprintable characters replaced)#####
*************************** 3. row ***************************
                        Id: 3
            Relay_log_name: ./mysql_sandbox18676-relay-bin.000006
             Relay_log_pos: 91540831
           Master_log_name: mysql-bin.000002
            Master_log_pos: 91540668
 Checkpoint_relay_log_name: ./mysql_sandbox18676-relay-bin.000006
  Checkpoint_relay_log_pos: 91360379
Checkpoint_master_log_name: mysql-bin.000002
 Checkpoint_master_log_pos: 91360216
          Checkpoint_seqno: 511
     Checkpoint_group_size: 64
   Checkpoint_group_bitmap: #####(unprintable characters replaced)#####
*************************** 4. row ***************************
                        Id: 4
            Relay_log_name: ./mysql_sandbox18676-relay-bin.000006
             Relay_log_pos: 91461999
           Master_log_name: mysql-bin.000002
            Master_log_pos: 91461836
 Checkpoint_relay_log_name: ./mysql_sandbox18676-relay-bin.000006
  Checkpoint_relay_log_pos: 91281068
Checkpoint_master_log_name: mysql-bin.000002
 Checkpoint_master_log_pos: 91280905
          Checkpoint_seqno: 510
     Checkpoint_group_size: 64
   Checkpoint_group_bitmap: #####(unprintable characters replaced)#####
*************************** 5. row ***************************
                        Id: 5
            Relay_log_name: ./mysql_sandbox18676-relay-bin.000006
             Relay_log_pos: 91373959
           Master_log_name: mysql-bin.000002
            Master_log_pos: 91373796
 Checkpoint_relay_log_name: ./mysql_sandbox18676-relay-bin.000006
  Checkpoint_relay_log_pos: 91192982
Checkpoint_master_log_name: mysql-bin.000002
 Checkpoint_master_log_pos: 91192819
          Checkpoint_seqno: 508
     Checkpoint_group_size: 64
   Checkpoint_group_bitmap: #####(unprintable characters replaced)#####

The table dedicated to parallel replication doesn't give us any information about GTID. And it doesn't say in which schema the transaction is happening. This lack of information, for a feature that is based on schema isolation, is quite startling.

So, we have a look at the crash-safe slave tables.

select * from mysql.slave_master_info\G
*************************** 1. row ***************************
       Number_of_lines: 23
       Master_log_name: mysql-bin.000002
        Master_log_pos: 385282815
                  Host: 127.0.0.1
             User_name: rsandbox
         User_password: rsandbox
                  Port: 18675
         Connect_retry: 60
           Enabled_ssl: 0
                Ssl_ca: 
            Ssl_capath: 
              Ssl_cert: 
            Ssl_cipher: 
               Ssl_key: 
Ssl_verify_server_cert: 0
             Heartbeat: 1800
                  Bind: 
    Ignored_server_ids: 0
                  Uuid: f6ea8d94-7147-11e2-a036-6c626da07446
           Retry_count: 86400
               Ssl_crl: 
           Ssl_crlpath: 
 Enabled_auto_position: 0

select * from mysql.slave_relay_log_info\G
*************************** 1. row ***************************
  Number_of_lines: 7
   Relay_log_name: ./mysql_sandbox18676-relay-bin.000006
    Relay_log_pos: 235324325
  Master_log_name: mysql-bin.000002
   Master_log_pos: 235324162
        Sql_delay: 0
Number_of_workers: 5
               Id: 1

What's wrong with this picture? Two main things:

  • There is no mention of GTID in these tables either. So, if you are using GTID, your only option is to look at the binary logs, and see if you get any solace when a failover occurs. But the server itself does not offer any help.
  • There is only one row available for the master and relay log info. When you are using parallel replication, this means that either every commit must lock the same row, or these tables are useless for keeping the slave crash safe. If the information used for crash safe comes from the parallel workers table, then the crash safe tables are redundant. But as you can see on your own, the parallel workers table has less information than master_info and relay_log_info.

Thus, we have a look at how GTID and parallel threads are implemented in Tungsten.

Even limiting the information to the tables found in the server, we find several differences:

  • The GTID is displayed in every row. (It's the column named seqno). The original binlog name and position are also preserved and associated with the GTID (in the column named eventid.)
  • Every row displays in which schema it is being processed. (It's the column named shard_id)
  • There is no separated table for crash-safe info and parallel threads. When Tungsten uses a single thread, the table has only one row. When it is using parallel appliers, then there are multiple rows, one for each applier. This way, there is no possibility of deadlock, as every thread locks only one row.

select * from tungsten_tsandbox.trep_commit_seqno
+---------+---------+--------+-----------+-----------+--------------+-------------------------------------+-----------------+---------------------+------------+---------------------+
| task_id | seqno   | fragno | last_frag | source_id | epoch_number | eventid                             | applied_latency | update_timestamp    | shard_id   | extract_timestamp   |
+---------+---------+--------+-----------+-----------+--------------+-------------------------------------+-----------------+---------------------+------------+---------------------+
|       0 | 2218566 |      0 | 1         | 127.0.0.1 |            0 | mysql-bin.000002:0000000330476211;0 |               1 | 2013-02-07 23:12:07 | evaluator1 | 2013-02-07 23:12:06 |
|       1 | 2218521 |      0 | 1         | 127.0.0.1 |            0 | mysql-bin.000002:0000000330469587;0 |               1 | 2013-02-07 23:12:07 | evaluator2 | 2013-02-07 23:12:06 |
|       2 | 2220380 |      0 | 1         | 127.0.0.1 |            0 | mysql-bin.000002:0000000330747639;0 |               1 | 2013-02-07 23:12:07 | evaluator3 | 2013-02-07 23:12:06 |
|       3 | 2219360 |      0 | 1         | 127.0.0.1 |            0 | mysql-bin.000002:0000000330594617;0 |               1 | 2013-02-07 23:12:07 | evaluator4 | 2013-02-07 23:12:06 |
|       4 | 2221220 |      0 | 1         | 127.0.0.1 |            0 | mysql-bin.000002:0000000330873205;0 |               0 | 2013-02-07 23:12:07 | evaluator5 | 2013-02-07 23:12:07 |
+---------+---------+--------+-----------+-----------+--------------+-------------------------------------+-----------------+---------------------+------------+---------------------+

You can see the same information in vertical output, to appreciate the level of detail.

select * from tungsten_tsandbox.trep_commit_seqno\G
*************************** 1. row ***************************
          task_id: 0
            seqno: 2257934
           fragno: 0
        last_frag: 1
        source_id: 127.0.0.1
     epoch_number: 0
          eventid: mysql-bin.000002:0000000336350320;0
  applied_latency: 9
 update_timestamp: 2013-02-07 23:12:26
         shard_id: evaluator1
extract_timestamp: 2013-02-07 23:12:17
*************************** 2. row ***************************
          task_id: 1
            seqno: 2257938
           fragno: 0
        last_frag: 1
        source_id: 127.0.0.1
     epoch_number: 0
          eventid: mysql-bin.000002:0000000336350875;0
  applied_latency: 9
 update_timestamp: 2013-02-07 23:12:26
         shard_id: evaluator2
extract_timestamp: 2013-02-07 23:12:17
*************************** 3. row ***************************
          task_id: 2
            seqno: 2257936
           fragno: 0
        last_frag: 1
        source_id: 127.0.0.1
     epoch_number: 0
          eventid: mysql-bin.000002:0000000336350648;0
  applied_latency: 9
 update_timestamp: 2013-02-07 23:12:26
         shard_id: evaluator3
extract_timestamp: 2013-02-07 23:12:17
*************************** 4. row ***************************
          task_id: 3
            seqno: 2257916
           fragno: 0
        last_frag: 1
        source_id: 127.0.0.1
     epoch_number: 0
          eventid: mysql-bin.000002:0000000336347768;0
  applied_latency: 9
 update_timestamp: 2013-02-07 23:12:26
         shard_id: evaluator4
extract_timestamp: 2013-02-07 23:12:17
*************************** 5. row ***************************
          task_id: 4
            seqno: 2257933
           fragno: 0
        last_frag: 1
        source_id: 127.0.0.1
     epoch_number: 0
          eventid: mysql-bin.000002:0000000336350156;0
  applied_latency: 9
 update_timestamp: 2013-02-07 23:12:26
         shard_id: evaluator5
extract_timestamp: 2013-02-07 23:12:17

In addition to the information that you can get from the database server, Tungsten has its own tools that provide information about the process. For example, trepctl status -name stores provides, among other things, detailed information about how many transactions were processed, accepted, and rejected by each channel, and if there was any collision that caused serialization.

trepctl status -name stores
Processing status command (stores)...
NAME                      VALUE
----                      -----
activeSeqno             : 2267132
doChecksum              : false
flushIntervalMillis     : 0
fsyncOnFlush            : false
logConnectionTimeout    : 28800
logDir                  : /home/tungsten/tsb2/db3/tlogs/tsandbox
logFileRetainMillis     : 604800000
logFileSize             : 100000000
maximumStoredSeqNo      : 2267230
minimumStoredSeqNo      : 0
name                    : thl
readOnly                : false
storeClass              : com.continuent.tungsten.replicator.thl.THL
timeoutMillis           : 2147483647
NAME                      VALUE
----                      -----
criticalPartition       : -1
discardCount            : 0
estimatedOfflineInterval: 0.0
eventCount              : 2267140
headSeqno               : 2267140
maxOfflineInterval      : 5
maxSize                 : 10
name                    : parallel-queue
queues                  : 5
serializationCount      : 0
serialized              : false
stopRequested           : false
store.0                 : THLParallelReadTask task_id=0 thread_name=store-thl-0 hi_seqno=2267140 lo_seqno=1 read=2267140 accepted=460813 discarded=1806327 events=0
store.1                 : THLParallelReadTask task_id=1 thread_name=store-thl-1 hi_seqno=2267140 lo_seqno=1 read=2267140 accepted=452812 discarded=1814328 events=0
store.2                 : THLParallelReadTask task_id=2 thread_name=store-thl-2 hi_seqno=2267140 lo_seqno=1 read=2267140 accepted=450812 discarded=1816328 events=0
store.3                 : THLParallelReadTask task_id=3 thread_name=store-thl-3 hi_seqno=2267140 lo_seqno=1 read=2267140 accepted=450397 discarded=1816743 events=0
store.4                 : THLParallelReadTask task_id=4 thread_name=store-thl-4 hi_seqno=2267140 lo_seqno=1 read=2267141 accepted=452306 discarded=1814834 events=0
storeClass              : com.continuent.tungsten.replicator.thl.THLParallelQueue
syncInterval            : 10000
Finished status command (stores)...

The same tool can show what is happening for each shard. When you are dealing with many channels, you need to know who is doing what, and sometime with a high level of detail. This is especially useful when things go wrong. Knowing what has happened to your transaction, and at which stage it stopped working could be a great help to fix problems. You can follow every transaction using either the GTID (appliedLastSeqno), or the binlog+position (appliedLastEventId), combined with the schema where it is happening (shardId.)

trepctl status -name shards
Processing status command (shards)...
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338943258;0
appliedLastSeqno  : 2275303
appliedLatency    : 18.942
eventCount        : 243189
shardId           : evaluator1
stage             : q-to-dbms
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338940934;0
appliedLastSeqno  : 2275288
appliedLatency    : 18.935
eventCount        : 231993
shardId           : evaluator10
stage             : q-to-dbms
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338939386;0
appliedLastSeqno  : 2275277
appliedLatency    : 18.931
eventCount        : 234687
shardId           : evaluator2
stage             : q-to-dbms
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338938221;0
appliedLastSeqno  : 2275269
appliedLatency    : 18.928
eventCount        : 231045
shardId           : evaluator3
stage             : q-to-dbms
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338942040;0
appliedLastSeqno  : 2275295
appliedLatency    : 18.933
eventCount        : 225755
shardId           : evaluator4
stage             : q-to-dbms
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338942486;0
appliedLastSeqno  : 2275298
appliedLatency    : 18.937
eventCount        : 221864
shardId           : evaluator5
stage             : q-to-dbms
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338942930;0
appliedLastSeqno  : 2275301
appliedLatency    : 18.94
eventCount        : 219574
shardId           : evaluator6
stage             : q-to-dbms
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338943372;0
appliedLastSeqno  : 2275304
appliedLatency    : 18.931
eventCount        : 220078
shardId           : evaluator7
stage             : q-to-dbms
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338942600;0
appliedLastSeqno  : 2275299
appliedLatency    : 18.929
eventCount        : 221647
shardId           : evaluator8
stage             : q-to-dbms
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000338940109;0
appliedLastSeqno  : 2275282
appliedLatency    : 18.931
eventCount        : 226607
shardId           : evaluator9
stage             : q-to-dbms
Finished status command (shards)...

And if the info by shard is not enough, we can also see the functioning of replication in terms of tasks. For the current transactions, we can check what is happening at every stage, with a level of detail that the MySQL server cannot provide.

trepctl status -name tasks
Processing status command (tasks)...
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000339749071;0
appliedLastSeqno  : 2280695
appliedLatency    : 22.267
applyTime         : 53.543
averageBlockSize  : 1.000     
cancelled         : false
currentLastEventId: mysql-bin.000002:0000000339749071;0
currentLastFragno : 0
currentLastSeqno  : 2280695
eventCount        : 2280695
extractTime       : 3053.902
filterTime        : 0.194
otherTime         : 2.864
stage             : remote-to-thl
state             : extract
taskId            : 0
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000339747579;0
appliedLastSeqno  : 2280685
appliedLatency    : 22.233
applyTime         : 135.079
averageBlockSize  : 9.983     
cancelled         : false
currentLastEventId: mysql-bin.000002:0000000339747579;0
currentLastFragno : 0
currentLastSeqno  : 2280685
eventCount        : 2280685
extractTime       : 2972.509
filterTime        : 0.167
otherTime         : 2.714
stage             : thl-to-q
state             : extract
taskId            : 0
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000339747579;0
appliedLastSeqno  : 2280685
appliedLatency    : 22.243
applyTime         : 174.149
averageBlockSize  : 9.813     
cancelled         : false
currentLastEventId: mysql-bin.000002:0000000339747579;0
currentLastFragno : 0
currentLastSeqno  : 2280685
eventCount        : 463769
extractTime       : 2930.461
filterTime        : 4.553
otherTime         : 1.317
stage             : q-to-dbms
state             : extract
taskId            : 0
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000339746639;0
appliedLastSeqno  : 2280679
appliedLatency    : 22.247
applyTime         : 173.182
averageBlockSize  : 9.790     
cancelled         : false
currentLastEventId: mysql-bin.000002:0000000339746639;0
currentLastFragno : 0
currentLastSeqno  : 2280679
eventCount        : 455841
extractTime       : 2931.707
filterTime        : 4.374
otherTime         : 1.219
stage             : q-to-dbms
state             : extract
taskId            : 1
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000339747249;0
appliedLastSeqno  : 2280683
appliedLatency    : 22.246
applyTime         : 171.505
averageBlockSize  : 9.819     
cancelled         : false
currentLastEventId: mysql-bin.000002:0000000339747249;0
currentLastFragno : 0
currentLastSeqno  : 2280683
eventCount        : 453846
extractTime       : 2933.467
filterTime        : 4.28
otherTime         : 1.23
stage             : q-to-dbms
state             : extract
taskId            : 2
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000339747415;0
appliedLastSeqno  : 2280684
appliedLatency    : 22.252
applyTime         : 168.773
averageBlockSize  : 9.792     
cancelled         : false
currentLastEventId: mysql-bin.000002:0000000339747415;0
currentLastFragno : 0
currentLastSeqno  : 2280684
eventCount        : 453447
extractTime       : 2936.219
filterTime        : 4.283
otherTime         : 1.213
stage             : q-to-dbms
state             : extract
taskId            : 3
NAME                VALUE
----                -----
appliedLastEventId: mysql-bin.000002:0000000339746311;0
appliedLastSeqno  : 2280677
appliedLatency    : 22.25
applyTime         : 167.426
averageBlockSize  : 9.804     
cancelled         : false
currentLastEventId: mysql-bin.000002:0000000339746311;0
currentLastFragno : 0
currentLastSeqno  : 2280677
eventCount        : 454922
extractTime       : 2937.622
filterTime        : 4.188
otherTime         : 1.25
stage             : q-to-dbms
state             : extract
taskId            : 4
Finished status command (tasks)...

Fixing an error

Let's try to see what happens with a simple, classic replication error. We will enter a record in the slave, and then do the same in the master. We will assume full knowledge of the facts, and try to repair the damage.

In MySQL 5.6, when the slave stops replication because of the duplicate key error, we get this:

show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: rsandbox
                  Master_Port: 18675
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000002
          Read_Master_Log_Pos: 136120191
               Relay_Log_File: mysql_sandbox18676-relay-bin.000006
                Relay_Log_Pos: 136120097
        Relay_Master_Log_File: mysql-bin.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1062
                   Last_Error: Error 'Duplicate entry '1' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1 values (1)'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 136119934
              Relay_Log_Space: 136120781
              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: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 1062
               Last_SQL_Error: Error 'Duplicate entry '1' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1 values (1)'
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1
                  Master_UUID: c3054160-7b4a-11e2-a17e-6c626da07446
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: 
           Master_Retry_Count: 86400
                  Master_Bind: 
      Last_IO_Error_Timestamp: 
     Last_SQL_Error_Timestamp: 130220 11:49:56
               Master_SSL_Crl: 
           Master_SSL_Crlpath: 
           Retrieved_Gtid_Set: c3054160-7b4a-11e2-a17e-6c626da07446:1-386581
            Executed_Gtid_Set: c3054160-7b4a-11e2-a17e-6c626da07446:1-386580,
c90226d2-7b4a-11e2-a17e-6c626da07446:1
                Auto_Position: 0

In this situation, we try the old remedy of skipping a transaction.

set global sql_slave_skip_counter=1;
ERROR 1858 (HY000): sql_slave_skip_counter can not be set when the server is running with GTID_MODE = ON. Instead, for each transaction that you want to skip, generate an empty transaction with the same GTID as the transaction

Oops! Now I have two problems:

  • How do I generate an empty transaction with a given GTID?
  • Which is the given GTID? I get several ones:
    show global variables like '%gtid_executed%'\G
    *************************** 1. row ***************************
    Variable_name: gtid_executed
            Value: c3054160-7b4a-11e2-a17e-6c626da07446:1-386580,
    c90226d2-7b4a-11e2-a17e-6c626da07446:1

I found this manual page about skipping transactions, but I don't get where I should run these instructions. I tried running them in the slave, but the replication error remains in place. I guess we need a clearer example that explains how to fix the error, because this surely does not look like a solution.

Let's try the same issue with Tungsten.

$ trepctl status
Processing status command...
NAME                     VALUE
----                     -----
appliedLastEventId     : NONE
appliedLastSeqno       : -1
appliedLatency         : -1.0
channels               : -1
clusterName            : default
currentEventId         : NONE
currentTimeMillis      : 1361356976587
dataServerHost         : 127.0.0.1
extensions             : 
latestEpochNumber      : -1
masterConnectUri       : thl://127.0.0.1:12110/
masterListenUri        : thl://127.0.0.1:12111/
maximumStoredSeqNo     : -1
minimumStoredSeqNo     : -1
offlineRequests        : NONE
pendingError           : Event application failed: seqno=444898 fragno=0 message=java.sql.SQLException: Statement failed on slave but succeeded on master
pendingErrorCode       : NONE
pendingErrorEventId    : mysql-bin.000002:0000000116727315;0
pendingErrorSeqno      : 444898
pendingExceptionMessage: java.sql.SQLException: Statement failed on slave but succeeded on master
                         insert into t1 values (1) /* ___SERVICE___ = [tsandbox] */
pipelineSource         : UNKNOWN
relativeLatency        : -1.0
resourcePrecedence     : 99
rmiPort                : 10102
role                   : slave
seqnoType              : java.lang.Long
serviceName            : tsandbox
serviceType            : unknown
simpleServiceName      : tsandbox
siteName               : default
sourceId               : 127.0.0.1
state                  : OFFLINE:ERROR
timeInStateSeconds     : 18.747
uptimeSeconds          : 923.323
version                : Tungsten Replicator 2.0.7 build 278
Finished status command...

The error tells me that GTID 444898 is at fault. The remedy that I would apply in this case is the same that I would do anyway, regardless of parallel replication.

$ trepctl online -skip-seqno 444898

$ trepctl status
Processing status command...
NAME                     VALUE
----                     -----
appliedLastEventId     : mysql-bin.000002:0000000116726621;0
appliedLastSeqno       : 444893
appliedLatency         : 0.0
channels               : 5
clusterName            : default
currentEventId         : NONE
currentTimeMillis      : 1361358074668
dataServerHost         : 127.0.0.1
extensions             : 
latestEpochNumber      : 0
masterConnectUri       : thl://127.0.0.1:12110/
masterListenUri        : thl://127.0.0.1:12111/
maximumStoredSeqNo     : 444898
minimumStoredSeqNo     : 0
offlineRequests        : NONE
pendingError           : NONE
pendingErrorCode       : NONE
pendingErrorEventId    : NONE
pendingErrorSeqno      : -1
pendingExceptionMessage: NONE
pipelineSource         : thl://127.0.0.1:12110/
relativeLatency        : 1599.668
resourcePrecedence     : 99
rmiPort                : 10102
role                   : slave
seqnoType              : java.lang.Long
serviceName            : tsandbox
serviceType            : local
simpleServiceName      : tsandbox
siteName               : default
sourceId               : 127.0.0.1
state                  : ONLINE
timeInStateSeconds     : 2.076
uptimeSeconds          : 2021.404
version                : Tungsten Replicator 2.0.7 build 278
Finished status command...

And we are back in business. Since GTID in Tungsten are well integrated in every aspect of the operations, I can use them to fix problems.

More loose ends

What we've seen above shows that the integration between existing replication features and the new ones is less than desirable. There are more issues that may come to the user's attention. One that struck me as very odd is Replicate_Ignore_Server_Ids

This value is found in 'SHOW SLAVE STATUS', and it designates the list of servers that were excluded from replication. This value is associated to the option 'IGNORE_SERVER_IDS' that you can give in CHANGE MASTER TO. What's odd with this value? It is that it only accepts server-IDs, not server-UUIDs. If you try to use a server-UUID in CHANGE MASTER TO, you get an error.

However, the reason for mentioning this variable is that, just by chance, I was able to "fix" the above problem, instead of using an empty transaction. I did the following:

stop slave;
change master to ignore_server_ids=(1);
start slave;
show slave status\G
# no errors
stop slave;
change master to ignore_server_ids=();
start slave;

And we have skipped a transaction in an undocumented way. Bug or feature?

8 comments:

Anonymous said...

I think you need to somehow figure out how to run start slave until because you need to skip just one statement. By adding the server_id to the list of servers to ignore you will ignore the error, but also ignore any other queries after it in the replication stream. So you need to figure out how to run one event from that server, then turn skipping off again. Good luck with that :D

Unknown said...
This comment has been removed by the author.
Unknown said...

I found your post because I had a similar problem with error 1062 while using GTID, so the default error skipping did not work.

However, I managed to solve the faulty replication on the slave by using the commands found on the manual page about skipping transactions.

Your show slave status\G;-log shows the following:
Retrieved_Gtid_Set: c3054160-7b4a-11e2-a17e-6c626da07446:1-386581
Executed_Gtid_Set: c3054160-7b4a-11e2-a17e-6c626da07446:1-386580,
c90226d2-7b4a-11e2-a17e-6c626da07446:1

The GTID that caused the error was c3054160-7b4a-11e2-a17e-6c626da07446:386581 (all GTIDs up to 386580 were executed, the log shows that the slave retrieved one more which could not be executed). Even if Retrieved_Gtid_Set showed 1-386586, the faulty GTID would be 386581.

Running the following commands on the slave machine (the one that stopped replicating, I ran them in the MySQL Command Line Client) solved the problem for me:

SET GTID_NEXT="c3054160-7b4a-11e2-a17e-6c626da07446:386581";

BEGIN;
COMMIT;

SET GTID_NEXT=AUTOMATIC;

FLUSH LOGS;
PURGE BINARY LOGS TO "mysql-bin.000002";
START SLAVE;

All GTIDs and commands are adjusted to your problem. Hope this helps!

Giuseppe Maxia said...

Christian,
Thanks for your comment. This method works, although it looks frightfully unfriendly.

Unknown said...

Yes you're right, it is not very user friendly, yet still friendlier than having to recreate the replication from a database dump if it happens once.

Thanks for your post anyway, it lead the way to solve my problem! In order to avoid it the next time, I'll just use users with limited rights to avoid writing in slave databases accidentally.

Wagner Bianchi said...

What I'm really missing this time is a way to check if how many transactions were really executed in parallel regardless of slave_parallel_type configurations...any hint on that? Cheers!

Giuseppe Maxia said...

@Wagner, can you elaborate? It is not clear which system you are referring to.

Anonymous said...

just brilliant!

Probably the best post about the issue I've seen