Wednesday 8 April 2020

How to analyse MySQL slow_query_log like a pro?



How to Properly log slow queries:


Tested on Mariadb 10.3 on Debian 10:

Check if slow query log is running:

MariaDB [(none)]> show global variables like  "%slow%";
+------------------------------+--------------------------------------+
| Variable_name                | Value                                                                                                                                |
+------------------------------+--------------------------------------+
| log_slow_admin_statements    | ON                                                                                                                                   |
| log_slow_disabled_statements | sp                                                                                                                                   |
| log_slow_filter              |
| log_slow_rate_limit          | 1                                                                                                                                    |
| log_slow_slave_statements    | ON                                                                                                                                   |
| log_slow_verbosity           |                                                                                                                                      |
| slow_launch_time             | 2                                                                                                                                    |
| slow_query_log               | OFF                                                                                                                                  |
| slow_query_log_file          | up-slow.log                                                                                                                          |
+------------------------------+---------------------------------



Rotate the log to avoid old data to polute your current analysis:

mv /var/lib/mysql/slow-query.log /var/lib/mysql/slow-query.log.rm1

flush logs:

MariaDB [(none)]> flush logs;
Query OK, 0 rows affected (0.000 sec)

set the log to query ALL queries:

MariaDB [(none)]> set global slow_query_log=1;

Check the long_query_time (this is the threshhold number ins seconds to save a query in slow_query_log)

 MariaDB [(none)]> select @@global.long_query_time;
+--------------------------+
| @@global.long_query_time |
+--------------------------+
|                10.000000 |
+--------------------------+
 1 row in set (0.000 sec)

Set long_query_time to zero to catch all queries. Notice that this affects performance, especially at high qps rates.

MariaDB [(none)]> set global long_query_time=0;
Query OK, 0 rows affected (0.000 sec)

Now watch slow query log size:

 ls  -lh /var/lib/mysql/up-slow.log


When the log file reached a couple fo GB, stop it:

MariaDB [(none)]> set slow_query_log=0;


Download perona query digest:

wget percona.com/get/pt-query-digest

chmod 755 pt-query-digest

Save the slow query log into a separate file:

cp  /var/lib/mysql/up-slow.log /var/lib/mysql/up-slow.log.out

And analyze the file with percona query digest:

perl  pt-query-digest /var/lib/mysql/up-slow.log




How to Properly analyze the log:

The first list gives an overview of the database activity:

# Overall: 8.31M total, 419 unique, 2.52k QPS, 9.38x concurrency _________
# Time range: 2020-04-08 09:06:28 to 10:01:24
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time         30923s       0      3s     4ms    16ms    21ms   167us
# Lock time           461s       0   385ms    55us    89us   142us    54us
# Rows sent         21.60M       0  58.01k    2.72    0.99  261.70    0.99
# Rows examine      26.66G       0   1.52M   3.36k  313.99  27.22k    0.99
# Rows affecte      38.95k       0      40    0.00       0    0.08       0
# Bytes sent        12.90G       0  23.10M   1.63k   2.27k  99.98k  874.75
# Query size         3.20G       6 464.07k  412.69  833.10 1012.18  313.99

The more interesting though is Profile of individual queries:

# Profile
# Rank Query ID                    Response time   Calls   R/Call V/M   It
# ==== =========================== =============== ======= ====== ===== ==
#    1 0xC549CF6B5AA5A6C68867CA... 6078.5728 19.7%   50213 0.1211  0.01 SELECT post_commentlike

Profile lists the queries which, altogether consumed have  %95 of the processing time.

Rank: Queries sorted by overal time taken to execute.
Response time : total time spent on this query (in milisecons and % of total time)
Calls: How many times the query is called
R/Call: Response tiem per call. Avergage response time per call.
V/M: Variance to mean ration. AKA index of dispersion.  0 no variance, 1 most variant.
Item: Abreviate version of a query.


Check queries and Index the tables when needed:

CREATE INDEX col ON tbl(col);

Source: This great video:

More info: