Incorrect slow log file used after disabling slowlog rotation
General
Escalation
General
Escalation
Description
Environment
CentOS Linux release 7.3.1611 (Core)
Percona Server 5.7.18-15
Smart Checklist
Activity
Lalit Choudhary August 23, 2018 at 8:41 AM
Hi Daniel,
I tested described behavior with the latest version of percona server 5.7.22 on centos 7.
I'm unable to reproduce the same issue.
Test:
mysql> show global variables where variable_name in ('slow_query_log','slow_query_log_file','long_query_time','max_slowlog_size');
+---------------------+-------------------------------+
| Variable_name | Value |
+---------------------+-------------------------------+
| long_query_time | 0.000000 |
| max_slowlog_size | 0 |
| slow_query_log | ON |
| slow_query_log_file | /var/lib/mysql/node3-slow.log |
+---------------------+-------------------------------+
4 rows in set (0.01 sec)
mysql> set global slow_query_log_file = "/var/lib/mysql/node3-slow";
Query OK, 0 rows affected (0.02 sec)
mysql> set global max_slowlog_size = 4096;
Query OK, 0 rows affected (0.00 sec)
mysql> flush slow logs;
Query OK, 0 rows affected (0.00 sec)
[root@node3 mysql]# sudo lsof | grep node3-slow
mysqld 7551 mysql 15w REG 253,0 416 25247737 /var/lib/mysql/node3-slow.000001
mysqld 7551 7552 mysql 15w REG 253,0 416 25247737 /var/lib/mysql/node3-slow.000001
mysqld 7551 7553 mysql 15w REG 253,0 416 25247737 /var/lib/mysql/node3-slow.000001
mysqld 7551 7554 mysql 15w REG 253,0 416 25247737 /var/lib/mysql/node3-slow.000001
mysqld 7551 7555 mysql 15w REG 253,0 416 25247737 /var/lib/mysql/node3-slow.000001
mysqld 7551 7556 mysql 15w REG 253,0 416 25247737 /var/lib/mysql/node3-slow.000001
mysqld 7551 7557 mysql 15w REG 253,0 416 25247737 /var/lib/mysql/node3-slow.000001
mysql> set global slow_query_log_file = "/var/lib/mysql/node3-slow.log";
Query OK, 0 rows affected (0.01 sec)
mysql> set global max_slowlog_size = 0;
Query OK, 0 rows affected (0.00 sec)
mysql> flush slow logs;
Query OK, 0 rows affected (0.01 sec)
[root@node3 mysql]# sudo lsof | grep node3-slow
mysqld 7551 mysql 15w REG 253,0 618 25247719 /var/lib/mysql/node3-slow.log
mysqld 7551 7552 mysql 15w REG 253,0 618 25247719 /var/lib/mysql/node3-slow.log
mysqld 7551 7553 mysql 15w REG 253,0 618 25247719 /var/lib/mysql/node3-slow.log
mysqld 7551 7554 mysql 15w REG 253,0 618 25247719 /var/lib/mysql/node3-slow.log
mysqld 7551 7555 mysql 15w REG 253,0 618 25247719 /var/lib/mysql/node3-slow.log
mysqld 7551 7556 mysql 15w REG 253,0 618 25247719 /var/lib/mysql/node3-slow.log
Cannot Reproduce
Details
Assignee
Lalit ChoudharyLalit ChoudharyReporter
Daniel KowalewskiDaniel Kowalewski(Deactivated)Labels
Affects versions
Priority
Medium
Details
Details
Assignee
Lalit ChoudharyReporter
Daniel KowalewskiLabels
Affects versions
Priority
MediumSmart Checklist
Open Smart Checklist
Smart Checklist
Open Smart Checklist
Smart Checklist
Open Smart Checklist
Created February 23, 2018 at 12:19 AM
Updated August 23, 2018 at 8:42 AM
Resolved August 23, 2018 at 8:42 AM
When disabling slow query log rotation by reversing the steps described here, the new value of `slow_query_log_file` is ignored until a server restart. The old file handle with the sequence number suffix remains open, and the correct file handle is never opened.
Start server with:
mysql [localhost] \{msandbox} ((none)) > show global variables where variable_name in ('slow_query_log','slow_query_log_file','long_query_time','max_slowlog_size'); +---------------------+----------------------------------------------------------+ | Variable_name | Value | +---------------------+----------------------------------------------------------+ | long_query_time | 0.000000 | | max_slowlog_size | 0 | | slow_query_log | ON | | slow_query_log_file | /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log | +---------------------+----------------------------------------------------------+ 4 rows in set (0.00 sec)Enable slow log rotation:
mysql [localhost] \{msandbox} ((none)) > set global slow_query_log_file = "/home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow"; Query OK, 0 rows affected (0.00 sec) mysql [localhost] \{msandbox} ((none)) > set global max_slowlog_size = 4096; Query OK, 0 rows affected (0.00 sec) mysql [localhost] \{msandbox} ((none)) > flush slow logs; Query OK, 0 rows affected (0.00 sec)Verify that file with sequence number suffix is open:
[vagrant@sandbox data]$ sudo lsof | grep sandbox-slow mysqld 5579 vagrant 14w REG 253,0 6988 72029567 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.000001 mysqld 5579 5580 vagrant 14w REG 253,0 6988 72029567 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.000001 mysqld 5579 5581 vagrant 14w REG 253,0 6988 72029567 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.000001 mysqld 5579 5582 vagrant 14w REG 253,0 6988 72029567 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.000001 mysqld 5579 5583 vagrant 14w REG 253,0 6988 72029567 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.000001 mysqld 5579 5584 vagrant 14w REG 253,0 6988 72029567 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.000001 ...Now reverse steps to return to default slow log configuration:
mysql [localhost] \{msandbox} ((none)) > set global slow_query_log_file = "/home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log"; Query OK, 0 rows affected (0.00 sec) mysql [localhost] \{msandbox} ((none)) > set global max_slowlog_size = 0; Query OK, 0 rows affected (0.00 sec) mysql [localhost] \{msandbox} ((none)) > flush slow logs; Query OK, 0 rows affected (0.00 sec)Confirm old file is still open:
[vagrant@sandbox data]$ sudo lsof | grep sandbox-slow mysqld 5579 vagrant 14w REG 253,0 2692 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5580 vagrant 14w REG 253,0 2692 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5581 vagrant 14w REG 253,0 2692 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5582 vagrant 14w REG 253,0 2692 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5583 vagrant 14w REG 253,0 2692 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5584 vagrant 14w REG 253,0 2692 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 ...Just to make sure, disable and enable the slow log:
mysql [localhost] \{msandbox} ((none)) > set global slow_query_log = 0; Query OK, 0 rows affected (0.00 sec) mysql [localhost] \{msandbox} ((none)) > set global slow_query_log = 1; Query OK, 0 rows affected (0.00 sec) mysql [localhost] \{msandbox} ((none)) > flush slow logs; Query OK, 0 rows affected (0.01 sec)Old file handle is still open:
[vagrant@sandbox data]$ sudo lsof | grep sandbox-slow mysqld 5579 vagrant 39w REG 253,0 4044 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5580 vagrant 39w REG 253,0 4044 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5581 vagrant 39w REG 253,0 4044 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5582 vagrant 39w REG 253,0 4044 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5583 vagrant 39w REG 253,0 4044 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5584 vagrant 39w REG 253,0 4044 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 mysqld 5579 5585 vagrant 39w REG 253,0 4044 67206059 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log.000001 ...After a restart of mysqld, the correct file is being used:
[vagrant@sandbox data]$ sudo lsof | grep sandbox-slow mysqld 5886 vagrant 14w REG 253,0 2549 72029565 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log mysqld 5886 5887 vagrant 14w REG 253,0 2549 72029565 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log mysqld 5886 5888 vagrant 14w REG 253,0 2549 72029565 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log mysqld 5886 5889 vagrant 14w REG 253,0 2549 72029565 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log mysqld 5886 5890 vagrant 14w REG 253,0 2549 72029565 /home/vagrant/sandboxes/msb_5_7_18/data/sandbox-slow.log ...