High CPU usage on interrupt processing

Svarov · Jun 8, 2018, 12:32 PM

Hello,

I’ve installed pfSense 2.4.3 on Fujitsu PRIMERGY RX1330 M3.
The full configuration is:
MB: Fujitsu PRIMERGY RX1330 M3
CPU: Intel(R) Xeon(R) CPU E3-1220 v6 @ 3.00GHz
RAM: 8G
RAID: Fujitsu PRAID CP400i SAS (2 disks in RAID1, 1TB)
LAN: PLAN-CP4x1Gbit-Cu-Intel-I350-T4 x2 (8 eth port on PCI + 2 integrated, also Intel)

And everything works fine as far as I tested — all 10 LANs, RAID, no errors in dmesg.
There’s only one thing that concerns me — high CPU load on interrupt processing.

Server is currently idle, but interrupt processing is always at around 4% up to 18% (rare peaks).
Is it OK or something doesn’t work as expected?

Here’s some system output:

top:
last pid: 98015;  load averages:  0.21,  0.25,  0.22                                                                                                                           up 0+00:28:40  15:05:59
42 processes:  1 running, 41 sleeping
CPU:  0.1% user,  0.0% nice,  0.1% system,  4.2% interrupt, 95.6% idle
Mem: 51M Active, 55M Inact, 272M Wired, 29M Buf, 7252M Free
Swap: 4096M Total, 4096M Free

  PID USERNAME    THR PRI NICE   SIZE    RES STATE   C   TIME    WCPU COMMAND
  315 root          1  22    0   263M 38960K accept  0   0:02   0.38% php-fpm
97182 root          1  20    0 20068K  3380K CPU2    2   0:00   0.02% top
22538 root          1  20    0 37704K  7992K kqread  2   0:00   0.01% nginx
16689 root          5  52    0 13036K  2356K uwait   1   0:00   0.01% dpinger

vmstat –i:
interrupt                          total       rate
irq4: uart0                          223          0
cpu0:timer                        355780        203
cpu3:timer                        842198        480
cpu2:timer                        283307        162
cpu1:timer                        274212        156
irq284: mfi0                      126370         72
irq285: xhci0                         55          0
irq286: ahci0                         39          0
irq287: igb4:que 0                 18894         11
irq288: igb4:que 1                  2932          2
irq289: igb4:que 2                  5402          3
irq290: igb4:que 3                  2363          1
irq291: igb4:link                      2          0
irq292: igb5:que 0                  1694          1
irq293: igb5:que 1                  1694          1
irq294: igb5:que 2                  1694          1
irq295: igb5:que 3                  1694          1
irq296: igb5:link                      1          0
irq302: igb7:que 0                  1693          1
irq303: igb7:que 1                  1693          1
irq304: igb7:que 2                  1693          1
irq305: igb7:que 3                  1693          1
irq306: igb7:link                      1          0
irq307: igb8:que 0                  1693          1
irq308: igb8:que 1                  1693          1
irq309: igb8:que 2                  1693          1
irq310: igb8:que 3                  1693          1
irq311: igb8:link                      1          0
irq312: igb9:que 0                  1694          1
irq313: igb9:que 1                  1694          1
irq314: igb9:que 2                  1694          1
irq315: igb9:que 3                  1694          1
irq316: igb9:link                      3          0
Total                            1938879       1106

stephenw10 · Jun 8, 2018, 1:12 PM

Do you have powerd enabled (speedstep)?

Steve

Svarov · Jun 8, 2018, 2:13 PM

No, powerd is not enabled.

I attached dmesg output below, maybe it will give some additional clues to what's going on.

Copyright (c) 1992-2017 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 11.1-RELEASE-p7 #10 r313908+986837ba7e9(RELENG_2_4): Mon Mar 26 18:08:25 CDT 2018
    root@buildbot2.netgate.com:/builder/ce-243/tmp/obj/builder/ce-243/tmp/FreeBSD-src/sys/pfSense amd64
