CPU usage increase suddenly

michmoor · Aug 5, 2023, 10:31 PM

I am trying to track down high cpu usage which based on the below output might be related to unbound. I havent made any changes to my dns resolver so why would there be a sudden increase in CPU utilization. Perhaps it isnt unbound related and im chasing the wrong thing. Any extra eyes would be appreciated.
I restarted the DNS resolver hoping that would resolve the issue but it didnt.
Version: 23.05.1-RELEASE (amd64)

edit: Seems this started around 8/4. I checked my config history and the only changes made was the creation of a GeoIP Native Alias and updating firewall rules using that new Alias.

last pid: 25033;  load averages:  0.88,  0.96,  0.85                                                                                                                                                                up 14+16:55:09  18:21:08
444 threads:   6 running, 399 sleeping, 39 waiting
CPU: 25.7% user,  0.0% nice,  1.8% system,  0.1% interrupt, 72.4% idle
Mem: 362M Active, 2702M Inact, 2217M Wired, 2504M Free
ARC: 1313M Total, 544M MFU, 659M MRU, 1461K Anon, 6168K Header, 101M Other
     1053M Compressed, 2440M Uncompressed, 2.32:1 Ratio
Swap: 1024M Total, 1024M Free

  PID USERNAME    PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
53691 unbound     113    0   179M   159M CPU2     2   2:31  99.63% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}
   11 root        187 ki31     0B    64K RUN      0 331.2H  82.06% [idle{idle: cpu0}]
   11 root        187 ki31     0B    64K RUN      2 323.2H  80.33% [idle{idle: cpu2}]
   11 root        187 ki31     0B    64K CPU3     3 317.3H  72.35% [idle{idle: cpu3}]
   11 root        187 ki31     0B    64K CPU1     1 320.7H  56.32% [idle{idle: cpu1}]
 8387 www          20    0    44M    23M kqread   1  25:34   1.14% /usr/local/sbin/haproxy -f /var/etc/haproxy/haproxy.cfg -p /var/run/haproxy.pid -D -x /tmp/haproxy.socket -sf 97864
18304 root         20    0    12M  2484K zcw->z   3   0:01   0.58% /usr/local/sbin/dhcpleases -l /var/dhcpd/var/db/dhcpd.leases -d networkingtitan.com -p /var/run/unbound.pid -u /var/unbound/dhcpleases_entries.conf -h /etc/hosts
23975 root         20    0   856M   708M uwait    0 111:17   0.53% /usr/local/bin/suricata -i lagg0.15 -D -c /usr/local/etc/suricata/suricata_22346_lagg0.15/suricata.yaml --pidfile /var/run/suricata_lagg0.1522346.pid{FM#01}
59321 root         20    0   666M   578M uwait    3 111:20   0.53% /usr/local/bin/suricata -i lagg0.3 -D -c /usr/local/etc/suricata/suricata_55358_lagg0.3/suricata.yaml --pidfile /var/run/suricata_lagg0.355358.pid{FM#01}
30622 root         20    0    13M  3152K select   3  98:33   0.53% /usr/sbin/syslogd -O rfc3164 -s -c -c -l /var/dhcpd/var/run/log -l /tmp/haproxy_chroot/var/run/log -P /var/run/syslog.pid -f /etc/syslog.conf -b 192.168.50.254
98310 root         20    0   746M   669M uwait    3 110:20   0.52% /usr/local/bin/suricata -i lagg0.11 -D -c /usr/local/etc/suricata/suricata_41457_lagg0.11/suricata.yaml --pidfile /var/run/suricata_lagg0.1141457.pid{FM#01}
    0 root        -60    -     0B  1760K -        1 101:26   0.32% [kernel{if_io_tqg_1}]
35711 root         20    0    13M  3584K bpf      2  62:29   0.22% /usr/local/sbin/filterlog -i pflog0 -p /var/run/filterlog.pid
59321 root         20    0   666M   578M bpf      3  41:45   0.21% /usr/local/bin/suricata -i lagg0.3 -D -c /usr/local/etc/suricata/suricata_55358_lagg0.3/suricata.yaml --pidfile /var/run/suricata_lagg0.355358.pid{W#01-lagg0.3}
    0 root        -60    -     0B  1760K -        2  32:26   0.21% [kernel{wg_tqg_2}]
    0 root        -60    -     0B  1760K -        2  70:02   0.19% [kernel{if_io_tqg_2}]
    0 root        -60    -     0B  1760K -        0  70:20   0.16% [kernel{if_io_tqg_0}]
14736 root         20    0    17M  4904K CPU0     0   0:00   0.16% top -aSH

michmoor · Aug 5, 2023, 10:50 PM

I found the culprit. I disabled pfBlockerNG and cpu went back to high 90% idle.
Is anyone aware of any issues recently with pfBlocker? Im running the latest package 3.2.0_5

edit: For anyone that comes after me and needs help or wonder how i went down this path of troubleshooting this was my thought process on this problem. I saw what was showing up consistently in my CPU process. Unbound on its own i generally dont have a problem with but i know pfblocker does manipulate it in some way so thats what led me to first restart the unbound service then pfblockerng.

Also this was useful: https://docs.netgate.com/pfsense/en/latest/troubleshooting/high-cpu-load.html#troubleshooting-high-cpu-load

stephenw10 · Aug 6, 2023, 1:04 AM

Hmm, it would be interesting to know exactly what pfBlocker was doing there, or asking Unbound to do.

Does it come back if you re-enable pfBlocker?

michmoor · Aug 6, 2023, 1:04 AM

@stephenw10 Interestingly when i try to start the DNSBL service it fails. Nothing in the log thats helpful.
PFblocker just the IP blocking is working without issue. Just the dns sinkholing is where we're failing. My curiosity here is peaked.
Any commands you can recommend to gain some insight?

michmoor · Aug 6, 2023, 2:00 AM

@stephenw10 Restarted the entire pfblocker package and now its functioning. The increased in CPU usage has come back -- unbound related.
How can i diagnose better?

Below is when i had pfblocker Enabled without DNSBL. Then I turned it back on.

michmoor · Aug 6, 2023, 3:22 PM

Just really weird that unbound tied with pfblocker is acting so strange.

Phizix · Aug 6, 2023, 3:52 PM

@michmoor,

Is it not expected for it to use some more CPU? So is it much more than expected?

Phizix

michmoor · Aug 6, 2023, 5:34 PM

@Phizix Historically on my SG-6100 cpu utilization isnt an issue. I have a baseline so thats how i know where this an issue. Right now although DNSBL is the problem its not causing any system instability. I would like to know why its acting this way if there is indeed an issue which i suspect there is.

Phizix · Aug 6, 2023, 6:29 PM

@michmoor,

Makes sense if you had a baseline to compare to. So indeed more CPU usage than normal.

I am curious what you find when you solve it. Was there a recent package update?

Phizix

michmoor · Aug 6, 2023, 7:54 PM

@Phizix I'll keep this thread as updated as i can. I started a reddit post on it so i hope the maintainer can respond there as well. @BBcan177

  PID USERNAME    THR PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
36790 unbound       1 118    0   294M   260M CPU3     3 551:03 100.96% unbound
 8387 www           1  20    0    44M    23M kqread   3  41:13   1.27% haproxy
59321 root          5  20    0   666M   578M nanslp   3 187:01   0.79% suricata
18304 root          1  20    0    12M  2488K kqread   3   7:11   0.75% dhcpleases
23975 root          5  20    0   859M   711M nanslp   3 172:29   0.70% suricata
98310 root          5  20    0   745M   667M nanslp   2 145:47   0.58% suricata
30622 root          1  20    0    13M  3152K select   0 105:28   0.44% syslogd
35711 root          1  20    0    13M  3584K bpf      3  66:04   0.22% filterlog
96223 root          1  20    0    14M  4000K CPU2     2   0:00   0.10% top
60163 nobody        1  20    0    16M  4996K select   3   0:32   0.08% softflowd
46104 zabbix        1   4    0    24M    11M select   1   5:45   0.08% zabbix_agentd
13937 root         17  68    0   107M    28M sigwai   1   7:27   0.08% charon
45925 zabbix        1  20    0    24M    11M select   1   5:39   0.07% zabbix_agentd
60519 dhcpd         1  20    0    25M    13M select   1   0:49   0.07% dhcpd
31822 root          1  20    0    18M  8012K select   0   9:39   0.05% openvpn
48305 root          3  20    0    69M    35M kqread   1   1:26   0.05% syslog-ng

michmoor · Aug 6, 2023, 9:53 PM

Problem solved. Re-installed pfblockerNG. Made sure i had the 'Keep settings' option enabled.
It was really a last option thing. I didnt know if a reinstall would fix it but i knew there was something wrong with the configuration.
I had a custom DNS block list that was blocking example.com. I have since removed it a while ago but i noticed the domain is still getting sink holed. I triple checked to make sure the domain wasnt listed but pfblocker was indeed blocking it.
Re-install and now im back to baseline. Weird bug in the package but without other tools to debug i cant say why the package freaked out the way it did. I also cant reproduce the problem anymore.

Phizix · Aug 6, 2023, 10:25 PM

@michmoor,

Thanks for the follow-up. Good to know.

Phizix

michmoor · Aug 8, 2023, 1:43 PM

The problem has come back.
Restarting unbound or dnbl doesnt solve the problem. The only solution is to disable DNSBL and cpu util goes back to normal.
I honestly have no idea and im at a lost.
I reinstalled the package from completely not saving any settings.

   11 root        187 ki31     0B    64K RUN      2 862:26  87.99% [idle{idle: cpu2}]
   11 root        187 ki31     0B    64K CPU3     3 835:22  84.28% [idle{idle: cpu3}]
   11 root        187 ki31     0B    64K CPU1     1 851:44  77.69% [idle{idle: cpu1}]
18451 unbound      68    0   235M   202M kqread   1   7:55  46.19% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}
18451 unbound      68    0   235M   202M kqread   1   0:00  46.00% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}
18451 unbound      68    0   235M   202M kqread   0   0:00  46.00% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}
18451 unbound      68    0   235M   202M kqread   2   0:00  46.00% /usr/local/sbin/unbound -c /var/unbound/unbound.conf{unbound}

michmoor · Aug 8, 2023, 2:15 PM

Interesting...Checking the DNS logs i see the same script being loaded over and over again.
Im still poking around. No clue right now :)
Whats also so weird is that unbound keeps restarting..

