9.2

Edit

MySQL slow queries

MySQL slow query log

This log contains data regarding MySQL queries with the execution time exceeding the set value. Log file names can be different (mysql-slow.log, slow.log, slow-queries.log, and so on):

Activate

  1. Log in to the database instance via SSH.

  2. In the MySQL console, specify:

    mysql -u username -p

  3. Print out global variables related to slow logs:

    mysql> show global variables like "slow_query_log%";

    Response example

     +----------------------------------+-----------------------------------+
 | Variable_name                    | Value                             |
 +----------------------------------+-----------------------------------+
 | `slow_query_log                  | OFF                               |
 | slow_query_log_always_write_time | 10.000000                         |
 | slow_query_log_file              | /var/log/mysql/slow-queries.log   |
 | slow_query_log_use_global_control|                                   |
 +----------------------------------+-----------------------------------+
 4 rows in set (0.00 sec)

    • slow_query_log_file is the location of the log file.

    • slow_query_log means the slow query logging is enabled.

  4. Check the query duration considered as long:

    mysql> show global variables like "long_query_time";

    Response example

    +-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.01 sec)
    • long_query_time: if the query execution time exceeds this value (in seconds), it's written to a slow log file.

  5. Enter the MySQL shell and run the following command:

    mysql> set global slow_query_log = 'ON';

    Logging is started immediately without restarting the MySQL service.

  6. Enable any other desired options. Here are some common examples:

    Log details for queries expected to retrieve all rows instead of using an index:

    mysql> set global log_queries_not_using_indexes = 'ON';

    Set the path to the slow query log:

    mysql> set global slow_query_log_file ='/var/log/mysql/slow-query.log';

    Set the amount of time a query needs to run before being logged (the default value is 10 seconds):

    mysql> set global long_query_time = 20;

  7. Confirm the changes are active by entering the MySQL shell and running the following command:

    show variables like '%slow%';

Analyze

The log contains specific MySQL queries considered slow.

mysql-slow.log example

# Time: 180409 9:29:56
# User@Host: mysqluser[mysqluser] @ <host> [133.27.5.100] Id: 25330256
# Schema: wfdb Last_errno: 0 Killed: 0
# Query_time: 1.669854 Lock_time: 0.000106 Rows_sent: 292 Rows_examined: 1345121 Rows_affected: 0
# Bytes_sent: 28268
SET timestamp=1523280596;
SELECT c.id,c.title, r.uuid FROM Campaign c INNER JOIN Run r ON (c.id=r.campaign_id) JOIN (select id, campaign_id, max(startDate) startDate FROM Run where Run.status = 'COMPLETED' GROUP BY campaign_id) r2 ON (r.campaign_id=r2.campaign_id AND r.startDate=r2.startDate) WHERE r.status = 'COMPLETED' AND (c.executingType IN ('HUMAN','COMPOSITE')) AND (c.status = 'ACTIVE')

Important fields are as follows:

  • Bytes_sent: the amount of sent bytes.
  • Timestamp: the UNIX timestamp when the query was executed.
  • Query_time: the execution time in milliseconds.

Search with keywords, for example, table names or column names:

grep -B 3 'table_name' /var/lib/mysql/mysql-slow.log

-B x gives you the x number of lines before the query.

note

You need this because the three lines prior to the actual query contain all the information about the execution of the query: when the query was executed, and how much time it took.

An alternate is as follows:

grep -A 3 'query_user' /var/lib/mysql/mysql-slow.log

The number of slow queries during the day, hour-wise:

grep Time mysql-slow.log | cut -d: -f1,2 | sort -r | uniq -c
note

You can either use sort -u or you can use sort | uniq -c but be sure that uniq won't work independently. It works only when you pipe it with sort. Sorting should be done prior to uniq.

Using mysqldumpslow to analyze the log

Getting the top ten underperforming queries:

mysqldumpslow -u root -p -s c -t 10

If you need to get into detailed log analytics, you should set up the ELK stack on your machine and connect your MySQL to the log analytics setup. Or, you can use New Relic for analyzing MySQL logs.

Explain statement

Once a long-performing query is found, you can use the EXPLAIN statement to understand why this query is so slow.

Using EXPLAIN is as simple as pre-pending it before the SELECT queries.

It may not seem like it, but there’s a lot of information packed into those ten columns! The columns returned by the query are:

  • id: a sequential identifier for each SELECT within the query (when you have nested subqueries).
  • select_type: the type of the SELECT query. Possible values are as follows:
    • SIMPLE: the query is a simple SELECT query without any subqueries or UNION.
    • PRIMARY: the SELECT is in the outermost query in a JOIN.
    • DERIVED: the SELECT is part of a subquery within a FROM clause.
    • SUBQUERY: the first SELECT in a subquery.
    • DEPENDENT SUBQUERY: a subquery depending on an outer query.
    • UNCACHEABLE SUBQUERY: a subquery that is not cacheable. There are certain conditions for a query to be cacheable.
    • UNION: SELECT is the second or later statement of a UNION.
    • DEPENDENT UNION: the second or later SELECT of a UNION depends on an outer query.
    • UNION RESULT: the SELECT is the result of a UNION.
  • table: the table referred to by a row.
  • type : how MySQL joins the tables used. This is one of the most insightful fields in the output because it can indicate something missing.

Indexes or how the query is written should be reconsidered. Possible values are:

  • system: the table has only zero or one row.

  • const: the table has only one matching row that is indexed.

    This is the fastest type of JOIN because the table only has to be read once, and the column’s value can be treated as a constant when joining other tables.

  • eq_ref: all parts of an index are used by the join, and the index is PRIMARY KEYor UNIQUE NOT NULL. This is the next best possible join type.

  • ref: all matching rows of an indexed column are read for each combination of rows from a previous table. This type of JOIN appears for indexed columns compared using the = or <=> operators.

  • fulltext: the JOIN uses the table’s FULLTEXT index.

  • ref_or_null: this is the same as ref but also contains rows with a null value for the column.

  • index_merge: the JOIN uses a list of indexes to produce a result set. The key column of the EXPLAIN‘s output will contain used keys.

  • unique_subquery: an IN subquery returns only one result from the table and makes use of the primary key.

  • index_subquery: the same as unique_subquery but returns more than one result row.

  • range: the index is used to find matching rows in a specific range, typically when the key column is compared to a constant using operators like BETWEEN, IN, >, >=, and so on.

  • index: the entire index tree is scanned to find matching rows.

  • all: the entire table is scanned to find matching rows for the JOIN. This is the worst JOIN Type and usually indicates a lack of appropriate indexes in a table.

  • possible_keys: shows the keys that can be used by MySQL to find rows from the table, though they may or may not be used in practice. In fact, this column can often help in optimizing queries since if the column is NULL, it indicates no relevant indexes could be found.

  • key: indicates the actual index used by MySQL. This column can contain an index that is not listed in the possible_key column. The MySQL optimizer always looks for an optimal key that can be used for the query. While joining many tables, it can figure out some other keys that are not listed in possible_key but are more optimal.

  • key_len: indicates the length of the index the Query Optimizer chose to use. For example, the key_len value of 4 means it requires enough memory to store four characters. Check out MySQL data type storage requirements to know more about this.

  • ref: shows the columns or constants that are compared to the index named in the key column. MySQL will either pick a constant value to be compared or a column itself based on the query execution plan. You can see this in the example given below.

  • rows: lists the number of records that were examined to produce the output. This is another important column worth focusing on while optimizing queries, especially for queries that use JOIN and subqueries.

  • Extra: contains additional information regarding the query execution plan. Values, such as Using temporary, Using filesort, and so on in this column can indicate a troublesome query. For a complete list of possible values and their meanings, refer to the MySQL documentation.

You can also add the EXTENDED keyword after EXPLAIN in your query, and MySQL will show you additional information about the way it executes the query. To see the information, follow your EXPLAIN query with SHOW WARNINGS. This is mostly useful for seeing the query that is executed after any transformations by the Query Optimizer.

← PreviousNext →