[9front] qemu clock/timer issue

[9front] qemu clock/timer issue

[Michael Forney]

I was recently running 9front in a VM on linux (qemu, with
-enable-kvm), and noticed several weird timing/clock issues. The date
command gives wildly varying results +- 1 minute:

cpu% date
Fri Feb  4 17:39:23 PST 2022
cpu% date
Fri Feb  4 17:39:12 PST 2022
cpu% date
Fri Feb  4 17:40:19 PST 2022
cpu% date
Fri Feb  4 17:39:18 PST 2022

`sleep 1` exits pretty much instantly, stats moves through the entire
width in a second or two, and clicking in scrollbars starts repeating
immediately.

I notice the following messages in my dmesg:
kvm: vcpu 3: requested 38141 ns lapic timer period limited to 200000 ns
kvm: vcpu 1: requested 9449 ns lapic timer period limited to 200000 ns
kvm: vcpu 2: requested 51204 ns lapic timer period limited to 200000 ns
kvm: vcpu 0: requested 74421 ns lapic timer period limited to 200000 ns

I don't remember this problem last time I ran 9front in qemu (around a
year ago), so I looked through commit history and found one commit
that seemed like it might be related:
http://git.9front.org/plan9front/plan9front/a05bab362f66ddd6fa65f2e7cda9eaaa0217ec08/commit.html

To check, I tried setting *nohpet=1 in my plan9.ini, which *seems* to
have solved the problem, though I still see those same messages in
dmesg on the linux host (but now the requested lapic timer period is
always around 100000 ns or greater).

Anyone know what's going on here?

Re: [9front] qemu clock/timer issue

[hiro]

do you have timesync running twice? check in ps output.

On 2/5/22, Michael Forney <mforney@mforney.org> wrote:
> I was recently running 9front in a VM on linux (qemu, with
> -enable-kvm), and noticed several weird timing/clock issues. The date
> command gives wildly varying results +- 1 minute:
>
> cpu% date
> Fri Feb  4 17:39:23 PST 2022
> cpu% date
> Fri Feb  4 17:39:12 PST 2022
> cpu% date
> Fri Feb  4 17:40:19 PST 2022
> cpu% date
> Fri Feb  4 17:39:18 PST 2022
>
> `sleep 1` exits pretty much instantly, stats moves through the entire
> width in a second or two, and clicking in scrollbars starts repeating
> immediately.
>
> I notice the following messages in my dmesg:
> kvm: vcpu 3: requested 38141 ns lapic timer period limited to 200000 ns
> kvm: vcpu 1: requested 9449 ns lapic timer period limited to 200000 ns
> kvm: vcpu 2: requested 51204 ns lapic timer period limited to 200000 ns
> kvm: vcpu 0: requested 74421 ns lapic timer period limited to 200000 ns
>
> I don't remember this problem last time I ran 9front in qemu (around a
> year ago), so I looked through commit history and found one commit
> that seemed like it might be related:
> http://git.9front.org/plan9front/plan9front/a05bab362f66ddd6fa65f2e7cda9eaaa0217ec08/commit.html
>
> To check, I tried setting *nohpet=1 in my plan9.ini, which *seems* to
> have solved the problem, though I still see those same messages in
> dmesg on the linux host (but now the requested lapic timer period is
> always around 100000 ns or greater).
>
> Anyone know what's going on here?
>

Re: [9front] qemu clock/timer issue

[Nick Owens]

kvm emulates a local APIC timer which the 9front kernel uses. the
timer period is clamped to a minimum period, and my understanding is
that the purpose is to protect the host from CPU consumption by
guests, but i don't have a citation for that. 9front requests a timer
period shorter than what the default minimum is and kvm warns about
it. it maybe needs more investigation as to whether we really need
such short timers.

in the meantime, you can lower the timer period minimum with

echo "options kvm min_timer_period_us=10" >> /etc/modprobe.d/kvm.conf

which is 10000ns. it won't kill all of the warnings since sometimes
the timer period is slightly shorter, but it will help with the dmesg
spam.

On Sat, Feb 5, 2022 at 7:30 AM Michael Forney <mforney@mforney.org> wrote:
>
> I was recently running 9front in a VM on linux (qemu, with
> -enable-kvm), and noticed several weird timing/clock issues. The date
> command gives wildly varying results +- 1 minute:
>
> cpu% date
> Fri Feb  4 17:39:23 PST 2022
> cpu% date
> Fri Feb  4 17:39:12 PST 2022
> cpu% date
> Fri Feb  4 17:40:19 PST 2022
> cpu% date
> Fri Feb  4 17:39:18 PST 2022
>
> `sleep 1` exits pretty much instantly, stats moves through the entire
> width in a second or two, and clicking in scrollbars starts repeating
> immediately.
>
> I notice the following messages in my dmesg:
> kvm: vcpu 3: requested 38141 ns lapic timer period limited to 200000 ns
> kvm: vcpu 1: requested 9449 ns lapic timer period limited to 200000 ns
> kvm: vcpu 2: requested 51204 ns lapic timer period limited to 200000 ns
> kvm: vcpu 0: requested 74421 ns lapic timer period limited to 200000 ns
>
> I don't remember this problem last time I ran 9front in qemu (around a
> year ago), so I looked through commit history and found one commit
> that seemed like it might be related:
> http://git.9front.org/plan9front/plan9front/a05bab362f66ddd6fa65f2e7cda9eaaa0217ec08/commit.html
>
> To check, I tried setting *nohpet=1 in my plan9.ini, which *seems* to
> have solved the problem, though I still see those same messages in
> dmesg on the linux host (but now the requested lapic timer period is
> always around 100000 ns or greater).
>
> Anyone know what's going on here?

