Issue PHP70-FPM ERROR: unable to read what child say: Bad file descriptor (9)

[Hassaan]

I am continuously receiving following errors in my `php-fpm` logs. I have read and tried some similar question available on serverfault.com but Issue does not resolved.


[11-Apr-2017 08:33:27] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 09:49:26] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 09:49:26] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 09:56:11] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 09:56:11] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:09:56] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:09:56] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:22:39] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:22:39] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:35:52] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:35:52] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:38:52] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:46:33] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:46:33] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:54:21] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:54:21] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 10:59:17] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:03:16] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:03:16] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:05:50] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:05:50] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:05:50] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:05:50] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:12:03] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:32:45] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:32:45] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:48:28] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:48:28] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:53:11] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:55:15] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 11:55:15] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 12:06:17] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 12:06:17] ERROR: unable to read what child say: Bad file descriptor (9)

My OS is CentOS7 and I am using `PHP7-FPM` with `nginx`

Server specification are below

Processor: Intel Xeon E5-1620v2

Sever Ram: 64GB DDR3

My current fpm configurations are below


pid = /run/plesk-php70-fpm.pid

error_log = /var/log/plesk-php70-fpm/error.log

log_level = error

emergency_restart_threshold = 10
emergency_restart_interval = 1m
process_control_timeout = 10s

listen.backlog = 65535

;[php-fpm-pool-settings]
pm = ondemand
pm.max_children = 2000
pm.process_idle_timeout = 10s
#pm.max_requests = 10000

#pm = dynamic
#pm.max_children = 5000
#pm.start_servers = 50
#pm.min_spare_servers = 20
#pm.max_spare_servers = 70
#pm.max_requests = 10000

I have tried `pm ondemand` & `pm dynamic` both

 

[IgorG]

Limit set by pm.max_children is reached.
pm.max_children should be increased.

 

[Hassaan]

Limit set by pm.max_children is reached.
pm.max_children should be increased.

Which should I use pm = ondemand or pm = dynamic

I don't have experience in tuning servers, can you recommend an optimized setting for me?

2nd question: I can check which domain is causing/reaching max_children ??

 

[IgorG]

I see this one:

pm.max_children = 2000

Try to increase it to 4000 for instance and check results.

 

[Bitpalast]

Which should I use pm = ondemand or pm = dynamic

dynamic
(leave everything unchanged, only raise the max children value)

I can check which domain is causing/reaching max_children ??

If a domain reaches the max_children setting, this is logged in the PHP FPM error log, e.g. /var/log/plesk-php56-fpm/error.log .

 

[Hassaan]

I see this one:

Try to increase it to 4000 for instance and check results.

Thank you for great response, I have changed to 4000 and regenerate PHP settings for all domains

Latest Logs

[11-Apr-2017 15:07:06] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:07:06] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:27:39] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:27:39] ERROR: unable to read what child say: Bad file descriptor (9)

 

[Bitpalast]

There are 20 minutes between the first an second two lines. This is o.k. and can be neglected. The bad file descriptor can have other reasons, too. It won't be possible to perfectly trace it down, there will always be some of these lines in the error log. It should not have any effect on the actual web content processing and delivery.

 

[Hassaan]

dynamic
(leave everything unchanged, only raise the max children value)


If a domain reaches the max_children setting, this is logged in the PHP FPM error log, e.g. /var/log/plesk-php56-fpm/error.log .

Thank you for great response.
I have raised the value of max children to 4000 but still see errors in logs.

As you mentioned I try to find max_children in logs but there is nothing like this

I run following command to find in logs

grep -i max_children /var/log/plesk-php70-fpm/error.log

 

[Hassaan]

There are 20 minutes between the first an second two lines. This is o.k. and can be neglected. The bad file descriptor can have other reasons, too. It won't be possible to perfectly trace it down, there will always be some of these lines in the error log. It should not have any effect on the actual web content processing and delivery.

Here are latest logs


[11-Apr-2017 15:07:06] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:07:06] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:27:39] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:27:39] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:39:35] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:39:35] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:43:42] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:43:42] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:56:26] ERROR: unable to read what child say: Bad file descriptor (9)
[11-Apr-2017 15:56:26] ERROR: unable to read what child say: Bad file descriptor (9)

 

