【已解决】慢查询日志里只有一个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; 接着执行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

回楼上：
我这边是生产环境，慢查询时长是1S。COMMIT前是有BEGIN和一些DML操作。

整个事务执行时间超过1S，这个在服务器繁忙的时候是可能会出现。

比较疑惑的是说，当事务执行时间超过1S的时候，慢日志是记录事务里的最后一个SQL吗？

你给的这个例子不是我想要的，这是为了出现COMMIT而设定的特殊场景，生产环境不是这样的。

RogerZhuo

@909413335
之前没看明白你的问题，slow log是server层面的，和事务没有关系，当前sql 执行完成后，就打印在里面了，哪怕事务未提交。
不过，为什么commit会花费1s的时间，就难解释

909413335

RogerZhuo 发表于 2013-07-24 15:43
@909413335
之前没看明白你的问题，slow log是server层面的，和事务没有关系，当前sql 执行完成后，就打印 ...

事务没提交，是不会写入到slow log的，你这个说话我表示质疑。

你有例子么？

909413335

RogerZhuo 发表于 2013-07-24 15:43
@909413335
之前没看明白你的问题，slow log是server层面的，和事务没有关系，当前sql 执行完成后，就打印 ...

事务没提交，是不会写入到slow log的，你这个说话我表示质疑。

你有例子么？

RogerZhuo

见附近图片。

对一个innodb表的操作，两个SQL，事务未提交。 注意slow log和sql结果集中的日期是相同的。