want paravirtualized clock enlightenment

[jmpesp]

@gjcolombo edit: This is the primary tracking issue for cases where a guest decides to stop using the TSC as a reference time source. We propose to address this by implementing a paravirt clock that allows the guest to use the TSC reliably. For more details about what can cause guests to abandon the TSC, see the discussion below.

---

one of my guests is showing some dmesg messages relating to clock skew:

[ 8996.144253] clocksource: timekeeping watchdog on CPU2: Marking clocksource 'tsc' as unstable because the skew is too large:
[ 8996.144260] clocksource:                       'acpi_pm' wd_now: f4b7d wd_last: 6c50c5 mask: ffffff
[ 8996.144261] clocksource:                       'tsc' cs_now: 1ca324f62cac cs_last: 1ca0b7a50c00 mask: ffffffffffffffff
[ 8996.144274] tsc: Marking TSC unstable due to clocksource watchdog
[ 8996.144401] TSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
[ 8996.144403] sched_clock: Marking unstable (8996101633485, 42749061)<-(8996259532949, -115136521)
[ 8996.145058] clocksource: Checking clocksource tsc synchronization from CPU 5.
[ 8996.146113] clocksource: Switched to clocksource acpi_pm

[jmpesp]

guest is

Linux inst4 5.10.0-18-amd64 #1 SMP Debian 5.10.140-1 (2022-09-02) x86_64 GNU/Linux

and the propolis version is 6282016343573335026e1f1adb5d4dedbcd8b079

[jmpesp]

if I grep out all lines in the dmesg that contain the string clock:

[    0.038996] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.113658] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x3259dcb07dd, max_idle_ns: 440795231854 ns
[    0.845735] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
               * this clock source is slow. Consider trying other clock sources
[    0.954091] clocksource: Switched to clocksource tsc-early
[    0.973840] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    1.378022] rtc_cmos 00:00: setting system clock to 2023-03-02T15:48:22 UTC (1677772102)
[    1.385631] sched_clock: Marking stable (1385398995, 152117)->(1500687633, -115136521)
[    2.397713] tsc: Refined TSC clocksource calibration: 3493.387 MHz
[    2.397741] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x325ae9f48fc, max_idle_ns: 440795209558 ns
[    2.397869] clocksource: Switched to clocksource tsc
[ 1525.639733] clocksource: timekeeping watchdog on CPU2: acpi_pm retried 2 times before success
[ 8996.144253] clocksource: timekeeping watchdog on CPU2: Marking clocksource 'tsc' as unstable because the skew is too large:
[ 8996.144260] clocksource:                       'acpi_pm' wd_now: f4b7d wd_last: 6c50c5 mask: ffffff
[ 8996.144261] clocksource:                       'tsc' cs_now: 1ca324f62cac cs_last: 1ca0b7a50c00 mask: ffffffffffffffff
[ 8996.144274] tsc: Marking TSC unstable due to clocksource watchdog
[ 8996.144403] sched_clock: Marking unstable (8996101633485, 42749061)<-(8996259532949, -115136521)
[ 8996.145058] clocksource: Checking clocksource tsc synchronization from CPU 5.
[ 8996.146113] clocksource: Switched to clocksource acpi_pm

[jmpesp]

full dmesg:

