MySQL Slow query log (Slow query log)

Like most relational databases, log files are an important part of the MySQL database. MySQL has several different log files, usually including error log files, binary logs, generic logs, slow query logs, and so on. These logs can help us locate events inside MYSQLD, database performance failures, record data change histories, user recovery databases, and more. This article mainly describes the general query log.

1, the MySQL log file system composition
A, error log: Records the issue that occurs when you start, run, or stop mysqld.
B. General log: Records the established client connections and executed statements.
C, update log: The statement that records the change data. The log is no longer used in MySQL 5.1.
D, binary log: A statement that records all changes to the data. Also used for replication.
E, slow query log: Records all queries that have been executed for more than long_query_time seconds, or queries that do not use indexes.
F, InnoDB logs: InnoDB redo Log

By default, all logs are created in the MYSQLD data directory.
You can force mysqld to close and reopen the log file (or, in some cases, switch to a new log) by refreshing the log.
When you execute a FLUSH logs statement or perform mysqladmin flush-logs or mysqladmin refresh, the log is aged.
In the case of MySQL replication, more log files will be maintained from the replication server, known as the replacement log.

2. Slow query log
The slow query log is a log file of related SQL statements that affect database performance in the MySQL server, which is improved to improve database performance by analyzing these special SQL statements.
Enable slow query logging by using the--slow_query_log[={0|1}] option. All SQL statements that execute longer than long_query_time seconds are logged to the slow query log.
By default, Hostname-slow.log is a slow query log file name, stored in the data directory, and the slow query log is not turned on by default.
Database-related managed SQL (such as optimize table, ANALYZE table, and ALTER TABLE) is not logged to the log by default.
For managed SQL, you can turn on record-managed slow SQL through--log-slow-admin-statements.
Mysqld is executed at the end of the statement and all locks are released into the slow query log. The sequence of records can be different from the order of execution. The time to obtain the initial lock on the table does not count as the execution time.

You can use the Mysqldumpslow command to get the query summary displayed in the log to handle the slow query log.
Queries processed with query caching are not added to the slow query log, and queries that have 0 rows or one row in the table and cannot benefit from the index are not written to the slow query log.
The MySQL server records whether SQL is written to the slow query log in the following order
A. The query must either not being an administrative statement, or--log-slow-adminstatements must has been specified.
B. The query must has taken at least long_query_time seconds, or log_queries_not_using_indexes must is enabled and the Qu Ery used no indexes for row lookups.
C. The query must has examined at least min_examined_row_limit rows.
D. The query must not being suppressed according to the log_throttle_queries_not_using_indexes setting.

3. Slow Query Log Demo

long_query_time: Set the threshold for slow queries. SQL exceeding the set value is recorded to the slow query log. The default value is 10s.
slow_query_log: specify whether to enable the slow query log
log_slow_queries: specify whether to enable slow query logging (this parameter should be replaced by slow_query_log, for compatibility compatibility)
slow_query_log_file: Specify the slow log file storage location, which can be empty, the system will give a default file host_name-slow.log
min_examined_row_limit: The query check returns less than the specified rows of this parameter SQL is not recorded in the slow query log
log_queries_not_using_indexes: whether slow query logs without indexes are logged to the index
    
--current version
[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 |
+ --------- + ------ + -------------------------------- -------------------------------------------------- --------------------------------- +

-From the following query, two system variables log_slow_queries and slow_query_log are set to 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 |
+ ----------------- + ----------- +

-For demonstration purposes, we set the global and session level long_query_time to 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
       ..... For the sake of demonstration, we insert some data, the process is omitted in the middle
[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: 141004 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;

    .... insert some records again ...
[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-this SQL is recorded, and its query time is 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)

--View table tb_slow index information, table tb_slow does not have any indexes
[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; --The query time is 0.199840, the reason is recorded because the index is not taken, because the table itself has no index
4. Format slow query logs

Structured slow query log is to extract the important information in the slow query log according to the ease of reading and the specific sorting method.
This method is somewhat similar to the tkprof in Oracle to format the Oracle trace file.
For the previous slow query log we use mysqldumpslow to extract as follows:

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

#The following is the format of the log file according to the maximum elapsed time and only 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
  
#Get help information for 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 times
                 l: lock time
                 r: rows sent #Number of records returned
                 t: query time
  -r reverse the sort order (largest last instead of first)
  -t NUM just show the top n queries
  -a do n‘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 do n‘t subtract lock time from total time

MySQL Slow query log (Slow query log)