FreeBSD clang version 5.0.1 (tags/RELEASE_501/final 320880) (based on LLVM 5.0.1)
VT(efifb): resolution 1024x768
CPU: Intel(R) Xeon(R) CPU E3-1220 v6 @ 3.00GHz (3000.10-MHz K8-class CPU)
  Origin="GenuineIntel"  Id=0x906e9  Family=0x6  Model=0x9e  Stepping=9
  Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
  Features2=0x7ffafbff<SSE3,PCLMULQDQ,DTES64,MON,DS_CPL,VMX,SMX,EST,TM2,SSSE3,SDBG,FMA,CX16,xTPR,PDCM,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,TSCDLT,AESNI,XSAVE,OSXSAVE,AVX,F16C,RDRAND>
  AMD Features=0x2c100800<SYSCALL,NX,Page1GB,RDTSCP,LM>
  AMD Features2=0x121<LAHF,ABM,Prefetch>
  Structured Extended Features=0x29c6fbf<FSGSBASE,TSCADJ,SGX,BMI1,HLE,AVX2,SMEP,BMI2,ERMS,INVPCID,RTM,NFPUSG,MPX,RDSEED,ADX,SMAP,CLFLUSHOPT,PROCTRACE>
  XSAVE Features=0xf<XSAVEOPT,XSAVEC,XINUSE,XSAVES>
  VT-x: PAT,HLT,MTF,PAUSE,EPT,UG,VPID
  TSC: P-state invariant, performance statistics
real memory  = 8589934592 (8192 MB)
avail memory = 7944486912 (7576 MB)
Event timer "LAPIC" quality 600
ACPI APIC Table: <FUJ    D3375-B1>
FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
FreeBSD/SMP: 1 package(s) x 4 core(s)
random: unblocking device.
ioapic0 <Version 2.0> irqs 0-119 on motherboard
SMP: AP CPU #3 Launched!
SMP: AP CPU #2 Launched!
SMP: AP CPU #1 Launched!
Timecounter "TSC-low" frequency 1500049087 Hz quality 1000
random: entropy device external interface
wlan: mac acl policy registered
kbd0 at kbdmux0
netmap: loaded module
module_register_init: MOD_LOAD (vesa, 0xffffffff81162bc0, 0) error 19
random: registering fast source Intel Secure Key RNG
random: fast provider: "Intel Secure Key RNG"
nexus0
cryptosoft0: <software crypto> on motherboard
padlock0: No ACE support.
acpi0: <FUJ D3375-B1> on motherboard
acpi0: Power Button (fixed)
cpu0: <ACPI CPU> on acpi0
cpu1: <ACPI CPU> on acpi0
cpu2: <ACPI CPU> on acpi0
cpu3: <ACPI CPU> on acpi0
hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff on acpi0
Timecounter "HPET" frequency 24000000 Hz quality 950
Event timer "HPET" frequency 24000000 Hz quality 550
Event timer "HPET1" frequency 24000000 Hz quality 440
Event timer "HPET2" frequency 24000000 Hz quality 440
Event timer "HPET3" frequency 24000000 Hz quality 440
Event timer "HPET4" frequency 24000000 Hz quality 440
atrtc0: <AT realtime clock> port 0x70-0x77 irq 8 on acpi0
atrtc0: Warning: Couldn't map I/O.
Event timer "RTC" frequency 32768 Hz quality 0
attimer0: <AT timer> port 0x40-0x43,0x50-0x53 irq 0 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1808-0x180b on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
pcib1: <ACPI PCI-PCI bridge> at device 1.0 on pci0
pci1: <ACPI PCI bus> on pcib1
igb0: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> mem 0xdf100000-0xdf1fffff,0xdf28c000-0xdf28ffff at device 0.0 on pci1
igb0: Using MSIX interrupts with 5 vectors
igb0: Ethernet address: b4:96:91:13:32:40
igb0: Bound queue 0 to cpu 0
igb0: Bound queue 1 to cpu 1
igb0: Bound queue 2 to cpu 2
igb0: Bound queue 3 to cpu 3
igb0: netmap queues/slots: TX 4/1024, RX 4/1024
igb1: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> mem 0xdf000000-0xdf0fffff,0xdf288000-0xdf28bfff at device 0.1 on pci1
igb1: Using MSIX interrupts with 5 vectors
igb1: Ethernet address: b4:96:91:13:32:41
igb1: Bound queue 0 to cpu 0
igb1: Bound queue 1 to cpu 1
igb1: Bound queue 2 to cpu 2
igb1: Bound queue 3 to cpu 3
igb1: netmap queues/slots: TX 4/1024, RX 4/1024
igb2: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> mem 0xdef00000-0xdeffffff,0xdf284000-0xdf287fff at device 0.2 on pci1
igb2: Using MSIX interrupts with 5 vectors
igb2: Ethernet address: b4:96:91:13:32:42
igb2: Bound queue 0 to cpu 0
igb2: Bound queue 1 to cpu 1
igb2: Bound queue 2 to cpu 2
igb2: Bound queue 3 to cpu 3
igb2: netmap queues/slots: TX 4/1024, RX 4/1024
igb3: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> mem 0xdee00000-0xdeefffff,0xdf280000-0xdf283fff at device 0.3 on pci1
igb3: Using MSIX interrupts with 5 vectors
igb3: Ethernet address: b4:96:91:13:32:43
igb3: Bound queue 0 to cpu 0
igb3: Bound queue 1 to cpu 1
igb3: Bound queue 2 to cpu 2
igb3: Bound queue 3 to cpu 3
igb3: netmap queues/slots: TX 4/1024, RX 4/1024
pcib2: <ACPI PCI-PCI bridge> at device 1.1 on pci0
pci2: <ACPI PCI bus> on pcib2
AVAGO MegaRAID SAS FreeBSD mrsas driver version: 06.709.07.00-fbsd
mfi0: <Fury> port 0xe000-0xe0ff mem 0xdf500000-0xdf50ffff,0xdf400000-0xdf4fffff at device 0.0 on pci2
mfi0: Using MSI
mfi0: Megaraid SAS driver Ver 4.23
mfi0: FW MaxCmds = 240, limiting to 128
mfi0: MaxCmd = 240, Drv MaxCmd = 128, MaxSgl = 70, state = 0xb73c00f0
mfi0: 465 (581773451s/0x0020/info) - Shutdown command received from host
mfi0: 466 (boot + 9s/0x0020/info) - Firmware initialization started (PCI ID 005f/1000/1211/1734)
mfi0: 467 (boot + 9s/0x0020/info) - Firmware version 4.270.01-4870
mfi0: 468 (boot + 11s/0x0020/info) - Package version 24.7.0-0061
mfi0: 469 (boot + 11s/0x0020/info) - Board Revision
mfi0: 470 (boot + 49s/0x0002/info) - Inserted: PD 02(e0x3e/s0)
xhci0: mfi0: <Intel Sunrise Point USB 3.0 controller> mem 0xdf800000-0xdf80ffff at device 20.0 on pci0
xhci0: 32 bytes context size, 64-bit DMA
471 (boot + 49s/0x0002/info) - Inserted: PD 02(e0x3e/s0) Info: enclPd=3e, scsiType=0, portMap=00, sasAddr=4433221102000000,000usbus00000000000000
mfi0: 472 (boot + 49s/0x0002/info) - Inserted: PD 03(e0x3e/s1)
 on xhci0
