Performance problems after 2.1.5 -> 2.2.4 upgrade

wwwdrich

I upgraded my WatchGuard x550e to 2.2.4 this weekend, and have been having horrible performance since then. If I watch the serial console on boot the output speed seems fine until about when I see the "Generating RRD graphs…done." message. From right around that point the output on the console slows to a crawl. Once it boots even running commands on the console can take 60-90 seconds and the commands cannot be interrupted. As an example, I just ran 'ls /tmp', and it is just sitting there. Ctrl-c has no immediate effect, although in 30-60 seconds it will usually exit the command if I hit it.

I have tried using truss to see where the command is hanging up, but since I have the same issue with truss it doesn't really help. I just ran 'truss -aefdD /bin/ls /tmp', and I'm still waiting for the first line of output. Once truss starts, it runs the ls command in less than a second. It doesn't appear to be a cache issue, since if I run that same 'ls /tmp' command immediately it will still pause for another 60 seconds or so before outputting anything.

Everything looks fine on the web dashboard (when it finally loads), I have plenty of space in in the filesystems and it is hardly using the 2GB of memory on the box. There is nothing in syslog or dmesg that looks odd either.

The odd thing is that there is an easy fix -- /etc/rc.conf_mount_rw. Since I'm running the nanobsd image on a CF card, I really don't want to do this; but it gets rid of the delay when running commands and makes the web interface responsive again. However, fstat -f doesn't show anything trying to write to the root partition, so I'm not sure why that makes a difference.

Any ideas? I have a nearly identical box that was a clean install instead of an upgrade and isn't showing this problem. From a diff of the boot messages the only obvious difference is that the working box has a CF card that is an ATA device and the CF card in the slow box is CFA.

-ada0: <cf card="" ver7.01k="">CFA-5 device
+ada0: <cf 20140121="" card="">ATA-0 device</cf></cf>

Here is the boot dmesg:

Copyright (c) 1992-2014 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
	The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 10.1-RELEASE-p15 #0 c5ab052(releng/10.1)-dirty: Sat Jul 25 20:29:48 CDT 2015
    root@pfs22-i386-builder:/usr/obj.i386/usr/pfSensesrc/src/sys/pfSense_wrap.10.i386 i386
FreeBSD clang version 3.4.1 (tags/RELEASE_34/dot1-final 208032) 20140512
VT: running with driver "vga".
module_register: module pci/mskc already exists!
Module pci/mskc failed to register: 17
module_register: module mskc/msk already exists!
Module mskc/msk failed to register: 17
module_register: module msk/miibus already exists!
Module msk/miibus failed to register: 17
module_register: module pci/skc already exists!
Module pci/skc failed to register: 17
module_register: module skc/sk already exists!
Module skc/sk failed to register: 17
module_register: module sk/miibus already exists!
Module sk/miibus failed to register: 17
CPU: Intel(R) Pentium(R) M processor 2.00GHz (2000.11-MHz 686-class CPU)
  Origin = "GenuineIntel"  Id = 0x6d6  Family = 0x6  Model = 0xd  Stepping = 6
  Features=0xafe9fbbf <fpu,vme,de,pse,tsc,msr,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,tm,pbe>Features2=0x180 <est,tm2>real memory  = 2146369536 (2046 MB)
