Analyze Slow Query Log File

MySQL Tutorials - Herong's Tutorial Examples

∟Analyze Slow Query Log File

This section provides a tutorial example on how to analyze slow query log file by reading its text lines or using the 'mysqldumpslow' command.

If you have slow query log turned on, you need to understand the slow query log file format to be able to read it.

The slow query log file is a text file with 5 lines per query shown below:

# Time: 2021-11-04T08:23:20.632423Z
# User@Host: herong[herong] @ localhost [127.0.0.1]  Id:  1753
# Query_time: 0.817586  Lock_time: 0.000043 Rows_sent: 0  Rows_examined: 1301718
SET timestamp=1636014199;
SELECT ID FROM Products WHERE Name LIKE ...

As you can see, MySQL records the following fields for each slow query:

1. Time - The timestamp when the query was logged.

2. User@Host - The user and the client host where the query came from.

3. Query_time - The query execution time in seconds.

4. Lock_time - The time to acquire locks in seconds.

5. Rows_sent - The number of rows sent to the client.

6. Rows_examined - The number of rows examined by the server.

7. "SET timestamp=..." - The SET statement to set the timestamp.

8. "SELECT ..." - The query statement been logged.

Sometimes, you may see "throttle" entries in the slow query log file as shown below:

# Time: 2021-11-04T12:15:24.413779Z
# User@Host: [] @  []  Id:  1753
# Query_time: 14.407339  Lock_time: 0.002269 Rows_sent: 1
  Rows_examined: 183960
SET timestamp=1636028123;
throttle:         41 'index not used' warning(s) suppressed.;

Now I can open the slow query log file in an editor and review query log entries one at a time.

If you want to sort similar slow queries in groups and get group statistics, you can use the "mysqldumpslow" command provided in the MySQL software package.

Here is an example of running the "mysqldumpslow" command on my slow query log file:

herong$ sudo mysqldumpslow /usr/lib/mysql/localhost-slow.log

Count: 15  Time=8.34s (125s)  Lock=0.00s (0s)  Rows=0.3 (5), []@[]
  throttle:         N 'S' warning(s) suppressed.

Count: 113  Time=0.35s (39s)  Lock=0.00s (0s)  Rows=0.4 (46), herong...
  SELECT ID FROM Products WHERE Name LIKE 'S' AND Code LIKE 'S' ...

...

The output tells us that there are several groups of similar slow queries. The groups are sorted with the highest average execution displayed first. Here is how to read group statistics in the output.

"Count: 15" - There are 15 slow queries in the group.
"Time=8.34s (125s)" - Average (Total) execution time in seconds of slow queries in the group.
"Lock=0.00s (0s)" - Average (Total) waiting time to acquire locks.
"Rows=0.3 (5)" - Average (Total) rows sent to client.
"throttle: N 'S' warning(s) suppressed." - Slow query pattern with "N" representing a number and "S" representing a text string. In this case, the slow query is a warning message in log file like "throttle: 41 'index not used' warning(s) suppressed.;"
"SELECT ID FROM Products WHERE Name LIKE 'S' AND Code LIKE 'S' ..." - Slow query pattern with "N" representing a number and "S" representing a text string. In this case, the slow query is a SELECT statement in the log file like "SELECT ID FROM Products WHERE Name LIKE '%Tutorial%' AND Code LIKE '%SQL%' LIMIT 1"

You can also focus on certain types of queries only by using the "-g" option of the "mysqldumpslow" command. For example:

herong$ sudo mysqldumpslow -g 'Prod.*' /usr/lib/mysql/localhost-slow.log

Count: 113  Time=0.35s (39s)  Lock=0.00s (0s)  Rows=0.4 (46), herong...
  SELECT ID FROM Products WHERE Name LIKE 'S' AND Code LIKE 'S' ...