mfi0: usbus0: 5.0Gbps Super Speed USB v3.0
473 (boot + 49s/0x0002/info) - Inserted: PD 03(e0x3e/s1) Info: enclPd=3e, scsiType=0, portMap=01, sasAddr=4433221103000000,0000000000000000
mfi0: 474 (boot + 49s/0x0020/info) - Controller operating temperature within normal range, full operation restored
mfi0: 475 (581772985s/0x0020/info) - Time established as 06/08/18 11:36:25; (50 seconds since power on)
pci0: <simple comms> at device 22.0 (no driver attached)
pci0: <simple comms> at device 22.1 (no driver attached)
ahci0: <Intel Sunrise Point (RAID) AHCI SATA controller> port 0xf050-0xf057,0xf040-0xf043,0xf020-0xf03f mem 0xdf814000-0xdf815fff,0xdf818000-0xdf8180ff,0xdf817000-0xdf8177ff at device 23.0 on pci0
ahci0: AHCI v1.31 with 8 6Gbps ports, Port Multiplier not supported
ahcich0: <AHCI channel> at channel 0 on ahci0
ahcich1: <AHCI channel> at channel 1 on ahci0
ahcich2: <AHCI channel> at channel 2 on ahci0
ahcich3: <AHCI channel> at channel 3 on ahci0
ahcich4: <AHCI channel> at channel 4 on ahci0
ahcich5: <AHCI channel> at channel 5 on ahci0
ahciem0: <AHCI enclosure management bridge> on ahci0
pcib3: <ACPI PCI-PCI bridge> at device 28.0 on pci0
pci3: <ACPI PCI bus> on pcib3
vgapci0: <VGA-compatible display> mem 0xdd000000-0xddffffff,0xde820000-0xde823fff,0xde000000-0xde7fffff at device 0.0 on pci3
pci3: <processor> at device 0.1 (no driver attached)
pcib4: <ACPI PCI-PCI bridge> at device 28.5 on pci0
pci4: <ACPI PCI bus> on pcib4
igb4: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> port 0xc000-0xc01f mem 0xdf600000-0xdf67ffff,0xdf680000-0xdf683fff at device 0.0 on pci4
igb4: Using MSIX interrupts with 5 vectors
igb4: Ethernet address: 90:1b:0e:d3:53:23
igb4: Bound queue 0 to cpu 0
igb4: Bound queue 1 to cpu 1
igb4: Bound queue 2 to cpu 2
igb4: Bound queue 3 to cpu 3
igb4: netmap queues/slots: TX 4/1024, RX 4/1024
pcib5: <ACPI PCI-PCI bridge> at device 28.6 on pci0
pci5: <ACPI PCI bus> on pcib5
igb5: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> port 0xd000-0xd01f mem 0xdf700000-0xdf77ffff,0xdf780000-0xdf783fff at device 0.0 on pci5
igb5: Using MSIX interrupts with 5 vectors
igb5: Ethernet address: 90:1b:0e:d3:57:24
igb5: Bound queue 0 to cpu 0
igb5: Bound queue 1 to cpu 1
igb5: Bound queue 2 to cpu 2
igb5: Bound queue 3 to cpu 3
igb5: netmap queues/slots: TX 4/1024, RX 4/1024
pcib6: <ACPI PCI-PCI bridge> at device 29.0 on pci0
pci6: <ACPI PCI bus> on pcib6
igb6: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> mem 0xdec00000-0xdecfffff,0xded8c000-0xded8ffff at device 0.0 on pci6
igb6: Using MSIX interrupts with 5 vectors
igb6: Ethernet address: b4:96:91:13:29:70
igb6: Bound queue 0 to cpu 0
igb6: Bound queue 1 to cpu 1
igb6: Bound queue 2 to cpu 2
igb6: Bound queue 3 to cpu 3
igb6: netmap queues/slots: TX 4/1024, RX 4/1024
igb7: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> mem 0xdeb00000-0xdebfffff,0xded88000-0xded8bfff at device 0.1 on pci6
igb7: Using MSIX interrupts with 5 vectors
igb7: Ethernet address: b4:96:91:13:29:71
igb7: Bound queue 0 to cpu 0
igb7: Bound queue 1 to cpu 1
igb7: Bound queue 2 to cpu 2
igb7: Bound queue 3 to cpu 3
igb7: netmap queues/slots: TX 4/1024, RX 4/1024
igb8: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> mem 0xdea00000-0xdeafffff,0xded84000-0xded87fff at device 0.2 on pci6
igb8: Using MSIX interrupts with 5 vectors
igb8: Ethernet address: b4:96:91:13:29:72
igb8: Bound queue 0 to cpu 0
igb8: Bound queue 1 to cpu 1
igb8: Bound queue 2 to cpu 2
igb8: Bound queue 3 to cpu 3
igb8: netmap queues/slots: TX 4/1024, RX 4/1024
igb9: <Intel(R) PRO/1000 Network Connection, Version - 2.5.3-k> mem 0xde900000-0xde9fffff,0xded80000-0xded83fff at device 0.3 on pci6
igb9: Using MSIX interrupts with 5 vectors
igb9: Ethernet address: b4:96:91:13:29:73
igb9: Bound queue 0 to cpu 0
igb9: Bound queue 1 to cpu 1
igb9: Bound queue 2 to cpu 2
igb9: Bound queue 3 to cpu 3
igb9: netmap queues/slots: TX 4/1024, RX 4/1024
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
pci0: <memory> at device 31.2 (no driver attached)
acpi_button0: <Power Button> on acpi0
uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
uart0: console (115200,n,8,1)
ppc0: cannot reserve I/O port range
est0: <Enhanced SpeedStep Frequency Control> on cpu0
est1: <Enhanced SpeedStep Frequency Control> on cpu1
est2: <Enhanced SpeedStep Frequency Control> on cpu2
est3: <Enhanced SpeedStep Frequency Control> on cpu3
Timecounters tick every 1.000 msec
nvme cam probe device init
ugen0.1: <0x8086 XHCI root HUB> at usbus0
mfid0 on mfi0
mfid0: 953344MB (1952448512 sectors) RAID volume (no label) is optimal
uhub0: <0x8086 XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus0
uhub0: 26 ports with 26 removable, self powered
ugen0.2: <American Megatrends Inc. Virtual Keyboard and Mouse> at usbus0
ukbd0 on uhub0
ukbd0: <Keyboard Interface> on usbus0
kbd1 at ukbd0
ses0 at ahciem0 bus 0 scbus6 target 0 lun 0
ses0: <AHCI SGPIO Enclosure 1.00 0001> SEMB S-E-S 2.00 device
cd0 at ahcich5 bus 0 scbus5 target 0 lun 0
ses0: SEMB SES Device
cd0: <HL-DT-ST DVDRAM GUD0N PF02> Removable CD-ROM SCSI device
cd0: Serial Number B7ARVC1211252
cd0: 150.000MB/s transfers (SATA 1.x, UDMA6, ATAPI 12bytes, PIO 8192bytes)
cd0: Attempt to query device size failed: NOT READY, Medium not present - tray closed
Trying to mount root from ufs:/dev/gptid/f21e550d-4955-11e8-b400-b49691133240 [rw]...
CPU: Intel(R) Xeon(R) CPU E3-1220 v6 @ 3.00GHz (3000.10-MHz K8-class CPU)
  Origin="GenuineIntel"  Id=0x906e9  Family=0x6  Model=0x9e  Stepping=9
  Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
  Features2=0x7ffafbff<SSE3,PCLMULQDQ,DTES64,MON,DS_CPL,VMX,SMX,EST,TM2,SSSE3,SDBG,FMA,CX16,xTPR,PDCM,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,TSCDLT,AESNI,XSAVE,OSXSAVE,AVX,F16C,RDRAND>
  AMD Features=0x2c100800<SYSCALL,NX,Page1GB,RDTSCP,LM>
  AMD Features2=0x121<LAHF,ABM,Prefetch>
  Structured Extended Features=0x29c6fbf<FSGSBASE,TSCADJ,SGX,BMI1,HLE,AVX2,SMEP,BMI2,ERMS,INVPCID,RTM,NFPUSG,MPX,RDSEED,ADX,SMAP,CLFLUSHOPT,PROCTRACE>
  Structured Extended Features3=0xc000000<IBPB,STIBP>
  XSAVE Features=0xf<XSAVEOPT,XSAVEC,XINUSE,XSAVES>
  VT-x: PAT,HLT,MTF,PAUSE,EPT,UG,VPID
  TSC: P-state invariant, performance statistics