Re: [9front] qemu clock/timer issue

[Michael Forney]

On 2022-02-05, Nick Owens <mischief@offblast.org> wrote:
> kvm emulates a local APIC timer which the 9front kernel uses. the
> timer period is clamped to a minimum period, and my understanding is
> that the purpose is to protect the host from CPU consumption by
> guests, but i don't have a citation for that. 9front requests a timer
> period shorter than what the default minimum is and kvm warns about
> it. it maybe needs more investigation as to whether we really need
> such short timers.
>
> in the meantime, you can lower the timer period minimum with
>
> echo "options kvm min_timer_period_us=10" >> /etc/modprobe.d/kvm.conf
>
> which is 10000ns. it won't kill all of the warnings since sometimes
> the timer period is slightly shorter, but it will help with the dmesg
> spam.

Thanks for the info! I tried lowering to min_timer_period_us=5 and
even then it seems that 9front requests even shorter lapic timers:

kvm: vcpu 2: requested 828 ns lapic timer period limited to 5000 ns
kvm: vcpu 0: requested 828 ns lapic timer period limited to 5000 ns
kvm: vcpu 3: requested 3822 ns lapic timer period limited to 5000 ns
kvm: vcpu 1: requested 2526 ns lapic timer period limited to 5000 ns

I did some more debugging and I believe the issue is with CPU
frequency detection using hpetcpufreq(). I should have noticed this
earlier, but without *nohpet=1, 9front detects the CPUs as having a
very low clock rate, for example 27 MHz, when it should be 3.3 GHz.

Nothing in the code seemed wrong to me, so I added some debug prints
to try to figure out where detection was going wrong.

Here's a boot log with HPET, detecting the wrong frequency:

Plan 9
HPET: fed00000 8086a201 100 MHz
loops=1000
	cycles 17384 [13196648 13214032]
	hpet 502 [394 896]
loops=2000
	cycles 42652 [56658413 56701065]
	hpet 643 [1318776 1319419]
<snip>
loops=38000
	cycles 477510 [2494452748 2494930258]
	hpet 13729 [75232811 75246540]
loops=39000
	cycles 491293 [2781515810 2782007103]
	hpet 14149 [83936532 83950681]
loops=40000
	cycles 498652 [2935179496 2935678148]
	hpet 1986869 [88595551 90582420]
498652 cycles 1986869 hpet ticks
cpuhz=25097376 cpumhz=25 cyclefreq=25097376 loopconst=1930
125 holes free
0x00026000 0x0009f000 495616
0x00100000 0x00110000 65536
0x005a1000 0x7ffff000 2141577216
2142138368 bytes free
pcirouting: PCI.0.1.3 at pin 1 link 60 irq 9 -> 10
cpu0: 25MHz GenuineIntel P6 (AX 000306F2 CX F7FAB223 DX 1F8BFBFF)
LAPIC: fee00000 0xfffffe80fee00000
ELCR: 0C00
cpu0: lapic clock at 8MHz
cpu1: 25MHz GenuineIntel P6 (AX 000306F2 CX F7FAB223 DX 1F8BFBFF)
cpu2: 25MHz GenuineIntel P6 (AX 000306F2 CX F7FAB223 DX 1F8BFBFF)
cpu3: 25MHz GenuineIntel P6 (AX 000306F2 CX F7FAB223 DX 1F8BFBFF)

It seems that the hpetcpufreq loop is seeing a huge jump in hpet ticks
at some point, causing the loop to stop prematurely. Looking through
qemu source, I believe the HPET is emulated with it's
"QEMU_CLOCK_VIRTUAL", which uses the host's
clock_gettime(CLOCK_MONOTONIC), taking care to save offsets so it
doesn't increase in between vm_stop and vm_start. I confirmed that
vm_stop is never called while reproducing the bug, which means that
reading the HPET counter is effectively doing
clock_gettime(CLOCK_MONOTONIC)/10 (100 MHz, so 10 ns period).

As I was debugging, I noticed that it doesn't happen all of the time,
and I can usually trigger it by resizing the qemu window. When I run
with -display none, I do not see the issue.

I am not quite sure how TSC works under VT-x (and my searches weren't
too helpful), but if is only counting cycles of the virtual CPUs,
while HPET is counting real time on the host, that could explain this
result. Perhaps when the qemu window is resized, the virtual CPU stops
running for some period, but the HPET keeps ticking. Then, when it is
resumed, 9front sees a huge jump in HPET ticks, with a comparatively
small number of clock cycles, and deduces from this that the CPU clock
speed is very slow.

This leaves me with a few questions:
- Is there a more robust method for determining CPU clock rate?
- Why does i8253cpufreq() work with qemu? As far as I can tell, they
are both implemented in qemu using the same clock, but it seems that
it is immune to the resize trick.

Maybe this is something I need to ask qemu developers.

Re: [9front] qemu clock/timer issue

[cinap_lenrek]

