How to enable slow query log in MySQL cluster

Products

• VMware Tanzu Application Service for VMs

Issue/Introduction

This article discusses how to enable slow query log in MySQL Cluster.

Environment

Resolution

Firstly, connect to MySQL service instance using the root credential. You can refer to this KB article and follow the steps which can also apply to the PCF MySQL tile. You just need to get the IP from MySQL tile instead of the ER tile. In my case, I connect to the MySQL instance 1 with IP 192.168.7.130.

Show the current value of slow_query_log and slow_query_log_file. You can see slow_query_log has default value OFF.

ubuntu@pivotal-ops-manager:~$ mysql -u root -pb9da6ee8a30da5c97e9b -h 192.168.7.130
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 78
Server version: 5.5.5-10.0.22-MariaDB-wsrep Source distribution, wsrep_25.11.r21a2415

Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> show variables like '%slow_query%';
+---------------------+--------------------------------------------------------------------------------------------------------------+
| Variable_name | Value |
+---------------------+--------------------------------------------------------------------------------------------------------------+
| slow_query_log | OFF |
| slow_query_log_file | 465fce26-5f89-40a6-98ac-67068dbc9111-slow.log |
+---------------------+--------------------------------------------------------------------------------------------------------------+
2 rows in set (0.02 sec)

Use the global option to change the value to,ON so that this value change is applied globally.

mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like '%slow%';
+---------------------+--------------------------------------------------------------------------------------------------------------+
| Variable_name | Value |
+---------------------+--------------------------------------------------------------------------------------------------------------+
| slow_query_log | ON |
| slow_query_log_file | 465fce26-5f89-40a6-98ac-67068dbc9111-slow.log |
+---------------------+--------------------------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)

Trigger slow running queries. Please be aware that only SQL running more than the value of long_query_time with default value 10sec will be logged. In my case, create a simple table, insert some data, then run "join" operation".

mysql> use alicedb;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> insert into alicetable(id) values (1);
Query OK, 1 row affected (0.18 sec)

mysql> insert into alicetable(id) values (2);
Query OK, 1 row affected (0.04 sec)

mysql> insert into alicetable(id) values (3);
Query OK, 1 row affected (0.03 sec)

mysql> insert into alicetable(id) values (4);
Query OK, 1 row affected (0.03 sec)

mysql> insert into alicetable select * from alicetable;
Query OK, 4 rows affected (0.07 sec)
Records: 4 Duplicates: 0 Warnings: 0

...

mysql> insert into alicetable select * from alicetable;
Query OK, 2048 rows affected (0.16 sec)
Records: 2048 Duplicates: 0 Warnings: 0

mysql> select a.id aid, b.id bid from alicetable a, alicetable b;

Connect to the MySQL service instance and locate the log file with name specified by slow_query_log_file. In my case, it's instance 1 with IP 192.168.7.130. The log file name is 465fce26-5f89-40a6-98ac-67068dbc9111-slow.log

root@465fce26-5f89-40a6-98ac-67068dbc9111:/# more ./var/vcap/store/mysql/465fce26-5f89-40a6-98ac-67068dbc9111-slow.log
/var/vcap/packages/mariadb/bin/mysqld, Version: 10.0.22-MariaDB-wsrep (Source distribution, wsrep_25.11.r21a2415). started w
ith:
Tcp port: 3306 Unix socket: /var/vcap/sys/run/mysql/mysqld.sock
Time Id Command Argument
/var/vcap/packages/mariadb/bin/mysqld, Version: 10.0.22-MariaDB-wsrep (Source distribution, wsrep_25.11.r21a2415). started w
ith:
Tcp port: 3306 Unix socket: /var/vcap/sys/run/mysql/mysqld.sock
Time Id Command Argument
# Time: 160628 1:52:10
# User@Host: root[root] @ [192.168.7.132]
# Thread_id: 81 Schema: alicedb QC_hit: No
# Query_time: 198.261290 Lock_time: 0.008474 Rows_sent: 7657459 Rows_examined: 16384
use alicedb;
SET timestamp=1467078730;
select a.id aid, b.id bid from alicetable a, alicetable b;
# Time: 160628 1:57:17
# User@Host: root[root] @ [192.168.7.132]
# Thread_id: 82 Schema: alicedb QC_hit: No
# Query_time: 205.817215 Lock_time: 0.000069 Rows_sent: 0 Rows_examined: 0
SET timestamp=1467079037;
select a.id aid, b.id bid from alicetable a, alicetable b;
# Time: 160628 1:57:18
# User@Host: root[root] @ [192.168.7.132]
# Thread_id: 84 Schema: alicedb QC_hit: No
# Query_time: 28.361613 Lock_time: 0.014729 Rows_sent: 0 Rows_examined: 0
SET timestamp=1467079038;
drop table alicetable;
root@465fce26-5f89-40a6-98ac-67068dbc9111:/# 

If you want to write the log to table and file both, you can change the value of variable log_output.   

{"timestamp":1463691855.062584877,"process_id":32436,"source":"loggregator trafficcontroller","log_level":"debug","message":"Received create/update event: 1","data":null,"file":"/var/vcap/data/compile/loggregator_trafficcontroller/loggregator/src/github.com/cloudfoundry/dropsonde/logging/logging.go","line":13,"method":"github.com/cloudfoundry/dropsonde/logging.Debugf"}
ubuntu@pivotal-ops-manager:~$ mysql -u root -pb9da6ee8a30da5c97e9b -h 192.168.7.129
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 39
Server version: 5.5.5-10.0.22-MariaDB-wsrep Source distribution, wsrep_25.11.r21a2415

Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SET GLOBAL log_output = 'FILE,TABLE';
Query OK, 0 rows affected (0.00 sec)
Then rerun the slow query, you can see the slow query log in mysql.slow_log table.  

mysql> select * from mysql.slow_log;
+----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+---------+----------------+-----------+-----------+-------------------------------------------------------------------------------+-----------+
| start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text | thread_id |
+----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+---------+----------------+-----------+-----------+-------------------------------------------------------------------------------+-----------+
| 2016-06-29 06:48:35.955678 | root[root] @ [192.168.7.61] | 00:02:11.001380 | 00:00:00.000113 | 23941572 | 4096 | alicedb | 0 | 0 | 0 | select a.id alice3, b.id alice4 from alicetable a, alicetable b, alicetable c | 35 |
+----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+---------+----------------+-----------+-----------+-------------------------------------------------------------------------------+-----------+
1 row in set (0.00 sec)

Additional Information

Important notes 

• You need to set the variable to "on" in all instances.
• Each node will only write to the slow log (file and/or table) if it actually handled the query. Like if instance 0 handled a query, then the slow log (file and/or table) will be written for instance 0.
• The variable change is persistent.