High CPU Usage (100%)

daniel_ · Dec 3, 2015, 8:33 PM

Hello,

CPU usage shown on the webgui page stays at 100% and sometimes drop but only to come back at 100% thereafter. I have disconnected all devices except for the modem on the WAN and my main computer on the LAN. And I'm not downloading anything or doing anything that generates high traffic. I currently only use PF sense as a firewall (no VPN, etc).

The strange thing is CPU usage drops to around 0% as soon as I disconnect the modem from the WAN…

Also, it's not like there was one thing always using most of the CPU, it changes over time.

Here are some examples of what I get:

last pid: 17891; load averages: 2.81, 2.76, 2.57 up 10+21:07:37 20:23:42
110 processes: 6 running, 92 sleeping, 12 waiting
CPU: 66.9% user, 0.0% nice, 33.1% system, 0.0% interrupt, 0.0% idle
Mem: 30M Active, 79M Inact, 83M Wired, 23M Buf, 27M Free
Swap:

PID USERNAME PRI NICE SIZE RES STATE TIME WCPU COMMAND
12706 root 77 0 10544K 2400K RUN 0:01 18.16% /sbin/pfctl -o basic -f /tmp/rules.debug
13404 unbound 52 0 21480K 9068K kqread 0:00 12.35% /usr/local/sbin/unbound -c /var/unbound/unbound.conf
82135 root 52 0 39828K 24520K piperd 1:53 11.18% php-fpm: pool lighty (php-fpm)
7468 root 52 0 39828K 24872K piperd 2:08 10.79% php-fpm: pool lighty (php-fpm)
11 root 155 ki31 0K 8K RUN 99.5H 6.30% [idle]
7116 dhcpd 26 0 16376K 8188K select 0:00 4.79% /usr/local/sbin/dhcpd -6 -user dhcpd -group _dhcp -chroot /var/dhcpd -cf
98966 dhcpd 21 0 16376K 9332K select 0:00 4.30% /usr/local/sbin/dhcpd -user dhcpd -group dhcp -chroot /var/dhcpd -cf /et
7219 root 24 0 5988K 1672K wait 0:00 4.30% /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/pref
70280 root 20 0 11384K 2764K RUN 0:42 0.78% top -aSH
12 root -56 - 0K 96K WAIT 90:40 0.00% [intr{swi5: fast taskq}]
52 root -8 - 0K 8K mdwait 37:31 0.00% [md1]
15 root -16 - 0K 8K RUN 30:28 0.00% [rand_harvestq]
29077 root 20 0 10292K 2048K select 30:01 0.00% /usr/sbin/syslogd -s -c -c -l /var/dhcpd/var/run/log -P /var/run/syslog.p
12 root -60 - 0K 96K WAIT 27:07 0.00% [intr{swi4: clock}]
5 root -16 - 0K 8K pftm 13:19 0.00% [pf purge]
33990 root 20 0 10124K 1856K select 11:42 0.00% /usr/local/sbin/apinger -c /var/etc/apinger.conf
280 root 20 0 27540K 14704K kqread 6:07 0.00% php-fpm: master process (/usr/local/lib/php-fpm.conf) (php-fpm)
47 root -8 - 0K 8K mdwait 3:58 0.00% [md0]
28357 root 20 0 10284K 2020K select 3:11 0.00% /usr/sbin/inetd -wW -R 0 -a 127.0.0.1 /var/etc/inetd.conf
1 root 46 0 9048K 676K wait 1:49 0.00% [init]
295 root 40 20 10516K 2184K kqread 1:36 0.00% /usr/local/sbin/check_reload_status
20 root 16 - 0K 8K syncer 1:27 0.00% [syncer]
12 root -72 - 0K 96K WAIT 1:25 0.00% [intr{swi1: netisr 0}]
37881 root 20 0 13104K 6584K kqread 1:09 0.00% /usr/local/sbin/lighttpd -f /var/etc/lighty-webConfigurator.conf
27517 root 20 0 10356K 2020K bpf 0:58 0.00% /usr/local/sbin/filterlog -i pflog0 -p /var/run/filterlog.pid
0 root -16 0 0K 72K swapin 0:57 0.00% [kernel{swapper}]
7 root -16 - 0K 8K psleep 0:38 0.00% [pagedaemon]
34156 root 20 0 11556K 2548K piperd 0:33 0.00% rrdtool -
18 root -16 - 0K 8K psleep 0:13 0.00% [bufdaemon]
16 root -68 - 0K 64K - 0:12 0.00% [usb{usbus1}]
16 root -68 - 0K 64K - 0:12 0.00% [usb{usbus0}]
19 root -16 - 0K 8K vlruwt 0:12 0.00% [vnlru]
97862 root 20 0 15908K 5268K select 0:07 0.00% sshd: admin@pts/0 (sshd)
17 root -16 ki-1 0K 8K pollid 0:04 0.00% [idlepoll]
38652 root 20 0 10236K 1960K nanslp 0:03 0.00% /usr/sbin/cron -s
0 root 8 0 0K 72K - 0:02 0.00% [kernel{thread taskq}]
42307 root 20 0 13268K 13168K select 0:01 0.00% /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid{ntpd}
55611 root 20 0 10832K 2884K ttyin 0:01 0.00% vi /cf/conf/config.xml
53198 root 20 0 10160K 2036K select 0:01 0.00% /usr/local/sbin/radvd -p /var/run/radvd.pid -C /var/etc/radvd.conf -m sys
63826 root 20 0 15908K 5204K select 0:01 0.00% sshd: admin@pts/1 (sshd)
89763 root 47 0 10084K 1852K kqread 0:01 0.00% /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/pref
32076 root 43 0 10076K 1708K nanslp 0:01 0.00% minicron: helper /usr/local/bin/ping_hosts.sh (minicron)
86769 root 52 20 10584K 2224K wait 0:01 0.00% /bin/sh /var/db/rrd/updaterrd.sh
318 root 20 0 8976K 3268K select 0:01 0.00% /sbin/devd -q
36104 root 20 0 10228K 1972K wait 0:01 0.00% /usr/local/sbin/dhcp6c -d -c /var/etc/dhcp6c_wan.conf -p /var/run/dhcp6c
14 root -8 - 0K 24K - 0:01 0.00% [geom{g_event}]
16422 root 74 0 27448K 15820K RUN 0:00 0.00% /usr/local/bin/php -f /usr/local/sbin/prefixes.php
89597 dhcpd 20 0 16504K 8216K select 0:00 0.00% /usr/local/sbin/dhcpd -6 -user dhcpd -group _dhcp -chroot /var/dhcpd -cf
4 root -16 - 0K 16K - 0:00 0.00% [cam{doneq0}]
98338 root 20 0 10948K 3088K pause 0:00 0.00% /bin/tcsh
12 root -88 - 0K 96K WAIT 0:00 0.00% [intr{irq14: ata0}]
6 root -16 - 0K 8K waitin 0:00 0.00% [sctp_iterator]
14 root -8 - 0K 24K - 0:00 0.00% [geom{g_down}]
4 root -16 - 0K 16K - 0:00 0.00% [cam{scanner}]
34421 _dhcp 20 0 10312K 2076K select 0:00 0.00% dhclient: vr1 (dhclient)

