binlog在並髮狀態下的記錄

標籤：

前兩天看binlog發現個奇怪的地方：對於position靠後的記錄，timestamp卻比之前的記錄還要小。當時覺得大概和並發有關係

後來做了個實驗

開兩個session

對於session1：

　　begin;

　　insert into t1 values(1);

　　insert into t1 values(3);

　　insert into t1 values(5);

 

此時在session2：

　　begin;

　　insert into t1 values(2);

　　insert into t1 values(4);

      。。。

      commit;

 

然後再在session1:

     insert into t1 values(7);

     。。。

　　commit;

 

觀察binlog

# at 22101158
#150702 20:31:27 server id 1 end_log_pos 22101230 Query thread_id=1234 exec_time=0 error_code=0
SET TIMESTAMP=1435894287/*!*/;
BEGIN
/*!*/;
# at 22101230
#150702 20:31:13 server id 1 end_log_pos 22101316 Query thread_id=1234 exec_time=0 error_code=0
SET TIMESTAMP=1435894273/*!*/;
insert t1 values(2)
/*!*/;
# at 22101316
#150702 20:31:14 server id 1 end_log_pos 22101402 Query thread_id=1234 exec_time=0 error_code=0
SET TIMESTAMP=1435894274/*!*/;
insert t1 values(4)
/*!*/;
# at 22101402
#150702 20:31:24 server id 1 end_log_pos 22101488 Query thread_id=1234 exec_time=0 error_code=0
SET TIMESTAMP=1435894284/*!*/;
insert t1 values(6)
/*!*/;
# at 22101488
#150702 20:31:27 server id 1 end_log_pos 22101515 Xid = 480617
COMMIT/*!*/;
# at 22101515
#150702 20:31:32 server id 1 end_log_pos 22101587 Query thread_id=1232 exec_time=0 error_code=0
SET TIMESTAMP=1435894292/*!*/;
BEGIN
/*!*/;
# at 22101587
#150702 20:30:52 server id 1 end_log_pos 22101673 Query thread_id=1232 exec_time=0 error_code=0
SET TIMESTAMP=1435894252/*!*/;
insert t1 values(1)
/*!*/;
# at 22101673
#150702 20:30:55 server id 1 end_log_pos 22101759 Query thread_id=1232 exec_time=0 error_code=0
SET TIMESTAMP=1435894255/*!*/;
insert t1 values(3)
/*!*/;
# at 22101759
#150702 20:30:56 server id 1 end_log_pos 22101845 Query thread_id=1232 exec_time=0 error_code=0
SET TIMESTAMP=1435894256/*!*/;
insert t1 values(5)
/*!*/;
# at 22101845
#150702 20:31:18 server id 1 end_log_pos 22101931 Query thread_id=1232 exec_time=0 error_code=0
SET TIMESTAMP=1435894278/*!*/;
insert t1 values(7)
/*!*/;
# at 22101931
#150702 20:31:20 server id 1 end_log_pos 22102017 Query thread_id=1232 exec_time=0 error_code=0
SET TIMESTAMP=1435894280/*!*/;
insert t1 values(9)
/*!*/;
# at 22102017
#150702 20:31:30 server id 1 end_log_pos 22102104 Query thread_id=1232 exec_time=0 error_code=0
SET TIMESTAMP=1435894290/*!*/;
insert t1 values(11)
/*!*/;
# at 22102104
#150702 20:31:32 server id 1 end_log_pos 22102131 Xid = 480613
COMMIT/*!*/;

 

可以看到session2的事務因為更早提交，所以position更靠前，但是因為請求時間比較晚，所以timestamp落後於session1所提交的事務

binlog在並髮狀態下的記錄