#109 High CPU usage with php-fpm and GNUSocial

Closed
opened 4 years ago by aab · 2 comments
aab commented 4 years ago

I'm seeing a php-fpm high cpu usage in gnusocial.net, which causes a daily block of the server. I've been using different values in /etc/php/7.3/fpm/pool.d/www.conf with no luck; anyways, these are the ones i'm using now:

[code] pm = ondemand pm.max_children = 200 pm.start_servers = 120 pm.min_spare_servers = 80 pm.max_spare_servers = 160 pm.max_requests = 500 [/code]

To get more info about the cpu peaks, i've enabled "slowlog" with

[code] slowlog = /var/log/$pool.log.slow request_slowlog_timeout = 10 (seconds) [/code]

so any request using more than 10 seconds to complete is logged. Just after enabling it, i get this:

[code] [07-Feb-2020 11:40:25] [pool www] pid 6249 script_filename = /var/www/gnusocial/public/index.php [0x00007f7feea1e9d0] imagecopy() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:148 [0x00007f7feea1e920] gdResourceToTruecolor() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:70 [0x00007f7feea1e850] initFromPath() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDecoder.php:339 [0x00007f7feea1e7e0] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDriver.php:66 [0x00007f7feea1e770] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManager.php:54 [0x00007f7feea1e700] make() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManagerStatic.php:58 [0x00007f7feea1e690] make() /var/www/gnusocial/lib/media/imagefile.php:65 [0x00007f7feea1e5b0] __construct() /var/www/gnusocial/lib/media/imagefile.php:160 [0x00007f7feea1e4f0] fromFileObject() /var/www/gnusocial/classes/File.php:570 [0x00007f7feea1e410] getThumbnail() /var/www/gnusocial/plugins/SensitiveContent/SensitiveContentPlugin.php:165 [0x00007f7feea1e270] onStartShowAttachmentRepresentation() /var/www/gnusocial/lib/util/event.php:89 [0x00007f7feea1e1c0] handle() /var/www/gnusocial/lib/media/attachmentlistitem.php:108 [0x00007f7feea1e0e0] showRepresentation() /var/www/gnusocial/lib/media/attachmentlistitem.php:102 [0x00007f7feea1e090] showNoticeAttachment() /var/www/gnusocial/lib/media/attachmentlistitem.php:85 [0x00007f7feea1e020] show() /var/www/gnusocial/lib/media/attachmentlist.php:99 [0x00007f7feea1df50] show() /var/www/gnusocial/lib/notices/noticelistitem.php:403 [0x00007f7feea1ded0] showNoticeAttachments() /var/www/gnusocial/lib/notices/noticelistitem.php:177 [0x00007f7feea1de70] showNoticeFooter() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:630 [0x00007f7feea1de10] showNoticeListItem() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:616 [0x00007f7feea1dd60] onStartShowNoticeItem() /var/www/gnusocial/lib/util/event.php:89

[07-Feb-2020 11:40:28] [pool www] pid 6111 script_filename = /var/www/gnusocial/public/index.php [0x00007f7feea1e930] imagecopy() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:148 [0x00007f7feea1e880] gdResourceToTruecolor() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:70 [0x00007f7feea1e7b0] initFromPath() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDecoder.php:339 [0x00007f7feea1e740] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDriver.php:66 [0x00007f7feea1e6d0] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManager.php:54 [0x00007f7feea1e660] make() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManagerStatic.php:58 [0x00007f7feea1e5f0] make() /var/www/gnusocial/lib/media/imagefile.php:65 [0x00007f7feea1e510] __construct() /var/www/gnusocial/lib/media/imagefile.php:160 [0x00007f7feea1e450] fromFileObject() /var/www/gnusocial/classes/File.php:570 [0x00007f7feea1e370] getThumbnail() /var/www/gnusocial/plugins/Embed/EmbedPlugin.php:312 [0x00007f7feea1e270] onStartShowAttachmentRepresentation() /var/www/gnusocial/lib/util/event.php:89 [0x00007f7feea1e1c0] handle() /var/www/gnusocial/lib/media/attachmentlistitem.php:108 [0x00007f7feea1e0e0] showRepresentation() /var/www/gnusocial/lib/media/attachmentlistitem.php:102 [0x00007f7feea1e090] showNoticeAttachment() /var/www/gnusocial/lib/media/attachmentlistitem.php:85 [0x00007f7feea1e020] show() /var/www/gnusocial/lib/media/attachmentlist.php:99 [0x00007f7feea1df50] show() /var/www/gnusocial/lib/notices/noticelistitem.php:403 [0x00007f7feea1ded0] showNoticeAttachments() /var/www/gnusocial/lib/notices/noticelistitem.php:177 [0x00007f7feea1de70] showNoticeFooter() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:630 [0x00007f7feea1de10] showNoticeListItem() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:616 [0x00007f7feea1dd60] onStartShowNoticeItem() /var/www/gnusocial/lib/util/event.php:89

