DBZ-5170 Mysql Commit Timestamp

[harveyyue]

https://issues.redhat.com/browse/DBZ-5170
I will update to all connectors doc later.

[jingtaozhang18]

Hi @harveyyue. Here is some information I found in binlog that maybe help you. The timestamps in Xid events have difference between auto-commit is enabled and disabled. Here is an example. If I execute SQLs as shown below.

Then binlog file is as show below.

So , the timestamps of transaction's Xid events maybe not ordered.

The order of transaction's timestamp is very important, which can be used to judge the sequence of states.

[harveyyue]

@jingtaozhang18, The session2 commit time (1654101009000) is less than session1 (1654101018000) according the mysql-binlog-connector parse the binlog event.
FYI

Session 1:
Step 1:
set autocommit=0;
update test_float set f1=16 where id=1;
Step 3:
commit;

Session 2:
Step 2:
update test_float set f1=18 where id=1;

Transaction (the sequence from transaction topic):
{"status":"BEGIN","id":"file=mysql-bin.000030,pos=389706","event_count":null,"data_collections":null,"ts_ms":1654100999000}
{"status":"END","id":"file=mysql-bin.000030,pos=389706","event_count":{"long":1},"data_collections":{"array":[{"data_collection":"workdb.test_float","event_count":1}]},"ts_ms":1654101018000}

{"status":"BEGIN","id":"file=mysql-bin.000030,pos=390084","event_count":null,"data_collections":null,"ts_ms":1654101009000}
{"status":"END","id":"file=mysql-bin.000030,pos=390084","event_count":{"long":1},"data_collections":{"array":[{"data_collection":"workdb.test_float","event_count":1}]},"ts_ms":1654101009000}

Data Event:
{"before":{"test_avro_transaction.workdb.test_float.Value":{"id":1,"f1":{"float":8.0},"f2":{"double":90.56999969482422},"f3":{"double":30.123},"f4":{"double":123.456787109375},"f5_23":{"float":100.0},"f6_24":{"float":100.0},"f7":{"float":100.12}}},"after":{"test_avro_transaction.workdb.test_float.Value":{"id":1,"f1":{"float":16.0},"f2":{"double":90.56999969482422},"f3":{"double":30.123},"f4":{"double":123.456787109375},"f5_23":{"float":100.0},"f6_24":{"float":100.0},"f7":{"float":100.12}}},"source":{"version":"2.0.0-SNAPSHOT","connector":"mysql","name":"test_avro_transaction","ts_ms":1654100999000,"snapshot":{"string":"false"},"db":"workdb","sequence":null,"table":{"string":"test_float"},"server_id":112233,"gtid":null,"file":"mysql-bin.000030","pos":389864,"row":0,"thread":{"long":5818},"query":null},"op":"u","ts_ms":{"long":1654101018190},"transaction":{"io.confluent.connect.avro.ConnectDefault":{"id":"file=mysql-bin.000030,pos=389706","total_order":1,"data_collection_order":1}}}

{"before":{"test_avro_transaction.workdb.test_float.Value":{"id":1,"f1":{"float":16.0},"f2":{"double":90.56999969482422},"f3":{"double":30.123},"f4":{"double":123.456787109375},"f5_23":{"float":100.0},"f6_24":{"float":100.0},"f7":{"float":100.12}}},"after":{"test_avro_transaction.workdb.test_float.Value":{"id":1,"f1":{"float":18.0},"f2":{"double":90.56999969482422},"f3":{"double":30.123},"f4":{"double":123.456787109375},"f5_23":{"float":100.0},"f6_24":{"float":100.0},"f7":{"float":100.12}}},"source":{"version":"2.0.0-SNAPSHOT","connector":"mysql","name":"test_avro_transaction","ts_ms":1654101009000,"snapshot":{"string":"false"},"db":"workdb","sequence":null,"table":{"string":"test_float"},"server_id":112233,"gtid":null,"file":"mysql-bin.000030","pos":390242,"row":0,"thread":{"long":5968},"query":null},"op":"u","ts_ms":{"long":1654101018194},"transaction":{"io.confluent.connect.avro.ConnectDefault":{"id":"file=mysql-bin.000030,pos=390084","total_order":1,"data_collection_order":1}}}

