This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

rrdtool high cpu usage

Hi,

This was fine until last night. Suddenly my Sophos Home firewall started to make noise due to high cpu usage

When i logged in to the console i could see rrdtool is consuming 100% cpu

top - 18:36:12 up  3:04,  1 user,  load average: 10.92, 10.53, 9.80
Tasks: 206 total,  12 running, 192 sleeping,   0 stopped,   2 zombie
Cpu(s): 96.7%us,  3.3%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   8004172k total,  3830528k used,  4173644k free,    63832k buffers
Swap:  4194300k total,        0k used,  4194300k free,  1642392k cached

  PID USER      PR  NI  VIRT  RES  SHR S   %CPU %MEM    TIME+  COMMAND
30413 root      20   0 13148 4828 3488 R     39  0.1  80:15.51 rrdtool
13131 root      20   0 13148 4824 3488 R     38  0.1  12:58.73 rrdtool
11229 root      20   0 13148 4824 3488 R     37  0.1  20:25.11 rrdtool
 7952 root      20   0 13148 4828 3488 R     37  0.1  38:55.45 rrdtool
18133 root      20   0 13148 4824 3488 R     36  0.1 110:18.69 rrdtool
23917 root      20   0 13148 4828 3488 R     36  0.1  95:15.67 rrdtool
 3027 root      20   0 13148 4824 3488 R     36  0.1  66:04.84 rrdtool
 9569 root      20   0 13148 4828 3488 R     36  0.1  28:52.32 rrdtool
 6094 root      20   0 13148 4828 3488 R     36  0.1  50:58.51 rrdtool
16320 root      20   0 13148 4824 3488 R     35  0.1   0:25.25 rrdtool
14795 root      20   0 13148 4824 3488 R     33  0.1   6:23.59 rrdtool
 5339 root      19  -1 34692 2676 1200 S      0  0.0   0:05.41 ulogd
 7601 httpprox  20   0 1503m 942m  12m S      0 12.1   0:59.32 httpproxy
13095 root      20   0 15764 9.9m 2680 S      0  0.1   0:00.16 create_rrd_grap
    1 root      20   0  3976  580  508 S      0  0.0   0:02.16 init

