Oracle中有个tkprof来格式化oracle的trace文件

Posted 2020-08-21 服务器-老张

1、mysql日志文件系统的组成
2、慢查询日志
3、慢查询日志演示
long_query_time ： 设定慢查询的阀值，超出次设定值的SQL即被记录到慢查询日志，缺省值为10s
slow_query_log ： 指定是否开启慢查询日志
log_slow_queries ： 指定是否开启慢查询日志(该参数要被slow_query_log取代，做兼容性保留)
slow_query_log_file ： 指定慢日志文件存放位置，可以为空，系统会给一个缺省的文件host_name-slow.log
min_examined_row_limit：查询检查返回少于该参数指定行的SQL不被记录到慢查询日志
log_queries_not_using_indexes: 不使用索引的慢查询日志是否记录到索引

--当前版本
[email protected][(none)]> show variables like ‘version‘;
+---------------+------------+
| Variable_name | Value |
+---------------+------------+
| version | 5.5.39-log |
+---------------+------------+
[email protected][(none)]> show variables like ‘%slow%‘;
+---------------------+---------------------------------+
| Variable_name | Value |
+---------------------+---------------------------------+
| log_slow_queries | OFF |
| slow_launch_time | 2 |
| slow_query_log | OFF |
| slow_query_log_file | /var/lib/mysql/suse11b-slow.log |
+---------------------+---------------------------------+
[email protected][tempdb]> set global log_slow_queries=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
[email protected][(none)]> show warnings;
+---------+------+-------------------------------------------------------------------------------------------------------------------+
| Level | Code | Message |
+---------+------+-------------------------------------------------------------------------------------------------------------------+
| Warning | 1287 | ‘@@log_slow_queries‘ is deprecated and will be removed in a future release. Please use ‘@@slow_query_log‘ instead |
+---------+------+-------------------------------------------------------------------------------------------------------------------+
--从下面的查询中可知，2个系统变量log_slow_queries，slow_query_log同时被置为on
[email protected][(none)]> show variables like ‘%slow%‘;
+---------------------+---------------------------------+
| Variable_name | Value |
+---------------------+---------------------------------+
| log_slow_queries | ON |
| slow_launch_time | 2 |
| slow_query_log | ON |
| slow_query_log_file | /var/lib/mysql/suse11b-slow.log |
+---------------------+---------------------------------+
[email protected][tempdb]> show variables like ‘%long_query_time%‘;
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
--为便于演示，我们将全局和session级别long_query_time设置为1
[email protected][tempdb]> set global long_query_time=1;
Query OK, 0 rows affected (0.00 sec)
[email protected][tempdb]> set session long_query_time=1;
Query OK, 0 rows affected (0.00 sec)
--Author : Leshami
--Blog : http://blog.csdn.net/leshami
[email protected][tempdb]> create table tb_slow as select * from information_schema.columns;
Query OK, 829 rows affected (0.10 sec)
Records: 829 Duplicates: 0 Warnings: 0
[email protected][tempdb]> insert into tb_slow select * from tb_slow;
Query OK, 829 rows affected (0.05 sec)
Records: 829 Duplicates: 0 Warnings: 0
.....为便于演示，我们插入一些数据，中间重复过程省略
[email protected][tempdb]> insert into tb_slow select * from tb_slow;
Query OK, 26528 rows affected (4.40 sec)
Records: 26528 Duplicates: 0 Warnings: 0
[email protected][tempdb]> system tail /var/lib/mysql/suse11b-slow.log
/usr/sbin/mysqld, Version: 5.5.39-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /var/lib/mysql/mysql.sock
Time Id Command Argument
# Time: 2881064151 22:05:48
# [email protected]: root[root] @ localhost []
# Query_time: 4.396858 Lock_time: 0.000140 Rows_sent: 0 Rows_examined: 53056
use tempdb;
SET timestamp=1412431548;
insert into tb_slow select * from tb_slow;
....再次插入一些记录....
[email protected][tempdb]> insert into tb_slow select * from tb_slow;
Query OK, 212224 rows affected (37.51 sec)
Records: 212224 Duplicates: 0 Warnings: 0
[email protected][tempdb]> select table_schema,table_name,count(*) from tb_slow
-> group by table_schema,table_name order by 3,2;
+--------------------+----------------------------------------------+----------+
| table_schema | table_name | count(*) |
+--------------------+----------------------------------------------+----------+
| information_schema | COLLATION_CHARACTER_SET_APPLICABILITY | 1024 |
| performance_schema | cond_instances | 1024 | ...........
| mysql | user | 21504 |
+--------------------+----------------------------------------------+----------+
83 rows in set (1.58 sec) 
[email protected][tempdb]> system tail /var/lib/mysql/suse11b-slow.log
# [email protected]: root[root] @ localhost []
# Query_time: 37.514172 Lock_time: 0.000123 Rows_sent: 0 Rows_examined: 424448
SET timestamp=1412431806;
insert into tb_slow select * from tb_slow;
# Time: 141004 22:10:47
# [email protected]: root[root] @ localhost []
# Query_time: 1.573293 Lock_time: 0.000183 Rows_sent: 83 Rows_examined: 424614
SET timestamp=1412431847;
select table_schema,table_name,count(*) from tb_slow --这条SQL被记录下来了，其查询时间为1.573293s
group by table_schema,table_name order by 3,2;
[email protected][tempdb]> show variables like ‘%log_queries_not_using_indexes‘;
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF |
+-------------------------------+-------+
[email protected][tempdb]> set global log_queries_not_using_indexes=1;
Query OK, 0 rows affected (0.00 sec)
--查看表tb_slow索引信息，表tb_slow无任何索引
[email protected][tempdb]> show index from tb_slow;
Empty set (0.00 sec)
[email protected][tempdb]> select count(*) from tb_slow;
+----------+
| count(*) |
+----------+
| 424448 |
+----------+
1 row in set (0.20 sec)
[email protected][tempdb]> system tail -n3 /var/lib/mysql/suse11b-slow.log
# Query_time: 0.199840 Lock_time: 0.000152 Rows_sent: 1 Rows_examined: 424448
SET timestamp=1412432188;
select count(*) from tb_slow; --此次查询时间为0.199840，被记录的原因是因为没有走索引，因为表本身没有索引
4、格式化慢查询日志
结构化慢查询日志就是把慢查询日志中的重要信息按照便于阅读以及按照特定的排序方式来提取SQL。
这种方式有点类似于Oracle中有个tkprof来格式化oracle的trace文件。
对于前面的慢查询日志我们使用mysqldumpslow来提取如下：
suse11b:~ # mysqldumpslow -s at,al /var/lib/mysql/suse11b-slow.log
Reading mysql slow query log from /var/lib/mysql/suse11b-slow.log
Count: 4 Time=16.87s (67s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
insert into tb_slow select * from tb_slow
Count: 1 Time=0.20s (0s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost
select count(*) from tb_slow
Count: 1 Time=1.57s (1s) Lock=0.00s (0s) Rows=83.0 (83), root[root]@localhost
select table_schema,table_name,count(*) from tb_slow
group by table_schema,table_name order by N,N
#以下是按照最大耗用时间排最后，只显示2条的方式格式化日志文件
suse11b:~ # mysqldumpslow -r -t 2 /var/lib/mysql/suse11b-slow.log
Reading mysql slow query log from /var/lib/mysql/suse11b-slow.log
Count: 1 Time=1.57s (1s) Lock=0.00s (0s) Rows=83.0 (83), root[root]@localhost
select table_schema,table_name,count(*) from tb_slow
group by table_schema,table_name order by N,N
Count: 4 Time=16.87s (67s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
insert into tb_slow select * from tb_slow

#获取mysqldumpslow的帮助信息
suse11b:~ # mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]
Parse and summarize the MySQL slow query log. Options are
--verbose verbose
--debug debug
--help write this text to standard output
-v verbose
-d debug
-s ORDER what to sort by (al, at, ar, c, l, r, t), ‘at‘ is default al: average lock time ar: average rows sent at: average query time c: count #query的次数 l: lock time r: rows sent #返回的记录数 t: query time 
-r reverse the sort order (largest last instead of first)
-t NUM just show the top n queries
-a don‘t abstract all numbers to N and strings to ‘S‘
-n NUM abstract numbers with at least n digits within names
-g PATTERN grep: only consider stmts that include this string
-h HOSTNAME hostname of db server for *-slow.log filename (can be wildcard), default is ‘*‘, i.e. match all
-i NAME name of server instance (if using mysql.server startup script)
-l don‘t subtract lock time from total time