[07-Feb-2020 11:40:28] [pool www] pid 6231 script_filename = /var/www/gnusocial/public/index.php [0x00007f7feea1e930] imagecreatetruecolor() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:138 [0x00007f7feea1e880] gdResourceToTruecolor() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:70 [0x00007f7feea1e7b0] initFromPath() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDecoder.php:339 [0x00007f7feea1e740] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDriver.php:66 [0x00007f7feea1e6d0] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManager.php:54 [0x00007f7feea1e660] make() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManagerStatic.php:58 [0x00007f7feea1e5f0] make() /var/www/gnusocial/lib/media/imagefile.php:65 [0x00007f7feea1e510] __construct() /var/www/gnusocial/lib/media/imagefile.php:160 [0x00007f7feea1e450] fromFileObject() /var/www/gnusocial/classes/File.php:570 [0x00007f7feea1e370] getThumbnail() /var/www/gnusocial/plugins/Embed/EmbedPlugin.php:312 [0x00007f7feea1e270] onStartShowAttachmentRepresentation() /var/www/gnusocial/lib/util/event.php:89 [0x00007f7feea1e1c0] handle() /var/www/gnusocial/lib/media/attachmentlistitem.php:108 [0x00007f7feea1e0e0] showRepresentation() /var/www/gnusocial/lib/media/attachmentlistitem.php:102 [0x00007f7feea1e090] showNoticeAttachment() /var/www/gnusocial/lib/media/attachmentlistitem.php:85 [0x00007f7feea1e020] show() /var/www/gnusocial/lib/media/attachmentlist.php:99 [0x00007f7feea1df50] show() /var/www/gnusocial/lib/notices/noticelistitem.php:403 [0x00007f7feea1ded0] showNoticeAttachments() /var/www/gnusocial/lib/notices/noticelistitem.php:177 [0x00007f7feea1de70] showNoticeFooter() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:630 [0x00007f7feea1de10] showNoticeListItem() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:616 [0x00007f7feea1dd60] onStartShowNoticeItem() /var/www/gnusocial/lib/util/event.php:89

[07-Feb-2020 11:40:38] [pool www] pid 6243 script_filename = /var/www/gnusocial/public/index.php [0x00007f7feea1e2b0] mysqli_query() /var/www/gnusocial/extlib/DB/mysqli.php:409 [0x00007f7feea1e210] simpleQuery() /var/www/gnusocial/extlib/DB/common.php:1333 [0x00007f7feea1e140] query() /var/www/gnusocial/extlib/DB/DataObject.php:1594 [0x00007f7feea1e000] _query() /var/www/gnusocial/classes/Memcached_DataObject.php:674 [0x00007f7feea1df00] _query() /var/www/gnusocial/extlib/DB/DataObject.php:3135 [0x00007f7feea1de90] query() /var/www/gnusocial/classes/Memcached_DataObject.php:642 [0x00007f7feea1dd80] cachedQuery() /var/www/gnusocial/plugins/TagCloud/lib/personaltagcloudsection.php:68 [0x00007f7feea1dcd0] getTags() /var/www/gnusocial/plugins/TagCloud/lib/tagcloudsection.php:52 [0x00007f7feea1dbf0] showContent() /var/www/gnusocial/lib/ui/section.php:62 [0x00007f7feea1db70] show() /var/www/gnusocial/plugins/TagCloud/TagCloudPlugin.php:70 [0x00007f7feea1dad0] onEndShowSections() /var/www/gnusocial/lib/util/event.php:89 [0x00007f7feea1da20] handle() /var/www/gnusocial/lib/action/action.php:1212 [0x00007f7feea1d9b0] showAside() /var/www/gnusocial/lib/action/action.php:1004 [0x00007f7feea1d940] showCore() /var/www/gnusocial/lib/action/action.php:837 [0x00007f7feea1d8c0] showBody() /var/www/gnusocial/lib/action/action.php:545 [0x00007f7feea1d850] showPage() /var/www/gnusocial/lib/util/managedaction.php:64 [0x00007f7feea1d7e0] handle() /var/www/gnusocial/lib/action/action.php:186 [0x00007f7feea1d720] execute() /var/www/gnusocial/lib/action/action.php:88 [0x00007f7feea1d660] run() /var/www/gnusocial/public/index.php:338 [0x00007f7feea1d100] main() /var/www/gnusocial/public/index.php:341 [/code]