then i ran ps aux and saw the following:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.0   3976   580 ?        Ss   15:32   0:02 init [3]  
root         2  0.0  0.0      0     0 ?        S    15:32   0:00 [kthreadd]
root         3  0.0  0.0      0     0 ?        S    15:32   0:00 [ksoftirqd/0]
root         5  0.0  0.0      0     0 ?        S<   15:32   0:00 [kworker/0:0H]
root         7  0.0  0.0      0     0 ?        S    15:32   0:00 [migration/0]
root         8  0.0  0.0      0     0 ?        S    15:32   0:00 [rcu_bh]
root         9  0.0  0.0      0     0 ?        S    15:32   0:02 [rcu_sched]
root        10  0.0  0.0      0     0 ?        S    15:32   0:00 [migration/1]
root        11  0.0  0.0      0     0 ?        S    15:32   0:00 [ksoftirqd/1]
root        12  0.0  0.0      0     0 ?        S    15:32   0:00 [kworker/1:0]
root        13  0.0  0.0      0     0 ?        S<   15:32   0:00 [kworker/1:0H]
root        14  0.0  0.0      0     0 ?        S    15:32   0:00 [migration/2]
root        15  0.0  0.0      0     0 ?        S    15:32   0:00 [ksoftirqd/2]
root        16  0.0  0.0      0     0 ?        S    15:32   0:00 [kworker/2:0]
root        17  0.0  0.0      0     0 ?        S<   15:32   0:00 [kworker/2:0H]
root        18  0.0  0.0      0     0 ?        S    15:32   0:00 [migration/3]
root        19  0.0  0.0      0     0 ?        S    15:32   0:00 [ksoftirqd/3]
root        20  0.0  0.0      0     0 ?        S    15:32   0:00 [kworker/3:0]
root        21  0.0  0.0      0     0 ?        S<   15:32   0:00 [kworker/3:0H]
root        22  0.0  0.0      0     0 ?        S<   15:32   0:00 [khelper]
root       133  0.0  0.0      0     0 ?        S<   15:32   0:00 [writeback]
root       136  0.0  0.0      0     0 ?        S<   15:32   0:00 [bioset]
root       137  0.0  0.0      0     0 ?        S<   15:32   0:00 [crypto]
root       139  0.0  0.0      0     0 ?        S<   15:32   0:00 [kblockd]
root       400  0.0  0.0      0     0 ?        S    15:32   0:00 [khubd]
root       408  0.0  0.0      0     0 ?        S<   15:32   0:00 [edac-poller]
root       513  0.0  0.0      0     0 ?        S    15:32   0:03 [kworker/1:1]
root       532  0.0  0.0      0     0 ?        S    15:32   0:00 [kswapd0]
root       596  0.0  0.0      0     0 ?        SN   15:32   0:00 [khugepaged]
root       597  0.0  0.0      0     0 ?        S    15:32   0:00 [fsnotify_mark]
root      1236  0.0  0.0      0     0 ?        S<   15:32   0:00 [deferwq]
root      1312  0.0  0.0      0     0 ?        S<   15:32   0:00 [nvme]
root      1327  0.0  0.0      0     0 ?        S<   15:32   0:00 [ata_sff]
root      1357  0.0  0.0      0     0 ?        S    15:32   0:00 [scsi_eh_0]
root      1360  0.0  0.0      0     0 ?        S    15:32   0:00 [scsi_eh_1]
root      1363  0.0  0.0      0     0 ?        S    15:32   0:00 [scsi_eh_2]
root      1366  0.0  0.0      0     0 ?        S    15:32   0:00 [scsi_eh_3]
root      1369  0.0  0.0      0     0 ?        S    15:32   0:00 [scsi_eh_4]
root      1372  0.0  0.0      0     0 ?        S    15:32   0:00 [scsi_eh_5]
root      1375  0.0  0.0      0     0 ?        S    15:32   0:00 [scsi_eh_6]
root      1378  0.0  0.0      0     0 ?        S    15:32   0:00 [scsi_eh_7]
root      1385  0.0  0.0      0     0 ?        S    15:32   0:00 [kworker/u8:6]
root      1386  0.0  0.0      0     0 ?        S    15:32   0:00 [kworker/u8:7]
root      2699  0.0  0.0      0     0 ?        S<   15:32   0:00 [kworker/1:1H]
root      2711  0.0  0.0      0     0 ?        S<   15:32   0:00 [kworker/0:1H]
root      2712  0.0  0.0      0     0 ?        S    15:32   0:02 [kworker/2:2]
root      2713  0.0  0.0      0     0 ?        S    15:32   0:01 [kworker/3:2]
root      2795  0.0  0.0      0     0 ?        S<   15:32   0:00 [kworker/2:1H]
root      2796  0.0  0.0      0     0 ?        S<   15:32   0:00 [kworker/3:1H]
root      2798  0.0  0.0      0     0 ?        S    15:32   0:00 [jbd2/sda6-8]
root      2799  0.0  0.0      0     0 ?        S<   15:32   0:00 [ext4-rsv-conver]
root      2861  0.0  0.0   4712  1104 ?        S<s  15:32   0:00 /sbin/udevd --daemon
root      2965  0.0  0.0   4464   608 ?        S    16:50   0:00 /usr/sbin/cron
root      2981  0.0  0.1  15764 10172 ?        Ss   16:50   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root      3027 61.7  0.0  13148  4824 ?        R    16:50  66:44 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
root      3232  0.1  0.0      0     0 ?        SN   15:32   0:13 [kipmi0]
root      3306  0.0  0.0      0     0 ?        S    15:32   0:00 [kworker/0:2]
root      3343  0.0  0.0      0     0 ?        S    15:32   0:00 [jbd2/sda1-8]
root      3344  0.0  0.0      0     0 ?        S<   15:32   0:00 [ext4-rsv-conver]
root      3345  0.0  0.0      0     0 ?        S    15:32   0:00 [jbd2/sda5-8]
root      3346  0.0  0.0      0     0 ?        S<   15:32   0:00 [ext4-rsv-conver]
root      3347  0.0  0.0      0     0 ?        S    15:32   0:00 [jbd2/sda7-8]
root      3348  0.0  0.0      0     0 ?        S<   15:32   0:00 [ext4-rsv-conver]
root      3349  0.0  0.0      0     0 ?        S    15:32   0:00 [jbd2/sda8-8]
root      3350  0.0  0.0      0     0 ?        S<   15:32   0:00 [ext4-rsv-conver]
root      3621  0.0  0.0   3988   812 ?        S    15:32   0:00 /usr/sbin/acpid -c /etc/acpi/events -s /var/run/acpid.socket
200       3634  0.0  0.0   4660   628 ?        Ss   15:32   0:00 /bin/dbus-daemon --system
201       3862  0.0  0.0  17228  4652 ?        Ssl  15:32   0:00 /usr/sbin/hald --daemon=yes
root      3863  0.0  0.0   5900  1284 ?        S    15:32   0:00 hald-runner
root      3885  0.0  0.0   8456  1964 ?        S    15:32   0:00 hald-addon-input: Listening on /dev/input/event0 /dev/input/event2 /dev/input/event3 /dev/input/event4
root      3900  0.0  0.0   8468  1968 ?        S    15:32   0:00 /usr/lib/hal/hald-addon-cpufreq
201       3901  0.0  0.0   8164  2136 ?        S    15:32   0:00 hald-addon-acpi: listening on acpid socket /var/run/acpid.socket
root      3931  0.0  0.0   8316  4380 ?        Ss   15:32   0:01 /sbin/haveged -w 1024 -v 0
root      3955  0.0  0.5  61900 44632 ?        Ss   15:32   0:02 confd [master]
root      3956  0.0  0.0   3956   536 ?        S    15:32   0:00 logger -p daemon.debug -t confd[3955]
root      3970  0.0  0.0   3956   396 ?        Ss   15:32   0:00 /usr/local/bin/confd-queuer
root      3982  0.0  0.0  10124  5932 ?        Ss   15:32   0:00 confd-qrunner.pl
root      3999  0.0  0.0  11024  5496 ?        S    15:32   0:01 /usr/local/bin/sysmond
root      4035  0.0  0.1  19436 14028 ?        S    15:32   0:00 /var/aua/aua.bin
root      4036  0.0  0.0   3956   244 ?        S    15:32   0:00 logger -p daemon.debug -t aua[4035]
root      4067  0.0  0.5  62032 41676 ?        S    15:32   0:00 confd [listener]
root      4280  0.0  0.1  16348 10440 ?        S    15:32   0:00 /usr/local/bin/notifier.plx -d
root      4313  0.0  2.8 267760 227612 ?       Ssl  15:32   0:04 /var/oculusd/oculusd 25000
rrdcache  4333  0.0  0.0 183780  1564 ?        Ssl  15:32   0:01 /usr/bin/rrdcached -l unix:/var/run/rrdcached/socket -m 777 -b /var/log/reporting/rrd -j /var/log/reporting/rrd -p /var/run/rrdcached/rrdcached.pid -B -F
at        4364  0.0  0.0   4404   360 ?        Ss   15:32   0:00 /usr/sbin/atd
postgres  4429  0.0  0.7 1137384 56968 ?       S    15:32   0:00 /usr/pgsql92-64/bin/postgres -D /var/storage/pgsql92/data
postgres  4431  0.0  0.2 1138056 18320 ?       Ss   15:32   0:00 postgres: checkpointer process                           
postgres  4432  0.0  0.0 1137900 7552 ?        Ss   15:32   0:00 postgres: writer process                                 
postgres  4433  0.0  0.2 1137900 17048 ?       Ss   15:32   0:00 postgres: wal writer process                             
postgres  4434  0.0  0.0 1139012 2416 ?        Ss   15:32   0:00 postgres: autovacuum launcher process                    
postgres  4435  0.0  0.0  26928   824 ?        Ss   15:32   0:00 postgres: archiver process   last was 000000010000002E0000008A
postgres  4436  0.0  0.0  27208  1120 ?        Ss   15:32   0:00 postgres: stats collector process                        
root      4492  0.1  2.3 194284 186296 ?       S    15:32   0:19 /var/mdw/mdw.plx
root      4501  0.0  0.0   3956   536 ?        S    15:32   0:00 logger -p daemon.debug -t middleware[4492]
root      4510  0.0  0.0      0     0 ?        S<   15:32   0:00 [redd]
root      4647  0.0  0.0   2292    24 ?        S    15:32   0:00 /usr/sbin/vlmcsd-x64-musl-static
root      4651  0.0  0.0   3980   408 ?        Ss   15:32   0:00 runsvdir -P /etc/service log: ...........................................................................................................................................................................................................................................................................................................................................................................................................
root      4652  0.0  0.0   4484   824 tty1     Ss+  15:32   0:00 /sbin/mingetty --no-hostname tty1
root      4653  0.0  0.0   4484   828 tty2     Ss+  15:32   0:00 /sbin/mingetty --no-hostname tty2
root      4654  0.0  0.0   4484   804 tty3     Ss+  15:32   0:00 /sbin/mingetty --no-hostname tty3
root      4655  0.0  0.0   4484   796 tty4     Ss+  15:32   0:00 /sbin/mingetty --no-hostname tty4
root      4656  0.0  0.0   3836   248 ?        Ss   15:32   0:00 runsv selfmonng
root      4657  0.1  0.1  14148 10356 ?        S    15:32   0:21 /usr/local/bin/selfmonng.plx
root      4689  0.0  0.0  13500  7444 ?        S    15:32   0:00 [timewarp check]
root      4857  0.0  0.0   3964   480 ?        Ss   15:32   0:00 /usr/local/bin/nwd
root      4873  0.0  0.0   4720   980 ?        S<   15:32   0:00 /sbin/udevd --daemon
root      4874  0.0  0.0   4720  1080 ?        S<   15:32   0:00 /sbin/udevd --daemon
root      5109  0.0  0.0   4424   796 ?        Ss   15:32   0:00 /usr/sbin/cron
root      5166  0.0  0.0   7568  1052 ?        Ss   15:32   0:00 /usr/sbin/sshd -f /etc/ssh/sshd_config
root      5189  0.0  0.1  14624 10216 ?        Ss   15:32   0:05 dns-resolver.plx
root      5293  0.0  0.0   7660  2352 ?        Ss   15:32   0:00 /usr/sbin/openvpn --config /etc/openvpn/openvpn.conf --writepid /var/run/openvpn.pid
root      5339  0.0  0.0  34692  2676 ?        S<sl 15:32   0:05 /usr/sbin/ulogd -c /etc/ulogd.conf -d
postgres  5342  0.0  0.3 1144132 26888 ?       Ss   15:32   0:04 postgres: reporting reporting [local] idle               
root      5402  0.0  0.0   5856   408 ?        S    15:32   0:00 supervising syslog-ng                     
root      5403  0.0  0.0  10608  5080 ?        Ss   15:32   0:03 /usr/sbin/syslog-ng -f /etc/syslog-ng.conf
root      5619  0.0  0.1  16464 11244 ?        S    15:32   0:00 ddclient - reading from dynamicdns.park-your-domain.com port 443
root      5621  0.0  0.1  19732 13968 ?        S    15:32   0:02 /usr/bin/perl /usr/local/bin/reporter/pfilter-reporter.pl
root      5622  0.0  0.1  20520 14720 ?        S    15:32   0:00 /usr/bin/perl /usr/local/bin/reporter/admin-reporter.pl
root      5623  0.0  0.0  31204  1736 ?        Sl   15:32   0:00 /usr/local/bin/reporter/vpn-reporter.pl
root      5624  0.0  0.0  30808  1992 ?        Sl   15:32   0:00 /usr/local/bin/reporter/websec-reporter.pl
root      5625  0.0  0.1  18752 12864 ?        S    15:32   0:00 /usr/bin/perl /usr/local/bin/reporter/mailsec-reporter.pl
root      5626  0.0  0.1  18928 13120 ?        S    15:32   0:00 /usr/bin/perl /usr/local/bin/reporter/ips-reporter.pl
root      5628  0.0  0.0  30688  1584 ?        Sl   15:32   0:00 /usr/local/bin/reporter/websec-reporter.pl -e
root      5629  0.0  0.0   4548  1144 ?        S    15:32   0:08 /usr/local/bin/reporter/waf-reporter
postgres  5652  0.0  0.0 1141296 5412 ?        Ss   15:32   0:00 postgres: smtp smtp [local] idle                         
postgres  5653  0.0  0.0 1141296 5372 ?        Ss   15:32   0:00 postgres: smtp smtp [local] idle                         
postgres  5657  0.0  0.1 1145496 13664 ?       Ss   15:32   0:00 postgres: reporting reporting [local] idle               
postgres  5658  0.0  0.0 1141300 4888 ?        Ss   15:32   0:00 postgres: reporting reporting [local] idle               
postgres  5684  0.0  0.0 1141396 5872 ?        Ss   15:32   0:00 postgres: hotspot hotspot [local] idle                   
root      5710  0.0  0.0  11464   788 ?        Ssl  15:32   0:00 /usr/local/bin/service_monitor
root      5762  0.0  0.6  79972 49432 ?        Ssl  15:32   0:03 /usr/sbin/named -4
postgres  5768  0.0  0.0 1141396 5808 ?        Ss   15:32   0:00 postgres: hotspot hotspot [local] idle                   
root      5823  0.0  0.0   6976  2232 ?        Ss   15:32   0:01 /usr/sbin/irqd
root      5848  0.0  0.0   7288  1420 ?        Ss   15:32   0:00 /usr/sbin/dhcrelay -q -i eth4.30 -i eth4.5 172.16.30.1
root      6017  0.0  0.4  78564 36868 ?        Ss   15:32   0:05 smtpd [master]
root      6021  0.0  0.0   4464   608 ?        S    17:05   0:00 /usr/sbin/cron
root      6026  0.0  0.3  42464 27176 ?        S    15:32   0:00 smtpd [queue manager]
root      6027  0.0  0.3  42464 26676 ?        S    15:32   0:00 smtpd [sandbox_watcher]
postgres  6028  0.0  0.0 1141388 6224 ?        Ss   15:32   0:00 postgres: smtp smtp 127.0.0.1(35343) idle                
root      6054  0.0  0.1  15764 10168 ?        Ss   17:05   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
smtp      6080  0.0  0.0  10960  2820 ?        S    15:32   0:01 /bin/exim -DINPUT -bdf
postgres  6082  0.0  0.0 1141288 5388 ?        Ss   15:32   0:00 postgres: smtp smtp 127.0.0.1(35346) idle                
root      6094 55.5  0.0  13148  4828 ?        R    17:05  51:38 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
root      6187  0.0  0.0  12384  4728 ?        Ss   15:32   0:00 /bin/httpd -f /etc/httpd/httpd.conf
root      6189  0.0  0.0   3956   536 ?        S    15:32   0:00 /bin/logger -t httpd -p local6.notice
wwwrun    6190  0.0  0.0  12296  1696 ?        S    15:32   0:00 /bin/httpd -f /etc/httpd/httpd.conf
root      6232  0.0  0.0   9628  3568 ?        Ss   15:32   0:00 /usr/sbin/dhcpd -cf /etc/dhcpd.conf eth4 eth4.100
root      6243  0.0  2.8 263132 229796 ?       Ssl  15:32   0:04 /usr/bin/cssd -d
root      6461  0.0  0.0   8408  1152 ?        Ss   15:32   0:00 /usr/libexec/postfix/master -w
root      6744  0.0  0.0   7588  2000 ?        Ss   15:32   0:00 /usr/sbin/dhclient -nw -cf /etc/eth5.conf -lf /var/db/eth5.leases -pf /var/run/dhclient_eth5.pid eth5
root      6808  0.0  0.0  15776  1852 ?        Ss   15:32   0:00 /sbin/ntpd
postgres  6939  0.0  0.0 1141312 5416 ?        Ss   15:33   0:00 postgres: sandbox sandbox [local] idle                   
postgres  6940  0.0  0.0 1141392 6060 ?        Ss   15:33   0:00 postgres: sandbox sandbox [local] idle                   
postgres  7218  0.0  0.0 1141456 6892 ?        Ss   15:35   0:05 postgres: smtp smtp 127.0.0.1(35407) idle                
root      7249  0.0  0.0      0     0 ?        Z    15:35   0:00 [aua.bin] <defunct>
810       7574  0.0  0.2 134696 17076 ?        Ss   15:36   0:01 /var/chroot-http/opt/ws/bin/urid --chroot /var/chroot-http --user 810 --admin /opt/ws/conf/admin.urilist --admin-ip /opt/ws/conf/adminip.kvlist
810       7601  0.5 12.0 1539088 965348 ?      Ssl  15:36   0:59 /var/chroot-http/usr/bin/httpproxy -f -c /var/chroot-http -u httpproxy
wwwrun    7848  0.0  0.0  12664  3916 ?        S    15:37   0:00 /bin/httpd -f /etc/httpd/httpd.conf
wwwrun    7852  0.0  0.0  12664  3916 ?        S    15:37   0:00 /bin/httpd -f /etc/httpd/httpd.conf
root      7864  0.0  0.0   4464   608 ?        S    17:20   0:00 /usr/sbin/cron
root      7899  0.0  0.1  15764 10168 ?        Ss   17:20   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root      7919  0.0  0.2  28212 16632 ?        Ss   15:37   0:00 /usr/apache/bin/httpd -k start
root      7952 50.7  0.0  13148  4828 ?        R    17:20  39:36 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
root      8560  0.0  0.0   3956   536 ?        S    15:37   0:00 /bin/logger -p local1.info -t httpd
nobody    8727  0.0  0.2 459124 19952 ?        Sl   15:37   0:06 /usr/apache/bin/httpd -k start
postgres  8836  0.0  0.1 1143796 8120 ?        Ss   15:37   0:00 postgres: reporting reporting [local] idle               
root      9509  0.0  0.0   4464   608 ?        S    17:35   0:00 /usr/sbin/cron
root      9536  0.0  0.1  15764 10168 ?        Ss   17:35   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root      9569 46.8  0.0  13148  4828 ?        R    17:35  29:32 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
root     11140  0.0  0.0   4464   608 ?        S    17:50   0:00 /usr/sbin/cron
root     11181  0.0  0.1  15764 10172 ?        Ss   17:50   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root     11229 43.8  0.0  13148  4824 ?        R    17:50  21:05 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
afcd     12825  0.0  0.3  72824 31972 ?        S<sl 18:02   0:00 /usr/sbin/afcd
postfix  12838  0.0  0.0   8528  2188 ?        S    18:02   0:00 qmgr -l -t unix -u -c
postfix  12839  0.0  0.0   8472  2248 ?        S    18:02   0:00 pickup -l -t unix -u -c
root     13062  0.0  0.0   4464   608 ?        S    18:05   0:00 /usr/sbin/cron
root     13095  0.0  0.1  15764 10164 ?        Ss   18:05   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root     13131 41.3  0.0  13148  4824 ?        R    18:05  13:39 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
root     14715  0.0  0.0   4464   608 ?        S    18:20   0:00 /usr/sbin/cron
root     14756  0.0  0.1  15764 10172 ?        Ss   18:20   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root     14795 39.1  0.0  13148  4824 ?        R    18:20   7:03 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
root     16219  0.0  0.0   4464   608 ?        S    18:35   0:00 /usr/sbin/cron
root     16254  0.0  0.1  15764 10172 ?        Ss   18:35   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root     16320 35.7  0.0  13148  4824 ?        R    18:35   1:05 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
root     16455  0.0  0.0   8084  3272 ?        Ss   18:35   0:00 sshd: loginuser [priv]                   
100      16483  0.0  0.0   8220  1500 ?        S    18:35   0:00 sshd: loginuser@pts/0                    
100      16501  0.0  0.0   7104  2072 pts/0    Ss   18:35   0:00 -bash
postfix  16509  0.0  0.0   8480  2184 ?        S    18:35   0:00 tlsmgr -l -t unix -u -c
root     16510  0.0  0.0  10260  2756 pts/0    S    18:35   0:00 sudo su
root     16515  0.0  0.0   6404  1188 pts/0    S    18:35   0:00 su
root     16528  0.0  0.0   7088  2172 pts/0    S    18:35   0:00 bash
root     16736  3.6  0.0      0     0 ?        Z    18:38   0:00 [confd.plx] <defunct>
root     16744  0.0  0.0   4916  1016 pts/0    R+   18:38   0:00 ps aux
root     18056  0.0  0.0   4464   608 ?        S    16:05   0:00 /usr/sbin/cron
root     18086  0.0  0.1  15764 10168 ?        Ss   16:05   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root     18133 72.5  0.0  13148  4824 ?        R    16:05 110:59 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
root     18341  0.0  0.0      0     0 ?        S    16:05   0:02 [kworker/0:1]
root     23842  0.0  0.0   4464   608 ?        S    16:20   0:00 /usr/sbin/cron
root     23875  0.0  0.1  15764 10168 ?        Ss   16:20   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root     23917 69.4  0.0  13148  4828 ?        R    16:20  95:55 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000
root     30358  0.0  0.0   4464   608 ?        S    16:35   0:00 /usr/sbin/cron
root     30383  0.0  0.1  15764 10168 ?        Ss   16:35   0:00 /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily
root     30413 65.7  0.0  13148  4828 ?        R    16:35  80:55 /usr/bin/rrdtool graph /var/log/reporting/images/cpuusage_daily.png_tmp --imgformat=PNG --alt-y-grid --rigid --lower-limit=0 --height=120 --width=500 --start -1d --title Cpu Usage (Daily) --x-grid MINUTE:30:HOUR:2:HOUR:2:0:%R --vertical-label=Percent DEF:a=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:AVERAGE DEF:x=/var/log/reporting/rrd/cpuusage.rrd:usage_pct:MAX CDEF:cdefa=a CDEF:cdefx=x VDEF:lsta=a,LAST VDEF:avga=a,AVERAGE VDEF:maxx=x,MAXIMUM AREA:cdefa#008680:Cpu usage (%) GPRINT:lsta:Current\:%8.2lf %s GPRINT:avga:Average\:%8.2lf %s GPRINT:maxx:Maximum\:%8.2lf %s\n LINE0.5:100#000000