avail memory = 2071531520 (1975 MB)
Event timer "LAPIC" quality 400
ACPI APIC Table: <intelr awrdacpi="">ioapic0 <version 2.0="">irqs 0-23 on motherboard
wlan: mac acl policy registered
kbd1 at kbdmux0
random: <software, yarrow="">initialized
cryptosoft0: <software crypto="">on motherboard
padlock0: No ACE support.
acpi0: <intelr awrdacpi="">on motherboard
acpi0: Power Button (fixed)
acpi0: reservation of a2, 1e (4) failed
acpi0: reservation of e0, 10 (4) failed
acpi0: reservation of 0, a0000 (3) failed
acpi0: reservation of 100000, 7fdf0000 (3) failed
cpu0: <acpi cpu="">on acpi0
attimer0: <at timer="">port 0x40-0x43 irq 0 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
atrtc0: <at realtime="" clock="">port 0x70-0x73 irq 8 on acpi0
Event timer "RTC" frequency 32768 Hz quality 0
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0
acpi_button0: <power button="">on acpi0
pcib0: <acpi host-pci="" bridge="">port 0xcf8-0xcff on acpi0
pci0: <acpi pci="" bus="">on pcib0
vgapci0: <vga-compatible display="">port 0xea00-0xea07 mem 0xd0100000-0xd017ffff,0xc0000000-0xcfffffff,0xd0180000-0xd01bffff irq 16 at device 2.0 on pci0
agp0: <intel 82915gm="" (915gm="" gmch)="" svga="" controller="">on vgapci0
agp0: aperture size is 256M, detected 764k stolen memory
vgapci0: Boot video device
uhci0: <intel 82801fb="" fr="" fw="" frw="" (ich6)="" usb="" controller="" usb-a="">port 0xeb00-0xeb1f irq 23 at device 29.0 on pci0
usbus0 on uhci0
uhci1: <intel 82801fb="" fr="" fw="" frw="" (ich6)="" usb="" controller="" usb-b="">port 0xed00-0xed1f irq 19 at device 29.1 on pci0
usbus1 on uhci1
uhci2: <intel 82801fb="" fr="" fw="" frw="" (ich6)="" usb="" controller="" usb-c="">port 0xe800-0xe81f irq 18 at device 29.2 on pci0
usbus2 on uhci2
uhci3: <intel 82801fb="" fr="" fw="" frw="" (ich6)="" usb="" controller="" usb-d="">port 0xe900-0xe91f irq 16 at device 29.3 on pci0
usbus3 on uhci3
ehci0: <intel 82801fb="" (ich6)="" usb="" 2.0="" controller="">mem 0xd01c0000-0xd01c03ff irq 23 at device 29.7 on pci0
usbus4: EHCI version 1.0
usbus4 on ehci0
pcib1: <acpi pci-pci="" bridge="">at device 30.0 on pci0
pci1: <acpi pci="" bus="">on pcib1
skc0: <marvell gigabit="" ethernet="" (led="" mod="" 2.2)="">port 0xc000-0xc0ff mem 0xd002c000-0xd002ffff irq 16 at device 0.0 on pci1
skc0: Marvell Yukon Lite Gigabit Ethernet rev. (0x9)
sk0: <marvell semiconductor,="" inc.="" yukon="">on skc0
sk0: Ethernet address: 00:90:7f:3e:38:29
miibus0: <mii bus="">on sk0
e1000phy0: <marvell 88e1011="" gigabit="" phy="">PHY 0 on miibus0
e1000phy0:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto
skc1: <marvell gigabit="" ethernet="" (led="" mod="" 2.2)="">port 0xc400-0xc4ff mem 0xd0020000-0xd0023fff irq 17 at device 1.0 on pci1
skc1: Marvell Yukon Lite Gigabit Ethernet rev. (0x9)
sk1: <marvell semiconductor,="" inc.="" yukon="">on skc1
sk1: Ethernet address: 00:90:7f:3e:38:28
miibus1: <mii bus="">on sk1
e1000phy1: <marvell 88e1011="" gigabit="" phy="">PHY 0 on miibus1
e1000phy1:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto
skc2: <marvell gigabit="" ethernet="" (led="" mod="" 2.2)="">port 0xc800-0xc8ff mem 0xd0024000-0xd0027fff irq 18 at device 2.0 on pci1
skc2: Marvell Yukon Lite Gigabit Ethernet rev. (0x9)
sk2: <marvell semiconductor,="" inc.="" yukon="">on skc2
sk2: Ethernet address: 00:90:7f:3e:38:27
miibus2: <mii bus="">on sk2
e1000phy2: <marvell 88e1011="" gigabit="" phy="">PHY 0 on miibus2
e1000phy2:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto
skc3: <marvell gigabit="" ethernet="" (led="" mod="" 2.2)="">port 0xcc00-0xccff mem 0xd0028000-0xd002bfff irq 19 at device 3.0 on pci1
skc3: Marvell Yukon Lite Gigabit Ethernet rev. (0x9)
sk3: <marvell semiconductor,="" inc.="" yukon="">on skc3
sk3: Ethernet address: 00:90:7f:3e:38:26
miibus3: <mii bus="">on sk3
e1000phy3: <marvell 88e1011="" gigabit="" phy="">PHY 0 on miibus3
e1000phy3:  none, 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-master, 1000baseT-FDX, 1000baseT-FDX-master, auto
pci1: <encrypt decrypt,="" network="" computer="" crypto="">at device 4.0 (no driver attached)
isab0: <pci-isa bridge="">at device 31.0 on pci0
isa0: <isa bus="">on isab0
atapci0: <intel ich6="" udma100="" controller="">port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xf000-0xf00f at device 31.1 on pci0
ata0: <ata channel="">at channel 0 on atapci0
ata1: <ata channel="">at channel 1 on atapci0
acpi_tz0: <thermal zone="">on acpi0
uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
uart0: console (115200,n,8,1)
uart1: <16550 or compatible> port 0x2f8-0x2ff irq 3 on acpi0
ppc0: <parallel port="">port 0x378-0x37f,0x778-0x77b irq 7 on acpi0
ppc0: Generic chipset (NIBBLE-only) in COMPATIBLE mode
ppbus0: <parallel port="" bus="">on ppc0
lpt0: <printer>on ppbus0
lpt0: Interrupt-driven port
ppi0: <parallel i="" o="">on ppbus0
pmtimer0 on isa0
orm0: <isa option="" rom="">at iomem 0xc0000-0xce7ff pnpid ORM0000 on isa0
atkbdc0: <keyboard controller="" (i8042)="">at port 0x60,0x64 on isa0
atkbd0: <at keyboard="">irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
est0: <enhanced speedstep="" frequency="" control="">on cpu0
p4tcc0: <cpu frequency="" thermal="" control="">on cpu0
random: unblocking device.
usbus0: 12Mbps Full Speed USB v1.0
Timecounters tick every 1.000 msec
IPsec: Initialized Security Association Processing.
usbus1: 12Mbps Full Speed USB v1.0
usbus2: 12Mbps Full Speed USB v1.0
usbus3: 12Mbps Full Speed USB v1.0
ugen0.1: <intel>at usbus0
uhub0: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus0
ugen1.1: <intel>at usbus1
uhub1: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus1
ugen2.1: <intel>at usbus2
uhub2: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus2
ugen3.1: <intel>at usbus3
uhub3: <intel 1="" 9="" uhci="" root="" hub,="" class="" 0,="" rev="" 1.00="" 1.00,="" addr="">on usbus3
usbus4: 480Mbps High Speed USB v2.0
ugen4.1: <intel>at usbus4
uhub4: <intel 1="" 9="" ehci="" root="" hub,="" class="" 0,="" rev="" 2.00="" 1.00,="" addr="">on usbus4
ada0 at ata0 bus 0 scbus0 target 0 lun 0
ada0: <cf card="" ver7.01k="">CFA-5 device
ada0: Serial Number 5B4410E300258AE0
ada0: 16.700MB/s transfers (PIO4, PIO 512bytes)
ada0: 7623MB (15613920 512 byte sectors: 16H 63S/T 15490C)
ada0: Previously was known as ad0
Timecounter "TSC" frequency 2000112740 Hz quality 800
uhub0: 2 ports with 2 removable, self powered
uhub1: 2 ports with 2 removable, self powered
uhub2: 2 ports with 2 removable, self powered
uhub3: 2 ports with 2 removable, self powered
Root mount waiting for: usbus4
Root mount waiting for: usbus4
Root mount waiting for: usbus4
Root mount waiting for: usbus4
uhub4: 8 ports with 8 removable, self powered
Trying to mount root from ufs:/dev/ufs/pfsense1 [ro,sync,noatime]...
Configuring crash dumps...
/dev/ufs/pfsense1: FILE SYSTEM CLEAN; SKIPPING CHECKS
/dev/ufs/pfsense1: clean, 2231156 free (2084 frags, 278634 blocks, 0.1% fragmentation)
/dev/ufs/cf: FILE SYSTEM CLEAN; SKIPPING CHECKS
/dev/ufs/cf: clean, 90359 free (23 frags, 11292 blocks, 0.0% fragmentation)
Filesystems are clean, continuing...
Mounting filesystems...
Setting up memory disks... done.

     ___
 ___/ f \134
