Forwarded to devs Plesk 17.8.11, upgraded from 17.5.3: high load average caused by /etc/cron.daily/50plesk-daily

[burnley]

TITLE:

Plesk 17.8.11, upgraded from 17.5.3: high load average caused by /etc/cron.daily/50plesk-daily​

PRODUCT, VERSION, OPERATING SYSTEM, ARCHITECTURE:

Plesk Onyx Version 17.8.11 Update #56, last updated on June 19, 2019 09:42 PM
CentOS Linux 7.6.1810 (Core)‬​

PROBLEM DESCRIPTION:

We haven't seen this behaviour in 17.5.3 with the current set of tasks which reads:
/usr/local/psa/bin/sw-engine-pleskrun /usr/local/psa/admin/plib/DailyMaintainance/script.php -f CheckForUpdates,UpdateKeys,PleskUsage,Sitebuilder,MailUsage,ExecuteStatistics,ProcessAutoreports,OptimizeStatistics,AnalyseDomainStatistics,AnalyseClientStatistics,LoadCustomizations,UpdateApsCache,UpdateApsApplications,ExecuteGlCleaner,StoreProtectedConfigs,ExecuteWebStatistics,UpdatePhpCurlCertificates,ExecuteQuotacheck,BackupRestoreStats,UpgradeExtensions,ComposerSelfUpdate,AutoresponderEndDate >/dev/null 2>&1

Now, ever since doing the in-place upgrade to 17.8.11, the servers load explodes at night and the culprit appears to be the one (or more?) of these tasks. There's a ridiculous number of interface_async_executor.php processes running concurrently, few numbers:

grep '/usr/local/psa/admin/bin/event_handler -i -u psaadm /usr/local/psa/admin/bin/php -- -f /usr/local/psa/admin/plib/scripts/interface_async_executor.php' plesk-high-loadavg.plesk1 | wc -l
820

grep '/usr/local/psa/admin/bin/event_handler -i -u psaadm /usr/local/psa/admin/bin/php -- -f /usr/local/psa/admin/plib/scripts/interface_async_executor.php' plesk-high-loadavg.plesk2 | wc -l
580

They're all running the event handler. The truncated "top" output shows:
3658 root 30 10 13256 176 0 S 3.6 0.0 0:00.02 /usr/local/psa/admin/bin/event_handler -i -u psaadm /usr/local/psa/admin/bin/php -- -f /usr/local/psa/admin/plib/scripts/interface_async_executor.php -- EventListener /usr/local/psa/admin/plib/modules/dnssec/library/EventListener.php handleEvent admin -#-#- -u psaadm /usr/local/psa/admin/bin/php -- -f /usr/local/psa/admin/plib/scripts/interface_async_executor.php -- EventListener /usr/local/psa/admin/plib/modules/servershield/library/Even+

For every Plesk event we're running a handler that does some form of logging, here are the events run at the time when the top snapshot was taken, hundreds of them:
27529 root 30 10 13256 176 0 S 4.3 0.0 0:00.01 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
326 root 30 10 13256 172 0 S 0.0 0.0 0:00.01 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
397 root 30 10 13256 172 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
406 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
411 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
415 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
419 root 30 10 13256 172 0 S 0.0 0.0 0:00.03 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
424 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
428 root 30 10 13256 172 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
432 root 30 10 13256 172 0 S 0.0 0.0 0:00.02 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
442 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_guid_update
446 root 30 10 13256 176 0 S 0.0 0.0 0:00.00 /usr/local/psa/admin/bin/event_handler -u root -- /usr/local/sbin/plesk-handler-logevent.sh -n actionlog__event_domain_status_update
[...]
On a closer inspection of our logs it turns out Plesk runs these event handlers for every subscription:
server1:
actionlog__event_siteapp_upgrade - 64
actionlog__event_domain_guid_update - 869
actionlog__event_domain_status_update - 869

server2:
actionlog__event_siteapp_upgrade - 68
actionlog__event_domain_guid_update - 1256
actionlog__event_domain_status_update - 1256

server3 (fairly new, the least populated)
actionlog__event_siteapp_upgrade - 1
actionlog__event_domain_guid_update - 90
actionlog__event_domain_status_update - 90