Nice writeup. Thank you for this investigation.

> Maybe this is something I need to ask qemu developers.

Yes, please try.

Maybe we are missing some instruction barriers when
reading the tsc counter?

The issue is hard to reproduce for me, i have no issues
with qemu or real hardware. I guess it also depends on
the host cpu and linux scheduling and the moon phase :(

Anyway, dont give up. It would be very nice to get to
the bottom of this.

--
cinap

Re: [9front] qemu clock/timer issue

[Douglas Guptill]

Hi:

On Mon, Feb 21, 2022 at 11:35:31PM +0100, cinap_lenrek@felloff.net wrote:
> Nice writeup. Thank you for this investigation.
> 
> > Maybe this is something I need to ask qemu developers.
> 
> Yes, please try.
> 
> Maybe we are missing some instruction barriers when
> reading the tsc counter?
> 
> The issue is hard to reproduce for me, i have no issues
> with qemu or real hardware. I guess it also depends on
> the host cpu and linux scheduling and the moon phase :(
> 
> Anyway, dont give up. It would be very nice to get to
> the bottom of this.
> 
> --
> cinap

I am having what looks like a similar problem.  Consistently.  It
shows up as soom as I boot the 9front iso file in qemu.

/var/log/messages and /var/log/syslog become terribly large.

Included below are the details that come to my mind.  I'll be glad to
send any others.

Suggestions appreciated.

Regards,
Douglas.


Details:
=======

toc
---
* 9front iso
* qemu:
* run command for qemu
* host cpu
* /var/log/syslog:
* /var/log/messages:

* 9front iso
------------

9front-10277.amd64.is

* qemu:
-------

doug@blackscram $ qemu-system-x86_64 --version
QEMU emulator version 8.1.2
Copyright (c) 2003-2023 Fabrice Bellard and the QEMU Project developers

- my slackbuild


* run command for qemu
----------------------

com is <qemu-system-x86_64 -name frog  -cpu host -accel kvm -smp 1 -m 1024      -device e1000,netdev=mytap,mac=DE:AD:BE:EF:50:62 -netdev tap,id=mytap,ifname=tap2,script=no,downscript=no  -boot menu=on,order=d -device virtio-scsi-pci -device scsi-hd,drive=isob -blockdev driver=file,node-name=isoa,filename=/data/48f2/9front/9front-10277.amd64.iso -blockdev driver=raw,node-name=isob,file=isoa,read-only=on -device virtio-scsi-pci -device scsi-hd,drive=hd1b -blockdev driver=file,node-name=hd1a,filename=/data/48f2/9front/qemu-9front-frog-img.raw -blockdev driver=raw,node-name=hd1b,file=hd1a>


* host cpu
----------

host is slackware64_15.0 on a 4-core cpu. (2009 vintage)
Details for 1 core are:

processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 26
model name      : Intel(R) Core(TM) i7 CPU         920  @ 2.67GHz
stepping        : 5
microcode       : 0xf
cpu MHz         : 2000.000
cache size      : 8192 KB
physical id     : 0
siblings        : 4
core id         : 0
cpu cores       : 4
apicid          : 0
initial apicid  : 0
fpu             : yes
fpu_exception   : yes
cpuid level     : 11
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ht tm pbe syscall nx rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm sse4_1 sse4_2 popcnt lahf_lm pti tpr_shadow vnmi flexpriority ept vpid dtherm ida
vmx flags       : vnmi preemption_timer invvpid ept_x_only flexpriority tsc_offset vtpr mtf vapic ept vpid
bugs            : cpu_meltdown spectre_v1 spectre_v2 spec_store_bypass l1tf mds swapgs itlb_multihit mmio_unknown
bogomips        : 5345.77
clflush size    : 64
cache_alignment : 64
address sizes   : 36 bits physical, 48 bits virtual
power management:


* /var/log/syslog:
-----------------
Apr 15 12:05:17 blackscram kernel: limit_periodic_timer_frequency: 1 callbacks suppressed
Apr 15 14:17:52 blackscram kernel: limit_periodic_timer_frequency: 3 callbacks suppressed
Apr 15 14:17:57 blackscram kernel: limit_periodic_timer_frequency: 16 callbacks suppressed
Apr 15 14:18:02 blackscram kernel: limit_periodic_timer_frequency: 12 callbacks suppressed
Apr 15 14:18:07 blackscram kernel: limit_periodic_timer_frequency: 16 callbacks suppressed
Apr 15 14:18:13 blackscram kernel: limit_periodic_timer_frequency: 13 callbacks suppressed
Apr 15 14:18:18 blackscram kernel: limit_periodic_timer_frequency: 11 callbacks suppressed
Apr 15 14:18:23 blackscram kernel: limit_periodic_timer_frequency: 8 callbacks suppressed
Apr 15 14:18:29 blackscram kernel: limit_periodic_timer_frequency: 4 callbacks suppressed
Apr 15 14:27:46 blackscram kernel: limit_periodic_timer_frequency: 2 callbacks suppressed

* /var/log/messages:
--------------------
Apr 15 12:04:58 blackscram kernel: br0: port 3(tap2) entered blocking state
Apr 15 12:04:58 blackscram kernel: br0: port 3(tap2) entered forwarding state
Apr 15 12:05:10 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:10 blackscram last message buffered 1 times
Apr 15 12:05:10 blackscram kernel: kvm: vcpu 0: requested 190362 ns lapic timer period limited to 200000 ns
Apr 15 12:05:11 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:12 blackscram last message buffered 2 times
Apr 15 12:05:12 blackscram kernel: kvm: vcpu 0: requested 184651 ns lapic timer period limited to 200000 ns
Apr 15 12:05:12 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:12 blackscram kernel: kvm: vcpu 0: requested 106347 ns lapic timer period limited to 200000 ns
Apr 15 12:05:13 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:17 blackscram last message buffered 1 times
Apr 15 12:05:17 blackscram kernel: kvm: vcpu 0: requested 198200 ns lapic timer period limited to 200000 ns
Apr 15 12:05:17 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:18 blackscram kernel: kvm: vcpu 0: requested 161606 ns lapic timer period limited to 200000 ns
Apr 15 12:05:18 blackscram kernel: kvm: vcpu 0: requested 165828 ns lapic timer period limited to 200000 ns
Apr 15 12:05:19 blackscram kernel: kvm: vcpu 0: requested 188536 ns lapic timer period limited to 200000 ns
Apr 15 12:05:19 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:20 blackscram kernel: kvm: vcpu 0: requested 140594 ns lapic timer period limited to 200000 ns
Apr 15 12:05:21 blackscram kernel: kvm: vcpu 0: requested 190006 ns lapic timer period limited to 200000 ns
Apr 15 12:05:22 blackscram kernel: kvm: vcpu 0: requested 121065 ns lapic timer period limited to 200000 ns
Apr 15 12:05:23 blackscram kernel: kvm: vcpu 0: requested 193715 ns lapic timer period limited to 200000 ns
Apr 15 12:05:24 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:25 blackscram kernel: kvm: vcpu 0: requested 155432 ns lapic timer period limited to 200000 ns
Apr 15 12:05:26 blackscram kernel: kvm: vcpu 0: requested 177594 ns lapic timer period limited to 200000 ns
Apr 15 12:05:28 blackscram kernel: kvm: vcpu 0: requested 112406 ns lapic timer period limited to 200000 ns
Apr 15 12:05:29 blackscram kernel: kvm: vcpu 0: requested 116480 ns lapic timer period limited to 200000 ns
Apr 15 12:05:30 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:31 blackscram last message buffered 2 times
Apr 15 12:05:33 blackscram kernel: kvm: vcpu 0: requested 106635 ns lapic timer period limited to 200000 ns
Apr 15 12:05:33 blackscram kernel: kvm: vcpu 0: requested 175396 ns lapic timer period limited to 200000 ns
Apr 15 12:05:34 blackscram kernel: kvm: vcpu 0: requested 146901 ns lapic timer period limited to 200000 ns
Apr 15 12:05:34 blackscram kernel: kvm: vcpu 0: requested 168680 ns lapic timer period limited to 200000 ns
Apr 15 12:05:35 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:36 blackscram kernel: kvm: vcpu 0: requested 151168 ns lapic timer period limited to 200000 ns
Apr 15 12:05:36 blackscram kernel: kvm: vcpu 0: requested 177654 ns lapic timer period limited to 200000 ns
Apr 15 12:05:38 blackscram kernel: kvm: vcpu 0: requested 142241 ns lapic timer period limited to 200000 ns
Apr 15 12:05:39 blackscram kernel: kvm: vcpu 0: requested 145284 ns lapic timer period limited to 200000 ns
Apr 15 12:05:39 blackscram kernel: kvm: vcpu 0: requested 161734 ns lapic timer period limited to 200000 ns
Apr 15 12:05:39 blackscram kernel: kvm: vcpu 0: requested 135094 ns lapic timer period limited to 200000 ns
Apr 15 12:05:41 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:41 blackscram last message buffered 1 times
Apr 15 12:05:41 blackscram kernel: kvm: vcpu 0: requested 110602 ns lapic timer period limited to 200000 ns
Apr 15 12:05:43 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:45 blackscram kernel: kvm: vcpu 0: requested 176470 ns lapic timer period limited to 200000 ns
Apr 15 12:05:45 blackscram kernel: kvm: vcpu 0: requested 144036 ns lapic timer period limited to 200000 ns
Apr 15 12:05:48 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:49 blackscram kernel: kvm: vcpu 0: requested 112791 ns lapic timer period limited to 200000 ns
Apr 15 12:05:51 blackscram kernel: kvm: vcpu 0: requested 156264 ns lapic timer period limited to 200000 ns
Apr 15 12:05:51 blackscram kernel: kvm: vcpu 0: requested 111279 ns lapic timer period limited to 200000 ns
Apr 15 12:05:52 blackscram kernel: kvm: vcpu 0: requested 171748 ns lapic timer period limited to 200000 ns
Apr 15 12:05:53 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:05:53 blackscram last message buffered 1 times
Apr 15 12:05:56 blackscram kernel: kvm: vcpu 0: requested 166632 ns lapic timer period limited to 200000 ns
Apr 15 12:05:57 blackscram kernel: kvm: vcpu 0: requested 115348 ns lapic timer period limited to 200000 ns
Apr 15 12:05:58 blackscram kernel: kvm: vcpu 0: requested 168569 ns lapic timer period limited to 200000 ns
Apr 15 12:05:58 blackscram kernel: kvm: vcpu 0: requested 198141 ns lapic timer period limited to 200000 ns
Apr 15 12:06:00 blackscram kernel: kvm: vcpu 0: requested 121266 ns lapic timer period limited to 200000 ns
Apr 15 12:06:02 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:06:02 blackscram kernel: kvm: vcpu 0: requested 106288 ns lapic timer period limited to 200000 ns
Apr 15 12:06:03 blackscram kernel: kvm: vcpu 0: requested 99933 ns lapic timer period limited to 200000 ns
Apr 15 12:06:03 blackscram kernel: kvm: vcpu 0: requested 100004 ns lapic timer period limited to 200000 ns
Apr 15 12:24:21 blackscram kernel: br0: port 3(tap2) entered disabled state
Apr 15 12:25:25 blackscram kernel: br0: port 3(tap2) entered blocking state
Apr 15 12:25:25 blackscram kernel: br0: port 3(tap2) entered forwarding state
Apr 15 12:25:26 blackscram kernel: br0: port 3(tap2) entered disabled state
Apr 15 12:55:53 blackscram syslogd[979]: -- MARK --
Apr 15 13:15:53 blackscram syslogd[979]: -- MARK --
Apr 15 13:35:53 blackscram syslogd[979]: -- MARK --
Apr 15 13:39:32 blackscram kernel: br0: port 3(tap2) entered blocking state
Apr 15 13:39:32 blackscram kernel: br0: port 3(tap2) entered forwarding state
Apr 15 13:39:33 blackscram kernel: br0: port 3(tap2) entered disabled state
Apr 15 13:45:46 blackscram kernel: br0: port 3(tap2) entered blocking state
Apr 15 13:45:46 blackscram kernel: br0: port 3(tap2) entered forwarding state
Apr 15 13:45:47 blackscram kernel: br0: port 3(tap2) entered disabled state
Apr 15 13:54:22 blackscram kernel: br0: port 3(tap2) entered blocking state
Apr 15 13:54:22 blackscram kernel: br0: port 3(tap2) entered forwarding state
Apr 15 13:54:23 blackscram kernel: br0: port 3(tap2) entered disabled state
Apr 15 14:03:40 blackscram kernel: br0: port 3(tap2) entered blocking state
Apr 15 14:03:40 blackscram kernel: br0: port 3(tap2) entered forwarding state
Apr 15 14:03:41 blackscram kernel: br0: port 3(tap2) entered disabled state
Apr 15 14:05:10 blackscram kernel: br0: port 3(tap2) entered blocking state
Apr 15 14:05:10 blackscram kernel: br0: port 3(tap2) entered forwarding state
Apr 15 14:05:20 blackscram dnsmasq-dhcp[28872]: DHCPDISCOVER(br0) de:ad:be:ef:cf:f6 
Apr 15 14:05:20 blackscram dnsmasq-dhcp[28872]: DHCPOFFER(br0) 192.168.50.5 de:ad:be:ef:cf:f6 
Apr 15 14:05:20 blackscram dnsmasq-dhcp[28872]: DHCPDISCOVER(br0) de:ad:be:ef:cf:f6 
Apr 15 14:05:20 blackscram dnsmasq-dhcp[28872]: DHCPOFFER(br0) 192.168.50.5 de:ad:be:ef:cf:f6 
Apr 15 14:05:20 blackscram dnsmasq-dhcp[28872]: DHCPREQUEST(br0) 192.168.50.5 de:ad:be:ef:cf:f6 
Apr 15 14:05:20 blackscram dnsmasq-dhcp[28872]: DHCPACK(br0) 192.168.50.5 de:ad:be:ef:cf:f6 
Apr 15 14:10:33 blackscram kernel: br0: port 3(tap2) entered disabled state
Apr 15 14:17:33 blackscram kernel: br0: port 3(tap2) entered blocking state
Apr 15 14:17:33 blackscram kernel: br0: port 3(tap2) entered forwarding state
Apr 15 14:17:47 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:17:47 blackscram last message buffered 1 times
Apr 15 14:17:47 blackscram kernel: kvm: vcpu 0: requested 111596 ns lapic timer period limited to 200000 ns
Apr 15 14:17:48 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:17:49 blackscram last message buffered 3 times
Apr 15 14:17:49 blackscram kernel: kvm: vcpu 0: requested 113549 ns lapic timer period limited to 200000 ns
Apr 15 14:17:50 blackscram kernel: kvm: vcpu 0: requested 194804 ns lapic timer period limited to 200000 ns
Apr 15 14:17:51 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:17:52 blackscram kernel: kvm: vcpu 0: requested 108682 ns lapic timer period limited to 200000 ns
Apr 15 14:17:52 blackscram kernel: kvm: vcpu 0: requested 194041 ns lapic timer period limited to 200000 ns
Apr 15 14:17:52 blackscram kernel: kvm: vcpu 0: requested 190017 ns lapic timer period limited to 200000 ns
Apr 15 14:17:53 blackscram kernel: kvm: vcpu 0: requested 150899 ns lapic timer period limited to 200000 ns
Apr 15 14:17:53 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:17:54 blackscram last message buffered 4 times
Apr 15 14:17:54 blackscram kernel: kvm: vcpu 0: requested 160123 ns lapic timer period limited to 200000 ns
Apr 15 14:17:57 blackscram kernel: kvm: vcpu 0: requested 120837 ns lapic timer period limited to 200000 ns
Apr 15 14:17:57 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:17:58 blackscram last message buffered 1 times
Apr 15 14:17:58 blackscram kernel: kvm: vcpu 0: requested 195711 ns lapic timer period limited to 200000 ns
Apr 15 14:17:58 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:17:59 blackscram last message buffered 2 times
Apr 15 14:17:59 blackscram kernel: kvm: vcpu 0: requested 114063 ns lapic timer period limited to 200000 ns
Apr 15 14:17:59 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:02 blackscram last message buffered 2 times
Apr 15 14:18:03 blackscram kernel: kvm: vcpu 0: requested 125424 ns lapic timer period limited to 200000 ns
Apr 15 14:18:03 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:03 blackscram last message buffered 2 times
Apr 15 14:18:03 blackscram kernel: kvm: vcpu 0: requested 147094 ns lapic timer period limited to 200000 ns
Apr 15 14:18:03 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:03 blackscram kernel: kvm: vcpu 0: requested 141200 ns lapic timer period limited to 200000 ns
Apr 15 14:18:03 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:04 blackscram kernel: kvm: vcpu 0: requested 116465 ns lapic timer period limited to 200000 ns
Apr 15 14:18:07 blackscram kernel: kvm: vcpu 0: requested 177058 ns lapic timer period limited to 200000 ns
Apr 15 14:18:08 blackscram kernel: kvm: vcpu 0: requested 135125 ns lapic timer period limited to 200000 ns
Apr 15 14:18:08 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:08 blackscram last message buffered 1 times
Apr 15 14:18:08 blackscram kernel: kvm: vcpu 0: requested 149235 ns lapic timer period limited to 200000 ns
Apr 15 14:18:09 blackscram kernel: kvm: vcpu 0: requested 128011 ns lapic timer period limited to 200000 ns
Apr 15 14:18:09 blackscram kernel: kvm: vcpu 0: requested 189997 ns lapic timer period limited to 200000 ns
Apr 15 14:18:09 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:13 blackscram last message buffered 5 times
Apr 15 14:18:14 blackscram kernel: kvm: vcpu 0: requested 176660 ns lapic timer period limited to 200000 ns
Apr 15 14:18:14 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:15 blackscram last message buffered 4 times
Apr 15 14:18:15 blackscram kernel: kvm: vcpu 0: requested 146119 ns lapic timer period limited to 200000 ns
Apr 15 14:18:18 blackscram kernel: kvm: vcpu 0: requested 181147 ns lapic timer period limited to 200000 ns
Apr 15 14:18:18 blackscram kernel: kvm: vcpu 0: requested 101907 ns lapic timer period limited to 200000 ns
Apr 15 14:18:19 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:19 blackscram kernel: kvm: vcpu 0: requested 101555 ns lapic timer period limited to 200000 ns
Apr 15 14:18:20 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:20 blackscram kernel: kvm: vcpu 0: requested 168584 ns lapic timer period limited to 200000 ns
Apr 15 14:18:20 blackscram kernel: kvm: vcpu 0: requested 189223 ns lapic timer period limited to 200000 ns
Apr 15 14:18:21 blackscram kernel: kvm: vcpu 0: requested 162485 ns lapic timer period limited to 200000 ns
Apr 15 14:18:21 blackscram kernel: kvm: vcpu 0: requested 178309 ns lapic timer period limited to 200000 ns
Apr 15 14:18:21 blackscram kernel: kvm: vcpu 0: requested 122322 ns lapic timer period limited to 200000 ns
Apr 15 14:18:23 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:24 blackscram last message buffered 1 times
Apr 15 14:18:24 blackscram kernel: kvm: vcpu 0: requested 165024 ns lapic timer period limited to 200000 ns
Apr 15 14:18:24 blackscram kernel: kvm: vcpu 0: requested 113987 ns lapic timer period limited to 200000 ns
Apr 15 14:18:25 blackscram kernel: kvm: vcpu 0: requested 171776 ns lapic timer period limited to 200000 ns
Apr 15 14:18:25 blackscram kernel: kvm: vcpu 0: requested 135552 ns lapic timer period limited to 200000 ns
Apr 15 14:18:25 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:25 blackscram kernel: kvm: vcpu 0: requested 126206 ns lapic timer period limited to 200000 ns
Apr 15 14:18:26 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:27 blackscram kernel: kvm: vcpu 0: requested 153040 ns lapic timer period limited to 200000 ns
Apr 15 14:18:29 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:29 blackscram kernel: kvm: vcpu 0: requested 106049 ns lapic timer period limited to 200000 ns
Apr 15 14:18:29 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:29 blackscram kernel: kvm: vcpu 0: requested 123580 ns lapic timer period limited to 200000 ns
Apr 15 14:18:30 blackscram kernel: kvm: vcpu 0: requested 159240 ns lapic timer period limited to 200000 ns
Apr 15 14:18:30 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:30 blackscram kernel: kvm: vcpu 0: requested 164069 ns lapic timer period limited to 200000 ns
Apr 15 14:18:30 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:18:30 blackscram kernel: kvm: vcpu 0: requested 190019 ns lapic timer period limited to 200000 ns
Apr 15 14:18:31 blackscram kernel: kvm: vcpu 0: requested 122008 ns lapic timer period limited to 200000 ns
Apr 15 14:26:56 blackscram dnsmasq-dhcp[28872]: DHCPRELEASE(br0) 192.168.50.5 52:54:00:12:34:56 unknown lease
Apr 15 14:27:06 blackscram kernel: br0: port 1(tap0) entered disabled state
Apr 15 14:27:27 blackscram kernel: br0: port 2(tap1) entered disabled state
Apr 15 14:27:46 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:27:46 blackscram kernel: kvm: vcpu 0: requested 136164 ns lapic timer period limited to 200000 ns
Apr 15 14:27:46 blackscram kernel: kvm: vcpu 0: requested 115297 ns lapic timer period limited to 200000 ns
Apr 15 14:27:46 blackscram kernel: kvm: vcpu 0: requested 178152 ns lapic timer period limited to 200000 ns
Apr 15 14:27:46 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:27:46 blackscram last message buffered 1 times
Apr 15 14:27:47 blackscram kernel: kvm: vcpu 0: requested 106015 ns lapic timer period limited to 200000 ns
Apr 15 14:27:47 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:27:47 blackscram kernel: kvm: vcpu 0: requested 147817 ns lapic timer period limited to 200000 ns
Apr 15 14:27:48 blackscram kernel: kvm: vcpu 0: requested 100335 ns lapic timer period limited to 200000 ns
Apr 15 14:27:48 blackscram kernel: br0: port 3(tap2) entered disabled state



-- 
Bold character derived from stubborn patience and adversity.
==
Douglas Guptill, B.Sc., CCP, M.Comp.Sci., THB

Re: [9front] qemu clock/timer issue

[Jacob Moody]

It is understood that this bug only happens with intel kvm virtual machines.
 From all that has been tested it was currently understood to affect newer intel machines.
It seems however that your machine is a bit older(10+ years) and still triggering this.
I've certainly run 9front in kvm on intel machines before so it is likely either
something that changed with us or something that has changed with QEMU. My money
is on some QEMU change.

If you do not feel comfortable debugging but would still be interested in helping
perhaps you can help bisect 9front and qemu (one side at a time) to see if you can
narrow down what has changed to get more information to fix these things.
I would start with the nightly iso just to double check, then move back through the releases
going back. Give that a go for a couple of them, then maybe try some older qemu.


Thanks,
moody

Re: [9front] qemu clock/timer issue

[Douglas Guptill]

[-- Attachment #1: Type: text/plain, Size: 1714 bytes --]

Hello moody:

On Tue, Apr 16, 2024 at 08:32:42AM -0500, Jacob Moody wrote:

> It is understood that this bug only happens with intel kvm virtual machines.
>  From all that has been tested it was currently understood to affect newer intel machines.
> It seems however that your machine is a bit older(10+ years) and still triggering this.
> I've certainly run 9front in kvm on intel machines before so it is likely either
> something that changed with us or something that has changed with QEMU. My money
> is on some QEMU change.

Ahhh.. That is a big help.  

> If you do not feel comfortable debugging

I'm a programmer. :)

I can look at the code, build and insert write statements, in qemu and
the kvm module of linux.  Cannot yet do anything like that with
9front.

> but would still be interested in helping

For sure.

> perhaps you can help bisect 9front and qemu (one side at a time) to see if you can
> narrow down what has changed to get more information to fix these things.
> I would start with the nightly iso just to double check,

Assuming that you mean a nightly iso of 9front, I just did that with
9front-10501.amd64.iso.gz.  No noticable change; but then I don't yet
understand 9front.  I stopped it quickly.  Attached is a jpg of what I
saw.

> then move back through the releases going back.

Sorry, I don't understand.  Releases of...qemu?  9front?

There is a newer qemu (9.0.0-rc3) out; I will make a build of that,
and then start looking at its code, and the kvm module code, to see if
I can find, and maybe understand, the offending code.

Thank you for the reply,
Douglas.
-- 
Bold character derived from stubborn patience and adversity.
==
Douglas Guptill, B.Sc., CCP, M.Comp.Sci., THB

[-- Attachment #2: 9front-10501.amd64.iso_boot-screen.jpg --]
[-- Type: image/jpeg, Size: 118357 bytes --]

Re: [9front] qemu clock/timer issue

[Jacob Moody]

On 4/16/24 12:07, Douglas Guptill wrote:
> Hello moody:
> 
> On Tue, Apr 16, 2024 at 08:32:42AM -0500, Jacob Moody wrote:
> 
>> It is understood that this bug only happens with intel kvm virtual machines.
>>  From all that has been tested it was currently understood to affect newer intel machines.
>> It seems however that your machine is a bit older(10+ years) and still triggering this.
>> I've certainly run 9front in kvm on intel machines before so it is likely either
>> something that changed with us or something that has changed with QEMU. My money
>> is on some QEMU change.
> 
> Ahhh.. That is a big help.  
> 
>> If you do not feel comfortable debugging
> 
> I'm a programmer. :)

Excellent news. Thank you. :)

> 
> I can look at the code, build and insert write statements, in qemu and
> the kvm module of linux.  Cannot yet do anything like that with
> 9front.

We can help with understanding any of the 9front bits.

> 
>> but would still be interested in helping
> 
> For sure.
> 
>> perhaps you can help bisect 9front and qemu (one side at a time) to see if you can
>> narrow down what has changed to get more information to fix these things.
>> I would start with the nightly iso just to double check,
> 
> Assuming that you mean a nightly iso of 9front, I just did that with
> 9front-10501.amd64.iso.gz.  No noticable change; but then I don't yet
> understand 9front.  I stopped it quickly.  Attached is a jpg of what I
> saw.

Got it, thanks for checking that. Also uramekus on the grid had some
additional context about this. He said that he personally has experienced
this syslog spam but there was otherwise no adverse effects. He mentioned
that: "options kvm min_timer_period_us=10" in modprobe.conf about kvm makes it shut up.

However there was _also_ the issue that mcf originally reported regarding the fast
running clock, just to clarify are you also observing this behavior? It seems perhaps
this syslog may not be directly related to the fast running clock. So perhaps there
are two different issues that we're observing.

In either case it would be nice to at least understand what is going on, and then perhaps
fix these things.

> 
>> then move back through the releases going back.
> 
> Sorry, I don't understand.  Releases of...qemu?  9front?
> 
> There is a newer qemu (9.0.0-rc3) out; I will make a build of that,
> and then start looking at its code, and the kvm module code, to see if
> I can find, and maybe understand, the offending code.

Yes I initially meant going back through 9front releases, however with
uramekus saying he has observed this for a long time I think it might
be better use of time to debug this with the latest code and just dig in.

I will say that your attached image does not having anything out of order
beside those mpintrassign lines, not entirely sure what that's about.


Thank you,
moody

Re: [9front] qemu clock/timer issue

[Michael Forney]

Jacob Moody <moody@posixcafe.org> wrote:
> It is understood that this bug only happens with intel kvm virtual machines.
>  From all that has been tested it was currently understood to affect newer intel machines.
> It seems however that your machine is a bit older(10+ years) and still triggering this.
> I've certainly run 9front in kvm on intel machines before so it is likely either
> something that changed with us or something that has changed with QEMU. My money
> is on some QEMU change.
> 
> If you do not feel comfortable debugging but would still be interested in helping
> perhaps you can help bisect 9front and qemu (one side at a time) to see if you can
> narrow down what has changed to get more information to fix these things.
> I would start with the nightly iso just to double check, then move back through the releases
> going back. Give that a go for a couple of them, then maybe try some older qemu.

If you look at my original mails, I had already bisected it to:
http://git.9front.org/plan9front/plan9front/a05bab362f66ddd6fa65f2e7cda9eaaa0217ec08/commit.html

This changes the mechanism by which CPU frequencies are detected
by default in 9front, and the timing/clock issues arise when the
frequency is detected incorrectly as 25MHz instead of 3.3GHz. The
issue went away when using *nohpet=1 to revert to i8253
clockinit/fastclock.

I wasn't able to explain why hpetcpufreq didn't work, but i8253cpufreq
did. They are both emulated with QEMU_CLOCK_VIRTUAL:
https://github.com/qemu/qemu/blob/62dbe54c24dbf77051bafe1039c31ddc8f37602d/hw/timer/hpet.c#L156
https://github.com/qemu/qemu/blob/62dbe54c24dbf77051bafe1039c31ddc8f37602d/hw/timer/i8254.c#L57-L58

Re: [9front] qemu clock/timer issue

[Jacob Moody]

On 4/16/24 13:46, Michael Forney wrote:
> Jacob Moody <moody@posixcafe.org> wrote:
>> It is understood that this bug only happens with intel kvm virtual machines.
>>  From all that has been tested it was currently understood to affect newer intel machines.
>> It seems however that your machine is a bit older(10+ years) and still triggering this.
>> I've certainly run 9front in kvm on intel machines before so it is likely either
>> something that changed with us or something that has changed with QEMU. My money
>> is on some QEMU change.
>>
>> If you do not feel comfortable debugging but would still be interested in helping
>> perhaps you can help bisect 9front and qemu (one side at a time) to see if you can
>> narrow down what has changed to get more information to fix these things.
>> I would start with the nightly iso just to double check, then move back through the releases
>> going back. Give that a go for a couple of them, then maybe try some older qemu.
> 
> If you look at my original mails, I had already bisected it to:
> http://git.9front.org/plan9front/plan9front/a05bab362f66ddd6fa65f2e7cda9eaaa0217ec08/commit.html
> 
> This changes the mechanism by which CPU frequencies are detected
> by default in 9front, and the timing/clock issues arise when the
> frequency is detected incorrectly as 25MHz instead of 3.3GHz. The
> issue went away when using *nohpet=1 to revert to i8253
> clockinit/fastclock.
> 
> I wasn't able to explain why hpetcpufreq didn't work, but i8253cpufreq
> did. They are both emulated with QEMU_CLOCK_VIRTUAL:
> https://github.com/qemu/qemu/blob/62dbe54c24dbf77051bafe1039c31ddc8f37602d/hw/timer/hpet.c#L156
> https://github.com/qemu/qemu/blob/62dbe54c24dbf77051bafe1039c31ddc8f37602d/hw/timer/i8254.c#L57-L58

Ah my bad, I had forgotten about this. Thank you for the original bisecting work and for reiterating.

- moody