/ p \134___/ Sense
\134___/   \134
    \134___/

Welcome to pfSense 2.2.4-RELEASE  ...

Creating symlinks......ELF ldconfig path: /lib /usr/lib /usr/lib/compat /usr/local/lib
a.out ldconfig path: /usr/lib/aout /usr/lib/compat/aout
done.
External config loader 1.0 is now starting...
Launching the init system... done.
Initializing...................... done.
Starting device manager (devd)...done.
Loading configuration......done.
Updating configuration...done.
Cleaning backup cache........done.
Setting up extended sysctls...done.
Setting timezone...done.
Configuring loopback interface...done.
Starting syslog...done.
Starting Secure Shell Services...done.
Setting up polling defaults...done.
Setting up interfaces microcode...done.
Configuring loopback interface...done.
Creating wireless clone interfaces...done.
Configuring LAGG interfaces...done.
Configuring VLAN interfaces...
sk1: link state changed to DOWN
vlan0: changing name to 'sk1_vlan192'
done.
Configuring QinQ interfaces...done.
Configuring WAN interface...
sk0: link state changed to DOWN
done.
Configuring LAN interface...done.
Configuring SYNC interface...
sk3: link state changed to DOWN
done.
Configuring VLAN192 interface...done.
bridge0: Ethernet address: 02:a3:d8:37:b1:00
bridge0: link state changed to DOWN
sk1: promiscuous mode enabled
sk0: promiscuous mode enabled
carp: demoted by 240 to 240 (interface down)
carp: demoted by 240 to 480 (interface down)
carp: demoted by 240 to 720 (interface down)
carp: demoted by 240 to 960 (interface down)
Configuring CARP settings...done.
Configuring WANIPV6 interface...done.
Configuring CARP settings...done.
Syncing OpenVPN settings...
tun1: changing name to 'ovpns1'
tap2: Ethernet address: 00:bd:df:df:00:02
tap2: changing name to 'ovpns2'
done.
ovpns1: link state changed to UP
ovpns2: link state changed to UP
Configuring firewall.
pflog0: promiscuous mode enabled
bridge0: link state changed to UP
ovpns2: promiscuous mode enabled
carp: VHID 10@sk1: INIT -> BACKUP
carp: demoted by -240 to 720 (interface up)
sk1: link state changed to UP
sk1_vlan192: link state changed to UP
carp: VHID 2@sk0: INIT -> BACKUP
carp: demoted by -240 to 480 (interface up)
carp: VHID 3@sk0: INIT -> BACKUP
carp: demoted by -240 to 240 (interface up)
carp: VHID 1@sk0: INIT -> BACKUP
carp: demoted by -240 to 0 (interface up)
sk0: link state changed to UP
.....done.
Starting PFLOG...done.
Setting up gateway monitors...
carp: VHID 10@sk1: BACKUP -> MASTER (master down)
carp: VHID 1@sk0: BACKUP -> MASTER (master down)
carp: VHID 3@sk0: BACKUP -> MASTER (master down)
carp: VHID 2@sk0: BACKUP -> MASTER (master down)
ovpns1: link state changed to DOWN
ovpns1: link state changed to UP
done.
Synchronizing user settings...done.
Starting webConfigurator...done.
Configuring CRON...done.
Starting DNS forwarder...done.
Starting NTP time client...done.
Starting DHCP service...done.
Starting DHCPv6 service...done.
Configuring firewall......done.
Starting SNMP daemon... done.
Generating RRD graphs...done.
kldload: can't load cpufreq: No such file or directory
Starting syslog...done.
Starting CRON... done.
Aug  3 08:21:41 php-fpm[36946]: /rc.start_packages: Restarting/Starting all packages.
 Starting package LADVD...done.
 Starting package Service Watchdog...done.
 Starting package NRPE v2...done.
 Starting package LCDproc-dev...\M^?\M^?\M^?\M^?\M^?\M^?\M^?\M^?\M^?\M^??done.
 Starting package softflowd...done.
 Starting package snort...
