20.10.2017 21:04, Ian Lepore ΠΙΫΕΤ: > On Fri, 2017-10-20 at 20:20 +0300, Boris Samorodov wrote: >> (CC to freebsd-virtualization_at_) >> >> 20.10.2017 19:32, Ian Lepore ΠΙΫΕΤ: >>> >>> On Fri, 2017-10-20 at 18:36 +0300, Boris Samorodov wrote: >>>> >>>> 20.10.2017 18:31, Boris Samorodov ΠΙΫΕΤ: >>>>> >>>>> >>>>> 20.10.2017 18:12, Ian Lepore ΠΙΫΕΤ: >>>>>> >>>>>> >>>>>> On Fri, 2017-10-20 at 14:46 +0300, Boris Samorodov wrote: >>>>>>> >>>>>>> >>>>>>> Hi All, >>>>>>> >>>>>>> I have got a host: >>>>>>> --- >>>>>>> bhyve-host% uname -a >>>>>>> FreeBSD sm.bsnet 12.0-CURRENT FreeBSD 12.0-CURRENT #3 r322868: Fri Aug >>>>>>> 25 05:25:26 MSK 2017 >>>>>>> bsam_at_builder.bsnet:/usr/obj/usr/src/sys/GENERIC-FASTamd64 amd64 >>>>>>> --- >>>>>>> >>>>>>> And a bhyve vm: >>>>>>> --- >>>>>>> bhyve-vm: uname -a >>>>>>> FreeBSD builder.bsnet 12.0-CURRENT FreeBSD 12.0-CURRENT #58 r324782: Fri >>>>>>> Oct 20 05:12:17 MSK 2017 >>>>>>> bsam_at_builder.bsnet:/usr/obj/usr/src/sys/PKG64Xamd64 amd64 >>>>>>> --- >>>>>>> >>>>>>> The only difference at kernel configs is a colored console. :-) >>>>>>> >>>>>>> And here I get some weird (is it?) result at the VM (I expect ntpd to be >>>>>>> more stable): >>>>>>> --- >>>>>>> bhyve-vm% for t in `jot 10`; do ntpq -pn; sleep 64; done >>>>>>> remoterefidst t when poll reachdelayoffset >>>>>>> jitter >>>>>>> ============================================================================== >>>>>>> XX.XX.XX.1XX.XX.XX.2454 u96430.605-1.202 >>>>>>> 316.407 >>>>>>> XX.XX.XX.1XX.XX.XX.2454 u76470.605-1.202 >>>>>>> 358.395 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u564170.615-328.42 >>>>>>> 181.405 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u364370.615-328.42 >>>>>>> 214.868 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u6764370.615-328.42 >>>>>>> 214.868 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u6364770.615-328.42 >>>>>>> 268.618 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u60641770.615-328.42 >>>>>>> 333.175 >>>>>>> XX.XX.XX.1.STEP.16 u 19106400.0000.000 >>>>>>> 0.000 >>>>>>> XX.XX.XX.1XX.XX.XX.2454 u276410.703-262.63 >>>>>>> 0.004 >>>>>>> XX.XX.XX.1XX.XX.XX.2454 u316410.649-331.43 >>>>>>> 68.800 >>>>>>> --- >>>>>>> >>>>>>> At the same time host's results are very stable: >>>>>>> --- >>>>>>> bhyve-host% for t in `jot 10`; do ntpq -pn; sleep 64; done >>>>>>> remoterefidst t when poll reachdelayoffset >>>>>>> jitter >>>>>>> ============================================================================== >>>>>>> >>>>>>> >>>>>>> >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u16410.4010.176 >>>>>>> 0.106 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u66430.4010.176 >>>>>>> 0.459 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u36470.4010.176 >>>>>>> 0.940 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u676470.4010.176 >>>>>>> 0.940 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u6464170.4010.176 >>>>>>> 1.566 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u6064370.4481.275 >>>>>>> 1.739 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u5564770.4481.275 >>>>>>> 2.365 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u53641770.4481.275 >>>>>>> 3.110 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u50643770.4481.275 >>>>>>> 3.929 >>>>>>> *XX.XX.XX.1XX.XX.XX.2454 u45643770.4438.750 >>>>>>> 4.722 >>>>>>> --- >>>>>>> >>>>>>> The network is organized via bridge -- host igb and vm tap interfaces >>>>>>> are members of one bridge. >>>>>>> >>>>>>> Are those results expected? Does it smell like a bug? Should I dig >>>>>>> furter? >>>>>>> >>>>>> So it is repeatedly stepping the clock in the VM? (Set >>>>>> kern.timecounter.stepwarnings=1 to log steps). >>>>> No kernel/ntpd messages for 20 minutes after setting this sysctl. >>>>> >>>>>> >>>>>> >>>>>> That is usually a sign >>>>>> that the chosen timecounter is running at a different frequency than it >>>>>> claimed to be when it registered itself -- the host may not be >>>>>> emulating the timer hardware properly in the guest. What is the output >>>>>> of sysctl kern.timecounter in the vm? >>>>> --- >>>>> bhyve-vm% sysctl kern.timecounter >>>>> >>>>> kern.timecounter.tsc_shift: 1 >>>>> kern.timecounter.smp_tsc_adjust: 0 >>>>> kern.timecounter.smp_tsc: 0 >>>>> kern.timecounter.invariant_tsc: 1 >>>>> kern.timecounter.fast_gettime: 1 >>>>> kern.timecounter.tick: 1 >>>>> kern.timecounter.choice: ACPI-fast(900) HPET(950) i8254(0) TSC-low(-100) >>>>> dummy(-1000000) >>>>> kern.timecounter.hardware: HPET >>>>> kern.timecounter.alloweddeviation: 5 >>>>> kern.timecounter.stepwarnings: 1 >>>>> kern.timecounter.tc.ACPI-fast.quality: 900 >>>>> kern.timecounter.tc.ACPI-fast.frequency: 3579545 >>>>> kern.timecounter.tc.ACPI-fast.counter: 4161213491 >>>>> kern.timecounter.tc.ACPI-fast.mask: 4294967295 >>>>> kern.timecounter.tc.HPET.quality: 950 >>>>> kern.timecounter.tc.HPET.frequency: 10000000 >>>>> kern.timecounter.tc.HPET.counter: 3518036865 >>>>> kern.timecounter.tc.HPET.mask: 4294967295 >>>>> kern.timecounter.tc.i8254.quality: 0 >>>>> kern.timecounter.tc.i8254.frequency: 1193182 >>>>> kern.timecounter.tc.i8254.counter: 47597 >>>>> kern.timecounter.tc.i8254.mask: 65535 >>>>> kern.timecounter.tc.TSC-low.quality: -100 >>>>> kern.timecounter.tc.TSC-low.frequency: 1199886114 >>>>> kern.timecounter.tc.TSC-low.counter: 1274338278 >>>>> kern.timecounter.tc.TSC-low.mask: 4294967295 >>>>> --- >>>> BTW, here is the host kern.timecounter: >>>> --- >>>> kern.timecounter.tsc_shift: 1 >>>> kern.timecounter.smp_tsc_adjust: 0 >>>> kern.timecounter.smp_tsc: 1 >>>> kern.timecounter.invariant_tsc: 1 >>>> kern.timecounter.fast_gettime: 1 >>>> kern.timecounter.tick: 1 >>>> kern.timecounter.choice: ACPI-fast(900) HPET(950) i8254(0) TSC-low(1000) >>>> dummy(-1000000) >>>> kern.timecounter.hardware: TSC-low >>>> kern.timecounter.alloweddeviation: 5 >>>> kern.timecounter.stepwarnings: 0 >>>> kern.timecounter.tc.ACPI-fast.quality: 900 >>>> kern.timecounter.tc.ACPI-fast.frequency: 3579545 >>>> kern.timecounter.tc.ACPI-fast.counter: 9047194 >>>> kern.timecounter.tc.ACPI-fast.mask: 16777215 >>>> kern.timecounter.tc.HPET.quality: 950 >>>> kern.timecounter.tc.HPET.frequency: 14318180 >>>> kern.timecounter.tc.HPET.counter: 2232552795 >>>> kern.timecounter.tc.HPET.mask: 4294967295 >>>> kern.timecounter.tc.i8254.quality: 0 >>>> kern.timecounter.tc.i8254.frequency: 1193182 >>>> kern.timecounter.tc.i8254.counter: 43410 >>>> kern.timecounter.tc.i8254.mask: 65535 >>>> kern.timecounter.tc.TSC-low.quality: 1000 >>>> kern.timecounter.tc.TSC-low.frequency: 1200067168 >>>> kern.timecounter.tc.TSC-low.counter: 2463146362 >>>> kern.timecounter.tc.TSC-low.mask: 4294967295 >>>> --- >>>> >>>>> >>>>> >>>>>> >>>>>> >>>>>> Also, what is the output of ntptime(8) in the vm? >>>>> --- >>>>> bhyve-vm% ntptime >>>>> >>>>> ntp_gettime() returns code 0 (OK) >>>>> time dd94930f.20ea2900Fri, Oct 20 2017 18:21:51.128, (.128573699), >>>>> maximum error 1309110 us, estimated error 3 us, TAI offset 37 >>>>> ntp_adjtime() returns code 0 (OK) >>>>> modes 0x0 (), >>>>> offset 0.000 us, frequency 0.000 ppm, interval 1 s, >>>>> maximum error 1309110 us, estimated error 3 us, >>>>> status 0x2001 (PLL,NANO), >>>>> time constant 6, precision 0.001 us, tolerance 496 ppm, >>>>> --- >>>>> >>>>> Ian, thank you for your help! >>>>> >>> It seems odd to me that the frequency of the host HPET is 14.3mhz and >>> that of the guest is 10.0mhz, but maybe that's a normal condition for >>> bhyve. I did find some google hits[1] for bhyve guest timekeeping >>> trouble with the HPET timer which was solved by switching to a >>> different timecounter. Timecounter choices can't be controlled from >>> loader.conf, so I guess a sysctl.conf entry of >>> kern.timecounter.hardware="ACPI-fast" is the only way to fix that. You >>> can also just do that command interactively first and see if it stops >>> the time steps and ntp settles down. >> The process seems to become more monotonic. But steps nevertheless: >> --- >> *XX.1XX.2454 u206410.717-12.7714.193 >> *XX.1XX.2454 u286430.751-41.97032.342 >> *XX.1XX.2454 u236470.748-59.50546.624 >> *XX.1XX.2454 u1864170.699-75.16456.482 >> *XX.1XX.2454 u1464370.669-90.11263.767 >> *XX.1XX.2454 u1164770.605-10.56760.914 >> *XX.1XX.2454 u7641770.591-169.54 116.762 >> *XX.1XX.2454 u3643770.591-169.54 102.107 >> *XX.1XX.2454 u68643770.591-169.54 102.107 >> *XX.1XX.2454 u63643770.591-169.5488.424 >> *XX.1XX.2454 u58643770.591-169.5492.949 >> *XX.1XX.2454 u55643770.591-169.54 111.512 >> *XX.1XX.2454 u50643770.591-169.54 140.827 >> *XX.1XX.2454 u45643770.591-169.54 177.360 >> *XX.1XX.2454 u43643770.591-169.54 219.057 >> XX.1.STEP.16 u5886400.0000.0000.000 >> --- >> >>> >>> This would be a workaround, not a fix per se. If the time steps go >>> away, then something in bhyve's emulation of HPET (maybe only on some >>> hardware?) must be buggy. >>> >>> >>> [1] https://lists.freebsd.org/pipermail/freebsd-virtualization/2015-April/003492.html >> Also thanks for the link. Unfortunately the problem seems to persist. >> > > Hmm, that almost looks normal... it noticed the clock was drifting > fast, so it went into a frequency-training cycle (at the point where > the offset stopped changing at -169.54) and then once it had figured > out the frequency it did a step to get realigned, and (presumably) > adjusted the frequency of the kernel clock. The output of ntptime > before and after the step would show that... before the step the > frequency would show as zero (which was the case in your ntptime output > earlier), and after the step it would be non-zero. No more steps would > occur after the first one, if that's what is happening here. Those were following steps: --- XX.1 XX.245 4 u 15 64 1 0.597 -51.802 7.547 XX.1 XX.245 4 u 17 64 1 0.597 -51.802 29.526 XX.1 XX.245 4 u 19 64 1 0.597 -51.802 52.760 XX.1 XX.245 4 u 19 64 3 0.597 -51.802 77.354 XX.1 XX.245 4 u 16 64 7 0.597 -51.802 103.182 XX.1 XX.245 4 u 12 64 17 0.597 -51.802 138.976 *XX.1 XX.245 4 u 9 64 37 0.700 -200.07 109.275 XX.1 .STEP. 16 u 1100 64 0 0.000 0.000 0.002 XX.1 XX.245 4 u 63 64 1 0.645 -3.620 0.002 XX.1 XX.245 4 u 34 64 1 0.645 -3.620 66.907 XX.1 XX.245 4 u 36 64 1 0.643 -115.30 85.082--- No stability. :-) But I see your point. I'll leave it till morning with hope it may stabilize. -- WBR, Boris Samorodov (bsam) FreeBSD Committer, http://www.FreeBSD.org The Power To ServeReceived on Fri Oct 20 2017 - 16:15:49 UTC
This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:41:13 UTC