tun1: changing name to 'ovpns1'
tun2: changing name to 'ovpns2'
tun3: changing name to 'ovpns3'
ovpns2: link state changed to UP
ovpns1: link state changed to UP
ovpns3: link state changed to UP
pflog0: promiscuous mode enabled
igb4: link state changed to UP
igb9: promiscuous mode enabled
igb9: promiscuous mode disabled

stephenw10 · Jun 10, 2018, 2:00 PM

Hmm, is the firewall actually idle? No traffic at all?

I'd have to guess this is related to your raid setup since I don't have anything similar to test against.
The mfi device is the highest interrupt load other than the cpu timers. I could be tickling the cpus sufficiently to cause that.

If you;re not actually seeing an issue there I doubt it's a problem.

You could move /tmp and /var to RAM drives as a test which prevent drive writes. That may reduce both interrupt loads.

Steve

Svarov · Jun 13, 2018, 8:12 AM

@stephenw10 said in High CPU usage on interrupt processing:

Hmm, is the firewall actually idle? No traffic at all?

Yeah, firewall is idle. The server is located in a small subnet and no one is currently connected to it.
There’s some occasional broadcast traffic (e.g. DHCP requests) form other devices/servers on the network, but I doubt it can cause any trouble.

I think you’re right about RAID.
I moved /tmp and /var to RAM but still there’s a lot of interrupts on mfi0 device, yet gstat shows no disk IO except some rare writes.

I’ll try remotely tinker with RAID-related settings in BIOS, maybe I find something I missed.
Thank you for suggestions!