Slow query log is rotated before it should when using max_slowlog_size

[Agustín]

While using max_slowlog_size, the slow query log is rotated every time slow_query_log is enabled, not really checking if the current slow log is indeed bigger than max_slowlog_size or not. The queries are being correctly logged in the slow log, though I don't show that here, to keep it short.

See the following outputs to reproduce.

mysql> show variables like '%version%';
+-------------------------+--------------------------------------------------+
| Variable_name | Value |
+-------------------------+--------------------------------------------------+
| innodb_version | 5.6.22-rel71.0 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.6.22-71.0-log |
| version_comment | Percona Server (GPL), Release 71.0, Revision 726 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+--------------------------------------------------+
7 rows in set (0.00 sec)

mysql> show variables like 'max_slowlog_%';
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| max_slowlog_files | 0 |
| max_slowlog_size | 8192 |
+-------------------+-------+
2 rows in set (0.00 sec)

mysql> show variables like 'slow_query_log%';
+------------------------------------+---------------------------------------------------------------------+
| Variable_name | Value |
+------------------------------------+---------------------------------------------------------------------+
| slow_query_log | ON |
| slow_query_log_always_write_time | 10.000000 |
| slow_query_log_file | /home/agustin.gallego/sandboxes/msb_ps5_6_22/data/msandbox-slow-log |
| slow_query_log_timestamp_always | OFF |
| slow_query_log_timestamp_precision | second |
| slow_query_log_use_global_control | |
+------------------------------------+---------------------------------------------------------------------+
6 rows in set (0.00 sec)

shell> ls -o msandbox-slow-log*
-rw-rw---- 1 agustin.gallego 250 Jan 30 19:32 msandbox-slow-log.000001

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

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

shell> ls -o msandbox-slow-log*
-rw-rw---- 1 agustin.gallego 250 Jan 30 19:32 msandbox-slow-log.000001
-rw-rw---- 1 agustin.gallego 250 Jan 30 19:34 msandbox-slow-log.000002

shell> cat msandbox-slow-log.000001
/home/agustin.gallego/mysql-binaries/ps5.6.22/bin/mysqld, Version: 5.6.22-71.0-log (Percona Server (GPL), Release 71.0, Revision 726). started with:
Tcp port: 5622 Unix socket: /tmp/mysql_sandbox5622.sock
Time Id Command Argument

This is also happening with latest percona server 5.5.

Let me know if you need any other outputs.

Agustín.

[Nilnandan Joshi (nilnandan-joshi)]

Hi Agustin, I'm unable to reproduce the same with PS 5.6.22 and 5.5.40 . Whenever I'm enable/disable slow log , it's not creating another slow log but add msg to the same file even if max_slowlog_size is 0 OR 8192. Is there anything specific in my.cnf which I need to mentioned?

For PS 5.6.22,

root@desktop:/var/lib/mysql# mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 37
Server version: 5.6.22-71.0-log Percona Server (GPL), Release 71.0, Revision 726

Copyright (c) 2009-2014 Percona LLC and/or its affiliates
Copyright (c) 2000, 2014, 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> show variables like '%version%';
+-------------------------+--------------------------------------------------+
| Variable_name | Value |
+-------------------------+--------------------------------------------------+
| innodb_version | 5.6.22-71.0 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.6.22-71.0-log |
| version_comment | Percona Server (GPL), Release 71.0, Revision 726 |
| version_compile_machine | x86_64 |
| version_compile_os | debian-linux-gnu |
+-------------------------+--------------------------------------------------+
7 rows in set (0.00 sec)

mysql> show variables like 'max_slowlog_%';
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| max_slowlog_files | 0 |
| max_slowlog_size | 8192 |
+-------------------+-------+
2 rows in set (0.01 sec)

mysql> show variables like 'slow_query_log%';
+------------------------------------+---------------------------------+
| Variable_name | Value |
+------------------------------------+---------------------------------+
| slow_query_log | ON |
| slow_query_log_always_write_time | 10.000000 |
| slow_query_log_file | /var/lib/mysql/desktop-slow.log |
| slow_query_log_timestamp_always | OFF |
| slow_query_log_timestamp_precision | second |
| slow_query_log_use_global_control | |
+------------------------------------+---------------------------------+
6 rows in set (0.00 sec)

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

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

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

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

mysql> set global slow_query_log=0...

[Nilnandan Joshi (nilnandan-joshi)]

My bad, Agustin. Able to reproduce the same while using log file name without .log extension.
For using max_slowlog_size, as per the Doc,
"Warning For this feature to work variable slow_query_log_file needs to be set up manually and without the .log sufix. The slow query log files will be named using slow_query_log_file as a stem, to which a dot and a sequence number will be appended."
http://www.percona.com/doc/percona-server/5.6/flexibility/slowlog_rotation.html

root@desktop:/var/lib/mysql# mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 37
Server version: 5.6.22-71.0-log Percona Server (GPL), Release 71.0, Revision 726

Copyright (c) 2009-2014 Percona LLC and/or its affiliates
Copyright (c) 2000, 2014, 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> show variables like '%version%';
+-------------------------+--------------------------------------------------+
| Variable_name | Value |
+-------------------------+--------------------------------------------------+
| innodb_version | 5.6.22-71.0 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.6.22-71.0-log |
| version_comment | Percona Server (GPL), Release 71.0, Revision 726 |
| version_compile_machine | x86_64 |
| version_compile_os | debian-linux-gnu |
+-------------------------+--------------------------------------------------+
7 rows in set (0.00 sec)

mysql> show variables like 'max_slowlog_%';
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| max_slowlog_files | 0 |
| max_slowlog_size | 8192 |
+-------------------+-------+
2 rows in set (0.00 sec)

mysql> show variables like 'slow_query_log%';
+------------------------------------+---------------------------------+
| Variable_name | Value |
+------------------------------------+---------------------------------+
| slow_query_log | ON |
| slow_query_log_always_write_time | 10.000000 |
| slow_query_log_file | /var/lib/mysql/desktop-slow-log |
| slow_query_log_timestamp_always | OFF |
| slow_query_log_timestamp_precision | second |
| slow_query_log_use_global_control | |
+------------------------------------+---------------------------------+
6 rows in set (0.00 sec)

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

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

mysql>...

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-server/pull/79
https://github.com/percona/percona-server/pull/80

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1606