[Bug 276967] sysctl dev.hwpstate_intel periodically slow

From: <bugzilla-noreply_at_freebsd.org>
Date: Sun, 11 Feb 2024 08:26:21 UTC

            Bug ID: 276967
           Summary: sysctl dev.hwpstate_intel periodically slow
           Product: Base System
           Version: 13.2-STABLE
          Hardware: Any
                OS: Any
            Status: New
          Severity: Affects Some People
          Priority: ---
         Component: kern
          Assignee: bugs@FreeBSD.org
          Reporter: thomas@gibfest.dk


We have a server which has developed a periodic issue where the server becomes
weirdly slow and unresponsive and only a hard reboot seems to help. It happened
again today and I tried digging into it a bit before rebooting.

This has become an issue since we upgraded from 13-STABLE-93f39b4675 (built
July 21st, 2023) to 13-STABLE-7a241fa318 (built on December 11th, 2023).
Digging through commits to stable/13 in that period did not turn up anything
that caught my eye.

It turns out it is because monitoring is running
/usr/sbin/prometheus_sysctl_exporter once every minute in a monitoring job.
This is usually not an issue. Digging into it today it turns out it is sysctl
itself that is being slow, when it has to print out the
dev.hwpstate_intel.X.epp number. Sometimes it is fast, sometimes it takes 1-10
seconds to return, and sometimes minutes.

I timed a `sysctl -a` and it took 39 minutes to return, pausing before printing
each of the 6 dev.hwpstate_intel.X.epp oids my system has.

Uptime was 39ish days when this happened, last time it happened uptime was just
over 3 weeks.

While the issue was active this morning I tried running "truss sysctl
dev.hwpstate_intel" and it doesn't show any difference between a "fast" run and
a "slow" run. It pauses after printing this line (the numbers vary but it is
always at the oidfmt call)

dev.hwpstate_intel.0.epp",6,0x3a7c02008450,0x3a7c020077d8,0x0,0) = 0 (0x0)

The next call after the oidfmt call is:

__sysctl("dev.hwpstate_intel.0.epp",4,0x0,0x3a7c020077d0,0x0,0) = 0 (0x0)

So I guess this might be what is taking a long time?

I've included /var/run/dmesg.boot in case it is relevant. The server is an
Intel NUC:

[tykling@nuc1 ~]$ cat /var/run/dmesg.boot 
Copyright (c) 1992-2021 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 13.2-STABLE stable/13-7a241fa318 GENERIC amd64
FreeBSD clang version 16.0.6 (https://github.com/llvm/llvm-project.git
VT(vga): resolution 640x480
CPU: Intel(R) Core(TM) i7-10710U CPU @ 1.10GHz (1600.00-MHz K8-class CPU)
  Origin="GenuineIntel"  Id=0xa0660  Family=0x6  Model=0xa6  Stepping=0
  AMD Features=0x2c100800<SYSCALL,NX,Page1GB,RDTSCP,LM>
  AMD Features2=0x121<LAHF,ABM,Prefetch>
  Structured Extended
  Structured Extended
  TSC: P-state invariant, performance statistics
real memory  = 34359738368 (32768 MB)
avail memory = 33013563392 (31484 MB)
Event timer "LAPIC" quality 600
FreeBSD/SMP: Multiprocessor System Detected: 6 CPUs
FreeBSD/SMP: 1 package(s) x 6 core(s)
random: registering fast source Intel Secure Key RNG
random: fast provider: "Intel Secure Key RNG"
random: unblocking device.
ioapic0 <Version 2.0> irqs 0-119
Launching APs: 2 3 4 1 5
random: entropy device external interface
kbd0 at kbdmux0
efirtc0: <EFI Realtime Clock>
efirtc0: registered as a time-of-day clock, resolution 1.000000s
smbios0: <System Management BIOS> at iomem 0x2f9df000-0x2f9df01e
smbios0: Version: 3.3, BCD Revision: 3.3
acpi0: <INTEL>
acpi0: Power Button (fixed)
cpu0: <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
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
acpi_ec0: <Embedded Controller: GPE 0x6e> port 0x62,0x66 on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
vgapci0: <VGA-compatible display> port 0x3000-0x303f mem
0x6000000000-0x6000ffffff,0x4000000000-0x400fffffff at device 2.0 on pci0
vgapci0: Boot video device
xhci0: <XHCI (generic) USB 3.0 controller> mem 0x6001000000-0x600100ffff at
device 20.0 on pci0
xhci0: 32 bytes context size, 64-bit DMA
usbus0 on xhci0
usbus0: 5.0Gbps Super Speed USB v3.0
pci0: <memory, RAM> at device 20.2 (no driver attached)
pci0: <serial bus> at device 21.0 (no driver attached)
pci0: <serial bus> at device 21.2 (no driver attached)
pci0: <simple comms> at device 22.0 (no driver attached)
ahci0: <AHCI SATA controller> port 0x3090-0x3097,0x3080-0x3083,0x3060-0x307f
mem 0x3d220000-0x3d221fff,0x3d223000-0x3d2230ff,0x3d222000-0x3d2227ff at device
23.0 on pci0
ahci0: AHCI v1.31 with 1 6Gbps ports, Port Multiplier not supported
ahcich2: <AHCI channel> at channel 2 on ahci0
pcib1: <ACPI PCI-PCI bridge> at device 29.0 on pci0
pci1: <ACPI PCI bus> on pcib1
nvme0: <Generic NVMe Device> mem 0x3d100000-0x3d103fff at device 0.0 on pci1
pcib2: <ACPI PCI-PCI bridge> at device 29.5 on pci0
pci2: <ACPI PCI bus> on pcib2
sdhci_pci0: <Generic SD HCI> mem 0x3d000000-0x3d000fff at device 0.0 on pci2
sdhci_pci0: 1 slot(s) allocated
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
pci0: <serial bus> at device 31.5 (no driver attached)
em0: <Intel(R) I219-V CMP(10)> mem 0x3d200000-0x3d21ffff at device 31.6 on pci0
em0: EEPROM V0.8-4
em0: Using 1024 TX descriptors and 1024 RX descriptors
em0: Using an MSI interrupt
em0: Ethernet address: 1c:69:7a:ab:fe:be
em0: netmap queues/slots: TX 1/1024, RX 1/1024
acpi_button0: <Sleep Button> on acpi0
acpi_button1: <Power Button> on acpi0
acpi_tz0: <Thermal Zone> on acpi0
acpi_syscontainer0: <System Container> on acpi0
acpi_tz1: <Thermal Zone> on acpi0
acpi_tz1: _HOT value is absurd, ignored (-73.1C)
atrtc0: <AT realtime clock> at port 0x70 irq 8 on isa0
atrtc0: Warning: Couldn't map I/O.
atrtc0: registered as a time-of-day clock, resolution 1.000000s
Event timer "RTC" frequency 32768 Hz quality 0
atrtc0: non-PNP ISA device will be removed from GENERIC in FreeBSD 15.
hwpstate_intel0: <Intel Speed Shift> on cpu0
hwpstate_intel1: <Intel Speed Shift> on cpu1
hwpstate_intel2: <Intel Speed Shift> on cpu2
hwpstate_intel3: <Intel Speed Shift> on cpu3
hwpstate_intel4: <Intel Speed Shift> on cpu4
hwpstate_intel5: <Intel Speed Shift> on cpu5
Timecounter "TSC" frequency 1607993387 Hz quality 1000
Timecounters tick every 1.000 msec
ZFS filesystem version: 5
ZFS storage pool version: features support (5000)
acpi_tz1: _TMP value is absurd, ignored (-263.1C)
ugen0.1: <Intel XHCI root HUB> at usbus0
uhub0 on usbus0
uhub0: <Intel XHCI root HUB, class 9/0, rev 3.00/1.00, addr 1> on usbus0
nvd0: <INTEL SSDPEKNW512G8> NVMe namespace
nvd0: 488386MB (1000215216 512 byte sectors)
ada0 at ahcich2 bus 0 scbus0 target 0 lun 0
ada0: <WDC WDS100T1R0A-68A4W0 411000WR> ACS-4 ATA SATA 3.x device
ada0: Serial Number 21356C802096
ada0: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 512bytes)
ada0: Command Queueing enabled
ada0: 953869MB (1953525168 512 byte sectors)
Trying to mount root from zfs:zroot/ROOT/13-STABLE-7a241fa318 []...
GEOM_MIRROR: Device mirror/swap launched (2/2).
uhub0: 18 ports with 18 removable, self powered
GEOM_ELI: Device mirror/swap.eli created.
GEOM_ELI: Encryption: AES-XTS 128
GEOM_ELI:     Crypto: accelerated software
pchtherm0: <CometLake-LP Thermal Subsystem> mem 0x6001017000-0x6001017fff at
device 18.0 on pci0
ig4iic0: <Intel Comet Lake-LP I2C Controller-0> at device 21.0 on pci0
ig4iic0: Using MSI
iicbus0: <Philips I2C bus (ACPI-hinted)> on ig4iic0
ig4iic1: <Intel Comet Lake-LP I2C Controller-2> at device 21.2 on pci0
ig4iic1: Using MSI
iicbus1: <Philips I2C bus (ACPI-hinted)> on ig4iic1
iicbus1: <unknown card> at addr 0x20
ichsmb0: <Intel Comet Lake SMBus controller> port 0xefa0-0xefbf mem
0x6001012000-0x60010120ff at device 31.4 on pci0
smbus0: <System Management Bus> on ichsmb0
acpi_wmi0: <ACPI-WMI mapping> on acpi0
acpi_wmi0: Embedded MOF found
ACPI: \134AMW0.WQBA: 1 arguments were passed to a non-method ACPI object
(Buffer) (20201113/nsarguments-361)
acpi_wmi1: <ACPI-WMI mapping> on acpi0
acpi_wmi2: <ACPI-WMI mapping> on acpi0
acpi_wmi2: Embedded MOF found
ACPI: \134_SB.WFDE.WQCC: 1 arguments were passed to a non-method ACPI object
(Buffer) (20201113/nsarguments-361)
acpi_wmi3: <ACPI-WMI mapping> on acpi0
acpi_wmi3: Embedded MOF found
ACPI: \134_SB.WFTE.WQCC: 1 arguments were passed to a non-method ACPI object
(Buffer) (20201113/nsarguments-361)
bridge1: Ethernet address: 58:9c:fc:10:8e:78
bridge0: Ethernet address: 58:9c:fc:10:cc:5a
lo0: link state changed to UP
em0: link state changed to UP
pflog0: promiscuous mode enabled
Accounting enabled

powerd is not enabled on the system. It used to be, but it has been disabled in
December when I first discovered this issue. I hoped disabling powerd would
make the issue go away but it hasn't.

I realise this isn't a lot to go on, and I can't really force the issue, so if
anyone has any suggestions to what I might try the next time it happens then
please share them. It might be weeks thought. The server is in production but I
can test stuff in off-hours.

Thank you! :)

You are receiving this mail because:
You are the assignee for the bug.