pfTop hangs my GUI in 2.5.2 RC

Trey

Indeed pfctl and pftop are not very happy, when looking at cpu usage...

last pid: 46705;  load averages:  4.63,  5.26,  5.75                                                                                                                                                                 up 0+07:02:25  19:51:31
119 processes: 9 running, 106 sleeping, 1 zombie, 3 lock
CPU 0:  0.7% user,  0.0% nice, 63.3% system,  0.0% interrupt, 36.0% idle
CPU 1:  0.0% user,  0.0% nice, 87.4% system,  0.0% interrupt, 12.6% idle
CPU 2:  0.0% user,  0.0% nice, 51.1% system,  0.0% interrupt, 48.9% idle
CPU 3:  0.0% user,  0.0% nice, 74.8% system,  0.0% interrupt, 25.2% idle
CPU 4:  0.0% user,  0.0% nice, 79.7% system,  0.0% interrupt, 20.3% idle
CPU 5:  0.0% user,  0.0% nice, 63.9% system,  0.0% interrupt, 36.1% idle
CPU 6:  0.0% user,  0.0% nice, 39.5% system,  0.0% interrupt, 60.5% idle
CPU 7:  0.0% user,  0.0% nice, 51.9% system,  0.0% interrupt, 48.1% idle
Mem: 189M Active, 650M Inact, 4241M Wired, 165M Buf, 10G Free
Swap: 3656M Total, 3656M Free

  PID USERNAME    THR PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
18015 root          1  20    0   503M    61M CPU7     7 345:55  99.96% pfctl
38322 root          1  20   20   134M    18M CPU4     4 373:08  99.95% pfctl
84187 root          1  20   20   134M    18M CPU3     3 393:25  99.91% pfctl
95080 root          1  80    0   503M    61M RUN      5 289:22  99.90% pfctl
39212 root          1  20    0   112M    91M CPU6     6  18:23  62.80% pftop
39821 root          1  80    0   112M    92M *pf_id   4  15:57  38.04% pftop
30353 root          1  72    0   146M  3636K RUN      7   2:32   2.41% pftop
11621 root          1  20    0   113M    98M *pf_id   5  15:43   2.41% pftop
40726 root          1  75    0   112M  3264K CPU1     1  18:52   1.00% pftop
82711 root          1  81    0   503M    61M CPU0     0 199:33   0.95% pfctl
18221 root          1  20    0    17M  7284K select   4   1:21   0.37% openvpn
45830 root          1  20    0    13M  3740K CPU5     5   0:00   0.07% top
93616 unbound       8  20    0   232M    50M kqread   7   0:06   0.06% unbound

jimp

Can you share your /tmp/rules.debug?

Do you have any packages installed?

Any large pf tables/aliases? If so, how large?

maverick_slo

@jimp
Packages
acme security 0.6.9_3 Automated Certificate Management Environment, for automated use of LetsEncrypt certificates.

Package Dependencies:
pecl-ssh2-1.3.1 socat-1.7.4.1_1 php74-7.4.20 php74-ftp-7.4.20
Cron sysutils 0.3.7_5 The cron utility is used to manage commands on a schedule.
haproxy-devel net 0.62_3 The Reliable, High Performance TCP/HTTP(S) Load Balancer.
This package implements the TCP, HTTP and HTTPS balancing features from haproxy.
Supports ACLs for smart backend switching.

Package Dependencies:
haproxy-2.2.14
iperf benchmarks 3.0.2_5 Iperf is a tool for testing network throughput, loss, and jitter.

Package Dependencies:
iperf3-3.10.1
openvpn-client-export security 1.6_1 Allows a pre-configured OpenVPN Windows Client or Mac OS X's Viscosity configuration bundle to be exported directly from pfSense.

Package Dependencies:
openvpn-client-export-2.5.2 openvpn-2.5.2_2 zip-3.0_1 p7zip-16.02_3
snort

No large tables at all.. largest has like 5 entries

Trey

@jimp

I can share files and screen, but not in this forum. To many IPs in there.

Packages:
FRR, FreeRadius, OpenVPN Client Export

Aliases:

Couple of our networks, like 12x 192.168.0.0/24 networks, couple of dns aliases,
did have bogus network on in the interface config, and disabled it now, but i think you have to reboot...

jimp

Is this bare metal hardware or a VM?

How many CPUs/cores?

Trey

@jimp

Bare metal SuperMicro:
Intel(R) Atom(TM) CPU C3758 @ 2.20GHz
8 CPUs: 1 package(s) x 8 core(s)
AES-NI CPU Crypto: Yes (active)
QAT Crypto: Yes (inactive)

jimp

I thought maybe https://redmine.pfsense.org/issues/10414 had popped back up, but I can't replicate it using the commands that used to trigger it before. It's worth trying on your hardware though to see what happens.

Do you have bogons enabled?

If so, try the following commands:

$ /etc/rc.update_bogons.sh 0
$ time pfctl -t bogonsv6 -T flush
$ time pfctl -t bogonsv6 -T add -f /etc/bogonsv6
$ time pfctl -t bogonsv6 -T add -f /etc/bogonsv6

(yes, that last one is done twice)

You may have to reboot before doing that if it's already in the bad state it was in before.

Trey

@jimp

time pfctl -t bogonsv6 -T flush
122609 addresses deleted.
0.000u 0.048s 0:00.04 100.0%    240+210k 0+0io 0pf+0w

 time pfctl -t bogonsv6 -T add -f /etc/bogonsv6
122609/122609 addresses added.
0.226u 0.218s 0:00.44 97.7%     212+185k 0+0io 0pf+0w

 time pfctl -t bogonsv6 -T add -f /etc/bogonsv6
0/122609 addresses added.
0.231u 0.079s 0:00.31 96.7%     208+182k 0+0io 0pf+0w

PS: It was still in this bad state but the commands still worked...

maverick_slo

I had similar result.

Hyperv, 4 cores.

Before the upgrade not a single issue wigh beta...

jimp

OK, so at least we know it isn't the same bug coming back to haunt us, though that would have likely made tracking down the cause and resolution much easier.

From your earlier output, the pfctl commands getting hung up are dumping the state table contents.

Try each of the following, but no need to post the individual state output, just the timing:

$ pfctl -si | grep -A4 State
$ time pfctl -ss
$ time pfctl -vvss

maverick_slo

State Table Total Rate
current entries 1434
searches 3714325 359.4/s
inserts 138111 13.4/s
removals 136676 13.2/s

4.50 real 0.01 user 4.48 sys

1.32 real 0.01 user 1.30 sys

Trey

Okay, after a reboot the pftop page works again.

CPU usage was back to none. Then a pfctl -ss was running long....

After it ended I run:

pfctl -si | grep -A4 State
State Table                          Total             Rate
  current entries                     2407
  searches                          404293          546.3/s
  inserts                            20698           28.0/s
  removals                           18291           24.7/s

time pfctl -ss
0.141u 140.191s 2:20.52 99.8%   203+177k 0+0io 0pf+0w

time pfctl -vvss
0.157u 87.638s 1:28.08 99.6%    203+177k 0+0io 0pf+0w

And perhaps these aliases add a lot of ipv4 and ipv6:

Jun 15 20:21:31 filterdns 68338 Adding Action: pf table: Office365Server host: outlook.office365.com
Jun 15 20:21:31 filterdns 68338 Adding Action: pf table: Office365Server host: outlook.office.com
Jun 15 20:21:31 filterdns 68338 Adding Action: pf table: MailExternalServerIPs host: outlook.office365.com
Jun 15 20:21:31 filterdns 68338 Adding Action: pf table: IcingaExternClients host: outlook.office365.com

jimp

Hmm, it definitely shouldn't be taking that long to print out only 2400 states.

Trey

Block bogon networks was now on before reboot and is still...

pfctl shows up in top every now and then and uses a lot of cpu...

jimp

It's not likely related to bogons or aliases/tables at this point, but something in the state table.

I've started https://redmine.pfsense.org/issues/12045 for this, and one of the other devs has a lead on a possible solution.

We're still trying to find a way to replicate it locally yet, but no luck.

jimp

OK I can't quite get up to the number of states you had with a quick and dirty test but I was able to get up to about 900 states and I definitely saw a slowdown.

20-50 states: 0.01s
300-450 states: 3s
850 states: 20s

I could easily see it degrading fast, need more data points but that certainly appears to be significant growth. The FreeBSD commit I linked in the Redmine above mentions factorial time (O(N!)) which would be quite bad in terms of efficiency.

We're working on getting a fix into a new build, it should be available soon.

Trey

Sounds greate. I did a ktrace und kdump on pfctl -ss

62033 pfctl    0.126404 CALL  mmap(0,0xa01000,0x3<PROT_READ|PROT_WRITE>,0x1002<MAP_PRIVATE|MAP_ANON>,0xffffffff,0)
 62033 pfctl    0.126446 RET   mmap 34374418432/0x800e00000
 62033 pfctl    0.126700 CALL  ioctl(0x3,DIOCGETSTATESNV,0x7fffffffe410)
 62033 pfctl    71.020411 RET   ioctl 0
 62033 pfctl    71.020973 CALL  mmap(0,0x5000,0x3<PROT_READ|PROT_WRITE>,0x1002<MAP_PRIVATE|MAP_ANON>,0xffffffff,0)
 62033 pfctl    71.020984 RET   mmap 34368081920/0x8007f5000

It keeps 71 sec? (not so sure about how kdump time output) in ioctl(0x3,DIOCGETSTATESNV,0x7fffffffe410).... Does this confirm the nvlist bottleneck or is ioctl something else ?

Trey

Okay, that is easy to answer:

Add DIOCGETSTATESNV, an nvlist-based alternative to DIOCGETSTATES.

Also from netgate: https://reviews.freebsd.org/D30243

So this should be it...

Trey

Okay just as scrolling through the kdump output of pfctl -ss .... has netgate some developer for the pfctl binary? Because from my small understanding it always reads two files from the filesystem for each state... 2400 states x reading 2 files...

For me it looks a little insane to not cache the "/etc/nsswitch.conf" and "/etc/protocols", as it should waste a lot of time... Perhaps not, because the os is caching it, but still seems like a good idea to cache all that stuff....

This is really executed for each state:


 62033 pfctl    71.128083 CALL  fstatat(AT_FDCWD,0x80032b331,0x7fffffffe240,0)
 62033 pfctl    71.128086 NAMI  "/etc/nsswitch.conf"
 62033 pfctl    71.128091 STRU  struct stat {dev=159, ino=26564847, mode=0100644, nlink=1, uid=0, gid=0, rdev=53065152, atime=1623785215.468672000, mtime=1623781736.833527000, ctime=1623781736.833527000, birthtime=1623619006, size=188, blksize=32768, blocks=8, flags=0x0 }
 62033 pfctl    71.128093 RET   fstatat 0
 62033 pfctl    71.128096 CALL  open(0x80032e6b6,0x100000<O_RDONLY|O_CLOEXEC>)
 62033 pfctl    71.128099 NAMI  "/etc/protocols"
 62033 pfctl    71.128103 RET   open 4
 62033 pfctl    71.128106 CALL  fstat(0x4,0x7fffffffdea0)
 62033 pfctl    71.128108 STRU  struct stat {dev=159, ino=26564791, mode=0100644, nlink=1, uid=0, gid=0, rdev=53064232, atime=1623785215.488007000, mtime=1623619006, ctime=1623752821.339423000, birthtime=1623619006, size=6394, blksize=32768, blocks=16, flags=0x0 }
 62033 pfctl    71.128110 RET   fstat 0
 62033 pfctl    71.128112 CALL  read(0x4,0x80226bf80,0x8000)
 62033 pfctl    71.128117 GIO   fd 4 read 4096 bytes
       "#
	# Internet protocols
	#
	# $FreeBSD$
	#	from: @(#)protocols	5.1 (Berkeley) 4/17/89
	#
	# See also http://www.iana.org/assignments/protocol-numbers
	#
	ip	0	IP		# internet protocol, pseudo protocol number
	#hopopt	0	HOPOPT		# hop-by-hop options for ipv6
	icmp	1	ICMP		# internet control message protocol
	igmp	2	IGMP		# internet group management protocol
	ggp	3	GGP		# gateway-gateway protocol
	ipencap	4	IP-ENCAP	# IP encapsulated in IP (officially ``IP'')
	st2	5	ST2		# ST2 datagram mode (RFC 1819) (officially ``ST'')
	tcp	6	TCP		# transmission control protocol
	cbt	7	CBT		# CBT, Tony Ballardie <A.Ballardie@cs.ucl.ac.uk>
	egp	8	EGP		# exterior gateway protocol
	igp	9	IGP		# any private interior gateway (Cisco: for IGRP)
	bbn-rcc	10	BBN-RCC-MON	# BBN RCC Monitoring
	nvp	11	NVP-II		# Network Voice Protocol
	pup	12	PUP		# PARC universal packet protocol
	argus	13	ARGUS		# ARGUS
	emcon	14	EMCON		# EMCON
	xnet	15	XNET		# Cross Net Debugger
	chaos	16	CHAOS		# Chaos
	udp	17	UDP		# user datagram protocol
	mux	18	MUX		# Multiplexing protocol
	dcn	19	DCN-MEAS	# DCN Measurement Subsystems
	hmp	20	HMP		# host monitoring protocol
	prm	21	PRM		# packet radio measurement protocol
	xns-idp	22	XNS-IDP		# Xerox NS IDP
	trunk-1	23	TRUNK-1		# Trunk-1
	trunk-2	24	TRUNK-2		# Trunk-2
	leaf-1	25	LEAF-1		# Leaf-1
	leaf-2	26	LEAF-2		# Leaf-2
	rdp	27	RDP		# "reliable datagram" protocol
	irtp	28	IRTP		# Internet Reliable Transaction Protocol
	iso-tp4	29	ISO-TP4		# ISO Transport Protocol Class 4
	netblt	30	NETBLT		# Bulk Data Transfer Protocol
	mfe-nsp	31	MFE-NSP		# MFE Network Services Protocol
	merit-inp	32	MERIT-INP	# MERIT Internodal Protocol
	dccp	33	DCCP		# Datagram Congestion Control Protocol
	3pc	34	3PC		# Third Party Connect Protocol
	idpr	35	IDPR		# Inter-Domain Policy Routing Protocol
	xtp	36	XTP		# Xpress Transfer Protocol
	ddp	37	DDP		# Datagram Delivery Protocol
	idpr-cmtp	38	IDPR-CMTP	# IDPR Control Message Transport Proto
	tp++	39	TP++		# TP++ Transport Protocol
	il	40	IL		# IL Transport Protocol
	ipv6	41	IPV6		# ipv6
	sdrp	42	SDRP		# Source Demand Routing Protocol
	ipv6-route	43	IPV6-ROUTE	# routing header for ipv6
	ipv6-frag	44	IPV6-FRAG	# fragment header for ipv6
	idrp	45	IDRP		# Inter-Domain Routing Protocol
	rsvp	46	RSVP		# Resource ReSerVation Protocol
	gre	47	GRE		# Generic Routing Encapsulation
	dsr	48	DSR		# Dynamic Source Routing Protocol
	bna	49	BNA		# BNA
	esp	50	ESP		# encapsulating security payload
	ah	51	AH		# authentication header
	i-nlsp	52	I-NLSP		# Integrated Net Layer Security TUBA
	swipe	53	SWIPE		# IP with Encryption
	narp	54	NARP		# NBMA Address Resolution Protocol
	mobile	55	MOBILE		# IP Mobility
	tlsp	56	TLSP		# Transport Layer Security Protocol
	skip	57	SKIP		# SKIP
	ipv6-icmp	58	IPV6-ICMP	icmp6	# ICMP for IPv6
	ipv6-nonxt	59	IPV6-NONXT	# no next header for ipv6
	ipv6-opts	60	IPV6-OPTS	# destination options for ipv6
	#	61			# any host internal protocol
	cftp	62	CFTP		# CFTP
	#	63			# any local network
	sat-expak	64	SAT-EXPAK	# SATNET and Backroom EXPAK
	kryptolan	65	KRYPTOLAN	# Kryptolan
	rvd	66	RVD		# MIT Remote Virtual Disk Protocol
	ippc	67	IPPC		# Internet Pluribus Packet Core
	#	68			# any distributed filesystem
	sat-mon	69	SAT-MON		# SATNET Monitoring
	visa	70	VISA		# VISA Protocol
	ipcv	71	IPCV		# Internet Packet Core Utility
	cpnx	72	CPNX		# Computer Protocol Network Executive
	cphb	73	CPHB		# Computer Protocol Heart Beat
	wsn	74	WSN		# Wang Span Network
	pvp	75	PVP		# Packet Video Protocol
	br-sat-mon	76	BR-SAT-MON	# Backroom SATNET Monitoring
	sun-nd	77	SUN-ND		# SUN ND PROTOCOL-Temporary
	wb-mon	78	WB-MON		# WIDEBAND Monitoring
	wb-expak	79	WB-EXPAK	# WIDEBAND EXPAK
	iso-ip	80	ISO-IP		# ISO Internet Protocol
	vmtp	81	VMTP		# Versatile Message Transport
	secure-vmtp	82	SECURE-VMTP	# SECURE-VMTP
	vines	83	VINES		# VINES
	ttp	84	TTP		# TTP
	#iptm	84	IPTM		# Protocol Internet Protocol Traffic
	nsfnet-igp	85	NSFNET-IGP	# NSFNET-IGP
	dgp	86	DGP		# Dissimilar Gateway Protocol
	tcf	87	TCF		# TCF
	eigrp	88	EIGRP		# Enhanced Interior Routing Protocol (Cisco)
	ospf	89	OSPFIGP		# Open Shortest Path First IGP
	sprite-rpc	90	Sprite-RPC	# Sprite RPC Protocol
	larp	91	LARP		# Locus Address Resolution Protocol
	mtp	"
 62033 pfctl    71.128119 RET   read 6394/0x18fa
 62033 pfctl    71.128125 CALL  close(0x4)
 62033 pfctl    71.128129 RET   close 0
 62033 pfctl    71.128137 CALL  write(0x1,0x802252000,0x4c)
 62033 pfctl    71.128142 GIO   fd 1 wrote 76 bytes
       "all tcp 192.168.0.68:80 <- 192.168.11.7:50425       ESTABLISHED:ESTABLISHED
       "

mfld

I was about to open a thread here on the same before daring to touch redmine.

I noticed this thread on reddit.

Lo and behold I upgraded a 2.4.5-p1 to 2.5.2-RC and now the CPU is locked with high load from pfctl -ss.

System is virtual instance in KVM, single core, 1GB RAM. Less than half the RAM is used. No fancy packages. Normal workload service DNS recursion over tcp/853 and 53/udp averages 30-40k states out of 100k so it is not yet scaling.

In my case the states are mostly UDP connection from DNS clients. System used to handle 30-40k states like this without breaking a sweat and CPU utilization showing less than 10%. Now it handles around 1k states OK, once there are around 5k states it falls over.

screenshot at just under 5000 states

Cloned instance, upgraded to a 2.6.0 snapshot and see the same there.

I will try update to today's 2.5.2-RC build and see if it helps

Current Base System
2.5.2.r.20210613.1712
Latest Base System
2.5.2.r.20210615.1851

Edit2: Initially I came up with high load after updating to 2.5.2.r.20210615.1851 but this is because I had ~20k new connections coming in all at once after the reboot and this is a 5 dollar VPS so... Happy to report that having been live on 2.5.2.r.20210615.1851 for about 20 minutes now I am back to tens of thousands of states with "normal for my spec" load.