【已解決】慢查詢日志里只有一個commit

909413335

慢查詢日志里面記錄的信息如下，SQL在哪里？在什么情況下會出現這樣的情況？


# Time: 130723  2:06:18
# User@Host: meizu_store[meizu_store] @  [192.168.16.85]
# Query_time: 1.194662  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1374516378;
commit;
# Time: 130723  2:22:28
# User@Host: meizu_store[meizu_store] @  [192.168.16.123]
# Query_time: 1.389423  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1374517348;
commit;
# Time: 130723  7:07:40
# User@Host: meizu_store[meizu_store] @  [192.168.16.104]
# Query_time: 1.065205  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1374534460;
commit;

chinafenghao

@909413335
嘗試在binlog中找1374516378這個時間戳前后的sql

RogerZhuo

目測一下，應該是設置了long_query_time=0;  如果commit;句子前面沒有begin子句的，應該是設置了set autocommit=0; 接著執(zhí)行commit;
也就是整個事務，只有一句Commit操作，不過，query_time還花費了1秒以上，就難解釋了。

可以用版主的方式查查binlog。

909413335

根據樓主的建議，我把BINLOG里前后日志都打出來了，如下：

1. # at 931501361
   
2. #130723  2:22:27 server id 2016204  end_log_pos 931501436         Query        thread_id=2213567        exec_time=0        error_code=0
   
3. SET TIMESTAMP=1374517347/*!*/;
   
4. BEGIN
   
5. /*!*/;
   
6. # at 931501436
   
7. #130723  2:22:27 server id 2016204  end_log_pos 931501794         Query        thread_id=2213567        exec_time=0        error_code=0
   
8. SET TIMESTAMP=1374517347/*!*/;
   
9. INSERT INTO T_APP_FREE_ORDER(FFINISHEDTIME,FID   ,FPHONE_SN,FPURCHASE_TIME,FSTATUS,FTOTALPRICE   ,FUSERID, FNUMBER, FUSER_NAME,FAPPID,FVERSIONID,FQUANTITY)    VALUES ('2013-07-23 02:22:26',131927742   ,'040BBG6F2ZND','2013-07-23 02:22:26',2,0
   
10.    ,0,'APMG130723020243', '',860056,2638611,1)
    
11. /*!*/;
    
12. # at 931501794
    
13. #130723  2:22:27 server id 2016204  end_log_pos 931501951         Query        thread_id=2213567        exec_time=0        error_code=0
    
14. SET TIMESTAMP=1374517347/*!*/;
    
15. DELETE FROM T_APP_DOWNLOAD   WHERE FNEW_PHONE_SN ='040BBG6F2ZND' and FVERSIONID=2638611
    
16. /*!*/;
    
17. # at 931501951
    
18. #130723  2:22:27 server id 2016204  end_log_pos 931502308         Query        thread_id=2213567        exec_time=0        error_code=0
    
19. SET TIMESTAMP=1374517347/*!*/;
    
20. INSERT INTO T_APP_DOWNLOAD(FAPPID,FCLIENTID   ,FDOWNLOAD_TIME,FID,FIP   ,FNEW_PHONE_SN,FORDERID,FORDER_ITEMID,FORDER_PHONE_SN   ,FVERSIONID, FDOWNLOAD_URL)    VALUES (860056,0   ,'2013-07-23 02:22:26',130477183,'42.48.201.226'   ,'040BBG6F2ZN
    
21. D',131927742,0,'040BBG6F2ZND'   ,2638611, '')
    
22. /*!*/;
    
23. # at 931502308
    
24. #130723  2:22:27 server id 2016204  end_log_pos 931502335         Xid = 431918794
    
25. COMMIT/*!*/;
    
26. # at 931502335
    
27. #130723  2:22:29 server id 2016204  end_log_pos 931502410         Query        thread_id=2213567        exec_time=0        error_code=0
    
28. SET TIMESTAMP=1374517349/*!*/;
    
29. BEGIN
    
30. /*!*/;

復制代碼

慢日志記錄如下：

1. # Time: 130723  2:06:18
   
2. # User@Host: meizu_store[meizu_store] @  [192.168.16.85]
   
3. # Query_time: 1.194662  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
   
4. SET timestamp=1374516378;
   
5. commit;
   
6. # Time: 130723  2:22:28
   
7. # User@Host: meizu_store[meizu_store] @  [192.168.16.123]
   
8. # Query_time: 1.389423  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
   
9. SET timestamp=1374517348;
   
10. commit;
    
11. # Time: 130723  7:07:40
    
12. # User@Host: meizu_store[meizu_store] @  [192.168.16.104]
    
13. # Query_time: 1.065205  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
    
14. SET timestamp=1374534460;
    
15. commit;

復制代碼

在2:22:27的時候有一個事務操作，事務提交時間也是2:22:27.下一個事務的開始時間是2:22:29，中間有一秒時間是沒有事務的。結合慢查詢，慢查詢里記錄的commit是2:22:28，是不是說27開始的那個事務，在28的時候才提交成功？整個提交時間花了1S多？

我想做個例子出來驗證，但是不知道怎么做。

RogerZhuo

mysql命令：

mysql> set long_query_time=0;
Query OK, 0 rows affected (0.00 sec)

mysql> set global slow_query_log=ON;
Query OK, 0 rows affected (0.00 sec)

mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> commit;
Query OK, 0 rows affected (0.00 sec)

mysql> commit;
Query OK, 0 rows affected (0.00 sec)


慢查詢日志：

SET timestamp=1374640303;
set autocommit=0;
# Time: 130724 12:31:47
# User@Host: root[root] @  [127.0.0.1]
# Thread_id: 19  Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.000040  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0  Rows_read: 0
# Bytes_sent: 11
SET timestamp=1374640307;
commit;
# Time: 130724 12:31:59
# User@Host: root[root] @  [127.0.0.1]
# Thread_id: 19  Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.000041  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0  Rows_read: 0
# Bytes_sent: 11
SET timestamp=1374640319;
commit;

909413335

回樓上：
我這邊是生產環(huán)境，慢查詢時長是1S。COMMIT前是有BEGIN和一些DML操作。

整個事務執(zhí)行時間超過1S，這個在服務器繁忙的時候是可能會出現。

比較疑惑的是說，當事務執(zhí)行時間超過1S的時候，慢日志是記錄事務里的最后一個SQL嗎？

你給的這個例子不是我想要的，這是為了出現COMMIT而設定的特殊場景，生產環(huán)境不是這樣的。

RogerZhuo

@909413335
之前沒看明白你的問題，slow log是server層面的，和事務沒有關系，當前sql 執(zhí)行完成后，就打印在里面了，哪怕事務未提交。
不過，為什么commit會花費1s的時間，就難解釋

909413335

RogerZhuo 發(fā)表于 2013-07-24 15:43
@909413335
之前沒看明白你的問題，slow log是server層面的，和事務沒有關系，當前sql 執(zhí)行完成后，就打印 ...

事務沒提交，是不會寫入到slow log的，你這個說話我表示質疑。

你有例子么？

909413335

RogerZhuo 發(fā)表于 2013-07-24 15:43
@909413335
之前沒看明白你的問題，slow log是server層面的，和事務沒有關系，當前sql 執(zhí)行完成后，就打印 ...

事務沒提交，是不會寫入到slow log的，你這個說話我表示質疑。

你有例子么？

RogerZhuo

見附近圖片。

對一個innodb表的操作，兩個SQL，事務未提交。 注意slow log和sql結果集中的日期是相同的。