Slow query log of MySQL optimization

Overview of slow query log

The so-called slow query log is used to record SQL statements with response time exceeding the set threshold in MySQL. By turning on the slow query switch, MySQL will record SQL with response time greater than the threshold in the log for performance analysis.

The slow query log option is off by default. If you want to turn it on, you need to set it manually.
The slow query log option is not recommended to be turned on all the time, because logging means IO operation, which has a certain impact on performance. Therefore, it is recommended to turn it off in the production environment, and turn it on properly in the development environment tuning phase.
Check whether the slow query log is enabled:

mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------+
| Variable_name       | Value                                   |
+---------------------+-----------------------------------------+
| slow_query_log      | OFF                                     |
| slow_query_log_file | /var/lib/mysql/DESKTOP-Q5J25HR-slow.log |
+---------------------+-----------------------------------------+
2 rows in set (0.03 sec)

The slow query log option turns ON the slow query switch. OFF means OFF and ON means ON.
Slow query log file is the name of the slow query log.

If you want to open the slow query log, execute the following statement:

set global slow_query_log = ON;
/* perhaps */
set global slow_query_log = 1;

The above two sentences mean the same thing. Any one of them can be executed. After execution, query again. It has been opened.

mysql> set global slow_query_log = ON;
Query OK, 0 rows affected (0.05 sec)

mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------+
| Variable_name       | Value                                   |
+---------------------+-----------------------------------------+
| slow_query_log      | ON                                      |
| slow_query_log_file | /var/lib/mysql/DESKTOP-Q5J25HR-slow.log |
+---------------------+-----------------------------------------+
2 rows in set (0.00 sec)

In the same way, the file name of the slow query log can be specified again, just set global slow query log file = file name.

As mentioned before, slow query log can only be recorded in the log when the response time of SQL statement exceeds a certain threshold. What is the threshold and how to set it?
The threshold value of the slow query log can be viewed by the following command:

mysql> show variables like '%long_query_time%';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

As you can see, the default threshold value is 10 seconds, which can also be modified by setting, such as 0.1 seconds:

set global long_query_time = 0.1;

After the long query time setting is completed, you need to exit the MySQL client and log in again before it takes effect. Then you can see that the value has changed to 0.1:

mysql> show variables like '%long_query_time%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.100000 |
+-----------------+----------+
1 row in set (0.01 sec)

Specific cases of slow query log

Next, the slow query log is demonstrated through a case study:
I have a test01 table in the current database. The table structure is as follows:

mysql> desc test01;
+--------+-------------+------+-----+---------+-------+
| Field  | Type        | Null | Key | Default | Extra |
+--------+-------------+------+-----+---------+-------+
| id     | int(4)      | YES  | MUL | NULL    |       |
| name   | varchar(20) | YES  |     | NULL    |       |
| passwd | char(20)    | YES  |     | NULL    |       |
| inf    | char(50)    | YES  |     | NULL    |       |
+--------+-------------+------+-----+---------+-------+
4 rows in set (0.04 sec)

Query as follows:

select * from test01;
select sleep(1);
select id, sleep(2) from test01;

The results are as follows:

mysql> select * from test01;
+------+------+--------+--------+
| id   | name | passwd | inf    |
+------+------+--------+--------+
|    1 | zz   | 123456 | asdfgh |
+------+------+--------+--------+
1 row in set (0.00 sec)

mysql> select sleep(1);
+----------+
| sleep(1) |
+----------+
|        0 |
+----------+
1 row in set (1.00 sec)

mysql> select id, sleep(2) from test01;
+------+----------+
| id   | sleep(2) |
+------+----------+
|    1 |        0 |
+------+----------+
1 row in set (2.00 sec)

At this time, we need to not care about the SQL itself, but look at the execution time of these three SQL statements. From the above, we can see that the execution of the first SQL statement takes almost no time, showing 0.00 sec, the display time of the second SQL statement is 1.00 sec, and the display time of the third SQL statement is 2.00 sec.
Because we set the threshold value to 0.1 seconds, the last two SQL statements should be recorded in the slow query log. Next, verify whether this is the case:
You can view the number of slow query SQL by the following command:

mysql> show global status like '%slow_queries%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 2     |
+---------------+-------+
1 row in set (0.02 sec)

The display record is 2, which is consistent with the actual situation.
You can view the specific path of the log by using the show variables like '% slow'query'log%' command.

mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------+
| Variable_name       | Value                                   |
+---------------------+-----------------------------------------+
| slow_query_log      | ON                                      |
| slow_query_log_file | /var/lib/mysql/DESKTOP-Q5J25HR-slow.log |
+---------------------+-----------------------------------------+
2 rows in set (0.00 sec)

Open / var/lib/mysql/DESKTOP-Q5J25HR-slow.log, and you can see that the two SQL statements with time exceeding the threshold are recorded in the log:

