677
MySQL運維案例分析：Binlog中的時間戳
背景
眾所周知，在Binlog文件中，經常會看到關於事件的時間屬性，出現的方式都是如下這樣的。
#161213 10:11:35 server id 11766 end_log_pos 263690453 CRC32 0xbee3aaf5 Xid = 83631678
我們清楚地知道，161213 10:11:35表示的就是時間值，但除此之外呢？還能知道它的什麼信息呢？
案例分析
先從一個典型的案例入手來講述其中的細節，比如曾經在Galera Cluster碰到的一個問題，可以先看一段Binlog內容，如下。
#161213 10:11:35 server id 11766 end_log_pos 263677208 CRC32 0xbfc41688 GTID [commit=yes]
#161213 10:10:44 server id 11766 end_log_pos 263677291 CRC32 0x02537685 Query thread_id=4901481 exec_time=0 error_code=0
#161213 10:10:44 server id 11766 end_log_pos 263677435 CRC32 0x0e70aab6 Write_rows: table id 17852 flags: STMT_END_F
#161213 10:10:44 server id 11766 end_log_pos 263677609 CRC32 0xb58d4c61 Update_rows: table id 17853 flags: STMT_END_F
#161213 10:11:35 server id 11766 end_log_pos 263690453 CRC32 0xbee3aaf5 Xid = 83631678#161213 10:11:30 server id 11766 end_log_pos 263690501 CRC32 0x6e798470 GTID [commit=yes]
#161213 10:11:30 server id 11766 end_log_pos 263690592 CRC32 0x2b6a6d34 Query thread_id=4900813 exec_time=5 error_code=0#161213 10:11:30 server id 11766 end_log_pos 263691291 CRC32 0xc0f9ed87 Update_rows: table id 17891 flags: STMT_END_F
#161213 10:11:30 server id 11766 end_log_pos 263691322 CRC32 0xe40764c4 Xid = 83631679#161213 10:11:35 server id 11766 end_log_pos 263691370 CRC32 0xbaa4ca30 GTID [commit=yes]#161213 10:11:35 server id 11766 end_log_pos 263691453 CRC32 0x030f321c Query thread_id=4900813 exec_time=0 error_code=0
#161213 10:11:35 server id 11766 end_log_pos 263692240 CRC32 0x7584d6a1 Delete_rows: table id 73 flags: STMT_END_F#161213 10:11:35 server id 11766 end_log_pos 263692271 CRC32 0x03abb120 Xid = 83631680
上麵列出來的是被處理過的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在記錄時間戳的問題上，是如何處理的。
時間戳是一個事件的屬性，但這個屬性的來源是哪裏，也就是說這個時間是什麼時候記錄下來的，可以看如下一段代碼。
Log_event::Log_event(
THD* thd_arg, uint16 flags_arg,
enum_event_cache_type cache_type_arg,
enum_event_logging_type logging_type_arg,
Log_event_header *header, Log_event_footer *footer)
: is_valid_param(false), temp_buf(0), exec_time(0),
event_cache_type(cache_type_arg), event_logging_type(logging_type_arg),
crc(0), common_header(header), common_footer(footer), thd(thd_arg)
{
server_id= thd->server_id;
common_header->unmasked_server_id= server_id;
/* 這裏就是用來在創建一個事件時，給這個事件的時間賦值的過程。
可以看到，這個時間的來源是thd->start_time的值，那我們需要
做的，就是弄清楚這個值的來源了 */
common_header->when= thd->start_time;
common_header->log_pos= 0;
common_header->flags= flags_arg;
}
如代碼中的解釋，需要找到thd->start_time的來源。這個值的設置很容易就可以找到，在每一條語句執行前都會做一次，通過函數thd->set_time()來設置。其中一個很重要的MySQL語句，在入口處理函數中就調用了，可以簡單看一下，如下。
bool dispatch_command(THD *thd, const COM_DATA *com_data,
enum enum_server_command command)
{ /* local variables... */
thd->set_command(command); /*
Commands which always take a long time are logged into
the slow log only if opt_log_slow_admin_statements is set.
*/
thd->enable_slow_log= TRUE;
thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
/* 就是在這裏，初始化這個時間為當前時間 */
thd->set_time(); /* other code ... */}
想必有些同學已經清楚了，其實Binlog事件中的時間戳是從語句那裏繼承過來的，一條語句產生多個事件，那這些事件的時間戳都是一樣的，而且都是和第一個事件一致的（這點可以自己驗證一下）。
那上麵關於exec_time=5的問題，該怎麼解釋呢？再來看一下代碼，如下。
Log_event(
thd_arg,
(thd_arg->thread_specific_used ? LOG_EVENT_THREAD_SPECIFIC_F :
0) |
(suppress_use ? LOG_EVENT_SUPPRESS_USE_F : 0),
using_trans ? Log_event::EVENT_TRANSACTIONAL_CACHE :
Log_event::EVENT_STMT_CACHE, Log_event::EVENT_NORMAL_LOGGING,
header(), footer()),
data_buf(0)
{
/* local vaiables */
/* exec_time calculation has changed to use the same method that is used
to fill out "thd_arg->start_time" */
struct timeval end_time;
ulonglong micro_end_time= my_micro_time();
my_micro_time_to_timeval(micro_end_time, &end_time);
/* 時間的計算，是用當前時間（執行完成的時間），減去thd_arg->start_time
的值，這個值在上麵已經見過，就是語句開始執行的時間，也就是說，exec_time
指的就是語句從開始到結束所用的時間，即實際上的語句執行時間 */
exec_time= end_time.tv_sec - thd_arg->start_time.tv_sec;
/* other code ... */
}
那麼現在就可以去解釋事務83631679為什麼執行了5秒鍾，但所有事件的時間都是10:11:30了。就是因為這個事務是自動提交的，隻有一條語句並且執行了5秒鍾，就是這麼簡單，僅此而已。
因為是自動提交的，這個事務隻有一條語句，thd->set_time()也隻會被設置一次，所以這個事務中的所有事件，都停留在了這個時間點上，所以就出現了上麵的現象。
發散思維
可能有同學有疑惑了，即使一個事務隻有一條語句，那也是有提交的，提交時間確實是在5秒之後做的，難道內部沒有做這個問題的處理？可以做一個實驗來看一下，還是一個事務一條語句，但此時不是自動提交，而是一個事務開始之後，等待了5秒鍾，再去手動提交，然後再看Binlog內容，如下：
mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)
mysql> insert into my1 values(13143306,'zhufeng');select sleep(5);commit;
Query OK, 1 row affected, 0 warning (0.00 sec)
+----------+
| sleep(5) |
+----------+
| 0 |
+----------+
1 row in set (5.00 sec)
Query OK, 0 rows affected (0.01 sec)
為了沒有時間誤差，上麵的三條語句是同時執行的，中間做了5秒的等待操作，現在看一下對應的Binlog內容。
#161216 12:53:25 server id 23932 end_log_pos 449 CRC32 0x2939a45b GTID [commit=yes]
#161216 12:53:20 server id 23932 end_log_pos 522 CRC32 0x1df41360 Query thread_id=21 exec_time= error_code=0
#161216 12:53:20 server id 23932 end_log_pos 614 CRC32 0xf1515ed0 Write_rows: table id 78 flags: STMT_END_F
#161216 12:53:25 server id 23932 end_log_pos 645 CRC32 0x69c2d142 Xid = 29321
此時很明顯地看到了，事務的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秒的案例如下。
#161213 10:11:30 server id 11766 end_log_pos 263690501 CRC32 0x6e798470 GTID [commit=yes]
#161213 10:11:30 server id 11766 end_log_pos 263690592 CRC32 0x2b6a6d34 Query thread_id=4900813 exec_time=5 error_code=0
#161213 10:11:30 server id 11766 end_log_pos 263691291 CRC32 0xc0f9ed87 Update_rows: table id 17891 flags: STMT_END_F
#161213 10:11:30 server id 11766 end_log_pos 263691322 CRC32 0xe40764c4 Xid = 83631679
為何一個更新語句執行了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章中。
# vim summarize_binlogs.sh
#!/bin/bash
BINLOG_FILE="mysql-bin.000046"
START_TIME="2015-06-28 8:45:00"
STOP_TIME="2015-06-28 10:10:00"
mysqlbinlog --base64-output=decode-rows -vv --start-datetime="${START_TIME}" --stop-datetime="${STOP_TIME}" ${BINLOG_FILE} | awk \
'BEGIN {x;s_type=""; stm="";endtm="";intsta=0;inttal=0;s_count=0;count=0;insert_count=0;update_count=0;delete_count=0;flag=0;bf=0;period=0;} \
{
if (match($0, /^(BEGIN)/)) {bg=1;} \
if (match($0, /#.*server id/)) {if(bg==1){statm=substr($1,2,6)" "$2;cmd=sprintf("date -d \"%s\" +%%s", statm);cmd|getline intsta;close(cmd);bg=0;bf=1;}
else if(bf==1){endtm=substr($1,2,6)" "$2;cmd=sprintf("date -d \"%s\" +%%s", endtm);cmd|getline inttal;close(cmd);}} \if(match($0, /#.*Table_map:.*mapped to number/)) {printf "Timestamp : " $1 " " $2 " Table : " $(NF-4); flag=1} \else if (match($0, /#.*Xid =.*/)) {xid=$(NF)} \
else if (match($0, /(### INSERT INTO .*..*)/)) {count=count+1;insert_count=insert_count+1;s_type="INSERT"; s_count=s_count+1;} \
else if (match($0, /(### UPDATE .*..*)/)) {count=count+1;update_count=update_count+1;s_type="UPDATE"; s_count=s_count+1;} \
else if (match($0, /(### DELETE FROM .*..*)/)) {count=count+1;delete_count=delete_count+1;s_type="DELETE"; s_count=s_count+1;} \
else if (match($0, /^(# at) /) && flag==1 && s_count>0) {print " Query Type : "s_type " " s_count " row(s) affected" ;s_type=""; s_count=0; } \
else if (match($0, /^(COMMIT)/)) {period=inttal-intsta;if(inttal==0){period=0};print "[Transaction total : " count " Insert(s) : " insert_count " Update(s) : " update_count " Delete(s) : " \
delete_count " Xid : "xid" period : "period" ] \n+----------------------+----------------------+----------------------+----------------------+"; \
count=0;insert_count=0;update_count=0; delete_count=0;s_type=""; s_count=0; flag=0;bf=0;bg=0;} } '
這段腳本可以幫我們很輕鬆地找到跨度比較長的事務，通過結果中的period列來表示。分析了period列的數據之後，結果如下。
zhufeng@zhufengmac:~$ cat sum|grep Transaction|awk '{if($19>0)print}'[Transaction total : 8 Insert(s) : 8 Update(s) : 0 Delete(s) : 0 Xid : 83631021 period : 1 ]
[Transaction total : 15 Insert(s) : 10 Update(s) : 4 Delete(s) : 1 Xid : 83631137 period : 1 ]
[Transaction total : 10 Insert(s) : 7 Update(s) : 3 Delete(s) : 0 Xid : 83631517 period : 1 ]
[Transaction total : 3 Insert(s) : 3 Update(s) : 0 Delete(s) : 0 Xid : 83631658 period : 1 ]
[Transaction total : 16 Insert(s) : 10 Update(s) : 6 Delete(s) : 0 Xid : 83631678 period : 51 ]
[Transaction total : 12 Insert(s) : 9 Update(s) : 3 Delete(s) : 0 Xid : 83631829 period : 1 ]
[Transaction total : 5 Insert(s) : 4 Update(s) : 1 Delete(s) : 0 Xid : 83632139 period : 1 ]
[Transaction total : 3 Insert(s) : 3 Update(s) : 0 Delete(s) : 0 Xid : 83632172 period : 1 ]
[Transaction total : 3 Insert(s) : 3 Update(s) : 0 Delete(s) : 0 Xid : 83632206 period : 1 ]
很快發現，Xid為83631678的事務，竟然長達51秒。然後打開對應的Binlog文件找到這個事務，內容如下。
#161213 10:11:35 server id 11766 end_log_pos 263677208 CRC32 0xbfc41688 GTID [commit=yes]
#161213 10:10:44 server id 11766 end_log_pos 263677291 CRC32 0x02537685 Query thread_id=4901481 exec_time=0 error_code=0
#161213 10:10:44 server id 11766 end_log_pos 263677435 CRC32 0x0e70aab6 Write_rows: table id 17852 flags: STMT_END_F
#161213 10:10:44 server id 11766 end_log_pos 263677609 CRC32 0xb58d4c61 Update_rows: table id 17853 flags: STMT_END_F
#161213 10:11:35 server id 11766 end_log_pos 263685326 CRC32 0xc512e73c Write_rows: table id 566 flags: STMT_END_F
#161213 10:11:35 server id 11766 end_log_pos 263685556 CRC32 0x805318e4 Write_rows: table id 566 flags: STMT_END_F
#161213 10:11:35 server id 11766 end_log_pos 263690422 CRC32 0x4de989c8 Write_rows: table id 73 flags: STMT_END_F
#161213 10:11:35 server id 11766 end_log_pos 263690453 CRC32 0xbee3aaf5 Xid = 83631678
發現什麼了嗎？這不是事務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
下麵的問題，可能是在實際運維過程中遇到的容易造成疑惑的問題，先來看看我們所熟知的show processlist結果，這裏請重點關注結果中的Time列信息，如下。
mysql> show processlist\G
*************************** 1. row ***************************
Id: 1
User: zhufeng.wang
Host: localhost:51703
db: NULL
Command: Sleep
Time: 5142
State:
Info: NULL
Rows_sent: 0
Rows_examined: 0
*************************** 2. row ***************************
Id: 2
User: zhufeng.wang
Host: localhost:62898
db: local
Command: Sleep
Time: 2077
State:
Info: NULL
Rows_sent: 2
Rows_examined: 2
上麵兩行信息中，Time值分別是5142和2077，它們是怎麼來的呢？對於這個問題，各位同學應該都是比較清楚的，它代表的是當前語句在執行時的時間點，與執行show processlist命令時的時間差，從下麵的MySQL代碼中可以證明這一點。
/* 用來計算Show Processlist中的Time列的值，thd_info->start_time
代表線程thd_info執行最後一個語句時的開始時間 */
if (thd_info->start_time)
protocol->store_long ((longlong) (now - thd_info->start_time));
else
protocol->store_null();
現在可以做一個實驗，開兩個會話，連接同一個MySQL服務器，一個會話（會話1）用來做實驗，另一個會話（會話2）用來不斷地執行show processlist命令以觀察現象，實驗結果很明確，隻要會話1保持無操作，在會話2的結果中，會話1的連接對應的Time值一直在增長，而隻要會話1執行任意一個命令，會話2的結果中，會話1的連接對應的Time值會被清零一次，然後再次繼續增長，如此往複循環。在了解上述內容之後，這個現象現在應該很容易理解了，因為在執行任意命令時（調用函數dispatch_command），都會執行thd->set_time()，將時間清為當前時間，即時間差被清零。
但是有沒有見過如下這樣的現象？
mysql> show processlist\G
*************************** 1. row ***************************
Id: 2
User: zhufeng.wang
Host: localhost:62898
db: local
Command: Query
Time: 1203070
State: User sleep
Info: select sleep(100)
Rows_sent: 0
Rows_examined: 0
...其他省略...
可以看到，此時會話1的Time值高達1203070，而對應的語句隻是select sleep(100)。是不是感到很奇怪，為什麼隻睡了100秒，而Time可以那麼高？
當然，這裏的語句是自己構造的，同時還發現，不管這樣的語句執行多少次，Time依然保持上漲，並不會清零，這是什麼原因？
很明顯，這樣的現象會給DBA造成一些困惑，在解決問題時會造成幹擾，所以有必要在這裏解釋清楚。下麵重點看一下set_time這個函數的實現。
inline void set_time()
{
/* 獲取當前timestamp，存到start_utime變量中 */
start_utime= utime_after_lock= my_micro_time();
if (user_time.tv_sec || user_time.tv_usec)
{
/* 這裏發現，當user_time不為0時，上麵獲取到的timestamp直接
被忽略了，而是使用了user_time的值，也就是說，隻要user_time
的值不變，那麼set_time的操作就不會改變當前連接的最新時間值，
我們就需要研究清楚，user_time到底是什麼！*/
start_time= user_time;
}
else
/* 正常路徑下，如果user_time為0，則更新當前連接最新時間*/
my_micro_time_to_timeval(start_utime, &start_time);
}
上麵代碼中提到的參數user_time，實際上對應的是MySQL會話參數timestamp，隻要顯式地設置了這個參數，user_time就不為0，那麼當前會話的起始時間就被固定在這一刻了。
現在明白了，隻要在會話1中執行一條命令，比如set timestamp=1490264145;，然後在會話2中觀察，就會發現，Time不僅非常大，而且在會話1中再執行任何語句時，會話2中的Time值都不會被清零了。
所以，如果在實際運維中遇到這樣的問題，就可以找一下有沒有連接執行過這樣的語句，從而造成了這樣的假象，因為這樣的問題出現時，都會把這類語句誤判為慢查詢，而實際又找不到這樣的查詢。
這個問題是不是有種似曾相識的感覺？沒錯，在Binlog裏經常會遇到這樣的命令，這是MySQL為了保持主從執行環境的一致性而做的，但如果在主庫上這樣操作，經常是不僅不好玩，反而會造成一頭霧水的感覺。
總結
這個問題，看似簡單，實則涉及很多關於Binlog的細節問題。講這些的主要目的就是讓DBA同學了解時間戳在Binlog中的作用及產生方法，以便在出現一些這方麵怪異的問題時，做到心中有數，胸有成竹。
本文選自《MySQL運維內參：MySQL、Galera、Inception核心原理與最佳實踐》，點此鏈接可在博文視點官網查看此書。
想及時獲得更多精彩文章，可在微信中搜索“博文視點”或者掃描下方二維碼並關注。
最後更新：2017-06-13 10:01:46