衆所周知，在binlog檔案中，經常會看到關于事件的時間屬性，出現的方式都是如下這樣的。
我們清楚地知道，161213 10:11:35表示的就是時間值，但除此之外呢？還能知道它的什麼資訊呢？
先從一個典型的案例入手來講述其中的細節，比如曾經在galera cluster碰到的一個問題，可以先看一段binlog内容，如下。
上面列出來的是被處理過的binlog内容，其中包括三個事務，每個事務隻列出了标志性的事件，比如事務開始的gtid事件、執行線程資訊及送出事件等。出現的順序，就是binlog内容的順序，這一點可以從xid的連續性看出來。
在上面一段内容中，重點關注一下時間資訊。每一個事務中的每一個事件都有時間屬性，可以看到，第一個事務是在10:11:35時間點送出的，第三個事務也是在這個時間送出的。但中間一個事務，即xid為83631679的事務，包括送出時間在内的所有事件時間，都是在10:11:30時間點發生的，比其他兩個事務足足早出現了5秒鐘！
很多同學看到這樣的現象之後，可能會有以下的疑問。
在binlog檔案中，不是以送出順序存儲的麼，前面送出的事務怎麼會存儲在後面的位置呢？
假設事務83631679的開始時間是10:11:30，那麼至少它的送出事件，即gtid事件的時間是10:11:35吧？
事務83631679的執行時間是5秒鐘，從exec_time=5可以看出來這個資訊的出現，那麼第二個問題就變得更加讓人疑惑了。
這裡能看出exec_time=5這樣的資訊，值得稱贊，這是一個很重要的資訊。因為現在明确地知道，事務83631679是在10:11:30開始的。那麼，這個query又執行了5秒鐘，可以和事務送出時間10:11:35對得上。現在要明确的一點就是，事務是在10:11:35送出的，隻不過在binlog内容看到的是10:11:30，那就要弄清楚binlog在記錄時間戳的問題上，是如何處理的。
時間戳是一個事件的屬性，但這個屬性的來源是哪裡，也就是說這個時間是什麼時候記錄下來的，可以看如下一段代碼。
如代碼中的解釋，需要找到thd->start_time的來源。這個值的設定很容易就可以找到，在每一條語句執行前都會做一次，通過函數thd->set_time()來設定。其中一個很重要的mysql語句，在入口處理函數中就調用了，可以簡單看一下，如下。
想必有些同學已經清楚了，其實binlog事件中的時間戳是從語句那裡繼承過來的，一條語句産生多個事件，那這些事件的時間戳都是一樣的，而且都是和第一個事件一緻的（這點可以自己驗證一下）。
那上面關于exec_time=5的問題，該怎麼解釋呢？再來看一下代碼，如下。
那麼現在就可以去解釋事務83631679為什麼執行了5秒鐘，但所有事件的時間都是10:11:30了。就是因為這個事務是自動送出的，隻有一條語句并且執行了5秒鐘，就是這麼簡單，僅此而已。
因為是自動送出的，這個事務隻有一條語句，thd->set_time()也隻會被設定一次，是以這個事務中的所有事件，都停留在了這個時間點上，是以就出現了上面的現象。
可能有同學有疑惑了，即使一個事務隻有一條語句，那也是有送出的，送出時間确實是在5秒之後做的，難道内部沒有做這個問題的處理？可以做一個實驗來看一下，還是一個事務一條語句，但此時不是自動送出，而是一個事務開始之後，等待了5秒鐘，再去手動送出，然後再看binlog内容，如下：
為了沒有時間誤差，上面的三條語句是同時執行的，中間做了5秒的等待操作，現在看一下對應的binlog内容。
此時很明顯地看到了，事務的xid及gtid兩個送出事件的時間，都比執行插入的時間晚5秒鐘。這正是因為，執行的commit語句與insert語句一樣，都是一條語句，在執行前都會執行thd->set_time()，進而影響了自己生成的binlog事件。
上面已經了解過，在一個事務中，會有事務開始的事件、事務送出的事件，也會有真正做事的事件，比如write_rows等，它們之間的順序，會與時間戳有一點關系。細心的同學可能已經發現，上一小節舉的例子中，gtid在最前面，它的時間是12:53:25，而write_rows在中間，但它的時間是12:53:20，這之間有什麼關系麼？
其實，這在之前介紹mysql 5.7多線程複制原理的時候已經講過，在mysql事務送出時，做的操作有如下三部分。
根據執行後的上下文環境，生成一個gtid事件。
組裝事務産生的gtid。
送出到各種存儲引擎。
從上面所做的事情中可以看到，gtid資訊其實是在送出時生成的。這一點在mysql 5.7中會更加明确，因為還需要我們已經熟知的last_committed及sequence_number來構造gtid（具體請參考第15章）。這也就可以解釋，為什麼gtid這個事件對應的時間和xid是一樣的了，就是因為它的時間是從commit語句那裡繼承過來的。當然，xid也是同樣的道理了，因為它們是同一個語句産生的兩個不同僚件。
但關于順序問題，是與gtid這個事件的作用有關的。在mysql binlog中，必須要提前知道gtid的具體資訊，是以在mysql送出并組裝對應的binlog時将其放到了最前面，進而導緻了目前看到的關于時間問題的現象。
再回過頭來看一下，最開始等待5秒的案例如下。
為何一個更新語句執行了5秒鐘？當然，可能有以下兩個原因。
這個語句對應的查詢條件，是一個慢查詢，掃描會花很長時間（5秒鐘），結果隻更新了一行（因為隻有一個update_rows事件），進而導緻了上面的現象。
本身執行不慢，但在等其他事務或鎖的執行操作時，等了5秒鐘。
這兩種原因都是有可能的，也都可以解釋得通。确定是哪種原因導緻問題的方法很簡單，那就是檢視慢查詢日志檔案，找到thread_id為4900813的慢查詢，或者對應的表的慢查詢，并且一定要在server_id為11766的執行個體上面（這一點每個人都知道，但有時候會被忽略掉）。如果找到了，那就是第一種原因；如果找不到，那就是第二種原因了。
找啊找，結果在那個時間段内，都沒有慢查詢。
不管什麼原因，執行了5秒鐘，肯定是慢查詢，怎麼能找不到呢？這裡對于mysql的慢查詢記錄要多說一點，鎖等待的時間在這裡是不計算在内的。是以，如果是第2種原因，那麼慢查詢就必然是查不到的，并且exec_time=5對這一點也很有說服力，因為執行時間的計算是從開始時間到結束時間的內插補點，和慢查詢的計算方法不同，是以這也說明了這5秒鐘時間都是在等待的。
那麼問題來了，它在等誰呢？竟然能等5秒鐘？想必有另一個事務，拿到了它想要的鎖，并且拿到鎖的時間肯定超過5秒鐘，那就需要繼續找了。此時已經知道，大事務有如下2種。
單條自動送出的語句，本身執行時間長（exec_time比較大）。
事務開始時間和結束時間的跨度長。
找row格式的binlog，咱有利器啊！來看下面一段腳本，這段腳本也會出現在第42章中。
這段腳本可以幫我們很輕松地找到跨度比較長的事務，通過結果中的period列來表示。分析了period列的資料之後，結果如下。
很快發現，xid為83631678的事務，竟然長達51秒。然後打開對應的binlog檔案找到這個事務，内容如下。
發現什麼了嗎？這不是事務83631678麼，是本章開始位置所展示出來的三個事務中的第一個？沒錯，正是它。
首先，關于gtid事件和xid事件的時間問題，上面已經解釋過了，這是送出語句的時間，是以都是10:11:35，先忽略它。而中間真正做事的一段内容，是需要重點關注的。前面兩個事件，分别是write_rows和update_rows，它們的時間是10:10:44，而後面三個write_rows事件的時間是10:11:35，中間長達51秒鐘，這段時間做什麼了？
再核對一下事務83631679中的update_rows要修改的表的記錄，與事務83631678中在10:10:44時間點發生的事件update_rows所要修改的記錄，是同一個表中的同一條記錄。那肯定是要等待了。
資料庫問題，都已經解釋清楚了，現在唯一的問題，就是需要找到業務開發人員，問一句，那個事務在哪個表上，在那51秒鐘的時間裡做什麼了
dba還要繼續處理其他問題，接力棒現在就交給開發同學了，明天聽你回話。
下面的問題，可能是在實際運維過程中遇到的容易造成疑惑的問題，先來看看我們所熟知的show processlist結果，這裡請重點關注結果中的time列資訊，如下。
上面兩行資訊中，time值分别是5142和2077，它們是怎麼來的呢？對于這個問題，各位同學應該都是比較清楚的，它代表的是目前語句在執行時的時間點，與執行show processlist指令時的時間差，從下面的mysql代碼中可以證明這一點。
現在可以做一個實驗，開兩個會話，連接配接同一個mysql伺服器，一個會話（會話1）用來做實驗，另一個會話（會話2）用來不斷地執行show processlist指令以觀察現象，實驗結果很明确，隻要會話1保持無操作，在會話2的結果中，會話1的連接配接對應的time值一直在增長，而隻要會話1執行任意一個指令，會話2的結果中，會話1的連接配接對應的time值會被清零一次，然後再次繼續增長，如此往複循環。在了解上述内容之後，這個現象現在應該很容易了解了，因為在執行任意指令時（調用函數dispatch_command），都會執行thd->set_time()，将時間清為目前時間，即時間差被清零。
但是有沒有見過如下這樣的現象？
可以看到，此時會話1的time值高達1203070，而對應的語句隻是select sleep(100)。是不是感到很奇怪，為什麼隻睡了100秒，而time可以那麼高？
當然，這裡的語句是自己構造的，同時還發現，不管這樣的語句執行多少次，time依然保持上漲，并不會清零，這是什麼原因？
很明顯，這樣的現象會給dba造成一些困惑，在解決問題時會造成幹擾，是以有必要在這裡解釋清楚。下面重點看一下set_time這個函數的實作。
上面代碼中提到的參數user_time，實際上對應的是mysql會話參數timestamp，隻要顯式地設定了這個參數，user_time就不為0，那麼目前會話的起始時間就被固定在這一刻了。
現在明白了，隻要在會話1中執行一條指令，比如set timestamp=1490264145;，然後在會話2中觀察，就會發現，time不僅非常大，而且在會話1中再執行任何語句時，會話2中的time值都不會被清零了。
是以，如果在實際運維中遇到這樣的問題，就可以找一下有沒有連接配接執行過這樣的語句，進而造成了這樣的假象，因為這樣的問題出現時，都會把這類語句誤判為慢查詢，而實際又找不到這樣的查詢。
這個問題是不是有種似曾相識的感覺？沒錯，在binlog裡經常會遇到這樣的指令，這是mysql為了保持主從執行環境的一緻性而做的，但如果在主庫上這樣操作，經常是不僅不好玩，反而會造成一頭霧水的感覺。
這個問題，看似簡單，實則涉及很多關于binlog的細節問題。講這些的主要目的就是讓dba同學了解時間戳在binlog中的作用及産生方法，以便在出現一些這方面怪異的問題時，做到心中有數，胸有成竹。
想及時獲得更多精彩文章，可在微信中搜尋“博文視點”或者掃描下方二維碼并關注。