Slow query log is rotated before it should when using max_slowlog_size

Bug #1416582 reported by Agustín on 2015-01-31
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Medium
Sergei Glushchenko
5.5
Fix Released
Medium
Sergei Glushchenko
5.6
Fix Released
Medium
Sergei Glushchenko

Bug Description

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.

Download full text (13.2 KiB)

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...

Changed in percona-server:
status: New → Incomplete
Download full text (4.4 KiB)

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>...

Read more...

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

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers