A basic tutorial on querying logs and slow query logs in MySQL,

A basic tutorial on querying logs and slow query logs in MySQL,

I. query logs

Query all the queries in MySQL by using "-- log [= file_name. Because all the queries, including all the select statements, are recorded, and the size is relatively large, it also has a great impact on the performance after enabling them. Therefore, please use this function with caution. This function is generally only used to track certain special SQL Performance problems for a short time. The default query log file name is hostname. log.
---- Check whether query logs are enabled by default:

[root@node4 mysql5.5]# service mysql start

Starting MySQL....                     [ OK ]

[root@node4 mysql5.5]# mysql

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.22-log Source distribution

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.


 

	
  


 

mysql> show variables like '%log';

+--------------------------------+-------+
| Variable_name         | Value |
+--------------------------------+-------+
| back_log            | 50  |
| general_log          | OFF  |
| innodb_locks_unsafe_for_binlog | OFF  |
| log              | OFF  |
| relay_log           |    |
| slow_query_log         | OFF  |
| sync_binlog          | 0   |
| sync_relay_log         | 0   |
+--------------------------------+-------+
8 rows in set (0.00 sec)

---- Note: the log and general_log parameters are compatible. By default, log query is disabled.
---- Use the following command to enable log query
Mysql> set global log = 1;

 

Query OK, 0 rows affected, 1 warning (0.03 sec)

mysql> show variables like '%log';

+ -------------------------------- + ------- +
| Variable_name | Value |
+ -------------------------------- + ------- +
| back_log | 50 |
| general_log | ON |
| innodb_locks_unsafe_for_binlog | OFF |
| log | ON |
| relay_log | |
| slow_query_log | OFF |
| sync_binlog | 0 |
| sync_relay_log | 0 |
+ -------------------------------- + ------- +
8 rows in set (0.00 sec)
---- The log parameter is outdated. If you use the log parameter in the startup option, it will be displayed in the err log.
---- Modify the my.cnf file and add log parameter settings

[root @ node4 mysql5.5] # vi my.cnf
[root @ node4 mysql5.5] # cat ./my.cnf | grep '^ log ='
log = / tmp / mysqlgen.log
---- Clear err log
[root @ node4 mysql5.5] # cat / dev / null> /tmp/mysql3306.err
[root @ node4 mysql5.5] # ll /tmp/mysql3306.err
-rw-rw ---- 1 mysql root 0 Jul 31 07:50 /tmp/mysql3306.err
[root @ node4 mysql5.5] # service mysql start

Starting MySQL... [OK] ---- view the err log content after Starting the database

[root@node4 mysql5.5]# cat /tmp/mysql3306.err 

130731 07:51:32 mysqld_safe Starting mysqld daemon with databases from /opt/mysql5.5/data
130731 7:51:32 [Warning] The syntax '--log' is deprecated and will be removed in a future release. Please use '--general-log' / '-general-log-file' instead.
130731 7:51:33 InnoDB: The InnoDB memory heap is disabled
130731 7:51:33 InnoDB: Mutexes and rw_locks use InnoDB's own implementation
130731 7:51:33 InnoDB: Compressed tables use zlib 1.2.3
130731 7:51:33 InnoDB: Initializing buffer pool, size = 128.0M
130731 7:51:33 InnoDB: Completed initialization of buffer pool
130731 7:51:33 InnoDB: highest supported file format is Barracuda.
130731 7:51:33 InnoDB: Waiting for the background threads to start
130731 7:51:34 InnoDB: 1.1.8 started; log sequence number 1625855
130731 7:51:34 [Note] Event Scheduler: Loaded 0 events
130731 7:51:34 [Note] /opt/mysql5.5/bin/mysqld: ready for connections.
Version: '5.5.22-log' socket: '/tmp/mysql.sock' port: 3306 Source distribution
---- Use the latest parameters
---- general_log and general_log_file.

[root@node4 mysql5.5]# service mysql stop

Shutting down MySQL.                    [ OK ]

[root@node4 mysql5.5]# vi my.cnf[root@node4 mysql5.5]# cat ./my.cnf |grep '^general'

general_log = 1 general_log_file = /tmp/mysqlgen.log

[root@node4 mysql5.5]# service mysql start

