Why audit logging with triggers in MySQL is bad for replication

Recently I was tasked with investigating slippage between master and slave in a standard replication setup.

The client was using Maatkit’s mk-table-checksum to check his slave data was indeed a fair copy of that of the master.

mk-table-checksum --algorithm=BIT_XOR h=hostname.local,u=root,p=xxx --replicate=checksum.checksum --emptyrepltbl --chunksize=500000 --databases mydb --sleep 1

1	mk-table-checksum --algorithm=BIT_XOR h=hostname.local,u=root,p=xxx --replicate=checksum.checksum --emptyrepltbl --chunksize=500000 --databases mydb --sleep 1

He could then examine the checksum.checksum table and see all was well, however there were various tables with different crc values.

 

db: mydb tbl: Foo_History chunk: 0 boundaries: 1=1 this_crc: 30627c76fe658fd9b77eaddf1ea8c03a this_cnt: 2593 master_crc: bdbadd7dae2636a8cf515bb886fb1295 master_cnt: 2593 ts: 2008-09-24 04:50:05

1 2 3 4 5 6 7 8 9

db: mydb tbl: Foo_History chunk: 0 boundaries: 1=1 this_crc: 30627c76fe658fd9b77eaddf1ea8c03a this_cnt: 2593 master_crc: bdbadd7dae2636a8cf515bb886fb1295 master_cnt: 2593 ts: 2008-09-24 04:50:05

 

So, now I needed to find out what was updating the table. Here is where tools like mysqlsla and Maatkit’s mk-log-parser come into their own as they both allow you to quickly parse the binary log files, extracting the relevant statements.

mysqlbinlog bin_log.000001 | mysqlsla -lt binary -

1	mysqlbinlog bin_log.000001 | mysqlsla -lt binary -

Check out http://hackmysql.com/mysqlsla_filters for how to filter by statement.

Looking through the binary logs I could see this table is actually an audit table for changes to the Foo table. The trail is kept using two triggers on that table.

 

select trigger_name, event_object_table, Event_Manipulation from information_schema.triggers where trigger_schema = 'mydb' and action_statement like '%Foo_History%'G *************************** 1. row *************************** trigger_name: Foo_Update event_object_table: Foo Event_Manipulation: UPDATE *************************** 2. row *************************** trigger_name: Foo_Delete event_object_table: Foo Event_Manipulation: DELETE

1 2 3 4 5 6 7 8 9 10 11 12 13

select trigger_name, event_object_table, Event_Manipulation from information_schema.triggers where trigger_schema = 'mydb' and  action_statement like '%Foo_History%'G *************************** 1. row ***************************       trigger_name: Foo_Update event_object_table: Foo Event_Manipulation: UPDATE *************************** 2. row ***************************       trigger_name: Foo_Delete event_object_table: Foo Event_Manipulation: DELETE

 

So whats the problem with that?, well there is a situation where two overlapping transactions updating the Foo table can be reordered once serialized on the slave.

Here is an example:

I recreated the tables and triggers, populating the Foo table with a handful of rows and then ran the following.

Here is the update trigger:

 

Create Trigger Foo_Update After UPDATE on Foo For Each Row INSERT into Foo_History (Foo_History_ID, Name, Value, Field_Id) Values (Old.Foo_History_ID, Old.Name, Old.Value, Old.Field_Id);

1 2 3

Create Trigger Foo_Update After UPDATE on Foo For Each Row INSERT into Foo_History (Foo_History_ID, Name, Value, Field_Id) Values (Old.Foo_History_ID, Old.Name, Old.Value, Old.Field_Id);

 

Transaction 1 starts and updates.

 

Start Transaction; Update Foo set Value=6 Where Field_ID = 3;

1 2	Start Transaction; Update Foo set Value=6 Where Field_ID = 3;

 

Transaction 2 starts, updates and commits.

 

Start Transaction; Update Foo set Value=6 Where Field_Id = 51; Commit;

1 2 3

Start Transaction; Update Foo set Value=6 Where Field_Id = 51; Commit;

Transaction 1 commits last.

 

Commit;

1

Commit;

 

Now when these statements get run on the slave they will be serialized, thus changing the order of the inserts made by the trigger. The Foo_History table is now out of sync.

Master:

 

*************************** 1. row *************************** Foo_History_Id: 1 Name: maxlength Value: 7 Field_Id: 3 *************************** 2. row *************************** Foo_History_Id: 2 Name: maxlength Value: 7 Field_Id: 51

1 2 3 4 5 6 7 8 9 10

*************************** 1. row ***************************     Foo_History_Id: 1           Name: maxlength          Value: 7       Field_Id: 3 *************************** 2. row ***************************     Foo_History_Id: 2           Name: maxlength          Value: 7       Field_Id: 51

 

Slave:

*************************** 1. row *************************** Foo_History_Id: 1 Name: maxlength Value: 7 Field_Id: 51 *************************** 2. row *************************** Foo_History_Id: 2 Name: maxlength Value: 7 Field_Id: 3

1 2 3 4 5 6 7 8 9 10

*************************** 1. row ***************************     Foo_History_Id: 1 Name: maxlength          Value: 7   Field_Id: 51 *************************** 2. row ***************************     Foo_History_Id: 2 Name: maxlength          Value: 7       Field_Id: 3

As you can see from the above, the updates were performed in a different order, with the inserts being assigned a different Foo_History_Id. This is because the statements are written to the binary log in commit order.