事关SQL执行时间，相当重要，求解释

[zuoxingyu]

下面是我做的三次测试：

#the first time
mysql> select now(); select sql_no_cache count(*) from customer where locale ='ad2dadaasdadas1dasdpasd1';select now();
+---------------------+
| now()               |
+---------------------+
| 2011-10-09 19:46:03 |
+---------------------+
1 row in set (0.00 sec)

+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (40.68 sec)

+---------------------+
| now()               |
+---------------------+
| 2011-10-09 19:46:57 |
+---------------------+
1 row in set (0.00 sec)


#######the second time
mysql> select now(); select sql_no_cache count(*) from customer where locale ='ad2dadaasdadas1dasdpasd1';select now();
+---------------------+
| now()               |
+---------------------+
| 2011-10-09 19:48:01 |
+---------------------+
1 row in set (0.00 sec)

+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (43.70 sec)

+---------------------+
| now()               |
+---------------------+
| 2011-10-09 19:48:55 |
+---------------------+
1 row in set (0.03 sec)

#the third time
mysql> select now(); select sql_no_cache count(*) from customer where locale ='ad2dadaasdadas1dasdpasd1';select now();
+---------------------+
| now()               |
+---------------------+
| 2011-10-09 19:49:25 |
+---------------------+
1 row in set (0.00 sec)

+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (46.41 sec)

+---------------------+
| now()               |
+---------------------+
| 2011-10-09 19:50:25 |
+---------------------+
1 row in set (0.03 sec)

第一次，两个now()之间间隔时间为：2011-10-09 19:46:57-2011-10-09 19:46:03=54S，但是实际执行时间为40.68 sec
后面两次也是一样的结果。

从数据看来，命令行得到的执行时间是不准确的，相差还很大，有10多秒的差距。那么SQL准确的执行时间，应该是哪个呢？
在这里想到了一些慢查询，查询时间只有1.2S，慢查询时间值设置在2S，1.2S的查询也进入了慢日志里面，是否和这个有关系？虽然我们反复执行得到的是1.2S，但是实际上确用了2S以上呢？

求解！

[zuoxingyu]

[Quote=引用 7 楼 acmain_chm 的回复:]
但如果MYSQL数据高负载，或者计算机高负荷的情况下。 select now() 后未必会马上CPU去执行一下个语句。
和餐厅里，上完第一盘菜后，直到下一盘菜到客人X的桌子上，未必是总是做菜时间。因为期间可能已经做了N盘菜到其它桌子上去了。
[/Quote]

我是在本机测试的，没有负载高的情况。
从测试的结果来看，profiling里才是真正的查询消耗时间。慢日志取的时间也是profiling的时间，这能够解释为什么慢查询里面的一些SQL，实际执行时间却不慢。

[wwwwb]

呵呵，实践出真知

[聪明的一休]

我试了一个100多秒的存储过程，分别是108秒和109秒，感觉不应该有10秒这么大的误差啊

set @dt=now(); CALL lp_bulk_insert(1000000); select timestampdiff(second,@dt,now());

[zuoxingyu]

[Quote=引用 9 楼 wwwwb 的回复:]
呵呵，实践出真知
[/Quote]

原来我一直在用错误的数据做优化。

[Rotel-刘志东]

select now() 本身也需要时间，并且这个时间是不可控的

[wwwwb]

SET profiling=1;
select sql_no_cache count(*) from customer where locale ='ad2dadaasdadas1dasdpasd1';
SHOW PROFILES;
假设上述SQL语句Query_ID为1
SHOW PROFILE FOR QUERY 1;
结果是什么，一般取执行时间用NOW()相减，40多秒的是MYSQL内部执行时间，无法取得

[小小小小周]

看他执行时间按照楼上的方法是最准确的。

楼主把now()改成sysdate()试试。

[nicenight]

差不多就行了，不用这么精确吧。
第一次的 now() 值可以保存在一个变量如 @a 中，第二次可以用 now() - @a 来得到差值，省去人力做减法了。
认为wwwwb说的有道理，你外部调用 now() 肯定要比内部计算来的长了。

关于 now() 和 sysdate() 还有一个小陷阱哦，上图，不解释：

mysql> select now(), sleep(3), now();
+---------------------+----------+---------------------+
| now()               | sleep(3) | now()               |
+---------------------+----------+---------------------+
| 2011-10-10 11:43:27 |        0 | 2011-10-10 11:43:27 |
+---------------------+----------+---------------------+
1 row in set (3.02 sec)

mysql>  select sysdate(), sleep(3), sysdate();
+---------------------+----------+---------------------+
| sysdate()           | sleep(3) | sysdate()           |
+---------------------+----------+---------------------+
| 2011-10-10 11:43:36 |        0 | 2011-10-10 11:43:39 |
+---------------------+----------+---------------------+
1 row in set (3.00 sec)

[rucypli]

首先确定下1 row in set (40.68 sec)
这个40.68是怎么得来的

[ACMAIN_CHM]

select now() 本身也需要时间，并且这个时间是不可控的。在执行完SELECT NOW后，MYSQL可能去做其它事情。

[zuoxingyu]

根据1楼的提示，测试结果如下：

mysql> select now(); select sql_no_cache count(*) from customer where locale ='ad2dadaasdadas1dasdpasd1';select now();
+---------------------+
| now()               |
+---------------------+
| 2011-10-09 21:43:12 |
+---------------------+
1 row in set (0.01 sec)

+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (40.24 sec)

+---------------------+
| now()               |
+---------------------+
| 2011-10-09 21:44:03 |
+---------------------+
1 row in set (0.01 sec)

mysql> show profiles;
+----------+-------------+-------------------------------------------------------------------------------------+
| Query_ID | Duration    | Query                                                                               |
+----------+-------------+-------------------------------------------------------------------------------------+
|        1 |  0.07349300 | select now()                                                                        |
|        2 | 51.17799800 | select sql_no_cache count(*) from customer where locale ='ad2dadaasdadas1dasdpasd1' |
|        3 |  0.00044100 | select now()                                                                        |
+----------+-------------+-------------------------------------------------------------------------------------+
3 rows in set (0.00 sec)

mysql> show profile for query 2;
+--------------------+-----------+
| Status             | Duration  |
+--------------------+-----------+
| starting           |  0.012984 |
| Opening tables     |  0.000535 |
| System lock        |  0.000015 |
| Table lock         |  0.000010 |
| init               |  0.015226 |
| optimizing         |  0.000165 |
| statistics         |  0.000362 |
| preparing          |  0.000107 |
| executing          |  0.000007 |
| Sending data       | 51.115373 |
| end                |  0.000014 |
| query end          |  0.000003 |
| freeing items      |  0.000111 |
| logging slow query |  0.000003 |
| logging slow query |  0.033072 |
| cleaning up        |  0.000011 |
+--------------------+-----------+
16 rows in set (0.00 sec)

这里的51和两个NOW的时间差是一致的。

[ACMAIN_CHM]

但如果MYSQL数据高负载，或者计算机高负荷的情况下。 select now() 后未必会马上CPU去执行一下个语句。
和餐厅里，上完第一盘菜后，直到下一盘菜到客人X的桌子上，未必是总是做菜时间。因为期间可能已经做了N盘菜到其它桌子上去了。

[rucypli]

看来客户端返回的时间并非真正执行时间 真正时间在profile里

[态度决定品质]

看你的执行日志
执行sql是cpu时间
执行时间包含io时间
io的同时 cpu已经执行下条语句了