[Hassaan]

There are 20 minutes between the first an second two lines. This is o.k. and can be neglected. The bad file descriptor can have other reasons, too. It won't be possible to perfectly trace it down, there will always be some of these lines in the error log. It should not have any effect on the actual web content processing and delivery.

I can Share other configs too, please let me know about it ...

 

[mizar]

Hello,

pm.max_children = 4000 is a rather big value, it means that site processing 4000 requests simultaneously - and it might be caused by inefficient database configuration (running mysqltuner.pl can provide recommendations for mysql settings). And if you using some CMS you might consider to enable some kind of caching plugins

 

[Hassaan]

Hello,

pm.max_children = 4000 is a rather big value, it means that site processing 4000 requests simultaneously - and it might be caused by inefficient database configuration (running mysqltuner.pl can provide recommendations for mysql settings). And if you using some CMS you might consider to enable some kind of caching plugins

Thank you so much for suggestions. I have run mysqltuner and logs are following


General recommendations:
Control warning line(s) into /var/log/mariadb/mariadb.log file
Control error line(s) into /var/log/mariadb/mariadb.log file
Restrict Host for user@% to user@SpecificDNSorIp
Enable the slow query log to troubleshoot bad queries
When making adjustments, make tmp_table_size/max_heap_table_size equal
Reduce your SELECT DISTINCT queries which have no LIMIT clause
Set thread_cache_size to 4 as a starting value
Performance shouldn't be activated for MySQL and MariaDB 5.5 and lower version
Consider installing Sys schema from GitHub - mysql/mysql-sys: The MySQL sys schema

Variables to adjust:
query_cache_type (=0)
sort_buffer_size (> 2M)
read_rnd_buffer_size (> 256K)
tmp_table_size (> 16M)
max_heap_table_size (> 16M)
thread_cache_size (start at 4)
performance_schema = OFF disable PFS
innodb_file_per_table=ON
innodb_log_file_size * innodb_log_files_in_group should be equals to 1/4 of buffer pool size (=64M) if possible.


My current my.cnf are below can to modify this as I am not expert and server is live in production, can you help me

[mysqld]

local-infile=0
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql

query_cache_limit=4M
query_cache_size=4000M
query_cache_type=1

symbolic-links=0

max_connections=2000

interactive_timeout=30
wait_timeout=30
connect_timeout=60

skip-name-resolve

 

[mizar]

IMHO, query_cache_size = 4000M is enormous size, generally it should be less the 128M.
I don't see the changes in innodb_buffer_pool_size modification, which is show amount of memory allocated by database server. Could you show result of query

First, you can count your database size by executing mysql query

SELECT CEILING(Total_InnoDB_Bytes*1.6/POWER(1024,3)) RIBPS FROM
(SELECT SUM(data_length+index_length) Total_InnoDB_Bytes
FROM information_schema.tables WHERE engine='InnoDB') A;

and the output of show engine innodb status query and the output of free -m command?

 

[Hassaan]

IMHO, query_cache_size = 4000M is enormous size, generally it should be less the 128M.
I don't see the changes in innodb_buffer_pool_size modification, which is show amount of memory allocated by database server. Could you show result of query

First, you can count your database size by executing mysql query

SELECT CEILING(Total_InnoDB_Bytes*1.6/POWER(1024,3)) RIBPS FROM
(SELECT SUM(data_length+index_length) Total_InnoDB_Bytes
FROM information_schema.tables WHERE engine='InnoDB') A;

and the output of show engine innodb status query and the output of free -m command?

Output of command is

MariaDB [(none)]> SELECT CEILING(Total_InnoDB_Bytes*1.6/POWER(1024,3)) RIBPS FROM
-> (SELECT SUM(data_length+index_length) Total_InnoDB_Bytes
-> FROM information_schema.tables WHERE engine='InnoDB') A;
+-------+
| RIBPS |
+-------+
| 1 |
+-------+
1 row in set (0.08 sec)


If have 64GB RAM in server so is this OK to have query_cache_size = 4000M ??

 

[mizar]

Quite strange, it seems you have a rather small local database, could you check that site which emit errors doesn't host database on remote database server?

> If have 64GB RAM in server so is this OK to have query_cache_size = 4000M ??
In general you should need 4G of memory cache, you can check cache usage by query