Starting MySQL...                     [ OK ]

[root@node4 mysql5.5]# mysql

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.22-log Source distribution

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.


 

	
  


 

mysql> show variables like '%log';

+--------------------------------+-------+
| Variable_name         | Value |
+--------------------------------+-------+
| back_log            | 50  |
| general_log          | ON  |
| innodb_locks_unsafe_for_binlog | OFF  |
| log              | ON  |
| relay_log           |    |
| slow_query_log         | OFF  |
| sync_binlog          | 0   |
| sync_relay_log         | 0   |
+--------------------------------+-------+
8 rows in set (0.04 sec)

mysql> show variables like '%file';

+ --------------------- + --------------------------- -------- +
| Variable_name | Value |
+ --------------------- + --------------------------- -------- +
| ft_stopword_file | (built-in) |
| general_log_file | /tmp/mysqlgen.log |
| init_file | |
| local_infile | ON |
| pid_file | /tmp/mysql3306.pid |
| relay_log_info_file | relay-log.info |
| slow_query_log_file | /opt/mysql5.5/data/node4-slow.log |
+ --------------------- + --------------------------- -------- +
7 rows in set (0.00 sec)
---- In the above operation, you can see that the query log is enabled, and the file directory is /tmp/mysqlgen.log.
---- What is recorded in the query log?

Perform the following query:

mysql> show databases;

+--------------------+
| Database      |
+--------------------+
| information_schema |
| mysql       |
| performance_schema |
| test        |
| test2       |
+--------------------+
5 rows in set (0.08 sec)

mysql> use test;

Database changed

mysql> show tables;

Empty set (0.00 sec)

mysql> use test2;

Database changed

mysql> show tables;

+-----------------+
| Tables_in_test2 |
+-----------------+
| course     |
| jack      |
| sc       |
| student     |
| t        |
| teacher     |
+-----------------+
6 rows in set (0.07 sec)

mysql> drop table t;

Query OK, 0 rows affected (0.13 sec)

mysql> select * from sc;

Empty set (0.04 sec) ---- you can see that the above operations are recorded in mysqlgen. log.

[root@node4 ~]# tail -f /tmp/mysqlgen.log

/opt/mysql5.5/bin/mysqld, Version: 5.5.22-log (Source distribution). started with:
Tcp port: 3306 Unix socket: /tmp/mysql.sock
Time         Id Command  Argument
130731 7:55:41    1 Query  show databases
130731 7:55:56    1 Query  SELECT DATABASE()
      1 Init DB  test
130731 7:55:59    1 Query  show tables
130731 7:56:19    1 Query  SELECT DATABASE()
      1 Init DB  test2
130731 7:56:23    1 Query  show tables
130731 7:56:27    1 Query  drop table t
130731 7:56:39    1 Query  select * from sc

Ii. Slow query logs
As the name suggests, slow query logs record a query with a long execution time, that is, the slow query we often call, enable this feature by setting -- log-slow-queries [= file_name] and set the record location and file name. The default file name is the hostname-slow.log, and the default directory is the data directory.
The slow query log uses a simple text format. You can view the content in the log in a variety of text editors. It records the statement execution time, execution time, execution user, connection host, and other related information. MySQL also provides the tool program mysqlslowdump, which is used to analyze full query logs, to help database administrators solve possible performance problems.

---- Use the log_slow_queries parameter to open a slow query. Because this parameter is out of date, a prompt message will appear in the err log.

---- Modify the my.cnf file and add the log_slow_queries parameter
[root @ node4 ~] # vi /opt/mysql5.5/my.cnf
[root @ node4 ~] # cat /opt/mysql5.5/my.cnf | grep '^ log_slow'
log_slow_queries = /tmp/mysqlslow.log
---- Clear err log content:
[root @ node4 ~] # cat / dev / null> /tmp/mysql3306.err
[root @ node4 ~] # service mysql start
Starting MySQL .... [OK]
---- View the information of err log


[root @ node4 data] # tail -f /tmp/mysql3306.err