[    0.000000] Linux version 5.10.0-18-amd64 (debian-kernel@lists.debian.org) (gcc-10 (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #1 SMP Debian 5.10.140-1 (2022-09-02)
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-5.10.0-18-amd64 root=UUID=41887436-0108-4b7f-8c26-e9adbc9ed9d0 ro quiet splash console=tty0 console=ttyS0,115200 init=/lib/systemd/systemd-bootchart
[    0.000000] [Firmware Bug]: TSC doesn't count with P0 frequency!
[    0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000beafffff] usable
[    0.000000] BIOS-e820: [mem 0x00000000beb00000-0x00000000bedfffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000bee00000-0x00000000bf8eefff] usable
[    0.000000] BIOS-e820: [mem 0x00000000bf8ef000-0x00000000bfb6efff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000bfb6f000-0x00000000bfb7efff] ACPI data
[    0.000000] BIOS-e820: [mem 0x00000000bfb7f000-0x00000000bfbfefff] ACPI NVS
[    0.000000] BIOS-e820: [mem 0x00000000bfbff000-0x00000000bffdffff] usable
[    0.000000] BIOS-e820: [mem 0x00000000bffe0000-0x00000000bfffffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000043fffffff] usable
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] efi: EFI v2.70 by EDK II
[    0.000000] efi: ACPI=0xbfb7e000 ACPI 2.0=0xbfb7e014 MEMATTR=0xbe228298 MOKvar=0xbe0d7000 
[    0.000000] secureboot: Secure boot disabled
[    0.000000] DMI not present or invalid.
[    0.000000] tsc: Fast TSC calibration using PIT
[    0.000000] tsc: Detected 3493.102 MHz processor
[    0.000108] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000110] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000114] last_pfn = 0x440000 max_arch_pfn = 0x400000000
[    0.000177] MTRR default type: write-back
[    0.000177] MTRR fixed ranges enabled:
[    0.000178]   00000-9FFFF write-back
[    0.000179]   A0000-FFFFF uncachable
[    0.000180] MTRR variable ranges enabled:
[    0.000181]   0 base 0000C0000000 mask FFFFC0000000 uncachable
[    0.000181]   1 base 000800000000 mask FFF800000000 uncachable
[    0.000182]   2 disabled
[    0.000182]   3 disabled
[    0.000183]   4 disabled
[    0.000183]   5 disabled
[    0.000184]   6 disabled
[    0.000184]   7 disabled
[    0.000184]   8 disabled
[    0.000185]   9 disabled
[    0.000194] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT  
[    0.000203] last_pfn = 0xbffe0 max_arch_pfn = 0x400000000
[    0.003924] e820: update [mem 0xbe0d7000-0xbe0d7fff] usable ==> reserved
[    0.003956] Using GB pages for direct mapping
[    0.004186] RAMDISK: [mem 0x3c07f000-0x3dc0efff]
[    0.004188] ACPI: Early table checksum verification disabled
[    0.004189] ACPI: RSDP 0x00000000BFB7E014 000024 (v02 OVMF  )
[    0.004192] ACPI: XSDT 0x00000000BFB7D0E8 000044 (v01 OVMF   OVMFEDK2 20130221      01000013)
[    0.004195] ACPI: FACP 0x00000000BFB7C000 0000F4 (v03 OVMF   OVMFEDK2 20130221 OVMF 00000099)
[    0.004198] ACPI: DSDT 0x00000000BFB7A000 000CBD (v01 INTEL  OVMF     00000004 INTL 20190509)
[    0.004201] ACPI: FACS 0x00000000BFBFE000 000040
[    0.004203] ACPI: APIC 0x00000000BFB7B000 0000B0 (v01 OVMF   OVMFEDK2 20130221 OVMF 00000099)
[    0.004205] ACPI: SSDT 0x00000000BFB79000 000057 (v01 REDHAT OVMF     00000001 INTL 20190509)
[    0.004207] ACPI: BGRT 0x00000000BFB78000 000038 (v01 INTEL  EDK2     00000002      01000013)
[    0.004209] ACPI: Reserving FACP table memory at [mem 0xbfb7c000-0xbfb7c0f3]
[    0.004210] ACPI: Reserving DSDT table memory at [mem 0xbfb7a000-0xbfb7acbc]
[    0.004211] ACPI: Reserving FACS table memory at [mem 0xbfbfe000-0xbfbfe03f]
[    0.004211] ACPI: Reserving APIC table memory at [mem 0xbfb7b000-0xbfb7b0af]
[    0.004212] ACPI: Reserving SSDT table memory at [mem 0xbfb79000-0xbfb79056]
[    0.004213] ACPI: Reserving BGRT table memory at [mem 0xbfb78000-0xbfb78037]
[    0.004225] ACPI: Local APIC address 0xfee00000
[    0.004519] No NUMA configuration found
[    0.004520] Faking a node at [mem 0x0000000000000000-0x000000043fffffff]
[    0.004527] NODE_DATA(0) allocated [mem 0x43ffd6000-0x43fffffff]
[    0.004917] Zone ranges:
[    0.004917]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.004918]   DMA32    [mem 0x0000000001000000-0x00000000ffffffff]
[    0.004919]   Normal   [mem 0x0000000100000000-0x000000043fffffff]
[    0.004920]   Device   empty
[    0.004921] Movable zone start for each node
[    0.004923] Early memory node ranges
[    0.004924]   node   0: [mem 0x0000000000001000-0x000000000009ffff]
[    0.004925]   node   0: [mem 0x0000000000100000-0x00000000beafffff]
[    0.004926]   node   0: [mem 0x00000000bee00000-0x00000000bf8eefff]
[    0.004926]   node   0: [mem 0x00000000bfbff000-0x00000000bffdffff]
[    0.004927]   node   0: [mem 0x0000000100000000-0x000000043fffffff]
[    0.004928] Initmem setup node 0 [mem 0x0000000000001000-0x000000043fffffff]
[    0.004929] On node 0 totalpages: 4192623
[    0.004930]   DMA zone: 64 pages used for memmap
[    0.004931]   DMA zone: 2042 pages reserved
[    0.004931]   DMA zone: 3999 pages, LIFO batch:0
[    0.004932]   DMA32 zone: 12200 pages used for memmap
[    0.004933]   DMA32 zone: 780752 pages, LIFO batch:63
[    0.004933]   Normal zone: 53248 pages used for memmap
[    0.004934]   Normal zone: 3407872 pages, LIFO batch:63
[    0.004944] On node 0, zone DMA: 1 pages in unavailable ranges
[    0.005112] On node 0, zone DMA: 96 pages in unavailable ranges
[    0.037036] On node 0, zone DMA32: 768 pages in unavailable ranges
[    0.037112] On node 0, zone DMA32: 784 pages in unavailable ranges
[    0.038461] On node 0, zone Normal: 32 pages in unavailable ranges
[    0.038902] ACPI: PM-Timer IO Port: 0xb008
[    0.038904] ACPI: Local APIC address 0xfee00000
[    0.038910] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.038936] IOAPIC[0]: apic_id 8, version 17, address 0xfec00000, GSI 0-31
[    0.038938] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.038939] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.038940] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.038941] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.038941] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.038942] ACPI: IRQ0 used by override.
[    0.038943] ACPI: IRQ5 used by override.
[    0.038943] ACPI: IRQ9 used by override.
[    0.038944] ACPI: IRQ10 used by override.
[    0.038944] ACPI: IRQ11 used by override.
[    0.038945] Using ACPI (MADT) for SMP configuration information
[    0.038961] e820: update [mem 0xbe126000-0xbe12efff] usable ==> reserved
[    0.038972] smpboot: Allowing 8 CPUs, 0 hotplug CPUs
[    0.038984] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.038985] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000fffff]
[    0.038986] PM: hibernation: Registered nosave memory: [mem 0xbe0d7000-0xbe0d7fff]
[    0.038986] PM: hibernation: Registered nosave memory: [mem 0xbe126000-0xbe12efff]
[    0.038987] PM: hibernation: Registered nosave memory: [mem 0xbeb00000-0xbedfffff]
[    0.038988] PM: hibernation: Registered nosave memory: [mem 0xbf8ef000-0xbfb6efff]
[    0.038989] PM: hibernation: Registered nosave memory: [mem 0xbfb6f000-0xbfb7efff]
[    0.038989] PM: hibernation: Registered nosave memory: [mem 0xbfb7f000-0xbfbfefff]
[    0.038990] PM: hibernation: Registered nosave memory: [mem 0xbffe0000-0xbfffffff]
[    0.038991] PM: hibernation: Registered nosave memory: [mem 0xc0000000-0xffffffff]
[    0.038992] [mem 0xc0000000-0xffffffff] available for PCI devices
[    0.038993] Booting paravirtualized kernel on bare hardware
[    0.038996] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.041922] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:8 nr_cpu_ids:8 nr_node_ids:1
[    0.043441] percpu: Embedded 58 pages/cpu s200664 r8192 d28712 u262144
[    0.043445] pcpu-alloc: s200664 r8192 d28712 u262144 alloc=1*2097152
[    0.043446] pcpu-alloc: [0] 0 1 2 3 4 5 6 7 
[    0.043472] Built 1 zonelists, mobility grouping on.  Total pages: 4125069
[    0.043473] Policy zone: Normal
[    0.043474] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-5.10.0-18-amd64 root=UUID=41887436-0108-4b7f-8c26-e9adbc9ed9d0 ro quiet splash console=tty0 console=ttyS0,115200 init=/lib/systemd/systemd-bootchart
[    0.054802] Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)
[    0.060401] Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)
[    0.060437] mem auto-init: stack:off, heap alloc:on, heap free:off
[    0.076984] Memory: 3140892K/16770492K available (12295K kernel code, 2536K rwdata, 7576K rodata, 2648K init, 3444K bss, 453000K reserved, 0K cma-reserved)
[    0.077505] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=8, Nodes=1
[    0.077539] ftrace: allocating 36478 entries in 143 pages
[    0.089710] ftrace: allocated 143 pages with 5 groups
[    0.090019] rcu: Hierarchical RCU implementation.
[    0.090020] rcu:     RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=8.
[    0.090021]  Rude variant of Tasks RCU enabled.
[    0.090021]  Tracing variant of Tasks RCU enabled.
[    0.090022] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.090023] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=8
[    0.093309] NR_IRQS: 524544, nr_irqs: 624, preallocated irqs: 16
[    0.093521] random: crng init done
[    0.093536] Console: colour dummy device 80x25
[    0.093543] printk: console [tty0] enabled
[    0.093589] printk: console [ttyS0] enabled
[    0.093602] ACPI: Core revision 20200925
[    0.093654] APIC: Switch to symmetric I/O mode setup
[    0.094892] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.113658] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x3259dcb07dd, max_idle_ns: 440795231854 ns
[    0.113660] Calibrating delay loop (skipped), value calculated using timer frequency.. 6986.20 BogoMIPS (lpj=13972408)
[    0.113662] pid_max: default: 32768 minimum: 301
[    0.114776] LSM: Security Framework initializing
[    0.114783] Yama: disabled by default; enable with sysctl kernel.yama.*
[    0.114834] AppArmor: AppArmor initialized
[    0.114835] TOMOYO Linux initialized
[    0.115011] Mount-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.115180] Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.115605] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 512
[    0.115606] Last level dTLB entries: 4KB 2048, 2MB 2048, 4MB 1024, 1GB 0
[    0.115608] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[    0.115609] Spectre V2 : Mitigation: Retpolines
[    0.115609] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.115610] Spectre V2 : Spectre v2 / SpectreRSB : Filling RSB on VMEXIT
[    0.115610] RETBleed: Mitigation: untrained return thunk
[    0.115612] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[    0.118368] Freeing SMP alternatives memory: 32K
[    0.227476] smpboot: CPU0: AMD Ryzen 9 3950X 16-Core Processor (family: 0x17, model: 0x71, stepping: 0x0)
[    0.227705] Performance Events: PMU not available due to virtualization, using software events only.
[    0.227812] rcu: Hierarchical SRCU implementation.
[    0.228066] NMI watchdog: Perf NMI watchdog permanently disabled
[    0.228281] smp: Bringing up secondary CPUs ...
[    0.228447] x86: Booting SMP configuration:
[    0.228448] .... node  #0, CPUs:      #1
[    0.004152] smpboot: CPU 1 Converting physical 0 to logical die 1
[    0.309887]  #2
[    0.004152] smpboot: CPU 2 Converting physical 0 to logical die 2
[    0.393887]  #3
[    0.004152] smpboot: CPU 3 Converting physical 0 to logical die 3
[    0.477842]  #4
[    0.004152] smpboot: CPU 4 Converting physical 0 to logical die 4
[    0.561864]  #5
[    0.004152] smpboot: CPU 5 Converting physical 0 to logical die 5
[    0.645882]  #6
[    0.004152] smpboot: CPU 6 Converting physical 0 to logical die 6
[    0.729865]  #7
[    0.004152] smpboot: CPU 7 Converting physical 0 to logical die 7
[    0.813752] smp: Brought up 1 node, 8 CPUs
[    0.813753] smpboot: Max logical packages: 8
[    0.813755] smpboot: Total of 8 processors activated (55890.37 BogoMIPS)
[    0.843855] node 0 deferred pages initialised in 28ms
[    0.843855] devtmpfs: initialized
[    0.843855] x86/mm: Memory block size: 128MB
[    0.845735] PM: Registering ACPI NVS region [mem 0xbfb7f000-0xbfbfefff] (524288 bytes)
[    0.845735] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.845742] futex hash table entries: 2048 (order: 5, 131072 bytes, linear)
[    0.845780] pinctrl core: initialized pinctrl subsystem
[    0.846049] NET: Registered protocol family 16
[    0.846118] audit: initializing netlink subsys (disabled)
[    0.846131] audit: type=2000 audit(1677772101.752:1): state=initialized audit_enabled=0 res=1
[    0.846131] thermal_sys: Registered thermal governor 'fair_share'
[    0.846131] thermal_sys: Registered thermal governor 'bang_bang'
[    0.846131] thermal_sys: Registered thermal governor 'step_wise'
[    0.846131] thermal_sys: Registered thermal governor 'user_space'
[    0.846131] thermal_sys: Registered thermal governor 'power_allocator'
[    0.846131] cpuidle: using governor ladder
[    0.846131] cpuidle: using governor menu
[    0.846440] ACPI: bus type PCI registered
[    0.846440] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.846440] PCI: Using configuration type 1 for base access
[    0.846440] PCI: Using configuration type 1 for extended access
[    0.846527] Kprobes globally optimized
[    0.846538] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[    0.846538] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.938702] ACPI: Added _OSI(Module Device)
[    0.938702] ACPI: Added _OSI(Processor Device)
[    0.938702] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.938702] ACPI: Added _OSI(Processor Aggregator Device)
[    0.938702] ACPI: Added _OSI(Linux-Dell-Video)
[    0.938702] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    0.938702] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    0.938702] ACPI: 2 ACPI AML tables successfully acquired and loaded
[    0.938702] ACPI Error: Could not enable GlobalLock event (20200925/evxfevnt-182)
[    0.941682] ACPI Warning: Could not enable fixed event - GlobalLock (1) (20200925/evxface-618)
[    0.941685] ACPI Error: No response from Global Lock hardware, disabling lock (20200925/evglock-59)
[    0.943646] ACPI: Interpreter enabled
[    0.943659] ACPI: (supports S0 S3 S4 S5)
[    0.943661] ACPI: Using IOAPIC for interrupt routing
[    0.943672] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.944924] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.945669] acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI HPX-Type3]
[    0.945796] PCI host bridge to bus 0000:00
[    0.945799] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.945800] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    0.945804] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    0.945805] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfeefffff window]
[    0.945807] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.946169] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[    0.947021] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[    0.948268] * Found PM-Timer Bug on the chipset. Due to workarounds for a bug,
               * this clock source is slow. Consider trying other clock sources
