同大多數關系型數據庫一樣，日志文件是MySQL數據庫的重要組成部分。MySQL有幾種不同的日志文件，通常包括錯誤日志文件，二進制日志，通用日志，慢查詢日志，等等。這些日志可以幫助我們定位mysqld內部發生的事件，數據庫性能故障，記錄數據的變更歷史，用戶恢復數據庫等等。本文主要描述通用查詢日志。
1、MySQL日志文件系統的組成
a、錯誤日志：記錄啟動、運行或停止mysqld時出現的問題。
b、通用日志：記錄建立的客戶端連接和執行的語句。
c、更新日志：記錄更改數據的語句。該日志在MySQL 5.1中已不再使用。
d、二進制日志：記錄所有更改數據的語句。還用於復制。
e、慢查詢日志：記錄所有執行時間超過long_query_time秒的所有查詢或不使用索引的查詢。
f、Innodb日志：innodb redo log
缺省情況下，所有日志創建於mysqld數據目錄中。
可以通過刷新日志，來強制mysqld來關閉和重新打開日志文件（或者在某些情況下切換到一個新的日志）。
當你執行一個FLUSH LOGS語句或執行mysqladmin flush-logs或mysqladmin refresh時，則日志被老化。
對於存在MySQL復制的情形下，從復制服務器將維護更多日志文件，被稱為接替日志。
2、慢查詢日志
慢查詢日志是將mysql服務器中影響數據庫性能的相關SQL語句記錄到日志文件，通過對這些特殊的SQL語句分析，改進以達到提高數據庫性能的目的。
通過使用--slow_query_log[={0|1}]選項來啟用慢查詢日志。所有執行時間超過long_query_time秒的SQL語句都會被記錄到慢查詢日志。
缺省情況下hostname-slow.log為慢查詢日志文件安名，存放到數據目錄，同時缺省情況下未開啟慢查詢日志。
缺省情況下數據庫相關管理型SQL(比如OPTIMIZE TABLE、ANALYZE TABLE和ALTER TABLE)不會被記錄到日志。
對於管理型SQL可以通過--log-slow-admin-statements開啟記錄管理型慢SQL。
mysqld在語句執行完並且所有鎖釋放后記入慢查詢日志。記錄順序可以與執行順序不相同。獲得初使表鎖定的時間不算作執行時間。
可以使用mysqldumpslow命令獲得日志中顯示的查詢摘要來處理慢查詢日志。
用查詢緩存處理的查詢不加到慢查詢日志中，表有零行或一行而不能從索引中受益的查詢也不寫入慢查詢日志。
MySQL服務器按以下順序記錄SQL是否寫入到慢查詢日志
a. The query must either not be an administrative statement, or --log-slow-adminstatements must have been specified.
b. The query must have taken at least long_query_time seconds, or log_queries_not_using_indexes must be enabled and the query used no indexes for row lookups.
c. The query must have examined at least min_examined_row_limit rows.
d. The query must not be suppressed according to the log_throttle_queries_not_using_indexes setting.
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: 不使用索引的慢查詢日志是否記錄到索引
-
-
--當前版本
-
root@localhost[(none)]>
show
variables
like
'version'
;
-
+
---------------+------------+
-
| Variable_name | Value |
-
+
---------------+------------+
-
| version | 5.5.39-log |
-
+
---------------+------------+
-
-
root@localhost[(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 |
-
+
---------------------+---------------------------------+
-
-
root@localhost[tempdb]>
set
global
log_slow_queries=
1
;
-
Query OK, 0 rows affected, 1 warning (0.00 sec)
-
-
root@localhost[(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
-
root@localhost[(
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 |
-
+
---------------------+---------------------------------+
-
-
root@localhost[tempdb]>
show
variables
like
'%long_query_time%'
;
-
+
-----------------+-----------+
-
| Variable_name | Value |
-
+
-----------------+-----------+
-
| long_query_time | 10.000000 |
-
+
-----------------+-----------+
-
-
--為便於演示，我們將全局和session級別long_query_time設置為1
-
root@localhost[tempdb]>
set
global
long_query_time=
1
;
-
Query OK, 0 rows affected (0.00 sec)
-
-
root@localhost[tempdb]>
set
session
long_query_time=
1
;
-
Query OK, 0 rows affected (0.00 sec)
-
-
--Author : Leshami
-
--Blog : http://blog.csdn.net/leshami
-
-
root@localhost[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
-
-
root@localhost[tempdb]>
insert
into
tb_slow
select
*
from
tb_slow;
-
Query OK, 829 rows affected (0.05 sec)
-
Records: 829 Duplicates: 0 Warnings: 0
-
.....為便於演示，我們插入一些數據，中間重復過程省略
-
root@localhost[tempdb]>
insert
into
tb_slow
select
*
from
tb_slow;
-
Query OK, 26528 rows affected (4.40 sec)
-
Records: 26528 Duplicates: 0 Warnings: 0
-
-
root@localhost[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: 141004 22:05:48
-
# User@Host: 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;
-
-
....再次插入一些記錄....
-
root@localhost[tempdb]>
insert
into
tb_slow
select
*
from
tb_slow;
-
Query OK, 212224 rows affected (37.51 sec)
-
Records: 212224 Duplicates: 0 Warnings: 0
-
-
root@localhost[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)
-
-
root@localhost[tempdb]>
system
tail /
var
/lib/mysql/suse11b-slow.log
-
#
User
@Host: 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
-
# User@Host: 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
;
-
-
root@localhost[tempdb]>
show
variables
like
'%log_queries_not_using_indexes'
;
-
+
-------------------------------+-------+
-
| Variable_name | Value |
-
+
-------------------------------+-------+
-
| log_queries_not_using_indexes | OFF |
-
+
-------------------------------+-------+
-
-
root@localhost[tempdb]>
set
global
log_queries_not_using_indexes=
1
;
-
Query OK, 0 rows affected (0.00 sec)
-
-
--查看表tb_slow索引信息，表tb_slow無任何索引
-
root@localhost[tempdb]>
show
index
from
tb_slow;
-
Empty
set
(
0.00
sec)
-
-
root@localhost[tempdb]>
select
count
(*)
from
tb_slow;
-
+
----------+
-
| count(*) |
-
+
----------+
-
| 424448 |
-
+
----------+
-
1 row in
set
(
0.20
sec)
-
-
root@localhost[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
原文地址：https://blog.csdn.net/leshami/article/details/39829605