查看mysql语句运行时间的2种方法

http://www.jb51.net/article/45185.htm

网站运行很慢的时候，我就特别起知道为什么这么慢，所以我查啊查,数据库绝对是很重要的一部分，里面运行的sql是绝对不能放过的。平时做项目的时候，我也会注意sql语句的书写，写出一些高效的sql来，所以我会经常测试自己写的sql语句。我把我知道的二个方法，总结一下发出来。

一，show profiles 之类的语句来查看

1，查一下profile是不是打开了，默认是不打开的。

mysql> show profiles;
Empty set (0.02 sec)
mysql> show variables like "%pro%";
+---------------------------+-------+
| Variable_name | Value |
+---------------------------+-------+
| profiling | OFF |
| profiling_history_size | 15 |
| protocol_version | 10 |
| slave_compressed_protocol | OFF |
+---------------------------+-------+
4 rows in set (0.00 sec)

我查看一下profiles里面没有东西，所以公司的电脑里面profile是没有打开的，我查看了一下mysql变量，果然是OFF的。

2，开启profile，然后测试

开启profile

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

测试如下：

mysql> show tables;
+----------------+
| Tables_in_test |
+----------------+
| aa |
| bb |
| comment |
| string_test |
| user |
+----------------+
5 rows in set (0.00 sec)
mysql> select * from aa;
+----+------+------------+------+
| id | name | nname | sex |
+----+------+------------+------+
| 2 | tank | bbbb,4bbbb | NULL |
| 3 | zhang| 3,c,u | NULL |
+----+------+------------+------+
2 rows in set (0.00 sec)
mysql> update aa set name='d';
Query OK, 2 rows affected (0.00 sec)
Rows matched: 2 Changed: 2 Warnings: 0
mysql> delete from bb;
Query OK, 2 rows affected (0.00 sec)
mysql> show profiles;
+----------+------------+------------------------+
| Query_ID | Duration | Query |
+----------+------------+------------------------+
| 1 | 0.00054775 | show tables |
| 2 | 0.00022400 | select * from aa |
| 3 | 0.00026275 | update aa set name='d' |
| 4 | 0.00043000 | delete from bb |
+----------+------------+------------------------+
4 rows in set (0.00 sec)
mysql> show profile;
+----------------------+-----------+
| Status | Duration |
+----------------------+-----------+
| (initialization) | 0.0000247 |
| checking permissions | 0.0000077 |
| Opening tables | 0.0000099 |
| System lock | 0.000004 |
| Table lock | 0.000005 |
| init | 0.0003057 |
| query end | 0.0000062 |
| freeing items | 0.000057 |
| closing tables | 0.000008 |
| logging slow query | 0.0000015 |
+----------------------+-----------+
10 rows in set (0.00 sec)
mysql> show profile for query 1;
+----------------------+-----------+
| Status | Duration |
+----------------------+-----------+
| (initialization) | 0.000028 |
| checking permissions | 0.000007 |
| Opening tables | 0.0000939 |
| System lock | 0.0000017 |
| Table lock | 0.0000055 |
| init | 0.000009 |
| optimizing | 0.0000027 |
| statistics | 0.0000085 |
| preparing | 0.0000065 |
| executing | 0.000004 |
| checking permissions | 0.000258 |
| Sending data | 0.000049 |
| end | 0.0000037 |
| query end | 0.0000027 |
| freeing items | 0.0000307 |
| closing tables | 0.0000032 |
| removing tmp table | 0.0000275 |
| closing tables | 0.0000037 |
| logging slow query | 0.000002 |
+----------------------+-----------+
19 rows in set (0.00 sec)
mysql> show profile for query 3;
+----------------------+-----------+
| Status | Duration |
+----------------------+-----------+
| (initialization) | 0.0000475 |
| checking permissions | 0.0000077 |
| Opening tables | 0.000026 |
| System lock | 0.0000042 |
| Table lock | 0.0000045 |
| init | 0.0000205 |
| Updating | 0.0000787 |
| end | 0.0000567 |
| query end | 0.000004 |
| freeing items | 0.0000067 |
| closing tables | 0.000004 |
| logging slow query | 0.000002 |
+----------------------+-----------+
12 rows in set (0.00 sec)