[    0.948270] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000
[    0.949252] pci 0000:00:01.3: quirk: [io  0xb000-0xb03f] claimed by PIIX4 ACPI
[    0.949879] pci 0000:00:08.0: [1af4:1000] type 00 class 0x020000
[    0.950115] pci 0000:00:08.0: reg 0x10: [io  0xc200-0xc3ff]
[    0.950240] pci 0000:00:08.0: reg 0x14: [mem 0xc000a000-0xc000bfff]
[    0.951650] pci 0000:00:10.0: [01de:0000] type 00 class 0x010802
[    0.951930] pci 0000:00:10.0: reg 0x10: [mem 0x800000000-0x800003fff 64bit]
[    0.952280] pci 0000:00:10.0: reg 0x20: [mem 0xc0000000-0xc0007fff]
[    0.952800] pci 0000:00:18.0: [1af4:1001] type 00 class 0x010000
[    0.952919] pci 0000:00:18.0: reg 0x10: [io  0xc000-0xc1ff]
[    0.952982] pci 0000:00:18.0: reg 0x14: [mem 0xc0008000-0xc0009fff]
[    0.953666] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
[    0.953719] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[    0.953787] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[    0.953852] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[    0.953917] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[    0.954034] iommu: Default domain type: Translated 
[    0.954055] vgaarb: loaded
[    0.954055] EDAC MC: Ver: 3.0.0
[    0.954055] Registered efivars operations
[    0.954055] NetLabel: Initializing
[    0.954055] NetLabel:  domain hash size = 128
[    0.954055] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    0.954055] NetLabel:  unlabeled traffic allowed by default
[    0.954055] PCI: Using ACPI for IRQ routing
[    0.954055] PCI: pci_cache_line_size set to 64 bytes
[    0.954055] pci 0000:00:10.0: can't claim BAR 0 [mem 0x800000000-0x800003fff 64bit]: no compatible bridge window
[    0.954055] e820: reserve RAM buffer [mem 0xbe0d7000-0xbfffffff]
[    0.954055] e820: reserve RAM buffer [mem 0xbe126000-0xbfffffff]
[    0.954055] e820: reserve RAM buffer [mem 0xbeb00000-0xbfffffff]
[    0.954055] e820: reserve RAM buffer [mem 0xbf8ef000-0xbfffffff]
[    0.954055] e820: reserve RAM buffer [mem 0xbffe0000-0xbfffffff]
[    0.954091] clocksource: Switched to clocksource tsc-early
[    0.964557] VFS: Disk quotas dquot_6.6.0
[    0.964568] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.964681] AppArmor: AppArmor Filesystem Enabled
[    0.964692] pnp: PnP ACPI init
[    0.964795] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.964816] system 00:01: [io  0x01e0-0x01ef] has been reserved
[    0.964817] system 00:01: [io  0x0160-0x016f] has been reserved
[    0.964818] system 00:01: [io  0x0370-0x0371] has been reserved
[    0.964819] system 00:01: [io  0x0402] has been reserved
[    0.964819] system 00:01: [io  0x0440-0x044f] has been reserved
[    0.964820] system 00:01: [io  0xafe0-0xafe3] has been reserved
[    0.964821] system 00:01: [io  0xb000-0xb03f] has been reserved
[    0.964822] system 00:01: [mem 0xfec00000-0xfec00fff] could not be reserved
[    0.964823] system 00:01: [mem 0xfee00000-0xfeefffff] has been reserved
[    0.964825] system 00:01: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.964836] pnp 00:02: Plug and Play ACPI device, IDs PNP0303 PNP030b (active)
[    0.964845] pnp 00:03: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.964854] pnp 00:04: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.964855] pnp: PnP ACPI: found 5 devices
[    0.973840] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    0.973878] NET: Registered protocol family 2
[    0.975325] IP idents hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.976808] tcp_listen_portaddr_hash hash table entries: 8192 (order: 5, 131072 bytes, linear)
[    0.977717] TCP established hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[    0.978530] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes, linear)
[    0.978592] TCP: Hash tables configured (established 131072 bind 65536)
[    0.978898] UDP hash table entries: 8192 (order: 6, 262144 bytes, linear)
[    0.979091] UDP-Lite hash table entries: 8192 (order: 6, 262144 bytes, linear)
[    0.979125] NET: Registered protocol family 1
[    0.979129] NET: Registered protocol family 44
[    0.979135] pci 0000:00:10.0: BAR 0: assigned [mem 0xc000c000-0xc000ffff 64bit]
[    0.979211] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    0.979212] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]
[    0.979212] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[    0.979213] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfeefffff window]
[    0.979232] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    0.979244] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[    0.979293] PCI: CLS 0 bytes, default 64
[    0.979352] Trying to unpack rootfs image as initramfs...
[    1.369292] Freeing initrd memory: 28224K
[    1.369356] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
[    1.369358] software IO TLB: mapped [mem 0x00000000b7fbe000-0x00000000bbfbe000] (64MB)
[    1.370947] Initialise system trusted keyrings
[    1.370955] Key type blacklist registered
[    1.371087] workingset: timestamp_bits=36 max_order=22 bucket_order=0
[    1.372051] zbud: loaded
[    1.372416] integrity: Platform Keyring initialized
[    1.372418] Key type asymmetric registered
[    1.372419] Asymmetric key parser 'x509' registered
[    1.372425] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[    1.372532] io scheduler mq-deadline registered
[    1.373196] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[    1.373208] efifb: probing for efifb
[    1.373221] efifb: framebuffer at 0xbeb00000, using 1876k, total 1875k
[    1.373221] efifb: mode is 800x600x32, linelength=3200, pages=1
[    1.373222] efifb: scrolling: redraw
[    1.373223] efifb: Truecolor: size=8:8:8:8, shift=24:16:8:0
[    1.373326] Console: switching to colour frame buffer device 100x37
[    1.373938] fb0: EFI VGA frame buffer device
[    1.374225] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    1.374364] 00:03: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16450
[    1.374560] 00:04: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16450
[    1.374751] serial8250: ttyS2 at I/O 0x3e8 (irq = 4, base_baud = 115200) is a 16450
[    1.375068] Linux agpgart interface v0.103
[    1.375110] AMD-Vi: AMD IOMMUv2 functionality not available on this system - This is not a bug.
[    1.376301] i8042: PNP: PS/2 Controller [PNP0303:PS2K] at 0x60,0x64 irq 1
[    1.376301] i8042: PNP: PS/2 appears to have AUX port disabled, if this is incorrect please boot with i8042.nopnp
[    1.376494] serio: i8042 KBD port at 0x60,0x64 irq 1
[    1.376638] mousedev: PS/2 mouse device common for all mice
[    1.376691] ACPI Error: Could not enable RealTimeClock event (20200925/evxfevnt-182)
[    1.377579] ACPI Warning: Could not enable fixed event - RealTimeClock (4) (20200925/evxface-618)
[    1.377599] rtc_cmos 00:00: RTC can wake from S4
[    1.377928] rtc_cmos 00:00: registered as rtc0
[    1.378022] rtc_cmos 00:00: setting system clock to 2023-03-02T15:48:22 UTC (1677772102)
[    1.378074] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram
[    1.378110] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    1.378461] ledtrig-cpu: registered to indicate activity on CPUs
[    1.378571] NET: Registered protocol family 10
[    1.384699] Segment Routing with IPv6
[    1.384725] mip6: Mobile IPv6
[    1.384727] NET: Registered protocol family 17
[    1.384833] mpls_gso: MPLS GSO support
[    1.385599] IPI shorthand broadcast: enabled
[    1.385631] sched_clock: Marking stable (1385398995, 152117)->(1500687633, -115136521)
[    1.385843] registered taskstats version 1
[    1.385845] Loading compiled-in X.509 certificates
[    1.420964] Loaded X.509 cert 'Debian Secure Boot CA: 6ccece7e4c6c0d1f6149f3dd27dfcc5cbb419ea1'
[    1.420988] Loaded X.509 cert 'Debian Secure Boot Signer 2022 - linux: 14011249c2675ea8e5148542202005810584b25f'
[    1.421257] zswap: loaded using pool lzo/zbud
[    1.421697] Key type ._fscrypt registered
[    1.421698] Key type .fscrypt registered
[    1.421699] Key type fscrypt-provisioning registered
[    1.421742] AppArmor: AppArmor sha1 policy hashing enabled
[    1.424185] Freeing unused kernel image (initmem) memory: 2648K
[    1.448408] Write protecting the kernel read-only data: 22528k
[    1.448996] Freeing unused kernel image (text/rodata gap) memory: 2040K
[    1.449207] Freeing unused kernel image (rodata/data gap) memory: 616K
[    1.487838] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[    1.487842] Run /init as init process
[    1.487843]   with arguments:
[    1.487844]     /init
[    1.487844]   with environment:
[    1.487844]     HOME=/
[    1.487845]     TERM=linux
[    1.487845]     BOOT_IMAGE=/boot/vmlinuz-5.10.0-18-amd64
[    1.532909] piix4_smbus 0000:00:01.3: SMBus base address uninitialized - upgrade BIOS or use force_addr=0xaddr
[    1.536825] PCI Interrupt Link [LNKA] enabled at IRQ 10
[    1.536918] virtio-pci 0000:00:08.0: virtio_pci: leaving for legacy driver
[    1.537342] virtio-pci 0000:00:18.0: can't derive routing for PCI INT B
[    1.537344] virtio-pci 0000:00:18.0: PCI INT B: no GSI
[    1.537407] virtio-pci 0000:00:18.0: virtio_pci: leaving for legacy driver
[    1.546676] virtio_blk virtio1: [vda] 42 512-byte logical blocks (21.5 kB/21.0 KiB)
[    1.546678] vda: detected capacity change from 0 to 21504
[    1.565140] GPT:Primary header thinks Alt. header is not at the end of the disk.
[    1.565141] GPT:4194303 != 146800639
[    1.565142] GPT:Alternate GPT header not at the end of the disk.
[    1.565142] GPT:4194303 != 146800639
[    1.565148] GPT: Use GNU Parted to correct GPT errors.
[    1.565152]  nvme0n1: p1 p2 p3
[    1.570133]  vda:
[    1.597005] virtio_net virtio0 enp0s8: renamed from eth0
[    1.847511] EXT4-fs (nvme0n1p3): mounted filesystem with ordered data mode. Opts: (null)
[    2.314024] systemd[1]: Inserted module 'autofs4'
[    2.366795] systemd[1]: systemd 247.3-7+deb11u1 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=unified)
[    2.366863] systemd[1]: Detected virtualization bhyve.
[    2.366867] systemd[1]: Detected architecture x86-64.
[    2.368002] systemd[1]: No hostname configured.
[    2.368009] systemd[1]: Set hostname to <localhost>.
[    2.397713] tsc: Refined TSC clocksource calibration: 3493.387 MHz
[    2.397741] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x325ae9f48fc, max_idle_ns: 440795209558 ns
[    2.397869] clocksource: Switched to clocksource tsc
[    2.907033] systemd[1]: Queued start job for default target Graphical Interface.
[    2.909913] systemd[1]: Created slice system-getty.slice.
[    2.910265] systemd[1]: Created slice system-modprobe.slice.
[    2.910602] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    2.910813] systemd[1]: Created slice User and Session Slice.
[    2.910877] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    2.910920] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    2.911084] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    2.911125] systemd[1]: Reached target Local Encrypted Volumes.
[    2.911165] systemd[1]: Reached target Paths.
[    2.911179] systemd[1]: Reached target Remote File Systems.
[    2.911190] systemd[1]: Reached target Slices.
[    2.911209] systemd[1]: Reached target Swap.
[    2.911337] systemd[1]: Listening on fsck to fsckd communication Socket.
[    2.911386] systemd[1]: Listening on initctl Compatibility Named Pipe.
[    2.911525] systemd[1]: Listening on Journal Audit Socket.
[    2.911606] systemd[1]: Listening on Journal Socket (/dev/log).
[    2.911707] systemd[1]: Listening on Journal Socket.
[    2.911861] systemd[1]: Listening on udev Control Socket.
[    2.911937] systemd[1]: Listening on udev Kernel Socket.
[    2.912800] systemd[1]: Mounting Huge Pages File System...
[    2.913894] systemd[1]: Mounting POSIX Message Queue File System...
[    2.915043] systemd[1]: Mounting Kernel Debug File System...
[    2.916088] systemd[1]: Mounting Kernel Trace File System...
[    2.917276] systemd[1]: Starting Create list of static device nodes for the current kernel...
[    2.918212] systemd[1]: Starting Load Kernel Module configfs...
[    2.919172] systemd[1]: Starting Load Kernel Module drm...
[    2.920230] systemd[1]: Starting Load Kernel Module fuse...
[    2.925398] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[    2.925465] systemd[1]: Condition check resulted in File System Check on Root Device being skipped.
[    2.927081] systemd[1]: Starting Journal Service...
[    2.940792] systemd[1]: Starting Load Kernel Modules...
[    2.941907] systemd[1]: Starting Remount Root and Kernel File Systems...
[    2.942959] systemd[1]: Starting Coldplug All udev Devices...
[    2.945057] systemd[1]: Mounted Huge Pages File System.
[    2.945149] systemd[1]: Mounted POSIX Message Queue File System.
[    2.945218] systemd[1]: Mounted Kernel Debug File System.
[    2.945320] systemd[1]: Mounted Kernel Trace File System.
[    2.945641] systemd[1]: Finished Create list of static device nodes for the current kernel.
[    2.945940] systemd[1]: modprobe@configfs.service: Succeeded.
[    2.946158] systemd[1]: Finished Load Kernel Module configfs.
[    2.947092] systemd[1]: Mounting Kernel Configuration File System...
[    2.949500] systemd[1]: Mounted Kernel Configuration File System.
[    2.952535] fuse: init (API version 7.32)
[    2.953405] systemd[1]: modprobe@fuse.service: Succeeded.
[    2.953654] systemd[1]: Finished Load Kernel Module fuse.
[    2.954734] systemd[1]: Mounting FUSE Control File System...
[    2.957072] systemd[1]: Mounted FUSE Control File System.
[    2.965020] EXT4-fs (nvme0n1p3): re-mounted. Opts: errors=remount-ro
[    2.965025] systemd[1]: Finished Load Kernel Modules.
[    2.965976] systemd[1]: Finished Remount Root and Kernel File Systems.
[    2.967129] systemd[1]: Starting Initial cloud-init job (pre-networking)...
[    2.985643] systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped.
[    2.985810] systemd[1]: Condition check resulted in Platform Persistent Storage Archival being skipped.
[    2.986649] systemd[1]: Starting Load/Save Random Seed...
[    2.987451] systemd[1]: Starting Apply Kernel Variables...
[    2.988167] systemd[1]: Starting Create System Users...
[    2.990292] systemd[1]: Started Journal Service.
[    3.007246] systemd-journald[246]: Received client request to flush runtime journal.
[    3.442034] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer
[    3.442400] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input1
[    3.461824] ACPI: Power Button [PWRF]
[    3.488251] input: PC Speaker as /devices/platform/pcspkr/input/input2
[    3.522175] cryptd: max_cpu_qlen set to 1000
[    3.535070] pstore: Using crash dump compression: deflate
[    3.535074] pstore: Registered efi as persistent store backend
[    3.561639] AVX2 version of gcm_enc/dec engaged.
[    3.561640] AES CTR mode by8 optimization enabled
[    3.862459] audit: type=1400 audit(1677772104.979:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="lsb_release" pid=369 comm="apparmor_parser"
[    3.867399] audit: type=1400 audit(1677772104.983:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=370 comm="apparmor_parser"
[    3.868087] audit: type=1400 audit(1677772104.983:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod" pid=370 comm="apparmor_parser"
[    3.922457] audit: type=1400 audit(1677772105.039:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="tcpdump" pid=368 comm="apparmor_parser"
[    6.427382] EXT4-fs (nvme0n1p3): resizing filesystem from 472571 to 18298363 blocks
[    7.240368] EXT4-fs (nvme0n1p3): resized filesystem to 18298363
[    8.756878] device-mapper: uevent: version 1.0.3
[    8.757012] device-mapper: ioctl: 4.43.0-ioctl (2020-10-01) initialised: dm-devel@redhat.com
[  104.625361] audit: type=1400 audit(1677771905.783:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/chronyd" pid=2122 comm="apparmor_parser"
[ 1362.397765] audit: type=1400 audit(1677773163.552:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="docker-default" pid=6719 comm="apparmor_parser"
[ 1362.963240] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[ 1362.965925] Bridge firewalling registered
[ 1363.188723] Initializing XFRM netlink socket
[ 1390.338518] docker0: port 1(veth5ee9b83) entered blocking state
[ 1390.338521] docker0: port 1(veth5ee9b83) entered disabled state
[ 1390.338556] device veth5ee9b83 entered promiscuous mode
[ 1391.381436] eth0: renamed from veth285c543
[ 1391.409317] docker0: port 1(veth5ee9b83) entered blocking state
[ 1391.409321] docker0: port 1(veth5ee9b83) entered forwarding state
[ 1391.639881] docker0: port 1(veth5ee9b83) entered disabled state
[ 1391.639942] veth285c543: renamed from eth0
[ 1391.859086] docker0: port 1(veth5ee9b83) entered disabled state
[ 1391.859301] device veth5ee9b83 left promiscuous mode
[ 1391.859313] docker0: port 1(veth5ee9b83) entered disabled state
[ 1525.639733] clocksource: timekeeping watchdog on CPU2: acpi_pm retried 2 times before success
[ 2758.363976] wireguard: WireGuard 1.0.0 loaded. See www.wireguard.com for information.
[ 2758.363979] wireguard: Copyright (C) 2015-2019 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
[ 2765.916484] FS-Cache: Loaded
[ 2765.979178] RPC: Registered named UNIX socket transport module.
[ 2765.979180] RPC: Registered udp transport module.
[ 2765.979181] RPC: Registered tcp transport module.
[ 2765.979181] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 2766.035243] FS-Cache: Netfs 'nfs' registered for caching
[ 2766.040460] Key type dns_resolver registered
[ 2766.212599] NFS: Registering the id_resolver key type
[ 2766.212610] Key type id_resolver registered
[ 2766.212610] Key type id_legacy registered
[ 8996.144253] clocksource: timekeeping watchdog on CPU2: Marking clocksource 'tsc' as unstable because the skew is too large:
[ 8996.144260] clocksource:                       'acpi_pm' wd_now: f4b7d wd_last: 6c50c5 mask: ffffff
[ 8996.144261] clocksource:                       'tsc' cs_now: 1ca324f62cac cs_last: 1ca0b7a50c00 mask: ffffffffffffffff
[ 8996.144274] tsc: Marking TSC unstable due to clocksource watchdog
[ 8996.144401] TSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
[ 8996.144403] sched_clock: Marking unstable (8996101633485, 42749061)<-(8996259532949, -115136521)
[ 8996.145058] clocksource: Checking clocksource tsc synchronization from CPU 5.
[ 8996.146113] clocksource: Switched to clocksource acpi_pm

[jmpesp]

answering some out-of-band questions:

• the host CPU is AMD Ryzen 9 3950X 16-Core Processor
• helios version is helios-1.0.21472
• the guest has been running for a few hours, and had not rebooted

[jordanhendricks]

Jotting down some notes about my cursory research into this so far looking at the linux 5.10 source:

• The first few lines of the warn message come from the "clocksource watchdog" (clocksource_watchdog() in kernel/time/clocksource.c). The clocksource watchdog is an alternate clocksource used to check the quality of another clock source. In this case, the watchdog source is the ACPI PM, and the clock source it's checking against is the TSC.
• The check that it's doing takes a delta of clock cycles for each source, and converts the time elapsed to nanoseconds. It computes the diff of those deltas and compares it against a threshold.
• The threshold is 0.065 seconds, indicating that the TSC frequency is at least that far off from the ACPI PM's reading.
• The {cs,wd}_{now,last} variables in the warn message are the cycle counts of the TSC (cs) and the ACPI PM (wd) clocks for the high end of the delta and the lower end.

I have a couple of follow up questions / things to explore, but I need to step away for a bit and wanted to write this down before I did.

[pfmooney]

How loaded was the host system when this occurred? We've seen behavior like this before when the host is busy. The thread(s) running vCPUs struggle to be scheduled in a timely manner.

@jordanhendricks's analysis helps shed light on how that could manifest itself in a reading which was reportedly unstable: If we took an excessively long exit to service the second (wd_end) PM timer reading, that would stretch out the perceived delta between it and the TSC. If the wd_end2 reading after that progressed without issue, the guest would have little visibility into the scheduling hiccup.

Using the values listed in the dmesg output, we can clean what sort of delay was observed:

PM timer: 6c50c5 to f4b7d (wrapping at 24 bits) is 10681015 ticks or 2983902982ns (@ 3579545Hz) TSC: 1ca0b7a50c00 to 1ca324f62cac is 10423967916 ticks or 2978276547ns (@ 3.5Ghz)

That puts the PM timer reading at ~5600us off the TSC. Jordan noted a threshold of 65ms, but that assumes the default uncertainty margins. I believe both the TSC and PM timer clocksources have their margins set according to their frequency, with a lower bound of 2 * WATCHDOG_MAX_SKEW which would be 200us - definitely below the calculated delta.

[jmpesp]

How loaded was the host system when this occurred? We've seen behavior like this before when the host is busy. The thread(s) running vCPUs struggle to be scheduled in a timely manner.

Pretty loaded, and there were several guests running at the time. They were all running a ffmpeg encoding test workload.

[gjcolombo]

This is still kicking around, I think--I saw it hit while running a local PHD test run in its multiple_migrations variation:

root@debian:~# echo Hello world
Hello world
root@debian:~# echo I have migrated![   35.594799] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[   35.598280] clocksource:                       'acpi_pm' wd_now: 67dd37 wd_last: c9e727 mask: ffffff
[   35.600486] clocksource:                       'tsc' cs_now: 1fd17bc48c cs_last: 1dbb1e5975 mask: ffffffffffffffff
[   35.603120] tsc: Marking TSC unstable due to clocksource watchdog
[   35.604508] TSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
[   35.606430] sched_clock: Marking unstable (35594603625, 9904438)<-(35623950231, -19442339)

I have migrated!
root@debian:~# [   35.614410] clocksource: Checking clocksource tsc synchronization from CPU 1.
[   35.616115] clocksource: Switched to clocksource acpi_pm

This test usually passes (this is the first time I've seen this flake in many recent runs), and I don't know of any reason this would have regressed recently, but wanted to make a note to keep this issue from getting any more stale.

[gjcolombo]

I'm able to force the TSC to be abandoned on a Debian 11 guest using the DTrace chill action. uname reports that the kernel version in my guest 5.10, but the kernel messages it emits are more 6.10-ish, so your mileage may vary--the script depends heavily on the kernel's actual watchdog implementation logic:

BEGIN {
    i = 0;
}

fbt:vmm:vpmtmr_handler:entry {
    i = i + 1;
    printf("[%d] [%u] PM timer read", i, walltimestamp);
}

fbt:vmm:vpmtmr_handler:return /(i % 3) == 1/ {
    chill(1000000);
    printf("[%d] [%u] delayed return from timer read!", i, walltimestamp);
}

The guest is using the ACPI PM timer as a watchdog for the TSC. Its watchdog sequence is

• read the PM timer
• read the TSC
• read the PM timer again
• read the PM timer again

If the differences between any pair of consecutive PM timer reads is too large, the guest concludes that there's too much scheduling or I/O weather for the watchdog to be reliable and abandons it. The script inserts a delay before returning from the first PM timer read--i.e. it inserts a delay between the moment the first PM timer value is captured and the moment the guest reads the TSC. With a proper chill value (1ms here) this gets the watchdog to fire reliably.