From mboxrd@z Thu Jan 1 00:00:00 1970 X-Spam-Checker-Version: SpamAssassin 3.4.4 (2020-01-24) on inbox.vuxu.org X-Spam-Level: * X-Spam-Status: No, score=1.2 required=5.0 tests=DKIM_SIGNED,DKIM_VALID, DKIM_VALID_AU,RDNS_NONE,T_SCC_BODY_TEXT_LINE autolearn=no autolearn_force=no version=3.4.4 Received: (qmail 18712 invoked from network); 21 Feb 2022 03:39:18 -0000 Received: from unknown (HELO 4ess.inri.net) (216.126.196.42) by inbox.vuxu.org with ESMTPUTF8; 21 Feb 2022 03:39:18 -0000 Received: from mail-pf1-f174.google.com ([209.85.210.174]) by 4ess; Sun Feb 20 22:25:38 -0500 2022 Received: by mail-pf1-f174.google.com with SMTP id g1so7560281pfv.1 for <9front@9front.org>; Sun, 20 Feb 2022 19:25:35 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=mforney.org; s=google; h=mime-version:in-reply-to:references:from:date:message-id:subject:to; bh=hifOypNv9K2VxeJU0lA2xqTZbbyikELEgweM1sZzWM4=; b=Q6pkz0NgnVdjUxJTG2jM4ljNvwhtatIudYNEcUVS7nvFFU5/xMxn38V5qRxOdVN/1x +j9Ysy0sZ2M9tXLaiZrTOXmel/opvlvWU6d4YMuFt7atlTQi4NpVZQJKrljRJ5oZZIO9 H9X0KkSZuweuhcHoDL/lhwz5VRTtkKjJrjhDrpGMYsbsc/N1/XHqBR8eb6+mx3A/tqAL qsBSX17pmR8LsLxvfjyxY+1fm2wQhSipno8zEq/FjPtcip2DkWeqXM6NqrEdwZ3TQlCl Xl/HWYAtb5bFtUFnZea4RDNWbO6PwQouBqxH/tjUNS4gGMELFJjl3Afpfe21B2BfFM3X ZgsA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:mime-version:in-reply-to:references:from:date :message-id:subject:to; bh=hifOypNv9K2VxeJU0lA2xqTZbbyikELEgweM1sZzWM4=; b=sG4+E98FMBMdcRrJH3usjtdMR5bR6wDX1RRxqmyxX5Zf3UBNf1W+reW4w4ebXMXU0g kSS3InIct1yg93Wt9rNkVz6cW4i9WF1lNAoszuB3VOkQNDfZfAztCTziaF99pBhKGPeb fO4Wv2RXXWGDGxDWifli5J2MRp/cByqzAHdOLUGWzcHzuCGJCfcXG70Dvr+t61w/6nK5 2r5O2Y6YinSz8SnKFIzZFTG+yR758O4/JcsRDEFzN19Fy+FY3ncEa0qVKTUy/31tgHYS obEJuSi852+9c34D6rGf6vaNOCOMYpwpeFYRAO238EcWCZSCYza+fwVRl4ZGUjjeLBeF VdeQ== X-Gm-Message-State: AOAM530O53ER3diPFNxKDuKtjFDWACp6yEZG3TJ6ewMlyXfZ6+d+ypyz fo9s41hithUWDaacfCDB9bf/qwcjYbAD5PFl5A9zBYtHNxCV4Q== X-Google-Smtp-Source: ABdhPJxCXeazy0ckiTdjayuOoCkBkVL257bWSfaKip/zMLilZQlaeycLb1xZ2n9A2j7vT8n84P40LBecDqlk8QmwG9s= X-Received: by 2002:a63:e64a:0:b0:373:687a:9bce with SMTP id p10-20020a63e64a000000b00373687a9bcemr4799118pgj.30.1645154750527; Thu, 17 Feb 2022 19:25:50 -0800 (PST) MIME-Version: 1.0 Received: by 2002:a05:7300:1583:b0:56:de7d:3a2 with HTTP; Thu, 17 Feb 2022 19:25:49 -0800 (PST) X-Originating-IP: [98.45.152.168] In-Reply-To: References: From: Michael Forney Date: Thu, 17 Feb 2022 19:25:49 -0800 Message-ID: To: 9front@9front.org Content-Type: text/plain; charset="UTF-8" List-ID: <9front.9front.org> List-Help: X-Glyph: ➈ X-Bullshit: open-source firewall event general-purpose interface Subject: Re: [9front] qemu clock/timer issue Reply-To: 9front@9front.org Precedence: bulk On 2022-02-05, Nick Owens 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] 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.