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
    
    

  • Banned

    @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



  • 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!