Another one:

last pid: 41826; load averages: 2.19, 2.52, 2.54 up 10+21:14:52 20:30:57
104 processes: 4 running, 87 sleeping, 1 zombie, 12 waiting
CPU: 50.4% user, 1.1% nice, 48.5% system, 0.0% interrupt, 0.0% idle
Mem: 20M Active, 82M Inact, 83M Wired, 23M Buf, 34M Free
Swap:

PID USERNAME PRI NICE SIZE RES STATE TIME WCPU COMMAND
33808 dhcpd 28 0 16376K 9332K select 0:00 8.25% /usr/local/sbin/dhcpd -user dhcpd -group dhcp -chroot /var/dhcpd -cf /et
7468 root 52 0 39828K 25968K nanslp 2:51 7.37% php-fpm: pool lighty (php-fpm)
28351 unbound 52 0 21480K 9068K kqread 0:00 7.18% /usr/local/sbin/unbound -c /var/unbound/unbound.conf
82135 root 52 0 39828K 25748K accept 2:36 6.88% php-fpm: pool lighty (php-fpm)
11 root 155 ki31 0K 8K RUN 99.5H 2.69% [idle]
86769 root 52 20 10584K 2224K piperd 0:01 1.66% /bin/sh /var/db/rrd/updaterrd.sh
70280 root 20 0 11384K 2764K RUN 0:47 0.78% top -aSH
12 root -56 - 0K 96K WAIT 90:40 0.00% [intr{swi5: fast taskq}]
52 root -8 - 0K 8K mdwait 37:32 0.00% [md1]
15 root -16 - 0K 8K - 30:28 0.00% [rand_harvestq]
29077 root 20 0 10292K 2048K select 30:02 0.00% /usr/sbin/syslogd -s -c -c -l /var/dhcpd/var/run/log -P /var/run/syslog.p
12 root -60 - 0K 96K WAIT 27:07 0.00% [intr{swi4: clock}]
5 root -16 - 0K 8K pftm 13:20 0.00% [pf purge]
33990 root 20 0 10124K 1856K select 11:43 0.00% /usr/local/sbin/apinger -c /var/etc/apinger.conf
280 root 20 0 27540K 14704K kqread 6:07 0.00% php-fpm: master process (/usr/local/lib/php-fpm.conf) (php-fpm)
47 root -8 - 0K 8K mdwait 3:58 0.00% [md0]
28357 root 20 0 10284K 2020K select 3:12 0.00% /usr/sbin/inetd -wW -R 0 -a 127.0.0.1 /var/etc/inetd.conf
1 root 52 0 9048K 676K wait 1:49 0.00% [init]
295 root 40 20 10516K 2184K kqread 1:36 0.00% /usr/local/sbin/check_reload_status
20 root 16 - 0K 8K syncer 1:27 0.00% [syncer]
12 root -72 - 0K 96K WAIT 1:25 0.00% [intr{swi1: netisr 0}]
37881 root 20 0 13104K 6584K kqread 1:09 0.00% /usr/local/sbin/lighttpd -f /var/etc/lighty-webConfigurator.conf
27517 root 20 0 10356K 2020K bpf 0:58 0.00% /usr/local/sbin/filterlog -i pflog0 -p /var/run/filterlog.pid
0 root -16 0 0K 72K swapin 0:57 0.00% [kernel{swapper}]
7 root -16 - 0K 8K psleep 0:38 0.00% [pagedaemon]
34156 root 20 0 11556K 2548K piperd 0:33 0.00% rrdtool -
18 root -16 - 0K 8K psleep 0:13 0.00% [bufdaemon]
16 root -68 - 0K 64K - 0:12 0.00% [usb{usbus1}]
16 root -68 - 0K 64K - 0:12 0.00% [usb{usbus0}]
19 root -16 - 0K 8K vlruwt 0:12 0.00% [vnlru]
97862 root 20 0 15908K 5268K select 0:07 0.00% sshd: admin@pts/0 (sshd)
17 root -16 ki-1 0K 8K pollid 0:04 0.00% [idlepoll]
38652 root 20 0 10236K 1960K nanslp 0:03 0.00% /usr/sbin/cron -s
0 root 8 0 0K 72K - 0:02 0.00% [kernel{thread taskq}]
42307 root 20 0 13268K 13168K select 0:02 0.00% /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid{ntpd}
53198 root 20 0 10160K 2036K select 0:01 0.00% /usr/local/sbin/radvd -p /var/run/radvd.pid -C /var/etc/radvd.conf -m sys
55611 root 20 0 10832K 2884K ttyin 0:01 0.00% vi /cf/conf/config.xml
89763 root 31 0 10084K 1872K kqread 0:01 0.00% /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/pref
63826 root 20 0 15908K 5204K select 0:01 0.00% sshd: admin@pts/1 (sshd)
36104 root 20 0 10228K 1972K wait 0:01 0.00% /usr/local/sbin/dhcp6c -d -c /var/etc/dhcp6c_wan.conf -p /var/run/dhcp6c
32076 root 46 0 10076K 1708K nanslp 0:01 0.00% minicron: helper /usr/local/bin/ping_hosts.sh (minicron)
318 root 20 0 8976K 3268K select 0:01 0.00% /sbin/devd -q
14 root -8 - 0K 24K - 0:01 0.00% [geom{g_event}]
89597 dhcpd 20 0 16504K 8216K select 0:00 0.00% /usr/local/sbin/dhcpd -6 -user dhcpd -group _dhcp -chroot /var/dhcpd -cf
4 root -16 - 0K 16K - 0:00 0.00% [cam{doneq0}]
98338 root 20 0 10948K 3088K pause 0:00 0.00% /bin/tcsh
12 root -88 - 0K 96K WAIT 0:00 0.00% [intr{irq14: ata0}]
6 root -16 - 0K 8K waitin 0:00 0.00% [sctp_iterator]
14 root -8 - 0K 24K - 0:00 0.00% [geom{g_down}]
34421 _dhcp 20 0 10312K 2076K select 0:00 0.00% dhclient: vr1 (dhclient)
4 root -16 - 0K 16K - 0:00 0.00% [cam{scanner}]
32674 root 20 0 10076K 1708K nanslp 0:00 0.00% minicron: helper /usr/local/sbin/fcgicli -f /etc/rc.expireaccounts (mini
75211 root 20 0 10948K 2972K pause 0:00 0.00% /bin/tcsh
9 root 155 ki31 0K 8K pgzero 0:00 0.00% [pagezero]
42876 root 52 0 10576K 2232K wait 0:00 0.00% login [pam] (login)

And a last one:

last pid: 6841; load averages: 2.07, 2.44, 2.51 up 10+21:15:31 20:31:36
104 processes: 3 running, 89 sleeping, 12 waiting
CPU: 80.7% user, 0.0% nice, 19.3% system, 0.0% interrupt, 0.0% idle
Mem: 20M Active, 82M Inact, 83M Wired, 23M Buf, 34M Free
Swap:

PID USERNAME PRI NICE SIZE RES STATE TIME WCPU COMMAND
866 root 77 0 10544K 2640K RUN 0:01 18.26% /sbin/pfctl -o basic -f /tmp/rules.debug
2185 unbound 52 0 21480K 9068K kqread 0:00 12.35% /usr/local/sbin/unbound -c /var/unbound/unbound.conf
7468 root 52 0 39828K 25980K nanslp 2:55 11.87% php-fpm: pool lighty (php-fpm)
82135 root 52 0 39828K 25760K piperd 2:40 10.79% php-fpm: pool lighty (php-fpm)
11 root 155 ki31 0K 8K RUN 99.5H 5.57% [idle]
96679 dhcpd 24 0 16376K 8188K select 0:00 4.30% /usr/local/sbin/dhcpd -6 -user dhcpd -group dhcp -chroot /var/dhcpd -cf
97046 root 39 0 5988K 1672K kqread 0:00 3.86% /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/pref
70280 root 20 0 11384K 2764K RUN 0:47 0.78% top -aSH
12 root -56 - 0K 96K WAIT 90:40 0.00% [intr{swi5: fast taskq}]
52 root -8 - 0K 8K mdwait 37:32 0.00% [md1]
15 root -16 - 0K 8K - 30:28 0.00% [rand_harvestq]
29077 root 20 0 10292K 2048K select 30:02 0.00% /usr/sbin/syslogd -s -c -c -l /var/dhcpd/var/run/log -P /var/run/syslog.p
12 root -60 - 0K 96K WAIT 27:08 0.00% [intr{swi4: clock}]
5 root -16 - 0K 8K pftm 13:20 0.00% [pf purge]
33990 root 20 0 10124K 1856K select 11:43 0.00% /usr/local/sbin/apinger -c /var/etc/apinger.conf
280 root 20 0 27540K 14704K kqread 6:07 0.00% php-fpm: master process (/usr/local/lib/php-fpm.conf) (php-fpm)
47 root -8 - 0K 8K mdwait 3:58 0.00% [md0]
28357 root 20 0 10284K 2020K select 3:12 0.00% /usr/sbin/inetd -wW -R 0 -a 127.0.0.1 /var/etc/inetd.conf
1 root 30 0 9048K 676K wait 1:49 0.00% [init]
295 root 40 20 10516K 2184K kqread 1:36 0.00% /usr/local/sbin/check_reload_status
20 root 16 - 0K 8K syncer 1:27 0.00% [syncer]
12 root -72 - 0K 96K WAIT 1:25 0.00% [intr{swi1: netisr 0}]
37881 root 20 0 13104K 6584K kqread 1:09 0.00% /usr/local/sbin/lighttpd -f /var/etc/lighty-webConfigurator.conf
27517 root 20 0 10356K 2020K bpf 0:58 0.00% /usr/local/sbin/filterlog -i pflog0 -p /var/run/filterlog.pid
0 root -16 0 0K 72K swapin 0:57 0.00% [kernel{swapper}]
7 root -16 - 0K 8K psleep 0:38 0.00% [pagedaemon]
34156 root 20 0 11556K 2548K piperd 0:33 0.00% rrdtool -
18 root -16 - 0K 8K psleep 0:13 0.00% [bufdaemon]
16 root -68 - 0K 64K - 0:12 0.00% [usb{usbus1}]
16 root -68 - 0K 64K - 0:12 0.00% [usb{usbus0}]
19 root -16 - 0K 8K vlruwt 0:12 0.00% [vnlru]
97862 root 20 0 15908K 5268K select 0:07 0.00% sshd: admin@pts/0 (sshd)
17 root -16 ki-1 0K 8K pollid 0:04 0.00% [idlepoll]
38652 root 20 0 10236K 1960K nanslp 0:03 0.00% /usr/sbin/cron -s
0 root 8 0 0K 72K - 0:02 0.00% [kernel{thread taskq}]
42307 root 20 0 13268K 13168K select 0:02 0.00% /usr/local/sbin/ntpd -g -c /var/etc/ntpd.conf -p /var/run/ntpd.pid{ntpd}
53198 root 20 0 10160K 2036K select 0:01 0.00% /usr/local/sbin/radvd -p /var/run/radvd.pid -C /var/etc/radvd.conf -m sys
55611 root 20 0 10832K 2884K ttyin 0:01 0.00% vi /cf/conf/config.xml
89763 root 43 0 10084K 1876K kqread 0:01 0.00% /usr/local/sbin/dhcpleases6 -c /usr/local/bin/php -f /usr/local/sbin/pref
63826 root 20 0 15908K 5204K select 0:01 0.00% sshd: admin@pts/1 (sshd)
86769 root 52 20 10584K 2224K wait 0:01 0.00% /bin/sh /var/db/rrd/updaterrd.sh
36104 root 20 0 10228K 1972K wait 0:01 0.00% /usr/local/sbin/dhcp6c -d -c /var/etc/dhcp6c_wan.conf -p /var/run/dhcp6c
32076 root 46 0 10076K 1708K nanslp 0:01 0.00% minicron: helper /usr/local/bin/ping_hosts.sh (minicron)
318 root 20 0 8976K 3268K select 0:01 0.00% /sbin/devd -q
14 root -8 - 0K 24K - 0:01 0.00% [geom{g_event}]
89597 dhcpd 20 0 16504K 8216K select 0:00 0.00% /usr/local/sbin/dhcpd -6 -user dhcpd -group _dhcp -chroot /var/dhcpd -cf
4 root -16 - 0K 16K - 0:00 0.00% [cam{doneq0}]
98338 root 20 0 10948K 3088K pause 0:00 0.00% /bin/tcsh
12 root -88 - 0K 96K WAIT 0:00 0.00% [intr{irq14: ata0}]
6 root -16 - 0K 8K waitin 0:00 0.00% [sctp_iterator]
14 root -8 - 0K 24K - 0:00 0.00% [geom{g_down}]
34421 _dhcp 20 0 10312K 2076K select 0:00 0.00% dhclient: vr1 (dhclient)
4 root -16 - 0K 16K - 0:00 0.00% [cam{scanner}]
32674 root 20 0 10076K 1708K nanslp 0:00 0.00% minicron: helper /usr/local/sbin/fcgicli -f /etc/rc.expireaccounts (mini
75211 root 20 0 10948K 2972K pause 0:00 0.00% /bin/tcsh

Any idea what could cause this high CPU usage ?

heper · Dec 4, 2015, 10:28 AM

System logs show gateway flipflop?
Try to adjust gateway monitor settings until it starts behaving

daniel_ · Dec 5, 2015, 3:15 PM

I don't know what you mean by gateway flipflop (I'm no network expert). In the gateway log, one message comes back every 12 seconds: "apinger: SIGHUP received, reloading configuration." Is it normal that it reloads config every 12 seconds ?

I'm not sure what you mean by adjusting monitor settings (again I'm not network expert), but I've disabled gateway monitoring on the two configured gateways (WAN_DHCP and WAN_DHCP6), applied and it didn't change CPU usage. Actually, I've even disabled both gateways, applied and it didn't change CPU usage, and I still had Internet access…