02:26:28 mysqld_safe Starting mysqld daemon with databases from /opt/mysql5.5/data
 2:26:28 [Warning] The syntax '--log-slow-queries' is deprecated and will be removed in a future release. Please use' --slow-query-log '/'-slow-query-log -file 'instead.
 2:26:28 [Warning] You need to use --log-bin to make --binlog-format work.
 2:26:28 InnoDB: The InnoDB memory heap is disabled
 2:26:28 InnoDB: Mutexes and rw_locks use InnoDB's own implementation
 2:26:28 InnoDB: Compressed tables use zlib 1.2.3
 2:26:28 InnoDB: Initializing buffer pool, size = 128.0M
 2:26:28 InnoDB: Completed initialization of buffer pool
 2:26:28 InnoDB: highest supported file format is Barracuda.
 2:26:28 InnoDB: Waiting for the background threads to start
 2:26:30 InnoDB: 1.1.8 started; log sequence number 3069452
 2:26:30 [Note] Event Scheduler: Loaded 0 events
 2:26:30 [Note] /opt/mysql5.5/bin/mysqld: ready for connections.
Version: '5.5.22-log' socket: '/tmp/mysql.sock' port: 3306 Source distribution

---- Use slow_query_log and slow_query_log_file
[root @ node4 ~] # vi /opt/mysql5.5/my.cnf
[root @ node4 ~] # cat /opt/mysql5.5/my.cnf | grep '^ slow_query'
slow_query_log = 1
slow_query_log_file = /tmp/mysqlslow.log1

[root @ node4 ~] # service mysql start
Starting MySQL ... [OK]
[root @ node4 ~] # mysql
Welcome to the MySQL monitor. Commands end with; or \ g.
Your MySQL connection id is 1
Server version: 5.5.22-log Source distribution

Copyright (c) 2000, 2011, Oracle and / or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and / or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\ h' for help. Type '\ c' to clear the current input statement.

mysql> show variables like '% slow%';

+ --------------------- + --------------------- +
| Variable_name | Value |
+ --------------------- + --------------------- +
| log_slow_queries | ON |
| slow_launch_time | 10 |
| slow_query_log | ON |
| slow_query_log_file | /tmp/mysqlslow.log1 |
+ --------------------- + --------------------- +
rows in set (0.00 sec)

---- Regarding the slow_launch_time parameter, first modify the parameter value
mysql> set global long_query_time = 1;
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like '% long_query%';
+ ----------------- + ---------- +
| Variable_name | Value |
+ ----------------- + ---------- +
| long_query_time | 1.000000 |
+ ----------------- + ---------- +
row in set (0.00 sec)

---- Perform related operations to view the content of/tmp/mysqlslow. log1

mysql> select database ();
+ ------------ +
database () |
+ ------------ +
| NULL |
+ ------------ +
row in set (0.00 sec)

mysql> use test;
Database changed
mysql> show tables;
Empty set (0.00 sec)

mysql> create table t as select * from information_schema.tables;
Query OK, 85 rows affected (0.38 sec)
Records: 85 Duplicates: 0 Warnings: 0

mysql> insert into t select * from t;
Query OK, 85 rows affected (0.05 sec)
Records: 85 Duplicates: 0 Warnings: 0

mysql> insert into t select * from t;
Query OK, 170 rows affected (0.03 sec)
Records: 170 Duplicates: 0 Warnings: 0

mysql> insert into t select * from t;
Query OK, 340 rows affected (0.05 sec)
Records: 340 Duplicates: 0 Warnings: 0

mysql> insert into t select * from t;
Query OK, 680 rows affected (0.08 sec)
Records: 680 Duplicates: 0 Warnings: 0

mysql> insert into t select * from t;
Query OK, 1360 rows affected (0.29 sec)
Records: 1360 Duplicates: 0 Warnings: 0

mysql> insert into t select * from t;
Query OK, 2720 rows affected (1.49 sec)
Records: 2720 Duplicates: 0 Warnings: 0

---- It has been over 1s here, check /tmp/mysqlslow.log1

[root @ node4 data] # tail -f /tmp/mysqlslow.log1
# Time: 130801 2:36:25
# User @ Host: root [root] @ localhost []
# Query_time: 2.274219 Lock_time: 0.000322 Rows_sent: 0 Rows_examined: 5440
use test;
SET timestamp = 1375295785;
insert into t select * from t;