/usr/sbin/mysqld, Version: 5.7.29-0ubuntu0.18.04.1 ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
/usr/sbin/mysqld, Version: 5.7.29-0ubuntu0.18.04.1 ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2020-03-31T13:41:25.726554Z
# User@Host: root[root] @ localhost []  Id:     6
# Query_time: 1.000644  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
use testDB;
SET timestamp=1585662085;
select sleep(1);
# Time: 2020-03-31T13:41:34.246770Z
# User@Host: root[root] @ localhost []  Id:     6
# Query_time: 2.000536  Lock_time: 0.000057 Rows_sent: 1  Rows_examined: 1
SET timestamp=1585662094;
select id, sleep(2) from test01;

mysqldumpslow tool

Although all the slow SQL statements can be found in the methods described above, they are obviously recorded in a log file, which will be very messy. Once there are more SQL statements, it is more difficult to locate them.
Fortunately, MySQL itself provides a special tool for viewing slow query logs, namely mysqldumpslow.
You can use MySQL dumpslow - help to view the specific usage:

chenyc@DESKTOP-Q5J25HR:~$ 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

From the above files, you can see that the tool is used as follows:

mysqldumpslow [options] [log name]

Description of common options:

  • -s is the order sort, followed by the following options:
    • al average locking time
    • ar average return recording time
    • at average query time
    • c count
    • l lock time
    • r reverse order
    • t query time
  • -t. Equivalent to top n, i.e. return the previous n statements
  • -g. Match regular expression, case insensitive
    Such as:
sudo mysqldumpslow -s r -t 3 -g 'select' /var/lib/mysql/DESKTOP-Q5J25HR-slow.log

The above command indicates that three statements sorted in reverse order are returned, and the statement contains the SQL statement of select.
The results are as follows:

chenyc@DESKTOP-Q5J25HR:~$ sudo mysqldumpslow -s r -t 3 -g 'select' /var/lib/mysql/DESKTOP-Q5J25HR-slow.log

