Topic: php-fpm 100% CPU with SMF

[sah62]

I'm running SMF 2.0.15 on a virtual machine hosted by Linode running Ubuntu 18.04.3 LTS. My web server is nginx 1.14, PHP version 7.2 (yes, I know it's not officially supported). Last night Linode did some kind of kernel maintenance on my host. After they rebooted the server, nginx and php-fpm installation started consuming 100% of available CPU by spawning multiple php-fpm child processes. It turns out that those processes were associated with connections to my forum. Here's a slice of what I see in my php-fpm slow processing log (set to capture requests taking > 10 seconds to process):

Code: [Select]

[17-Oct-2019 14:38:58]  [pool www] pid 25703
script_filename = /var/www/forum/index.php
[0x00007f3deaa1b7a0] preg_split() /var/www/forum/Sources/Load.php:262
[0x00007f3deaa1b6a0] {closure}() /var/www/forum/Sources/News.php:432
[0x00007f3deaa1b550] cdata_parse() /var/www/forum/Sources/News.php:784
[0x00007f3deaa1b3b0] getXmlRecent() /var/www/forum/Sources/News.php:237
[0x00007f3deaa1b170] ShowXmlFeed() /var/www/forum/index.php:170

[17-Oct-2019 14:39:18]  [pool www] pid 25707
script_filename = /var/www/forum/index.php
[0x00007f3deaa1b7d0] preg_split() /var/www/forum/Sources/Load.php:239
[0x00007f3deaa1b6a0] {closure}() /var/www/forum/Sources/News.php:398
[0x00007f3deaa1b550] cdata_parse() /var/www/forum/Sources/News.php:784
[0x00007f3deaa1b3b0] getXmlRecent() /var/www/forum/Sources/News.php:237
[0x00007f3deaa1b170] ShowXmlFeed() /var/www/forum/index.php:170

[17-Oct-2019 14:39:31]  [pool www] pid 25712
script_filename = /var/www/forum/index.php
[0x00007f3deaa1b7a0] preg_split() /var/www/forum/Sources/Load.php:262
[0x00007f3deaa1b6a0] {closure}() /var/www/forum/Sources/News.php:432
[0x00007f3deaa1b550] cdata_parse() /var/www/forum/Sources/News.php:784
[0x00007f3deaa1b3b0] getXmlRecent() /var/www/forum/Sources/News.php:237
[0x00007f3deaa1b170] ShowXmlFeed() /var/www/forum/index.php:170

[17-Oct-2019 14:39:55]  [pool www] pid 25715
script_filename = /var/www/forum/index.php
[0x00007f3deaa1b7d0] array_search() /var/www/forum/Sources/Load.php:242
[0x00007f3deaa1b6a0] {closure}() /var/www/forum/Sources/News.php:397
[0x00007f3deaa1b550] cdata_parse() /var/www/forum/Sources/News.php:784
[0x00007f3deaa1b3b0] getXmlRecent() /var/www/forum/Sources/News.php:237
[0x00007f3deaa1b170] ShowXmlFeed() /var/www/forum/index.php:170

Here's the code from Load.php:

Code: [Select]

237                 'strpos' => function($haystack, $needle, $offset = 0) use ($utf8, &$ent_check, &$ent_list, $modSettings)
 238                 {
 239                         $haystack_arr = preg_split('~(' . $ent_list . '|.)~' . ($utf8 ? 'u' : ''), $ent_check($haystack), -1, PREG_SPLI     T_DELIM_CAPTURE | PREG_SPLIT_NO_EMPTY);
 240                         if (strlen($needle) === 1)
 241                         {
 242                                 $result = array_search($needle, array_slice($haystack_arr, $offset));
 243                                 return is_int($result) ? $result + $offset : false;
 244                         }
 245                         else
 246                         {
 247                                 $needle_arr = preg_split('~(' . $ent_list . '|.)~' . ($utf8 ? 'u' : '') . '', $ent_check($needle), -1,      PREG_SPLIT_DELIM_CAPTURE | PREG_SPLIT_NO_EMPTY);
 248                                 $needle_size = count($needle_arr);
 249                                 $result = array_search($needle_arr[0], array_slice($haystack_arr, $offset));
 250                                 while ((int) $result === $result)
 251                                 {
 252                                         $offset += $result;
 253                                         if (array_slice($haystack_arr, $offset, $needle_size) === $needle_arr)
 254                                                 return $offset;
 255                                         $result = array_search($needle_arr[0], array_slice($haystack_arr, ++$offset));
 256                                 }
 257                                 return false;
 258                         }
 259                 },
 260                 'substr' => function($string, $start, $length = null) use ($utf8, &$ent_check, &$ent_list, $modSettings)
 261                 {
 262                         $ent_arr = preg_split('~(&#' . (empty($modSettings['disableEntityCheck']) ? '\d{1,7}' : '021') . ';|"|&amp     ;|<|>| |.)~' . ($utf8 ? 'u' : ''), $ent_check($string), -1, PREG_SPLIT_DELIM_CAPTURE | PREG_SPLIT_NO_EMPTY);
 263                         return $length === null ? implode('', array_slice($ent_arr, $start)) : implode('', array_slice($ent_arr, $start     , $length));
 264                 },

Can anyone help point me in the right direction to figure out what's going on here? I have multiple Drupal web sites running on this server without any issues. It's just this instance of SMF that's unhappy with something. The SMF installation is in a subdirectory of the root of one of my Drupal sites since I use the SMF forum as one of the services provided from this site.

[Arantor]

Well, spawning multiple PHP-FPM processes would be normal; you spin up a pool of PHP interpreters and leave them on to serve your site when requests happen (so that you don't have to load the PHP interpreter every time)

Is this the only instance using PHP-FPM? The code in question is part of the RSS feed support; I'd wonder if you're being hammered and didn't notice it before but do now because you were actively looking?

[sah62]

I use PHP-FPM for 3 other sites on the same server. Each has it's own pool. I have the site in maintenance mode right now and the CPU situation is under control, but my users won't be very happy about that for long.

It's not the multiple processes I'm concerned about. I understand that's normal. What's concerning is that the processes for this one pool are consuming all of the available CPU to the detriment of everything else that's running on the server. The CPU load didn't spike until after the server was rebooted. I watch it pretty closely and haven't seen this before. When I count the unique IP addresses that appear in my nginx access log, these appear at the top (count followed by IP address):

Code: [Select]

331 40.77.167.53
310 207.46.13.45
309 40.77.167.48
281 40.77.167.51
277 40.77.167.40
249 157.55.39.159
236 207.46.13.76
174 216.244.66.229
161 157.55.39.136

All crawlers, and all but one of those addresses are in space owned by Microsoft. I could add each of those addresses to my firewall to block them, but is that the best thing to do?

[Arantor]

That does somewhat suggest there is a configuration problem if it only happened after the reboot, but I'd still wonder how frequently those IPs are hitting the server? Actual numbers of hits per second would be interesting data.

[sah62]

Are there any configuration parameters in particular that I should look at? I'm not really sure how to measure requests/second.

[sah62]

For what it's worth, turning off "Enable XML/RSS news" seems to be helping things stay under control. At least I've been able to bring my forum back online without pegging the CPUs at 100%.

[vbgamer45]

Could be due to Bing bot. I sometimes see that very aggressive.

[sah62]

I use Munin to monitor this server. I've enabled the plugins for nginx, so now I have a view into connections and requests/second. It's not that helpful right now since the load is under control, but it'll be useful if I turn "Enable XML/RSS news" back on and the issue returns. Thanks for the help.