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:
