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:

http://www.speedemy.com/

Master Master replication tutorial for Mariadb

We have two servers. lets call them mater1 (1.1.1.1) and master2 (2.2.2.2) .
This instruction is tested for mariadb 10.1 on Debian 8.

First set my.cnf on both servers:

on master1:

[mysqld]
server-id=1
bind-address = 0.0.0.0
log_bin=/var/log/mysql/mariadb-bin
expire_logs_days=10
sync_binlog = 1
slave_compressed_protocol = 1
binlog_format = row

#to avoid in PRIMARY / UNIQUE key collisions when we write on both servers
auto-increment-increment=2
auto-increment-offset=1

on master2:

[mysqld]
server-id=2 #server id of each server should be unique
bind-address = 0.0.0.0
log_bin=/var/log/mysql/mariadb-bin
expire_logs_days=10
sync_binlog = 1
slave_compressed_protocol = 1
binlog_format = row


--------------
copy databases form master1 to master2

on master1
mysqldump -uroot -p --opt --routines --triggers --events --single-transaction --master-data=2 -A > alldb.sql

on maste2:
mysql -uroot -p < alldb.sql

--------------

Now setting up the databases


On master1:

MariaDB [(none)]> create user 'replication'@'2.2.2.2' identified by 'MYSECRETPASSWD';
MariaDB [(none)]> grant replication slave on *.* to 'replication'@'2.2.2.2';
MariaDB [(none)]> flush privileges;

On master2:
MariaDB [(none)]> create user 'replication'@'1.1.1.1' identified by 'MYSECRETPASSWD';
MariaDB [(none)]> grant replication slave on *.* to 'replication'@'1.1.1.1';
MariaDB [(none)]> flush privileges;


on Master 1:

MariaDB [(none)]> SELECT @@GLOBAL.gtid_current_pos;
+---------------------------+
| @@GLOBAL.gtid_current_pos |
+---------------------------+
| 0-1-26067388              |
+---------------------------+



on Master 2:
MariaDB [(none)]> flush privileges;
MariaDB [(none)]> stop slave;
MariaDB [(none)]> reset slave;
MariaDB [(none)]> set global gtid_slave_pos = "0-1-26067388";
MariaDB [(none)]> change master to master_host='1.1.1.1', master_user='replication', master_password='MYSECRETPASSWD', master_use_gtid=slave_pos;
MariaDB [(none)]> start slave; 

MariaDB [(none)]> SELECT @@GLOBAL.gtid_current_pos;
+---------------------------+
| @@GLOBAL.gtid_current_pos |
+---------------------------+
| 0-2-26067398              |
+---------------------------+


on Master 1:

MariaDB [(none)]> stop slave;
MariaDB [(none)]> reset slave;
MariaDB [(none)]> set global gtid_slave_pos = "0-2-26067398";
MariaDB [(none)]> change master to master_host='2.2.2.2', master_user='replication', master_password='MYSECRETPASSWD', master_use_gtid=slave_pos;
MariaDB [(none)]> start slave;

Check whether slaves are set properly:

MariaDB [(none)]> show slave status\G;

you should see both:

  Slave_IO_Running: Yes
  Slave_SQL_Running: Yes



---------
Test replication by creating a new database on master1:

MariaDB [(none)]> create database replication_test;

On Master2, check whether replication_test in created:

MariaDB [(none)]> show databases;
+--------------------+
| Database
|
+--------------------+
| information_schema |
| mysql
|
| performance_schema |
| replication_test
|
+--------------------+

To be absolutely sure, try the same tests the othe way round.

That's it. enjyo Master/Master replication.

Curtesy of the book MariaDB High Performance-Packt Publishing (2014) by Pierre Mavro

a working my.cnf for Mariadb

#
# The MySQL database server configuration file.
#

[client]
port = 3306
socket = /var/run/mysqld/mysqld.sock

[mysqld_safe]
socket = /var/run/mysqld/mysqld.sock
nice = 0

[mysqld]

user = mysql
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
skip-external-locking
#skip-innodb
default-storage-engine=InnoDB
#
# Instead of skip-networking the default is now to listen only on
# localhost which is more compatible and is not less secure.
#bind-address = 127.0.0.1

#
# * Fine Tuning
#
key_buffer = 128M
max_allowed_packet = 64M
thread_stack = 192K
thread_cache_size       = 64
# This replaces the startup script and checks MyISAM tables if needed
# the first time they are touched
myisam-recover         = BACKUP
max_connections        = 1000

interactive_timeout= 1
wait_timeout= 1

#log-slow-queries = /var/log/mysql/slow_query.log
#long_query_time = 10
#log_queries_not_using_indexes = 1

table_cache            = 6048
thread_concurrency     = 22

join_buffer_size = 8M
sort_buffer_size = 32M
max_heap_table_size = 4412M
max_connect_errors = 10
tmp_table_size = 4412M




#*** MyISAM Specific options
key_buffer_size = 32M
read_buffer_size = 4M
read_rnd_buffer_size = 8M

myisam_sort_buffer_size = 128M
#myisam_max_sort_file_size = 10G
#myisam_max_extra_sort_file_size = 10G



#finally added
table_definition_cache = 2048


#default-storage-engine = innodb
innodb_buffer_pool_size = 25000M
innodb_log_file_size = 1500M
innodb_flush_method = O_DIRECT #O_DSYNC
innodb_file_per_table = 1
innodb_flush_log_at_trx_commit = 2
innodb_log_buffer_size = 4M
innodb_additional_mem_pool_size = 20M

# num cpu's/cores *2 is a good base line for innodb_thread_concurrency
innodb_thread_concurrency = 16




#
# * Query Cache Configuration
#
query_cache_limit = 2M
query_cache_size  = 256M
query_cache_min_res_unit = 1k

#
# * Logging and Replication
#
# Both location gets rotated by the cronjob.
# Be aware that this log type is a performance killer.
# As of 5.1 you can enable the log at runtime!
#general_log_file        = /var/log/mysql/mysql.log
#general_log             = 1

log_error                = /var/log/mysql/error.log

#server-id = 1
#log_bin = /var/log/mysql/mysql-bin.log
#binlog_do_db = shahbin

#expire_logs_days = 10
#max_binlog_size         = 100M


[mysqldump]
quick
quote-names
max_allowed_packet = 16M

[mysql]
#no-auto-rehash # faster start of mysql but no tab completition

[isamchk]
key_buffer = 16M

!includedir /etc/mysql/conf.d/