done.
 Starting package haproxy-devel...done.
 Starting package OpenVPN Client Export Utility...done.
 Starting package pfBlockerNG...\M^?\M^?\M^?\M^?\M^?\M^?\M^?\M^?\M^?\M^??done.
 Starting /usr/local/etc/rc.d/fanctrld.sh...done.
 Starting /usr/local/etc/rc.d/haproxy.sh...done.
 Starting /usr/local/etc/rc.d/nrpe2.sh...done.
pfSense (nanobsd) 2.2.4-RELEASE i386 Sat Jul 25 19:56:41 CDT 2015
Bootup complete</cf></intel></intel></intel></intel></intel></intel></intel></intel></intel></intel></cpu></enhanced></at></keyboard></isa></parallel></printer></parallel></parallel></thermal></ata></ata></intel></isa></pci-isa></encrypt></marvell></mii></marvell></marvell></marvell></mii></marvell></marvell></marvell></mii></marvell></marvell></marvell></mii></marvell></marvell></acpi></acpi></intel></intel></intel></intel></intel></intel></vga-compatible></acpi></acpi></power></at></at></acpi></intelr></software></software,></version></intelr></est,tm2></fpu,vme,de,pse,tsc,msr,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,tm,pbe>

And my loader.conf and loader.conf.local files:

loader_color="NO"
autoboot_delay="5"
beastie_disable="YES"
vm.kmem_size="435544320"
vm.kmem_size_max="535544320"
boot_serial="YES"
console="comconsole"
comconsole_speed="115200"
hw.usb.no_pf="1"

# Shut up Intel driver messages
legal.intel_ipw.license_ack=1
legal.intel_iwi.license_ack=1

# Disable MSK watchdog
hw.msk.msi_disable=1

# Force EST for powerd
#hint.p4tcc.0.disabled=1
#hint.acpi_throttle.0.disabled=1

# Drivers with working network LEDs
if_sk_load="yes"
if_msk_load="yes"

# Disable DMA
#hw.ata.atapi_dma="0"
#hw.ata.ata_dma="0"
hint.ata.0.mode=PIO4

# Attempt to fix LAN hangs
#hw.pci.enable_msi=0
#hw.pci.enable_msix=0

doktornotor

@wwwdrich:

The odd thing is that there is an easy fix – /etc/rc.conf_mount_rw. Since I'm running the nanobsd image on a CF card, I really don't want to do this; but it gets rid of the delay when running commands and makes the web interface responsive again

Helps to read the release notes. https://doc.pfsense.org/index.php/2.2.4_New_Features_and_Changes#Security.2FErrata_Notices

wwwdrich

Aha! I did read the release notes before upgrading, but I didn't catch that (assuming you're talking about the forcesync patch for #2401). I didn't equate "noticable slowness" with "takes forever", but I guess that's close enough. And in reading the bug, I see it's exactly what I'm experiencing.

Thanks for the pointer!