Reading mysql slow query log from /var/lib/mysql/DESKTOP-Q5J25HR-slow.log
Count: 1  Time=2.00s (2s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select id, sleep(N) from test01

Count: 1  Time=1.00s (1s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select sleep(N)

Died at /usr/bin/mysqldumpslow line 167, <> chunk 2.

Profiles tool

profiles is used to analyze massive data. This command records all executed SQL statements.
This option is also off by default and needs to be turned on manually.
Query profiles option command:

mysql> show variables like '%profiling%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | OFF   |
| profiling_history_size | 15    |
+------------------------+-------+
3 rows in set (0.01 sec)

Open command:

mysql> set profiling = ON;
Query OK, 0 rows affected, 1 warning (0.00 sec)

To view it again, you can view it in another way:

mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
|           1 |
+-------------+
1 row in set, 1 warning (0.00 sec)

The above options, 1 for on, 0 for off.
In order to view the profile more intuitively, we need to execute two more SQL statements:

mysql> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.00 sec)

mysql> select * from test01;
+------+------+--------+--------+
| id   | name | passwd | inf    |
+------+------+--------+--------+
|    1 | zz   | 123456 | asdfgh |
+------+------+--------+--------+
1 row in set (0.00 sec)

OK, that's all for the preparation. Now let's look at the profile:

mysql> show profiles;
+----------+------------+-----------------------------------+
| Query_ID | Duration   | Query                             |
+----------+------------+-----------------------------------+
|        1 | 0.00214400 | show variables like '%profiling%' |
|        2 | 0.00017400 | select @@profiling                |
|        3 | 3.00062925 | select sleep(3)                   |
|        4 | 0.00023450 | select * from test01              |
+----------+------------+-----------------------------------+
4 rows in set, 1 warning (0.00 sec)

As shown above, it records all statements, with the second column Duration representing the execution time.
Although we can see the execution time of each SQL, we cannot know exactly how much time we spend on IO and CPU. Therefore, we can also use the following statements to view more accurate content:

show profile all for query $(Query_ID);

The above query "id is the id number of the first column in the show profiles result. Such as:

mysql> show profile all for query 4;
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| Status               | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function       | Source_file
    | Source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| starting             | 0.000045 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | NULL                  | NULL
    |        NULL |
| checking permissions | 0.000008 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | check_access          | sql_authorization.cc |         809 |
| Opening tables       | 0.000020 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | open_tables           | sql_base.cc
    |        5781 |
| init                 | 0.000017 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | handle_query          | sql_select.cc
    |         128 |
| System lock          | 0.000016 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 2 |     0 | mysql_lock_tables     | lock.cc
    |         330 |
| optimizing           | 0.000005 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc
    |         158 |
| statistics           | 0.000014 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc
    |         374 |
| preparing            | 0.000010 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc
    |         482 |
| executing            | 0.000004 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | exec                  | sql_executor.cc
    |         126 |
| Sending data         | 0.000051 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 8 |     0 | exec                  | sql_executor.cc
    |         202 |
| end                  | 0.000005 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | handle_query          | sql_select.cc
    |         206 |
| query end            | 0.000007 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc
    |        4956 |
| closing tables       | 0.000007 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc
    |        5009 |
| freeing items        | 0.000013 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_parse           | sql_parse.cc
    |        5622 |
| cleaning up          | 0.000013 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc
    |        1931 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+-------------
--+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------
----+-------------+
15 rows in set, 1 warning (0.00 sec)

Because there are too many options in the above results, it seems a bit messy. In fact, we don't pay attention to many things, but mainly focus on CPU and IO. Therefore, it can be further simplified as follows:

mysql> show profile cpu, block io for query 4;
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000045 | 0.000000 |   0.000000 |            0 |             0 |
| checking permissions | 0.000008 | 0.000000 |   0.000000 |            0 |             0 |
| Opening tables       | 0.000020 | 0.000000 |   0.000000 |            0 |             0 |
| init                 | 0.000017 | 0.000000 |   0.000000 |            0 |             0 |
| System lock          | 0.000016 | 0.000000 |   0.000000 |            0 |             0 |
| optimizing           | 0.000005 | 0.000000 |   0.000000 |            0 |             0 |
| statistics           | 0.000014 | 0.000000 |   0.000000 |            0 |             0 |
| preparing            | 0.000010 | 0.000000 |   0.000000 |            0 |             0 |
| executing            | 0.000004 | 0.000000 |   0.000000 |            0 |             0 |
| Sending data         | 0.000051 | 0.000000 |   0.000000 |            0 |             0 |
| end                  | 0.000005 | 0.000000 |   0.000000 |            0 |             0 |
| query end            | 0.000007 | 0.000000 |   0.000000 |            0 |             0 |
| closing tables       | 0.000007 | 0.000000 |   0.000000 |            0 |             0 |
| freeing items        | 0.000013 | 0.000000 |   0.000000 |            0 |             0 |
| cleaning up          | 0.000013 | 0.000000 |   0.000000 |            0 |             0 |
+----------------------+----------+----------+------------+--------------+---------------+
15 rows in set, 1 warning (0.00 sec)

Global query log

As with profiles, when the global query log option is turned on, it will record all SQL statements. However, because this operation consumes performance, it is only recommended to turn it on temporarily in the development environment.
View global query log command:

mysql> show variables like '%general_log%';
+------------------+------------------------------------+
| Variable_name    | Value                              |
+------------------+------------------------------------+
| general_log      | OFF                                |
| general_log_file | /var/lib/mysql/DESKTOP-Q5J25HR.log |
+------------------+------------------------------------+
2 rows in set (0.01 sec)

Open the global query log option:

set global general_log = on;

Query again:

mysql> show variables like '%general_log%';
+------------------+------------------------------------+
| Variable_name    | Value                              |
+------------------+------------------------------------+
| general_log      | ON                                 |
| general_log_file | /var/lib/mysql/DESKTOP-Q5J25HR.log |
+------------------+------------------------------------+
2 rows in set (0.00 sec)

After the above settings are completed, you need to make the following settings:

set global log_output = 'table';

Similarly, prepare the following SQL:

select * from test01;
select id, name from test01 where id = 1;

The global query log is recorded in the mysql.general_log table.

mysql> select * from mysql.general_log;
+----------------------------+---------------------------+-----------+-----------+--------------+------------------------------------------+
| event_time                 | user_host                 | thread_id | server_id | command_type | argument
          |
+----------------------------+---------------------------+-----------+-----------+--------------+------------------------------------------+
| 2020-03-31 22:31:24.750895 | root[root] @ localhost [] |         6 |         0 | Query        | select * from test01
          |
| 2020-03-31 22:31:26.128924 | root[root] @ localhost [] |         6 |         0 | Query        | select id, name from test01 whe
re id = 1 |
| 2020-03-31 22:32:15.736558 | root[root] @ localhost [] |         6 |         0 | Query        | select * from mysql.general_log
          |
+----------------------------+---------------------------+-----------+-----------+--------------+--------------------------------
----------+
3 rows in set (0.01 sec)

Since there are records in the table and records in the file, you only need to make the following settings:

Set global general? Log? File = '/ TMP / MySQL? General. Log'; -- set file path
 Set global log_output ='File '; -- set log to file

You can view the file path with the following command:

mysql> show variables like '%general_log%';
+------------------+------------------------+
| Variable_name    | Value                  |
+------------------+------------------------+
| general_log      | ON                     |
| general_log_file | /tmp/mysql_general.log |
+------------------+------------------------+
2 rows in set (0.00 sec)

Execute the above two SQL statements:

select * from test01;
select id, name from test01 where id = 1;

View the contents of the file and get the following results:

chenyc@DESKTOP-Q5J25HR:~$ sudo cat /tmp/mysql_general.log
/usr/sbin/mysqld, Version: 5.7.29-0ubuntu0.18.04.1 ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
2020-03-31T14:35:49.793176Z         6 Query     show variables like '%general_log%'
2020-03-31T14:37:20.241374Z         6 Query     select * from test01
2020-03-31T14:37:21.408617Z         6 Query     select id, name from test01 where id = 1

Tags: MySQL SQL Ubuntu Unix

Posted on Tue, 31 Mar 2020 14:44:01 -0700 by misteraven