MySQL Bugs: #82870: mysqld opens too many descriptors for slow query log

Bug #82870	mysqld opens too many descriptors for slow query log
Submitted:	6 Sep 2016 10:07	Modified:	12 Jan 2018 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:		CPU Architecture:	Any
Tags:	(no regression here)

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.

FLUSH SLOW LOGS seems to be not working

General query log affected as well. With log_output='table' things get even worse: descriptor created for each thread running and not closed after.

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.

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.

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.

Console output that shows that bug is repeated

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

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.

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';

Sinisa, sorry, missed your comment.

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

Posted by developer:
 
Added a note "Log Tables and “Too many open files” Errors" here:
https://dev.mysql.com/doc/refman/8.0/en/log-destinations.html

Also added a cross reference to that note here:
https://dev.mysql.com/doc/refman/8.0/en/query-log.html
https://dev.mysql.com/doc/refman/8.0/en/slow-query-log.html