Bug #82870 mysqld opens too many descriptors for slow query log
Submitted: 6 Sep 2016 10:07 Modified: 12 Jan 20:01
Reporter: Sveta Smirnova (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.7.14 OS:Any
Assigned to:
Tags: (no regression here)

[6 Sep 2016 10:07] Sveta Smirnova
Description:
mysqld opens too many descriptors for slow query log if I turn it ON and OFF while concurrent environment is running.

Behavior is not repeatable with version 5.6

How to repeat:
1. Start MTR:

./mtr --start innodb &

2. CREATE DATABASE sbtest;
3. sysbench --test=/home/sveta/src/sysbench/sysbench/tests/db/oltp.lua --mysql-engine-trx=yes --mysql-table-engine=innodb --oltp_table_size=1000 --oltp_tables_count=1 --mysql-user=root --mysql-host=127.0.0.1 --mysql-port=13000 --num-threads=8 prepare
 (Replace path to oltp.lua to correct on your machine)
4. mysql> set global log_output='file';
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 long_query_time=0;
Query OK, 0 rows affected (0,00 sec)

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

5. Check what you have only 3 descriptors so far:

sveta@Thinkie:~/Lessons/R/stepic-base$ lsof -p 18972 | grep slow
mysqld  18972 sveta   15u   REG               0,43        35 35139893 /home/sveta/build/mysql-5.7/mysql-test/var/mysqld.1/data/mysql/slow_log.CSM
mysqld  18972 sveta   50r   REG               0,43         0 35139868 /home/sveta/build/mysql-5.7/mysql-test/var/mysqld.1/data/mysql/slow_log.CSV
mysqld  18972 sveta   51w   REG               0,43   2240609 35139921 /home/sveta/build/mysql-5.7/mysql-test/var/mysqld.1/mysqld-slow.log

6. Run concurrent environment:

sysbench --test=/home/sveta/src/sysbench/sysbench/tests/db/oltp.lua --mysql-engine-trx=yes --mysql-table-engine=innodb --oltp_table_size=1000 --oltp_tables_count=1 --mysql-user=root --mysql-host=127.0.0.1 --mysql-port=13000 --num-threads=8 --max-requests=1000 run

7. Turn OFF and ON slow log:

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

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

8. Now you have 4 descriptors:

sveta@Thinkie:~/Lessons/R/stepic-base$ lsof -p 18972 | grep slow
mysqld  18972 sveta   15u   REG               0,43        35 35139893 /home/sveta/build/mysql-5.7/mysql-test/var/mysqld.1/data/mysql/slow_log.CSM
mysqld  18972 sveta   50r   REG               0,43         0 35139868 /home/sveta/build/mysql-5.7/mysql-test/var/mysqld.1/data/mysql/slow_log.CSV
mysqld  18972 sveta   51r   REG               0,43         0 35139868 /home/sveta/build/mysql-5.7/mysql-test/var/mysqld.1/data/mysql/slow_log.CSV
mysqld  18972 sveta   52w   REG               0,43  14143997 35139921 /home/sveta/build/mysql-5.7/mysql-test/var/mysqld.1/mysqld-slow.log

9. Repeat steps 6-8 until you get "Too many files" error

My customer observed same behavior, but duplicate entry created for mysqld-slow.log, not for slow_log.CSV

Workaround: Stop slow query log, then, if you see many open slow_log.CSV run FLUSH TABLES, and if many mysqld-slow.log run FLUSH SLOW LOGS

Suggested fix:
Do not keep so many file descriptors open.
[7 Sep 2016 9:32] Sveta Smirnova
FLUSH SLOW LOGS seems to be not working
[7 Sep 2016 10:03] Sveta Smirnova
General query log affected as well. With log_output='table' things get even worse: descriptor created for each thread running and not closed after.
[7 Sep 2016 14:36] Sinisa Milivojevic
Sveta, 

Thank you for your bug report. I have two questions before I attempt to reproduce your test case:

* Did you use our standard built binary, without any patches ???

* Is oltp.lua available with sysbench and if yes, did you use it unchanged ???

Thanks in advance.
[7 Sep 2016 18:10] Sveta Smirnova
Hi Sinisa,

yes and yes. Otherwise I'd mentioned it ;)

Btw version of sysbench is 0.5 or 1.0 available from https://github.com/akopytov/sysbench And you can use any lua script which runs queries. What it does does not matter, number of parallel threads matters.
[12 Sep 2016 15:27] Sinisa Milivojevic
Hi Sveta,

I have been able to repeat the bug with a pretty complex setup that you have provided. The output is in the file attached.
[12 Sep 2016 15:27] Sinisa Milivojevic
Console output that shows that bug is repeated

Attachment: output.bug (application/octet-stream, text), 15.13 KiB.

[22 Feb 2017 15:09] Sinisa Milivojevic
Hi Sveta,

We managed to reproduce the case when our server open too many file descriptors. We were not able to reproduce "Too many files" error. Hence, can you send us your configuration.

Is it possible that you might have set the value of 'open_files_limit' lesser
than that of 'table_open_cache_instances' ??? If that is the case then there is no need of sending us your config.
[12 Jan 19:59] Vinicius Malvestio Grippa
This bug is also reproducible in MySQL 5.6.28-76.1-log.

I've used the steps that Sveta provided, changing step 4:

4. mysql> set global log_output='table';
[12 Jan 20:01] Sveta Smirnova
Sinisa, sorry, missed your comment.

I do not use any special options, just start mysqld using MySQL Test Framework. It sets everything.