High CPU usage after updating to 5.2.0-alpha-1654086634.2fefa6f3.bullseye

Infos:

  • Used Zammad version: 5.2.0-alpha-1654086634.2fefa6f3.bullseye
  • Used Zammad installation type: (source, package, docker-compose, …) package
  • Operating system: Debian Bullseye
  • Browser + version: Chrome latest

Expected behavior: low CPU use

Actual behavior: High CPU use

Steps to reproduce the behavior: just installed with apt-get upgrade

Since upgrading to 5.2.0-alpha-1654086634.2fefa6f3.bullseye I’ve seen a high CPU usage by this process:

1867705 ?        Rs     0:00 script/background-services.rb start APP_RUNNER_CLI=systemctl RAILS_LOG_TO_STDOUT= APP_USER=zammad APP_GROUP=zammad APP_SAFE_NAME=zammad

Zammad log is filled by a repeated action occurring every 6 seconds:

I, [2022-06-01T15:51:37.795552 #1350169-7160]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2022-06-01T15:51:37.795718 #1350169-7160]  INFO -- : Using File as web socket session store.
I, [2022-06-01T15:51:38.195765 #1350169-7160]  INFO -- : Setting.set('product_logo', "27ad73322e96990eb351803af90d2c44.png")
I, [2022-06-01T15:51:40.081320 #1350169-7160]  INFO -- : Setting.set('models_searchable', ["Chat::Session", "KnowledgeBase::Answer::Translation", "Organization", "Ticket", "User"])

I, [2022-06-01T15:51:43.472829 #1350230-7160]  INFO -- : Using Zammad's file store as Rails cache store.
I, [2022-06-01T15:51:43.472968 #1350230-7160]  INFO -- : Using File as web socket session store.
I, [2022-06-01T15:51:43.869807 #1350230-7160]  INFO -- : Setting.set('product_logo', "27ad73322e96990eb351803af90d2c44.png")
I, [2022-06-01T15:51:45.798615 #1350230-7160]  INFO -- : Setting.set('models_searchable', ["Chat::Session", "KnowledgeBase::Answer::Translation", "Organization", "Ticket", "User"])

This process is using up to 100% CPU. Log message was not present before the last apt upgrade and started right after the upgrade.

I had to shutdown Zammad because the high cpu usage drained all the AWS burstable capacity.

Any idea on how to solve this issue? Thanks!

Hi @admin-gbm

This update contains script/scheduler.rb renaming to script/background-services.rb.

Do you have any custom changes that may cause it to die? It looks like the script may be constantly restarting.

This script may take a lot of CPU during boot up but then use resources according to load.

Is this a fresh installation? Upgrade of an existing system?

Friendly side note: Using development versions of Zammad for production is not suggested. You’re proceeding on your own danger here.

1 Like

Looks like a bug.
Syslog actually hints for the reason:

Jun  2 15:34:20 zammad systemd[1]: Started zammad-worker-1.service.
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: bundler: failed to load command: script/background-services.rb (script/background-services.rb)
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: /opt/zammad/lib/background_services/cli.rb:4:in `<class:BackgroundServices>': uninitialized constant Thor (NameError)
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/lib/background_services/cli.rb:3:in `<main>'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/zeitwerk-2.5.4/lib/zeitwerk/kernel.rb:27:in `require'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from script/background-services.rb:16:in `<top (required)>'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:58:in `load'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:58:in `kernel_load'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:23:in `run'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:479:in `exec'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:31:in `dispatch'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:25:in `start'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/exe/bundle:49:in `block in <top (required)>'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/friendly_errors.rb:103:in `with_friendly_errors'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/exe/bundle:37:in `<top (required)>'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/bin/bundle:121:in `load'
Jun  2 15:34:23 zammad zammad-worker-1.service[14318]: #011from /opt/zammad/bin/bundle:121:in `<main>'
Jun  2 15:34:23 zammad systemd[1]: zammad-worker-1.service: Main process exited, code=exited, status=1/FAILURE
Jun  2 15:34:23 zammad systemd[1]: zammad-worker-1.service: Failed with result 'exit-code'.
Jun  2 15:34:23 zammad systemd[1]: zammad-worker-1.service: Service RestartSec=100ms expired, scheduling restart.
Jun  2 15:34:23 zammad systemd[1]: zammad-worker-1.service: Scheduled restart job, restart counter is at 23.

Could you please create an issue? Thank you.

Looks like this is exactly what’s happening. It’s not a fresh installation, it’s a test server I keep updated via apt and it gets the dev Zammad’s updates nearly daily.
I did not make any custom changes, or at least I do not remeber as it was installed more than two years ago. There must be something in that renaming causing script/background-services.rb to crash. It’s been working fine until yesterday’s update. I just tried today’s update (5.2.0-alpha-1654107415.b3639fb8.bullseye) but it did not solve the issue. Too bad I do not know Ruby so I cannot help. I will monitor the next updates for a solution, in case I’ll start a new fresh one. Thanks for your help.

I know I know, I been there (in the dangerous zone) sooo many times! :slight_smile:

Fortunately it’s a personal test server, it helps me prevent the nasty bugs reach the clients. Thanks anyway for the advice, it’s always appreciated!

I have the same syslog error:

Jun  2 12:06:24 systemd[1]: Started zammad.service.
Jun  2 12:06:24 systemd[1]: Started zammad-web.service.
Jun  2 12:06:24 systemd[1]: Started zammad-web-1.service.
Jun  2 12:06:24 systemd[1]: Started zammad-websocket.service.
Jun  2 12:06:24 systemd[1]: Started zammad-websocket-1.service.
Jun  2 12:06:24 systemd[1]: Started zammad-worker.service.
Jun  2 12:06:24 systemd[1]: Started zammad-worker-1.service.
Jun  2 12:06:27 zammad-web-1.service[1864364]: => Booting Puma
Jun  2 12:06:27 zammad-web-1.service[1864364]: => Rails 6.1.6 application starting in production
Jun  2 12:06:27 zammad-web-1.service[1864364]: => Run `bin/rails server --help` for more startup options
Jun  2 12:06:32 zammad-web-1.service[1864364]: Puma starting in single mode...
Jun  2 12:06:32 zammad-web-1.service[1864364]: * Version 4.3.12 (ruby 3.0.4-p208), codename: Mysterious Traveller
Jun  2 12:06:32 zammad-web-1.service[1864364]: * Min threads: 5, max threads: 30
Jun  2 12:06:32 zammad-web-1.service[1864364]: * Environment: production
Jun  2 12:06:32 zammad-web-1.service[1864364]: * Listening on tcp://127.0.0.1:3000
Jun  2 12:06:32 zammad-web-1.service[1864364]: Use Ctrl-C to stop
Jun  2 12:06:33 zammad-worker-1.service[1864369]: bundler: failed to load command: script/background-services.rb (script/background-services.rb)
Jun  2 12:06:33 zammad-worker-1.service[1864369]: /opt/zammad/lib/background_services/cli.rb:4:in `<class:BackgroundServices>': uninitialized constant Thor (NameError)
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/lib/background_services/cli.rb:3:in `<main>'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bootsnap-1.12.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/zeitwerk-2.5.4/lib/zeitwerk/kernel.rb:27:in `require'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from script/background-services.rb:16:in `<top (required)>'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:58:in `load'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:58:in `kernel_load'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:23:in `run'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:479:in `exec'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:31:in `dispatch'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:25:in `start'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/exe/bundle:49:in `block in <top (required)>'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/friendly_errors.rb:103:in `with_friendly_errors'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/exe/bundle:37:in `<top (required)>'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/bin/bundle:121:in `load'
Jun  2 12:06:33 zammad-worker-1.service[1864369]: #011from /opt/zammad/bin/bundle:121:in `<main>'
Jun  2 12:06:33 systemd[1]: zammad-worker-1.service: Main process exited, code=exited, status=1/FAILURE
Jun  2 12:06:33 systemd[1]: zammad-worker-1.service: Failed with result 'exit-code'.
Jun  2 12:06:33 systemd[1]: zammad-worker-1.service: Consumed 5.228s CPU time.

I’m opening an issue on Github. Thanks.

The fix is now merged in develop branch and will be available as alpha package soon.

Thank you @admin-gbm for noticing this!

1 Like