Binlog Event:
信息: Received Event{header=EventHeaderV4{timestamp=1654100999000, eventType=QUERY, serverId=112233, headerLength=19, dataLength=67, nextPosition=389792, currentPosition=389706, flags=8}, data=QueryEventData{threadId=5818, executionTime=0, errorCode=0, database='workdb', sql='BEGIN'}}
信息: Received Event{header=EventHeaderV4{timestamp=1654100999000, eventType=TABLE_MAP, serverId=112233, headerLength=19, dataLength=53, nextPosition=389864, currentPosition=389792, flags=0}, data=TableMapEventData{tableId=170, database='workdb', table='test_float', columnTypes=3, 4, 4, 5, 4, 4, 4, 4, columnMetadata=0, 4, 4, 8, 4, 4, 4, 4, columnNullability={1, 2, 3, 4, 5, 6, 7}, eventMetadata=TableMapEventMetadata{signedness={}, defaultCharset=null, columnCharsets=null, columnNames=null, setStrValues=null, enumStrValues=null, geometryTypes=null, simplePrimaryKeys=null, primaryKeysWithPrefix=null, enumAndSetDefaultCharset=null, enumAndSetColumnCharsets=null,visibility=null}}}
信息: Received Event{header=EventHeaderV4{timestamp=1654100999000, eventType=EXT_UPDATE_ROWS, serverId=112233, headerLength=19, dataLength=91, nextPosition=389974, currentPosition=389864, flags=0}, data=UpdateRowsEventData{tableId=170, includedColumnsBeforeUpdate={0, 1, 2, 3, 4, 5, 6, 7}, includedColumns={0, 1, 2, 3, 4, 5, 6, 7}, rows=[
{before=[1, 8.0, 90.57, 30.123, 123.45679, 100.0, 100.0, 100.12], after=[1, 16.0, 90.57, 30.123, 123.45679, 100.0, 100.0, 100.12]}
]}}
信息: Received Event{header=EventHeaderV4{timestamp=1654101018000, eventType=XID, serverId=112233, headerLength=19, dataLength=12, nextPosition=390005, currentPosition=389974, flags=0}, data=XidEventData{xid=141522}}

信息: Received Event{header=EventHeaderV4{timestamp=1654101009000, eventType=QUERY, serverId=112233, headerLength=19, dataLength=67, nextPosition=390170, currentPosition=390084, flags=8}, data=QueryEventData{threadId=5968, executionTime=9, errorCode=0, database='workdb', sql='BEGIN'}}
信息: Received Event{header=EventHeaderV4{timestamp=1654101009000, eventType=TABLE_MAP, serverId=112233, headerLength=19, dataLength=53, nextPosition=390242, currentPosition=390170, flags=0}, data=TableMapEventData{tableId=170, database='workdb', table='test_float', columnTypes=3, 4, 4, 5, 4, 4, 4, 4, columnMetadata=0, 4, 4, 8, 4, 4, 4, 4, columnNullability={1, 2, 3, 4, 5, 6, 7}, eventMetadata=TableMapEventMetadata{signedness={}, defaultCharset=null, columnCharsets=null, columnNames=null, setStrValues=null, enumStrValues=null, geometryTypes=null, simplePrimaryKeys=null, primaryKeysWithPrefix=null, enumAndSetDefaultCharset=null, enumAndSetColumnCharsets=null,visibility=null}}}
信息: Received Event{header=EventHeaderV4{timestamp=1654101009000, eventType=EXT_UPDATE_ROWS, serverId=112233, headerLength=19, dataLength=91, nextPosition=390352, currentPosition=390242, flags=0}, data=UpdateRowsEventData{tableId=170, includedColumnsBeforeUpdate={0, 1, 2, 3, 4, 5, 6, 7}, includedColumns={0, 1, 2, 3, 4, 5, 6, 7}, rows=[
{before=[1, 16.0, 90.57, 30.123, 123.45679, 100.0, 100.0, 100.12], after=[1, 18.0, 90.57, 30.123, 123.45679, 100.0, 100.0, 100.12]}
]}}
信息: Received Event{header=EventHeaderV4{timestamp=1654101009000, eventType=XID, serverId=112233, headerLength=19, dataLength=12, nextPosition=390383, currentPosition=390352, flags=0}, data=XidEventData{xid=141537}}

[jingtaozhang18]

Hi @harveyyue, the example you showed above is exactly what I was trying to say. And I think the timestamp of session 2 can't relfect the tranasaction commit time. The transaction commit time I understand is when the change of the transaction can be seen. Do you have any good idea to solve this problem?

[harveyyue]

Hi @harveyyue, the example you showed above is exactly what I was trying to say. And I think the timestamp of session 2 can't relfect the tranasaction commit time. The transaction commit time I understand is when the change of the transaction can be seen. Do you have any good idea to solve this problem?

Regarding the binlog event data which I have posted, the session2 transaction commit time is 1654101009000, the session1 is 1654101018000, I think we just to consume the binlog data without any data changes.

[jingtaozhang18]

Yes, I think your current work is very meaningful. I also have no idea about this problem and I will learn more about the design philosophy of MySQL Binlog timestamp. If you have any ideas, please share with me, Thanks!

[jpechane]

@harveyyue @jingtaozhang18 Hi guys, when do we stand on this PR then? Does it provide the expected data albeit they might be a bit difficult to correctl interpret?

[harveyyue]

Vitess pr: debezium/debezium-connector-vitess#83

[jpechane]

@harveyyue Applied, thanks a lot!