show status like 'Qc%'

Check the values Qcache_free_memory - which is reflect free memory of caching, and Qcache_lowmem_prunes (should be much greater the 0) - which is reflect queries which is not cached if you doesn't have a free memory

 

[Hassaan]

Quite strange, it seems you have a rather small local database, could you check that site which emit errors doesn't host database on remote database server?

Yes, all database are small not even cross 1GB in size. I have hosted multiple website but any from them does not have more then 3K visitors per day. No, I don't use remote database server.


Output of SHOW status LIKE 'Qc%';

MariaDB [(none)]> SHOW status LIKE 'Qc%';
+-------------------------+------------+
| Variable_name | Value |
+-------------------------+------------+
| Qcache_free_blocks | 14117 |
| Qcache_free_memory | 4017163376 |
| Qcache_hits | 319810 |
| Qcache_inserts | 588039 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 29911 |
| Qcache_queries_in_cache | 128483 |
| Qcache_total_blocks | 271345 |
+-------------------------+------------+
8 rows in set (0.00 sec)


My database server is (running) since Mon 2017-04-10 16:44:46 PKT; 1 day 5h ago.

I don't use CMS like wordpress etc, I am PHP developer and developed my own project and included cache with them. I use file cache, like once page is render then it will also save on disk and for specific time I do not render page again and use local file, saved on disk.

 

[Bitpalast]

pm.max_children = 4000 is a rather big value, it means that site processing 4000 requests simultaneously

I'd like to annotate that on Onyx 17.0 / CentOS 7.3 we had several severe issues with frequent web server and PHP-FPM outages when the pm.max_children value was lower. We have now raised it to a value much bigger than the 4000 that Hassaan is trying, and only since we've done that, things are working fine and smoothly. I'd rather leave it that high. If the system has enough RAM it can handle it. Anyway, probably not the issue here.

We are seeing occasional "bad file descriptor" entries on all systems with PHP-FPM. These can also be caused by the request_terminate_timeout value or simple permissions issues with files or log files. We have never observed any issues like 5xx errors for months so I'd not really invest too much time into the "bad file descriptor" issue when the number of logged events is low compared to the traffic on a server. Just my opinion, though.

 

[Hassaan]

"bad file descriptor" issue

"bad file descriptor" issue is not only issue I received, I received 499 errors in logs of some domain and high mysql load consumption.

Here I'm attaching mysqltuner Full logs, I hope it might help ...



>> MySQLTuner 1.7.1 - Major Hayden <[email protected]>
>> Bug reports, feature requests, and downloads at http://mysqltuner.com/
>> Run with '--help' for additional options and output filtering