Killing the rrdtool process didn't do anything as a second after another rrdtool process spawned. i had to kill all /usr/local/bin/create_rrd_graphs.plx --mode monthly,daily and then was able to pkill rrdtool. Few minutes later it was back draining my cpu so i had no choice but rename /usr/local/bin/create_rrd_graphs.plx to /usr/local/bin/create_rrd_graphs.plx.old. Today i let it run for three hours but it didnt finish whatever it was doing. I then cleand up the /var/log/reporting/rrd folder (as per https://community.sophos.com/utm-firewall/astaroorg/f/utm-9-2-beta/65432/9-190-bug-high-cpu-load-after-up2date) but it didnt make any difference.

I didn't do any updates on the firewall so i have no idea what could cause this. my CPU is "Intel(R) Xeon(R) CPU E3-1230 v5 @ 3.40GHz" so i don't think it is struggling with RRD graphs.



This thread was automatically locked due to age.
Parents
  • Same here. Running it on hyper-v. Even did a reinstall - as soon as the new instance got updated it started again. It was so bad that i actually installed XG (and i really don't like it). So it's some sort of an update that broke it. Judging by CPU usage chart (on both old and new instance) it ramps up in 25% steps until it hits 100% CPU usage.

Reply
  • Same here. Running it on hyper-v. Even did a reinstall - as soon as the new instance got updated it started again. It was so bad that i actually installed XG (and i really don't like it). So it's some sort of an update that broke it. Judging by CPU usage chart (on both old and new instance) it ramps up in 25% steps until it hits 100% CPU usage.

Children
  • i'm seeing exactly the same thing on a pair of Poweredge servers, 100% CPU because of rrdtool

  • i've renamed the rrdtool binary for now, and cpu usage has dropped back down, but obviously i assume graphs will die for now in the UI

  • What happened with the graphs after you renamed those?

  • graphs are dead for now, system keeps running normally otherwise though, and my users can connect over OpenVPN which they couldn't before. currently chatting with sophos support about the issue, could be corrupted reporting database

  • Can you all post your pattern update version?  It should be on the front page of your UTM.  Mine at this time is Pattern version: 196964

    There has not been any version updates for UTM, patterns are the only thing I am thinking might be the issue, unless it's a VM problem which may have updated VM.  

    OPNSense 64-bit | Intel Xeon 4-core v3 1225 3.20Ghz
    16GB Memory | 500GB SSD HDD | ATT Fiber 1GB
    (Former Sophos UTM Veteran, Former XG Rookie)

  • sure thing, i'm on the following: 

    Firmware version:9.705-3

    Pattern version:196211

    Last check:13 minutes ago​

  • Hi Dave and welcome to the UTM Community!

    The following resets the graphs.  I don't know if it might fix this issue.

    rm /var/log/reporting/rrd/*
    /etc/init.d/syslogng restart
    /etc/init.d/rrdcache restart
    /usr/local/bin/reporter/system-reporter.pl

    Any luck with that?

    Cheers -  Bob

     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • Has anyone tried this? Is the issue permanently fixed or happening again afterwards?

  • hi, thanks for the tip. that doesn't seem to have fixed the problem no. did a 'killall rrdtool' first, followed by your commands, all CPU is now consumed by this process: 


    PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
    29139 root 20 0 59876 52m 2752 R 4 0.7 1:45.75 create_rrd_grap
    9493 root 20 0 63944 56m 2752 R 4 0.7 1:49.58 create_rrd_grap
    10010 root 20 0 63944 56m 2752 R 4 0.7 1:57.64 create_rrd_grap
    17982 root 20 0 61856 54m 2752 R 4 0.7 2:00.10 create_rrd_grap
    23427 root 20 0 62508 55m 2752 R 4 0.7 1:54.96 create_rrd_grap
    29199 root 20 0 60008 52m 2752 R 4 0.7 1:59.32 create_rrd_grap
    32129 root 20 0 60800 53m 2752 R 4 0.7 1:55.50 create_rrd_grap

    Cpu(s): 97.5%us,  2.3%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.2%si,  0.0%st

  • Haigh Dave,

    It would be interesting to hear what Sophos Support has to say about this.  If this were a Home-use situation, I would be tempted to do a postgresql92 rebuild.  Let us know if that's what Support does.

    Cheers - Bob

     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA