Ruby process suddenly uses so much of CPU, up to 70%


(Lê Trần Đạt) #1

Recently I’ve just created a Wordpress blog and install wp-discourse plugin. I also generated an API key for the plugin. Everything was working fine, but after that the CPU usage is increased so much.

I tried to revoke the API key, shutdown Wordpress blog but the CPU is still very high, up to 70%.

I also restart the app:

root@daynhauhoc:/var/discourse# ./launcher restart app
WARNING: No swap limit support
76b48a7f2747fc69c2dac1aef37b6753ed96940de824c058c30423e6959e51c1
cid found, ensuring container is started
76b48a7f2747fc69c2dac1aef37b6753ed96940de824c058c30423e6959e51c1
root@daynhauhoc:/var/discourse#

This is the recent logs I run with ./launcher logs app

[32] 28 Dec 07:02:58.010 * 10 changes in 300 seconds. Saving...
[32] 28 Dec 07:02:58.021 * Background saving started by pid 4642
[4642] 28 Dec 07:03:04.741 * DB saved on disk
[4642] 28 Dec 07:03:04.752 * RDB: 19 MB of memory used by copy-on-write
[32] 28 Dec 07:03:04.877 * Background saving terminated with success
[32] 28 Dec 07:08:05.067 * 10 changes in 300 seconds. Saving...
[32] 28 Dec 07:08:05.075 * Background saving started by pid 5026
[5026] 28 Dec 07:08:09.971 * DB saved on disk
[5026] 28 Dec 07:08:09.981 * RDB: 25 MB of memory used by copy-on-write
[32] 28 Dec 07:08:09.997 * Background saving terminated with success
Shutting Down
run-parts: executing /etc/runit/3.d/01-nginx
ok: down: nginx: 0s, normally up
run-parts: executing /etc/runit/3.d/02-unicorn
exiting
ok: down: unicorn: 0s, normally up
run-parts: executing /etc/runit/3.d/10-redis
[32 | signal handler] (1419750508) Received SIGTERM scheduling shutdown...
[32] 28 Dec 07:08:28.848 # User requested shutdown...
[32] 28 Dec 07:08:28.849 * Saving the final RDB snapshot before exiting.
[32] 28 Dec 07:08:32.060 * DB saved on disk
[32] 28 Dec 07:08:32.061 # Redis is now ready to exit, bye bye...
ok: down: redis: 0s, normally up
run-parts: executing /etc/runit/3.d/99-postgres
2014-12-28 07:08:32 UTC LOG:  received smart shutdown request
2014-12-28 07:08:32 UTC LOG:  autovacuum launcher shutting down
2014-12-28 07:08:32 UTC LOG:  shutting down
2014-12-28 07:08:32 UTC LOG:  database system is shut down
ok: down: postgres: 0s, normally up
run-parts: executing /etc/runit/3.d/99-ssh
Received signal 15; terminating.
ok: down: sshd: 1s, normally up
run-parts: executing /etc/runit/1.d/00-ensure-links
run-parts: executing /etc/runit/1.d/anacron
run-parts: executing /etc/runit/1.d/cleanup-pids
Cleaning stale PID files
run-parts: executing /etc/runit/1.d/copy-env
Started runsvdir, PID is 24
ok: run: redis: (pid 34) 0s
ok: run: postgres: (pid 36) 0s
                _._
           _.-``__ ''-._
      _.-``    `.  `_.  ''-._           Redis 2.8.17 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._
 (    '      ,       .-`  | `,    )     Running in stand alone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 6379
 |    `-._   `._    /     _.-'    |     PID: 34
  `-._    `-._  `-./  _.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |           http://redis.io
  `-._    `-._`-.__.-'_.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |
  `-._    `-._`-.__.-'_.-'    _.-'
      `-._    `-.__.-'    _.-'
          `-._        _.-'
              `-.__.-'

[34] 28 Dec 07:08:34.611 # Server started, Redis version 2.8.17
rsyslogd: invalid or yet-unknown config file command 'KLogPermitNonKernelFacility' - have you forgotten to load a module? [try http://www.rsyslog.com/e/3003 ]
[34] 28 Dec 07:08:34.613 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
rsyslogd: warning: ~ action is deprecated, consider using the 'stop' statement instead [try http://www.rsyslog.com/e/2307 ]
rsyslogd: Could no open output pipe '/dev/xconsole': No such file or directory [try http://www.rsyslog.com/e/2039 ]
Server listening on 0.0.0.0 port 22.
Server listening on :: port 22.
2014-12-28 07:08:34 UTC LOG:  database system was shut down at 2014-12-28 07:08:32 UTC
2014-12-28 07:08:34 UTC LOG:  database system is ready to accept connections
2014-12-28 07:08:34 UTC LOG:  autovacuum launcher started
supervisor pid: 35 unicorn pid: 62
[34] 28 Dec 07:08:47.063 * DB loaded from disk: 12.448 seconds
[34] 28 Dec 07:08:47.075 * The server is now ready to accept connections on port 6379

(Jeff Atwood) #2

Are you running WP and Discourse on the same server? I am unclear about your setup here.


(Lê Trần Đạt) #3

WP and Discourse are on different servers. I am still monitoring the CPU usage, let it runs for 24h then I will come back to ask since the CPU usage is back to normal*.

* It is now slightly higher than 5 hrs before but it is acceptable.

I just installed iftop to check the outbound bandwidth and found out that Google is requesting data for indexing (maybe)

Do you think the recent high CPU usage is caused by Google Bot?

This is the bandwidth Graphs

You can see the CPU + Bandwidth is increased significantly since Dec 28 01:00:00 PM


(Sam Saffron) #4

Which process is this, one of the unicorns or a sidekiq? Look at the command line of the offending pid. If it is sidekiq, what is going on in your job queue?