mysql 开启profiles_MySQL优化之profile

登陆到数据库(schema)

mysql> use test

Database changed

开启profile

mysql> set profiling=1;

Query OK, 0 rows affected (0.00 sec)

现在开始执行需要测试的SQL语句，MySQL数据库将会记录想关的调试信息

mysql> SHOW TABLES;

+----------------------+

| Tables_in_test |

+----------------------+

| account |

| branch |

+----------------------+

2 rows in set (0.00 sec)

mysql> SELECT COUNT(*) FROM account;

+----------+

| COUNT(*) |

+----------+

| 24 |

+----------+

1 row in set (0.00 sec)

显示当前所有已经记录的PROFILES：

mysql> SHOW PROFILES;

+----------+------------+------------------------------+

| Query_ID | Duration | Query |

+----------+------------+------------------------------+

| 1 | 0.00100800 | SHOW TABLES |

| 2 | 0.00021700 | SELECT COUNT(*) FROM account |

+----------+------------+------------------------------+

2 rows in set (0.00 sec)

获取指定查询的开销，对应上面profiles中的Query_ID：

mysql> SHOW PROFILE FOR QUERY 2;+--------------------+----------+

| Status | Duration |

+--------------------+----------+

| starting | 0.000078 |

| Opening tables | 0.000031 |

| System lock | 0.000015 |

| Table lock | 0.000010 |

| init | 0.000012 |

| optimizing | 0.000019 |

| executing | 0.000022 |

| end | 0.000006 |

| query end | 0.000003 |

| freeing items | 0.000014 |

| logging slow query | 0.000003 |

| cleaning up | 0.000004 |

+--------------------+----------+

12 rows in set (0.00 sec)

其他的一些具体的参数：

mysql> SHOW PROFILE BLOCK IO, CPU FOR QUERY 2;+--------------------+----------+----------+------------+--------------+---------------+

| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |

+--------------------+----------+----------+------------+--------------+---------------+

| starting | 0.000078 | 0.000000 | 0.000000 | 0 | 0 |

| Opening tables | 0.000031 | 0.000000 | 0.000000 | 0 | 0 |

| System lock | 0.000015 | 0.000000 | 0.000000 | 0 | 0 |

| Table lock | 0.000010 | 0.000000 | 0.000000 | 0 | 0 |

| init | 0.000012 | 0.000000 | 0.000000 | 0 | 0 |

| optimizing | 0.000019 | 0.000000 | 0.000000 | 0 | 0 |

| executing | 0.000022 | 0.000000 | 0.000000 | 0 | 0 |

| end | 0.000006 | 0.000000 | 0.000000 | 0 | 0 |

| query end | 0.000003 | 0.000000 | 0.000000 | 0 | 0 |

| freeing items | 0.000014 | 0.000000 | 0.000000 | 0 | 0 |

| logging slow query | 0.000003 | 0.000000 | 0.000000 | 0 | 0 |

| cleaning up | 0.000004 | 0.000000 | 0.000000 | 0 | 0 |

+--------------------+----------+----------+------------+--------------+---------------+

12 rows in set (0.00 sec)

下面的SQL语句用于查询query_id为2的SQL开销，且按最大耗用时间倒序排列

mysql> set @query_id=2;

mysql> SELECT STATE, SUM(DURATION) AS Total_R,

->   ROUND(

->        100 * SUM(DURATION) /

->           (SELECT SUM(DURATION)

->            FROM INFORMATION_SCHEMA.PROFILING

->            WHERE QUERY_ID = @query_id

->        ), 2) AS Pct_R,

->     COUNT(*) AS Calls,

->     SUM(DURATION) / COUNT(*) AS "R/Call"

->  FROM INFORMATION_SCHEMA.PROFILING

->  WHERE QUERY_ID = @query_id

->  GROUP BY STATE

->  ORDER BY Total_R DESC;

结果如下：

+--------------------+----------+-------+-------+--------------+

| STATE | Total_R | Pct_R | Calls | R/Call |

+--------------------+----------+-------+-------+--------------+

| starting | 0.000078 | 35.94 | 1 | 0.0000780000 |

| Opening tables | 0.000031 | 14.29 | 1 | 0.0000310000 |

| executing | 0.000022 | 10.14 | 1 | 0.0000220000 |

| optimizing | 0.000019 | 8.76 | 1 | 0.0000190000 |

| System lock | 0.000015 | 6.91 | 1 | 0.0000150000 |

| freeing items | 0.000014 | 6.45 | 1 | 0.0000140000 |

| init | 0.000012 | 5.53 | 1 | 0.0000120000 |

| Table lock | 0.000010 | 4.61 | 1 | 0.0000100000 |

| end | 0.000006 | 2.76 | 1 | 0.0000060000 |

| cleaning up | 0.000004 | 1.84 | 1 | 0.0000040000 |

| query end | 0.000003 | 1.38 | 1 | 0.0000030000 |

| logging slow query | 0.000003 | 1.38 | 1 | 0.0000030000 |

+--------------------+----------+-------+-------+--------------+

12 rows in set (0.03 sec)

开启profiling后，我们可以通过show profile等方式查看，其实质是这些开销信息被记录到information_schema.profiling表

如下面的查询，部分信息省略

mysql> SELECT * FROM INFORMATION_SCHEMA.PROFILING LIMIT 3,3\G;*************************** 1. row ***************************QUERY_ID:1SEQ:4STATE: System lock

DURATION:0.000004CPU_USER:0.000000CPU_SYSTEM:0.000000CONTEXT_VOLUNTARY:0CONTEXT_INVOLUNTARY:0BLOCK_OPS_IN:0BLOCK_OPS_OUT:0MESSAGES_SENT:0MESSAGES_RECEIVED:0PAGE_FAULTS_MAJOR:0PAGE_FAULTS_MINOR:0SWAPS:0SOURCE_FUNCTION: unknownfunctionSOURCE_FILE: lock.ccSOURCE_LINE:260

停止profile,可以设置profiling参数，或者在session退出之后,profiling会被自动关闭

mysql> set profiling=off;

Query OK, 0 rows

affected, 1 warning (0.00 sec)