stephenw10 · Aug 8, 2023, 2:37 PM

Can you disable python mode in pfBlocker to test?

If you run ps -auxwwd can you see what script is actually running?

michmoor · Aug 8, 2023, 2:41 PM

@stephenw10 I think i solved it. Im fairly confident its solved now....i hope

The clues are in the DNS logs. I noticed Unbound kept restarting and i remember a while ago reading on the forums that DHCP registration causes Unbound to restart. I do have registration enabled for all VLANs so i wasnt totally buying that as a reason. Regardless I reviewed each DHCP configuration for the vlans and what do i find?

Ahhh this aggressive lease timer. I stood up new DNS servers for a vlan and needed clients to switch over quickly. I never updated this until today. Switched back to defaults and CPU utilization shot back down to normal baseline levels.

Someone correct me if im wrong but i thought the DHCP registration issue with needed Unbound to restart was solved in the latest release?

stephenw10 · Aug 8, 2023, 2:50 PM

Part of that issue was solved but it still restarts Unbound to load the new values every time. Which is.... sub optimal!

Yes, 60s is very short. Any reason it was set to that?

michmoor · Aug 8, 2023, 2:56 PM

@stephenw10 said in CPU usage increase suddenly:

Yes, 60s is very short. Any reason it was set to that?

Reply

I stood up new DNS servers and wanted devices to cut over right away which worked but caused an issue for myself.

This entire issue smelled like a config problem but i couldn't prove it at the time. I went against my rule of rebooting the firewall as i truly dislike doing that especially if things were working before.