daniel_ · Dec 5, 2015, 4:44 PM

I saw that error in system > routing (it kept coming back every few seconds):

radvd[31817]: prefix length should be 64 for vr0

I googled it and found things like that: http://superuser.com/questions/662851/radvd-wont-accept-non-64-subnets

So I manually set the prefix length to 60 (in the WAN interface config). That took care of this message.

Then it seemed like the processor usage dropped a bit, but still had frequent 100% peaks. Plus other services kept logging (things like reload…)

So I disabled IPv6 on WAN and LAN interfaces and the constant logging stopped, and the processor usage dropped and is now oscillating between 0 and 50%.

I would prefer to have IPv6 on, but at least now I've got a more healthy situation for my firewall...

Here's a chunk of the log before turning off IPv6, if anyone can tell me what's wrong with IPv6 on my firewall...

Dec 5 17:29:23 kernel: arpresolve: can't allocate llinfo for 192.168.0.1 on vr1
Dec 5 17:29:23 check_reload_status: rc.newwanip starting vr1
Dec 5 17:29:23 php-fpm[62205]: /interfaces.php: ROUTING: setting default route to 192.168.0.1
Dec 5 17:29:24 check_reload_status: Restarting ipsec tunnels
Dec 5 17:29:29 php-fpm[4112]: /rc.newwanip: rc.newwanip: Info: starting on vr1.
Dec 5 17:29:29 php-fpm[4112]: /rc.newwanip: rc.newwanip: on (IP address: 192.168.0.10) (interface: WAN[wan]) (real interface: vr1).
Dec 5 17:29:31 php-fpm[62205]: /interfaces.php: Shutting down Router Advertisment daemon cleanly
Dec 5 17:29:31 check_reload_status: updating dyndns wan
Dec 5 17:29:31 check_reload_status: Restarting ipsec tunnels
Dec 5 17:29:36 php-fpm[4112]: /rc.newwanip: ROUTING: setting default route to 192.168.0.1
Dec 5 17:29:39 check_reload_status: updating dyndns lan
Dec 5 17:29:41 check_reload_status: Reloading filter
Dec 5 17:29:41 php-fpm[62205]: /interfaces.php: Creating rrd update script
Dec 5 17:29:44 php-fpm[4112]: /rc.newwanip: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1449332984] unbound[48401:0] error: bind: address already in use [1449332984] unbound[48401:0] fatal error: could not open ports'
Dec 5 17:29:46 php-fpm[4112]: /rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Dec 5 17:29:46 php-fpm[4112]: /rc.newwanip: Creating rrd update script
Dec 5 17:29:48 php-fpm[4112]: /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 192.168.0.10 -> 192.168.0.10 - Restarting packages.
Dec 5 17:29:48 check_reload_status: Starting packages
Dec 5 17:29:51 php-fpm[4112]: /rc.start_packages: Restarting/Starting all packages.