Performance problems after 2.1.5 -> 2.2.4 upgrade
-
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 -
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
-
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!