0

This Apache/MySQL server (Debian 8) running a Drupal site shows a strange behaviour:

There's always one Apache process running with 100% CPU utilization (according to htop). Every four minutes (~240 seconds), the process terminates and immediately another Apache process jumps to the top with 100% CPU utilization - for another four minutes.

Looking at Apache's error log, the terminated process is listed with an PHP Fatal error "Maximum execution time of 240 seconds exceeded":

[:error] [pid 31280] [client 185.17.206.72:55628] PHP Fatal error: Maximum execution time of 240 seconds exceeded in /var/www/drupal/modules/field/field.attach.inc on line 328

This pattern continues through the business times. During the night, when there are less visitors on the site, the error message comes up less frequent.

The system has five cores (a VM) and is running Apache 2.4, PHP 5.6, Percona 5.6 and Drupal 7. I ran MySQL with slow query log, but there are no slow queries that match with these frequent PHP timeouts.

I ran strace on a few Apache processes working with 100% CPU utilization, but found nothing very prominent: The process halts on a poll every few moments, for a couple of seconds. But that seems to be the normal behaviour.

There's no lack of DB connections (according to e.g. mysqltuner and tuningprimer).

Looking at the requests that correspond to these timeouts (I used a log format with PID and the time taken to finish the requests: LogFormat "%h %l %u %t %>s %D %P \"%r\" %b" exectime), I see no pattern: It happens for various different requests and these are requests that normally finish in 1s and less.

I just wonder what's going on with these consecutive PHP errors and how I could get a grip of them. Any ideas on how to further analyze this?

ThoriumBR
  • 5,302
  • 2
  • 24
  • 34
flight
  • 394
  • 4
  • 14
  • You should look at the request parameters in your Apache log and try to run it yourself to figure out what is happening. If it's not obvious, add a debug argument with traces in the code to clarify what is happening. – Julie Pelletier Jun 06 '16 at 16:19
  • Yep, forgot to mention: There's no clear pattern visible in the requests that correspond to the timeouts according to the access log. It's happening for various different requests and these are requests that normally finish in 1s and less. – flight Jun 06 '16 at 16:50
  • If that's the case, I'm wondering if you don't have some cases where you have lock problems. Some scripts simply do something like `while (!getLock())` which would run at 100% CPU. – Julie Pelletier Jun 07 '16 at 03:49

0 Answers0