On one hand, I'm not sure if 10 seconds is enough to complete the requests.

On the other, the server is a VPS with a quad-core and 16 GB of RAM (never above 3 GB of use); GNUSocial is the only web service installed; i guess it should be more than enough for managing around 300 accounts.

Is this a bad config of my php-fpm, or is it because of the slowness of the requests?

Please, let me know if there's anything i can do to further debug the problem.

I'm seeing a php-fpm high cpu usage in gnusocial.net, which causes a daily block of the server. I've been using different values in /etc/php/7.3/fpm/pool.d/www.conf with no luck; anyways, these are the ones i'm using now: [code] pm = ondemand pm.max_children = 200 pm.start_servers = 120 pm.min_spare_servers = 80 pm.max_spare_servers = 160 pm.max_requests = 500 [/code] To get more info about the cpu peaks, i've enabled "slowlog" with [code] slowlog = /var/log/$pool.log.slow request_slowlog_timeout = 10 (seconds) [/code] so any request using more than 10 seconds to complete is logged. Just after enabling it, i get this: [code] [07-Feb-2020 11:40:25] [pool www] pid 6249 script_filename = /var/www/gnusocial/public/index.php [0x00007f7feea1e9d0] imagecopy() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:148 [0x00007f7feea1e920] gdResourceToTruecolor() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:70 [0x00007f7feea1e850] initFromPath() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDecoder.php:339 [0x00007f7feea1e7e0] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDriver.php:66 [0x00007f7feea1e770] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManager.php:54 [0x00007f7feea1e700] make() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManagerStatic.php:58 [0x00007f7feea1e690] make() /var/www/gnusocial/lib/media/imagefile.php:65 [0x00007f7feea1e5b0] __construct() /var/www/gnusocial/lib/media/imagefile.php:160 [0x00007f7feea1e4f0] fromFileObject() /var/www/gnusocial/classes/File.php:570 [0x00007f7feea1e410] getThumbnail() /var/www/gnusocial/plugins/SensitiveContent/SensitiveContentPlugin.php:165 [0x00007f7feea1e270] onStartShowAttachmentRepresentation() /var/www/gnusocial/lib/util/event.php:89 [0x00007f7feea1e1c0] handle() /var/www/gnusocial/lib/media/attachmentlistitem.php:108 [0x00007f7feea1e0e0] showRepresentation() /var/www/gnusocial/lib/media/attachmentlistitem.php:102 [0x00007f7feea1e090] showNoticeAttachment() /var/www/gnusocial/lib/media/attachmentlistitem.php:85 [0x00007f7feea1e020] show() /var/www/gnusocial/lib/media/attachmentlist.php:99 [0x00007f7feea1df50] show() /var/www/gnusocial/lib/notices/noticelistitem.php:403 [0x00007f7feea1ded0] showNoticeAttachments() /var/www/gnusocial/lib/notices/noticelistitem.php:177 [0x00007f7feea1de70] showNoticeFooter() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:630 [0x00007f7feea1de10] showNoticeListItem() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:616 [0x00007f7feea1dd60] onStartShowNoticeItem() /var/www/gnusocial/lib/util/event.php:89 [07-Feb-2020 11:40:28] [pool www] pid 6111 script_filename = /var/www/gnusocial/public/index.php [0x00007f7feea1e930] imagecopy() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:148 [0x00007f7feea1e880] gdResourceToTruecolor() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:70 [0x00007f7feea1e7b0] initFromPath() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDecoder.php:339 [0x00007f7feea1e740] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDriver.php:66 [0x00007f7feea1e6d0] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManager.php:54 [0x00007f7feea1e660] make() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManagerStatic.php:58 [0x00007f7feea1e5f0] make() /var/www/gnusocial/lib/media/imagefile.php:65 [0x00007f7feea1e510] __construct() /var/www/gnusocial/lib/media/imagefile.php:160 [0x00007f7feea1e450] fromFileObject() /var/www/gnusocial/classes/File.php:570 [0x00007f7feea1e370] getThumbnail() /var/www/gnusocial/plugins/Embed/EmbedPlugin.php:312 [0x00007f7feea1e270] onStartShowAttachmentRepresentation() /var/www/gnusocial/lib/util/event.php:89 [0x00007f7feea1e1c0] handle() /var/www/gnusocial/lib/media/attachmentlistitem.php:108 [0x00007f7feea1e0e0] showRepresentation() /var/www/gnusocial/lib/media/attachmentlistitem.php:102 [0x00007f7feea1e090] showNoticeAttachment() /var/www/gnusocial/lib/media/attachmentlistitem.php:85 [0x00007f7feea1e020] show() /var/www/gnusocial/lib/media/attachmentlist.php:99 [0x00007f7feea1df50] show() /var/www/gnusocial/lib/notices/noticelistitem.php:403 [0x00007f7feea1ded0] showNoticeAttachments() /var/www/gnusocial/lib/notices/noticelistitem.php:177 [0x00007f7feea1de70] showNoticeFooter() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:630 [0x00007f7feea1de10] showNoticeListItem() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:616 [0x00007f7feea1dd60] onStartShowNoticeItem() /var/www/gnusocial/lib/util/event.php:89 [07-Feb-2020 11:40:28] [pool www] pid 6231 script_filename = /var/www/gnusocial/public/index.php [0x00007f7feea1e930] imagecreatetruecolor() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:138 [0x00007f7feea1e880] gdResourceToTruecolor() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/Gd/Decoder.php:70 [0x00007f7feea1e7b0] initFromPath() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDecoder.php:339 [0x00007f7feea1e740] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/AbstractDriver.php:66 [0x00007f7feea1e6d0] init() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManager.php:54 [0x00007f7feea1e660] make() /var/www/gnusocial/vendor/intervention/image/src/Intervention/Image/ImageManagerStatic.php:58 [0x00007f7feea1e5f0] make() /var/www/gnusocial/lib/media/imagefile.php:65 [0x00007f7feea1e510] __construct() /var/www/gnusocial/lib/media/imagefile.php:160 [0x00007f7feea1e450] fromFileObject() /var/www/gnusocial/classes/File.php:570 [0x00007f7feea1e370] getThumbnail() /var/www/gnusocial/plugins/Embed/EmbedPlugin.php:312 [0x00007f7feea1e270] onStartShowAttachmentRepresentation() /var/www/gnusocial/lib/util/event.php:89 [0x00007f7feea1e1c0] handle() /var/www/gnusocial/lib/media/attachmentlistitem.php:108 [0x00007f7feea1e0e0] showRepresentation() /var/www/gnusocial/lib/media/attachmentlistitem.php:102 [0x00007f7feea1e090] showNoticeAttachment() /var/www/gnusocial/lib/media/attachmentlistitem.php:85 [0x00007f7feea1e020] show() /var/www/gnusocial/lib/media/attachmentlist.php:99 [0x00007f7feea1df50] show() /var/www/gnusocial/lib/notices/noticelistitem.php:403 [0x00007f7feea1ded0] showNoticeAttachments() /var/www/gnusocial/lib/notices/noticelistitem.php:177 [0x00007f7feea1de70] showNoticeFooter() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:630 [0x00007f7feea1de10] showNoticeListItem() /var/www/gnusocial/lib/modules/ActivityHandlerModule.php:616 [0x00007f7feea1dd60] onStartShowNoticeItem() /var/www/gnusocial/lib/util/event.php:89 [07-Feb-2020 11:40:38] [pool www] pid 6243 script_filename = /var/www/gnusocial/public/index.php [0x00007f7feea1e2b0] mysqli_query() /var/www/gnusocial/extlib/DB/mysqli.php:409 [0x00007f7feea1e210] simpleQuery() /var/www/gnusocial/extlib/DB/common.php:1333 [0x00007f7feea1e140] query() /var/www/gnusocial/extlib/DB/DataObject.php:1594 [0x00007f7feea1e000] _query() /var/www/gnusocial/classes/Memcached_DataObject.php:674 [0x00007f7feea1df00] _query() /var/www/gnusocial/extlib/DB/DataObject.php:3135 [0x00007f7feea1de90] query() /var/www/gnusocial/classes/Memcached_DataObject.php:642 [0x00007f7feea1dd80] cachedQuery() /var/www/gnusocial/plugins/TagCloud/lib/personaltagcloudsection.php:68 [0x00007f7feea1dcd0] getTags() /var/www/gnusocial/plugins/TagCloud/lib/tagcloudsection.php:52 [0x00007f7feea1dbf0] showContent() /var/www/gnusocial/lib/ui/section.php:62 [0x00007f7feea1db70] show() /var/www/gnusocial/plugins/TagCloud/TagCloudPlugin.php:70 [0x00007f7feea1dad0] onEndShowSections() /var/www/gnusocial/lib/util/event.php:89 [0x00007f7feea1da20] handle() /var/www/gnusocial/lib/action/action.php:1212 [0x00007f7feea1d9b0] showAside() /var/www/gnusocial/lib/action/action.php:1004 [0x00007f7feea1d940] showCore() /var/www/gnusocial/lib/action/action.php:837 [0x00007f7feea1d8c0] showBody() /var/www/gnusocial/lib/action/action.php:545 [0x00007f7feea1d850] showPage() /var/www/gnusocial/lib/util/managedaction.php:64 [0x00007f7feea1d7e0] handle() /var/www/gnusocial/lib/action/action.php:186 [0x00007f7feea1d720] execute() /var/www/gnusocial/lib/action/action.php:88 [0x00007f7feea1d660] run() /var/www/gnusocial/public/index.php:338 [0x00007f7feea1d100] main() /var/www/gnusocial/public/index.php:341 [/code] On one hand, I'm not sure if 10 seconds is enough to complete the requests. On the other, the server is a VPS with a quad-core and 16 GB of RAM (never above 3 GB of use); GNUSocial is the only web service installed; i guess it should be more than enough for managing around 300 accounts. Is this a bad config of my php-fpm, or is it because of the slowness of the requests? Please, let me know if there's anything i can do to further debug the problem.
aab commented 4 years ago
Poster