[--] Skipped version check for MySQLTuner script
[OK] Currently running supported MySQL version 5.5.52-MariaDB
[OK] Operating on 64-bit architecture
-------- Log file Recommendations ------------------------------------------------------------------
[--] Log file: /var/log/mariadb/mariadb.log(93K)
[OK] Log file /var/log/mariadb/mariadb.log exists
[OK] Log file /var/log/mariadb/mariadb.log is readable.
[OK] Log file /var/log/mariadb/mariadb.log is not empty
[OK] Log file /var/log/mariadb/mariadb.log is smaller than 32 Mb
[!!] /var/log/mariadb/mariadb.log contains 319 warning(s).
[!!] /var/log/mariadb/mariadb.log contains 123 error(s).
[--] 20 start(s) detected in /var/log/mariadb/mariadb.log
[--] 1) 170410 16:44:45 [Note] /usr/libexec/mysqld: ready for connections.
[--] 2) 170410 0:42:15 [Note] /usr/libexec/mysqld: ready for connections.
[--] 3) 170409 4:22:32 [Note] /usr/libexec/mysqld: ready for connections.
[--] 4) 170404 2:15:22 [Note] /usr/libexec/mysqld: ready for connections.
[--] 5) 170331 17:00:48 [Note] /usr/libexec/mysqld: ready for connections.
[--] 6) 170328 19:56:06 [Note] /usr/libexec/mysqld: ready for connections.
[--] 7) 170328 19:45:06 [Note] /usr/libexec/mysqld: ready for connections.
[--] 8) 170322 17:00:00 [Note] /usr/libexec/mysqld: ready for connections.
[--] 9) 170321 11:32:53 [Note] /usr/libexec/mysqld: ready for connections.
[--] 10) 170317 15:53:34 [Note] /usr/libexec/mysqld: ready for connections.
[--] 34 shutdown(s) detected in /var/log/mariadb/mariadb.log
[--] 1) 170410 16:44:43 [Note] /usr/libexec/mysqld: Shutdown complete
[--] 2) 170410 0:42:14 [Note] /usr/libexec/mysqld: Shutdown complete
[--] 3) 170409 4:21:51 [Note] /usr/libexec/mysqld: Shutdown complete
[--] 4) 170409 4:21:35 [Note] /usr/libexec/mysqld: Shutdown complete
[--] 5) 170409 4:18:33 [Note] /usr/libexec/mysqld: Shutdown complete
[--] 6) 170409 4:18:31 [Note] /usr/libexec/mysqld: Shutdown complete
[--] 7) 170404 2:15:20 [Note] /usr/libexec/mysqld: Shutdown complete
[--] 8) 170331 17:00:47 [Note] /usr/libexec/mysqld: Shutdown complete
[--] 9) 170328 19:56:05 [Note] /usr/libexec/mysqld: Shutdown complete
[--] 10) 170328 19:45:04 [Note] /usr/libexec/mysqld: Shutdown complete
-------- Storage Engine Statistics -----------------------------------------------------------------
[--] Status: +ARCHIVE +Aria +BLACKHOLE +CSV +FEDERATED +InnoDB +MEMORY +MRG_MYISAM +MyISAM +PERFORMANCE_SCHEMA
[--] Data in MyISAM tables: 609M (Tables: 37)
[--] Data in InnoDB tables: 70M (Tables: 391)
[OK] Total fragmented tables: 0
-------- Security Recommendations ------------------------------------------------------------------
[OK] There are no anonymous accounts for any database users
[OK] All database users have passwords assigned
[!!] User 'dmfil*****@%' hasn't specific host restriction.
[!!] User 'mp3fu*****@%' hasn't specific host restriction.
[!!] User 'mp4son*****@%' hasn't specific host restriction.
[!!] User 'pkn*****@%' hasn't specific host restriction.
[!!] User 'playh*****@%' hasn't specific host restriction.
[!!] User 'playhd*****@%' hasn't specific host restriction.
[!!] User 'post_on_fb@%' hasn't specific host restriction.
[!!] User 'songspk*****@%' hasn't specific host restriction.
[!!] User 'webext*****@%' hasn't specific host restriction.
[!!] User 'ytfi*****@%' hasn't specific host restriction.
[!!] There is no basic password file list!
-------- CVE Security Recommendations --------------------------------------------------------------
[--] Skipped due to --cvefile option undefined
-------- Performance Metrics -----------------------------------------------------------------------
[--] Up for: 1d 7h 56m 18s (3M q [30.465 qps], 992K conn, TX: 1G, RX: 521M)
[--] Reads / Writes: 58% / 42%
[--] Binary logging is disabled
[--] Physical Memory : 62.9G
[--] Max MySQL memory : 9.7G
[--] Other process memory: 1.4G
[--] Total buffers: 4.3G global + 2.8M per thread (2000 max threads)
[--] P_S Max memory usage: 0B
[--] Galera GCache Max memory usage: 0B
[OK] Maximum reached memory usage: 4.4G (6.95% of installed RAM)
[OK] Maximum possible memory usage: 9.7G (15.48% of installed RAM)
[OK] Overall possible memory usage with other process is compatible with memory available
[OK] Slow queries: 0% (0/3M)
[OK] Highest usage of available connections: 1% (23/2000)
[OK] Aborted connections: 0.09% (887/992739)
[!!] Query cache may be disabled by default due to mutex contention.
[OK] Query cache efficiency: 25.7% (347K cached / 1M selects)
[OK] Query cache prunes per day: 0
[!!] Sorts requiring temporary tables: 166% (346K temp sorts / 208K sorts)
[OK] No joins without indexes
[!!] Temporary tables created on disk: 56% (25K on disk / 45K total)
[!!] Thread cache is disabled
[!!] Table cache hit rate: 11% (400 open / 3K opened)
[OK] Open file limit used: 13% (141/1K)
[OK] Table locks acquired immediately: 99% (1M immediate / 1M locks)
-------- Performance schema ------------------------------------------------------------------------
[--] Performance schema is disabled.
[--] Memory used by P_S: 0B
[--] Sys schema isn't installed.
-------- ThreadPool Metrics ------------------------------------------------------------------------
[--] ThreadPool stat is enabled.
[--] Thread Pool Size: 8 thread(s).
[--] Using default value is good enough for your version (5.5.52-MariaDB)
-------- MyISAM Metrics ----------------------------------------------------------------------------
[!!] Key buffer used: 50.9% (68M used / 134M cache)
[OK] Key buffer size / total MyISAM indexes: 128.0M/94.4M
[OK] Read Key buffer hit rate: 99.8% (59M cached / 132K reads)
[!!] Write Key buffer hit rate: 88.9% (1M cached / 1M writes)
-------- InnoDB Metrics ----------------------------------------------------------------------------
[--] InnoDB is enabled.
[--] InnoDB Thread Concurrency: 0
[!!] InnoDB File per table is not activated
[OK] InnoDB buffer pool / data size: 128.0M/70.4M
[!!] Ratio InnoDB log file size / InnoDB Buffer pool size (7.8125 %): 5.0M * 2/128.0M should be equal 25%
[OK] InnoDB buffer pool instances: 1
[--] InnoDB Buffer Pool Chunk Size not used or defined in your version
[OK] InnoDB Read buffer efficiency: 100.00% (5066453838 hits/ 5066456565 total)
[!!] InnoDB Write Log efficiency: 37.45% (4086 hits/ 10912 total)
[OK] InnoDB log waits: 0.00% (0 waits / 14998 writes)
-------- AriaDB Metrics ----------------------------------------------------------------------------
[--] AriaDB is enabled.
[OK] Aria pagecache size / total Aria indexes: 128.0M/1B
[OK] Aria pagecache hit rate: 100.0% (303M cached / 13K reads)
-------- TokuDB Metrics ----------------------------------------------------------------------------
[--] TokuDB is disabled.
-------- XtraDB Metrics ----------------------------------------------------------------------------
[--] XtraDB is disabled.
-------- RocksDB Metrics ---------------------------------------------------------------------------
[--] RocksDB is disabled.
-------- Spider Metrics ----------------------------------------------------------------------------
[--] Spider is disabled.
-------- Connect Metrics ---------------------------------------------------------------------------
[--] Connect is disabled.
-------- Galera Metrics ----------------------------------------------------------------------------
[--] Galera is disabled.
-------- Replication Metrics -----------------------------------------------------------------------
[--] Galera Synchronous replication: NO
[--] No replication slave(s) for this server.
[--] This is a standalone server.
-------- Recommendations ---------------------------------------------------------------------------
General recommendations:
Control warning line(s) into /var/log/mariadb/mariadb.log file
Control error line(s) into /var/log/mariadb/mariadb.log file
Restrict Host for user@% to user@SpecificDNSorIp
Enable the slow query log to troubleshoot bad queries
When making adjustments, make tmp_table_size/max_heap_table_size equal
Reduce your SELECT DISTINCT queries which have no LIMIT clause
Set thread_cache_size to 4 as a starting value
Increase table_open_cache gradually to avoid file descriptor limits
Read this before increasing table_open_cache over 64: table_cache negative scalability
Beware that open_files_limit (1024) variable
should be greater than table_open_cache (400)
Performance shouldn't be activated for MySQL and MariaDB 5.5 and lower version
Consider installing Sys schema from GitHub - mysql/mysql-sys: The MySQL sys schema
Variables to adjust:
query_cache_type (=0)
sort_buffer_size (> 2M)
read_rnd_buffer_size (> 256K)
tmp_table_size (> 16M)
max_heap_table_size (> 16M)
thread_cache_size (start at 4)
table_open_cache (> 400)
performance_schema = OFF disable PFS
innodb_file_per_table=ON
innodb_log_file_size * innodb_log_files_in_group should be equals to 1/4 of buffer pool size (=64M) if possible.

 

[mizar]

Hello,

Doesn't see any big problems here.
Did you plan to enable slow query log - to check what queries are running a lot of time

 

[B4c4rd1]

dynamic

Why dynamic?