server4:
actionlog__event_siteapp_upgrade - 28
actionlog__event_domain_guid_update - 714
actionlog__event_domain_status_update - 714

... and so on.

Our handler logs entries like these for the two most often executed events:

2019-06-07 01:28:17.070140 plesk-handler-logevent.sh [pid:27651] - Plesk event handler detected: [serverhostname: plesk.server][serverprimaryip: 192.168.0.300][serveruniqueid: 8c642ae1-ab90-5f0d-8d39-a63a91791c91][event: UNSET, UNUSED][eventhandler: actionlog__event_domain_guid_update][eventdata: {'PHP_IDE_CONFIG': '', 'NEW_STATUS': '', 'RANDOM_DELAY': '10', 'LOGNAME': 'root', 'OLD_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'HOME': '/root', 'START_HOURS_RANGE': '0', 'NEW_CLIENT_GUID': 'd1a143f1-a0d8-4e45-a6a8-26aca798e916', 'MAILTO': 'root', 'SHELL': '/bin/sh', 'SHLVL': '8', 'NEW_EXTENDED_STATUS_OF_DOMAIN': '', 'NEW_DOMAIN_NAME': 'domain.com', 'OLD_EXTENDED_STATUS_OF_DOMAIN': '', 'OLD_STATUS': '', 'LANG': 'en_US.UTF-8', 'XDG_RUNTIME_DIR': '/run/user/0', 'NEW_DOMAIN_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'OLD_DOMAIN_NAME': 'domain.com', 'OLD_DOMAIN_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'XDG_SESSION_ID': '53576', 'NEW_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', '_': '/usr/local/psa/admin/bin/event_handler', 'PLESK_INTERNAL_PHP_EXEC': '', 'PWD': '/', 'OLD_CLIENT_GUID': 'd1a143f1-a0d8-4e45-a6a8-26aca798e916', 'USER': 'root'}]
2019-06-07 01:28:54.167665 plesk-handler-logevent.sh [pid:31735] - Plesk event handler detected: [serverhostname: plesk.server][serverprimaryip: 192.168.0.300][serveruniqueid: 8c642ae1-ab90-5f0d-8d39-a63a91791c91][event: UNSET, UNUSED][eventhandler: actionlog__event_domain_status_update][eventdata: {'PHP_IDE_CONFIG': '', 'NEW_STATUS': '0', 'RANDOM_DELAY': '10', 'LOGNAME': 'root', 'OLD_GUID': '', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'HOME': '/root', 'START_HOURS_RANGE': '0', 'NEW_CLIENT_GUID': 'd1a143f1-a0d8-4e45-a6a8-26aca798e916', 'MAILTO': 'root', 'SHELL': '/bin/sh', 'SHLVL': '8', 'NEW_EXTENDED_STATUS_OF_DOMAIN': 'active', 'NEW_DOMAIN_NAME': 'domain.com', 'OLD_EXTENDED_STATUS_OF_DOMAIN': 'active', 'OLD_STATUS': '0', 'LANG': 'en_US.UTF-8', 'XDG_RUNTIME_DIR': '/run/user/0', 'NEW_DOMAIN_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'OLD_DOMAIN_NAME': 'domain.com', 'OLD_DOMAIN_GUID': '50f3e6e1-2928-402c-82ab-11a403e59693', 'XDG_SESSION_ID': '53576', 'NEW_GUID': '', '_': '/usr/local/psa/admin/bin/event_handler', 'PLESK_INTERNAL_PHP_EXEC': '', 'PWD': '/', 'OLD_CLIENT_GUID': 'd1a143f1-a0d8-4e45-a6a8-26aca798e916', 'USER': 'root'}]

Why are these jobs run?​

STEPS TO REPRODUCE:

Upgrade Plesk from 17.5.3 to 17.8.11. Previously the load resulted after running the daily cron wasn't an issue.​

ACTUAL RESULT:

Spike in load average caused by Plesk daily cron.​

EXPECTED RESULT:

Similar behaviour load-wise between 17.5.3 and 17.8.11. If anything, 17.8.11 should be an improvement.​

ANY ADDITIONAL INFORMATION:

​

YOUR EXPECTATIONS FROM PLESK SERVICE TEAM:

Confirm bug​

 

[IgorG]

Could you please re-write PROBLEM DESCRIPTION without link to another thread?
Thanks.

 

[burnley]

Done Igor, hopefully it's readable at your end. Thanks.

 

[IgorG]

Thank you, @burnley
Developers informed me that investigation directly on your server is required. So, for providing access to your server you have to contact Plesk Support Team.
If Plesk license was bought directly from us, then create a ticket with a reference to this topic from the forum.
If the license was purchased from a partner, then you can go to a partner for support, and the partner will go to us for Plesk support. Or you can buy a Plesk support subscription (1st month for free) and start a ticket to us directly.

 

[burnley]

Hi Igor, thanks for the follow-up. We can't unfortunately provide remote access to any of the affected machines, but we're more than willing to assist in investigating the issue, which is still occurring on a daily basis. What we need to know at the moment is: which one of the daily tasks listed in my initial post is responsible with running the hook for "domain status updated" every night, for each domain on the server?

 

[IgorG]

1. Please make sure the parameter syncExecution in the panel.ini has the following meaning:
   

   [eventListener]
   syncExecution = false

   
   
2. In order to diagnose the issue, you need to add parameters to the file that allow debugging:
   

   [debug]
   enabled = on
    
   [log]
   priority = 7
    
   show.util_exec = on
   show.util_exec_io = on

You'll get a lot of log entries like this:

[2018-10-26 19:55:58.738] DEBUG [util_exec] [5bd30edeb42e4] Starting: event_handler -i -u psaadm /opt/psa/admin/bin/php -- -f /opt/psa/admin/plib/scripts/interface_async_executor.php -- EventListener /opt/psa/admin/plib/modules/servershield/library/EventListener.php handleEvent admin -#-#- -u psaadm /opt/psa/admin/bin/php -- -f /opt/psa/admin/plib/scripts/interface_async_executor.php -- EventListener /opt/psa/admin/plib/modules/wp-toolkit/library/EventListener.php handleEvent admin -#-#- -u psaadm /opt/psa/admin/bin/php -- -f /opt/psa/admin/plib/scripts/interface_async_executor.php -- EventListener /opt/psa/admin/plib/registry/EventListener/drweb.php handleEvent admin -#-#- -u psaadm /opt/psa/admin/bin/php -- -f /opt/psa/admin/plib/scripts/interface_async_executor.php -- EventListener /opt/psa/admin/plib/registry/EventListener/kav.php handleEvent admin -#-#-, stdin: 
[2018-10-26 19:55:58.741] DEBUG [util_exec] [5bd30edeb42e4] Finished in 0.00276s, Error code: TRUE, stdout: , stderr:
[2018-10-26 19:55:58.741] DEBUG [util_exec] [5bd30edeb42e4] Stdin: {"0":"domain","1":58,"2":"domain_update","3":{"Domain Name":"test.a10-52-55-209.qa.plesk.ru","Domain GUID":"e00bec9a-36b7-4d3d-a5b6-07f059dc8b36","Client GUID":"e2397f4f-9363-46b1-9472-c09ef5a84128"},"4":{"Domain Name":"test1.a10-52-55-209.qa.plesk.ru","Domain GUID":"e00bec9a-36b7-4d3d-a5b6-07f059dc8b36","Client GUID":"e2397f4f-9363-46b1-9472-c09ef5a84128"},"enableNotifications":true,"_SERVER":}}

From this data it will be possible to understand what processes are slow, as well as try to establish what kind of operation or what task is the cause of the generated processes. However, this task can be difficult, and you'd better contact our support team.

 

[burnley]

Thanks Igor, I've enabled the settings you suggested and will report back when more information will become available. Appreciated.

 

[IgorG]

will report back when more information will become available.

Please report it directly to Plesk Support.
Thanks.

 

[burnley]

Tks Igor, logged as #183672

 

[burnley]

Just to follow-up, Plesk Support confirmed it as a bug in the CF extension and documented it here:
High server load. A lot of processes interface_async_executor.php (servershield/library/EventListener)