二，timestampdiff来查看测试时间

mysql> set @d=now();
Query OK, 0 rows affected (0.00 sec)
mysql> select * from comment;
+------+-----+------+------------+---------------------+
| c_id | mid | name | content | datetime |
+------+-----+------+------------+---------------------+
| 1 | 1 | ?? | 2222222211 | 2010-05-12 00:00:00 |
| 2 | 1 | ?? | ????(??) | 2010-05-13 00:00:00 |
| 3 | 2 | tank | ?????? | 0000-00-00 00:00:00 |
+------+-----+------+-------
4000
-----+---------------------+
3 rows in set (0.00 sec)
mysql> select timestampdiff(second,@d,now());
+--------------------------------+
| timestampdiff(second,@d,now()) |
+--------------------------------+
| 0 |
+--------------------------------+
1 row in set (0.00 sec)

这种方法有一点要注意，就是三条sql语句要尽量连一起执行，不然误差太大，根本不准

set @d=now();
select * from comment;
select timestampdiff(second,@d,now());

如果是用命令行来执行的话，有一点要注意，就是在select timestampdiff(second,@d,now());后面，一定要多copy一个空行，不然最后一个sql要你自己按回车执行，这样就不准了。

其实我觉得吧，真正要我们关心的是那些查询慢的sql,因为真正影响速度的是他们，关于慢查询的东西，有空写一下。
http://jingyan.baidu.com/article/d169e1864d254d436711d852.html

shell之获取数据库SQL执行时间（精确到毫秒）

shell之获取时间（精确到毫秒）

需求：通过shell获取数据库当前时间，并计算从打开数据库连接--查询--关闭数据库连接所耗费的时间（精确到毫秒）

步骤：

1、获取时间（获取时间）

注意：

1：连接数据库的最后关闭时必须顶格写否则报错

2：shell无法直接获取精确到毫秒的时间，需要通过计算获取

方法/步骤

获取时间（获取时间）

[oracle@rhel6 zxx_shell]$ cat 3-time.sh 

#!/bin/bash

var=            #声明全局变量

function getTiming()

{

  exec_start=$1

  exec_end=$2

  

  exec_start_s=`echo $exec_start | cut -d '.' -f 1`  #获取开始时间的秒

  exec_start_ns=`echo $exec_start | cut -d '.' -f 2` #获取开始时间的纳秒

  exec_end_s=`echo $exec_end | cut -d '.' -f 1`   #获取结束时间的秒

  exec_end_ns=`echo $exec_end | cut -d '.' -f 2` #获取结束时间的纳秒

  exec_time_ms=$[$[$[ 10#$exec_end_s - 10#$exec_start_s ] * 1000] + $[$[10#$exec_end_ns / 1000000] - $[10#$exec_start_ns / 1000000] ] ]

  nowdate=`date +%Y%m%d-%T`

  echo "--------$nowdate-------->":$exec_time_ms 

}

date=   #声明全局变量

function importTargetData()

{

    exec_start=`date +%s.%N`   #获取时间格式：秒.纳秒

    sql="select sysdate from dual;"

    date=`sqlplus -s zxx/zxx@orclone <<EOF  #接收数据库查询返回值

      set heading off

      set termout off

      set feedback off 

      $sql

      quit;

EOF`          #一定要顶格写

    exec_end=`date +%s.%N`

    var=$(getTiming $exec_start $exec_end)  

    

}

  importTargetData

  echo $var

  echo $date

[oracle@rhel6 zxx_shell]$ ./3-time.sh 

--------20150805-15:26:19-------->:75

05-AUG-15