下面是我做的三次测试:#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以上呢?求解!
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以上呢?求解!
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() 值可以保存在一个变量如 @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)
这个40.68是怎么得来的
+---------------------+
| 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的时间差是一致的。
和餐厅里,上完第一盘菜后,直到下一盘菜到客人X的桌子上,未必是总是做菜时间。因为期间可能已经做了N盘菜到其它桌子上去了。
我是在本机测试的,没有负载高的情况。
从测试的结果来看,profiling里才是真正的查询消耗时间。慢日志取的时间也是profiling的时间,这能够解释为什么慢查询里面的一些SQL,实际执行时间却不慢。
set @dt=now(); CALL lp_bulk_insert(1000000); select timestampdiff(second,@dt,now());
执行sql是cpu时间
执行时间包含io时间
io的同时 cpu已经执行下条语句了