Ok, news on this. I've detected massive connections from Friendica hosts. Just to try, i made last night a filter in fail2ban for those hosts and... the server is running smoothly again.

I've restored php config to a (i think) more sane version, similar to the one found in #54. PHP's slow log now writes maybe twice and hour, in contrast with several every ten minutes that it was writing yesterday.

I'm reading now about rate limiting in nginx, as i'd like those hosts to connect again, but i'm afraid they'll keep on being banned until i find the correct answer for this.

Once again, sorry for the noise; please, feel free to close this bug report, and i'll write a new one about rate limiting when i get it to work.

Ok, news on this. I've detected massive connections from Friendica hosts. Just to try, i made last night a filter in fail2ban for those hosts and... the server is running smoothly again. I've restored php config to a (i think) more sane version, similar to the one found in https://notabug.org/diogo/gnu-social/issues/54. PHP's slow log now writes maybe twice and hour, in contrast with several every ten minutes that it was writing yesterday. I'm reading now about rate limiting in nginx, as i'd like those hosts to connect again, but i'm afraid they'll keep on being banned until i find the correct answer for this. Once again, sorry for the noise; please, feel free to close this bug report, and i'll write a new one about rate limiting when i get it to work.
aab commented 4 years ago
Poster

After some days experimenting with rate-limiting in nginx, everything is back to normal. If something, this has tought me than php-fpm will try to process EVERYTHING you throw at it :)

Closing now, as this is not a GS bug.

After some days experimenting with rate-limiting in nginx, everything is back to normal. If something, this has tought me than php-fpm will try to process EVERYTHING you throw at it :) Closing now, as this is not a GS bug.
Sign in to join this conversation.
No Milestone
No assignee
1 Participants
Loading...
Cancel
Save
There is no content yet.