---- log_queries_not_using_indexes parameter experiment

mysql> show variables like '% indexes%';
+ ------------------------------- + ------- +
| Variable_name | Value |
+ ------------------------------- + ------- +
| log_queries_not_using_indexes | OFF |
+ ------------------------------- + ------- +
row in set (0.00 sec)

mysql> set log_queries_not_using_indexes = 1;
ERROR 1229 (HY000): Variable 'log_queries_not_using_indexes' is a GLOBAL variable and should be set with SET GLOBAL
mysql> set global log_queries_not_using_indexes = 1;
Query OK, 0 rows affected (0.01 sec)

mysql> show variables like '% indexes%';
+ ------------------------------- + ------- +
| Variable_name | Value |
+ ------------------------------- + ------- +
| log_queries_not_using_indexes | ON |
+ ------------------------------- + ------- +
row in set (0.00 sec)

mysql> desc t;
+ ----------------- + --------------------- + ------ +- --- + --------- + ------- +
Field | Type | Null | Key | Default | Extra |
+ ----------------- + --------------------- + ------ +- --- + --------- + ------- +
| TABLE_CATALOG | varchar (512) | NO | | | |
| TABLE_SCHEMA | varchar (64) | NO | | | |
| TABLE_NAME | varchar (64) | NO | | | |
| TABLE_TYPE | varchar (64) | NO | | | |
| ENGINE | varchar (64) | YES | | NULL | |
VERSION | bigint (21) unsigned | YES | | NULL | |
| ROW_FORMAT | varchar (10) | YES | | NULL | |
| TABLE_ROWS | bigint (21) unsigned | YES | | NULL | |
| AVG_ROW_LENGTH | bigint (21) unsigned | YES | | NULL | |
DATA_LENGTH | bigint (21) unsigned | YES | | NULL | |
MAX_DATA_LENGTH | bigint (21) unsigned | YES | | NULL | |
| INDEX_LENGTH | bigint (21) unsigned | YES | | NULL | |
DATA_FREE | bigint (21) unsigned | YES | | NULL | |
| AUTO_INCREMENT | bigint (21) unsigned | YES | | NULL | |
| CREATE_TIME | datetime | YES | | NULL | |
| UPDATE_TIME | datetime | YES | | NULL | |
| CHECK_TIME | datetime | YES | | NULL | |
| TABLE_COLLATION | varchar (32) | YES | | NULL | |
| CHECKSUM | bigint (21) unsigned | YES | | NULL | |
| CREATE_OPTIONS | varchar (255) | YES | | NULL | |
| TABLE_COMMENT | varchar (2048) | NO | | | |
+ ----------------- + --------------------- + ------ +- --- + --------- + ------- +
rows in set (0.05 sec)
---- The following command is to view the index
mysql> show index from t;
Empty set (0.01 sec)

mysql> select * from t where engine = 'xxx';
Empty set (0.18 sec)

# Time: 130801 2:43:43
# User @ Host: root [root] @ localhost []
# Query_time: 0.185773 Lock_time: 0.148868 Rows_sent: 0 Rows_examined: 5440
SET timestamp = 1375296223;
select * from t where engine = 'xxx';

PS: slow query log related variables

Command line parameters:

-- Log-slow-queries

Specifies the location where the log file is stored, which can be null, and the system gives a default file host_name-slow.log

System Variables

Log_slow_queries

Specifies the location where the log file is stored, which can be null, and the system gives a default file host_name-slow.log

Slow_query_log

The slow quere log switch. If the value is 1, the slow query is enabled.

Slow_query_log_file

Specifies the location where the log file is stored, which can be null, and the system gives a default file host_name-slow.log

Long_query_time

The time when the record expires. The default value is 10 s.

Log_queries_not_using_indexes

You can choose whether to enable the query that does not use the index after logs.

Iii. Mysqldumpslow

If there is a lot of log Content, it will be exhausted if you look at it with one eye. mysql comes with an analysis tool, which is used as follows:

[root@node4 data]# 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
         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

Articles you may be interested in:

• How to start and use a common query log instance in MySQL
• Basic tutorial on analysis of MySQL slow query logs
• How to use the general query log in MySQL to find the statement with the most queries