From owner-freebsd-virtualization@freebsd.org Fri Oct 20 18:15:49 2017 Return-Path: Delivered-To: freebsd-virtualization@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 7AF34E3C7AE; Fri, 20 Oct 2017 18:15:49 +0000 (UTC) (envelope-from bsam@passap.ru) Received: from forward105j.mail.yandex.net (forward105j.mail.yandex.net [IPv6:2a02:6b8:0:801:2::108]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "forwards.mail.yandex.net", Issuer "Yandex CA" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 946A3157C; Fri, 20 Oct 2017 18:15:48 +0000 (UTC) (envelope-from bsam@passap.ru) Received: from mxback9g.mail.yandex.net (mxback9g.mail.yandex.net [IPv6:2a02:6b8:0:1472:2741:0:8b7:170]) by forward105j.mail.yandex.net (Yandex) with ESMTP id DA1A2183DC6; Fri, 20 Oct 2017 21:15:45 +0300 (MSK) Received: from smtp1j.mail.yandex.net (smtp1j.mail.yandex.net [2a02:6b8:0:801::ab]) by mxback9g.mail.yandex.net (nwsmtp/Yandex) with ESMTP id sWvRtAedPA-FjDKSv2v; Fri, 20 Oct 2017 21:15:45 +0300 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=passap.ru; s=mail; t=1508523345; bh=EkROp2IuGx5O7R+XmYyYVamjxLmExSwjYxyW6PRYLpM=; h=Subject:To:References:From:Message-ID:Date:In-Reply-To; b=MLOpgLEsIFucNhXK7/tx+8Z7ncNiCKAYtxtNLoq3xXclnGP+OlXKyIIIb5Fu8Y0Q8 TC2pFUenw7gacb9DPpRfIlV0AjTyGRHw8pRfDnQnmG3rVeUj9hvRQhZEaGSM9gZ+EP 4kSm8D7svRc3Wgko3BZyoRQimDV3XHdXkTvEe2xQ= Received: by smtp1j.mail.yandex.net (nwsmtp/Yandex) with ESMTPSA id 8WICKTfZc9-FiwmYCAN; Fri, 20 Oct 2017 21:15:44 +0300 (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client certificate not present) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=passap.ru; s=mail; t=1508523344; bh=EkROp2IuGx5O7R+XmYyYVamjxLmExSwjYxyW6PRYLpM=; h=Subject:To:References:From:Message-ID:Date:In-Reply-To; b=Ss/KBtWVkBMaCITjfZmP2FoGH4na4+PtzvpfW2mkpOnMv/V2PYDZ8E4SzEIGVO33u Q7k9IIkxbaqHCI9Nru5PZ4eS7AqEslGRSzZHQ/7468oFTeJj5ysh+vzpacqHaj9Ujp VLwCjy2qA1H10nU8JC5YsoBO3fo3nMHTYSIlyHbg= Authentication-Results: smtp1j.mail.yandex.net; dkim=pass header.i=@passap.ru Subject: Re: host, bhyve vm and ntpd To: Ian Lepore , freebsd-current@FreeBSD.org, freebsd-virtualization@FreeBSD.org References: <2931f1cc-6574-b58d-4b94-5f77fa5cdb85@passap.ru> <1508512327.1383.55.camel@freebsd.org> <39bf2426-2edf-d485-7c81-519e931154be@passap.ru> <1508517160.1383.63.camel@freebsd.org> <76ff7afb-3d3a-96f6-1275-89472ff5683d@passap.ru> <1508522667.1383.69.camel@freebsd.org> From: Boris Samorodov Message-ID: <30992c14-7b78-ab9f-5693-931e6ca41f1b@passap.ru> Date: Fri, 20 Oct 2017 21:15:44 +0300 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:52.0) Gecko/20100101 Thunderbird/52.4.0 MIME-Version: 1.0 In-Reply-To: <1508522667.1383.69.camel@freebsd.org> Content-Type: text/plain; charset=koi8-r Content-Language: en-US Content-Transfer-Encoding: 8bit X-BeenThere: freebsd-virtualization@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: "Discussion of various virtualization techniques FreeBSD supports." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 20 Oct 2017 18:15:49 -0000 20.10.2017 21:04, Ian Lepore ΠΙΫΕΤ: > On Fri, 2017-10-20 at 20:20 +0300, Boris Samorodov wrote: >> (CC to freebsd-virtualization@) >> >> 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@builder.bsnet:/usr/obj/usr/src/sys/GENERIC-FASTššamd64 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@builder.bsnet:/usr/obj/usr/src/sys/PKG64Xššamd64 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 >>>>>>> šššššremotešššššššššššrefidššššššst t when poll reachšššdelayšššoffset >>>>>>> jitter >>>>>>> ============================================================================== >>>>>>> šXX.XX.XX.1ššššššXX.XX.XX.245ššššš4 ušššš9ššš64šššš3šššš0.605ššš-1.202 >>>>>>> 316.407 >>>>>>> šXX.XX.XX.1ššššššXX.XX.XX.245ššššš4 ušššš7ššš64šššš7šššš0.605ššš-1.202 >>>>>>> 358.395 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 ušššš5ššš64ššš17šššš0.615šš-328.42 >>>>>>> 181.405 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 ušššš3ššš64ššš37šššš0.615šš-328.42 >>>>>>> 214.868 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš67ššš64ššš37šššš0.615šš-328.42 >>>>>>> 214.868 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš63ššš64ššš77šššš0.615šš-328.42 >>>>>>> 268.618 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš60ššš64šš177šššš0.615šš-328.42 >>>>>>> 333.175 >>>>>>> šXX.XX.XX.1šššššš.STEP.šššššššššš16 u 1910ššš64šššš0šššš0.000šššš0.000 >>>>>>> 0.000 >>>>>>> šXX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš27ššš64šššš1šššš0.703šš-262.63 >>>>>>> 0.004 >>>>>>> šXX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš31ššš64šššš1šššš0.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 >>>>>>> šššššremotešššššššššššrefidššššššst t when poll reachšššdelayšššoffset >>>>>>> jitter >>>>>>> ============================================================================== >>>>>>> >>>>>>> >>>>>>> >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 ušššš1ššš64šššš1šššš0.401šššš0.176 >>>>>>> 0.106 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 ušššš6ššš64šššš3šššš0.401šššš0.176 >>>>>>> 0.459 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 ušššš3ššš64šššš7šššš0.401šššš0.176 >>>>>>> 0.940 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš67ššš64šššš7šššš0.401šššš0.176 >>>>>>> 0.940 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš64ššš64ššš17šššš0.401šššš0.176 >>>>>>> 1.566 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš60ššš64ššš37šššš0.448šššš1.275 >>>>>>> 1.739 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš55ššš64ššš77šššš0.448šššš1.275 >>>>>>> 2.365 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš53ššš64šš177šššš0.448šššš1.275 >>>>>>> 3.110 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš50ššš64šš377šššš0.448šššš1.275 >>>>>>> 3.929 >>>>>>> *XX.XX.XX.1ššššššXX.XX.XX.245ššššš4 uššš45ššš64šš377šššš0.443šššš8.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.20ea2900ššFri, 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.1ššššššXX.245ššššš4 uššš20ššš64šššš1šššš0.717šš-12.771ššš4.193 >> *XX.1ššššššXX.245ššššš4 uššš28ššš64šššš3šššš0.751šš-41.970šš32.342 >> *XX.1ššššššXX.245ššššš4 uššš23ššš64šššš7šššš0.748šš-59.505šš46.624 >> *XX.1ššššššXX.245ššššš4 uššš18ššš64ššš17šššš0.699šš-75.164šš56.482 >> *XX.1ššššššXX.245ššššš4 uššš14ššš64ššš37šššš0.669šš-90.112šš63.767 >> *XX.1ššššššXX.245ššššš4 uššš11ššš64ššš77šššš0.605šš-10.567šš60.914 >> *XX.1ššššššXX.245ššššš4 ušššš7ššš64šš177šššš0.591šš-169.54 116.762 >> *XX.1ššššššXX.245ššššš4 ušššš3ššš64šš377šššš0.591šš-169.54 102.107 >> *XX.1ššššššXX.245ššššš4 uššš68ššš64šš377šššš0.591šš-169.54 102.107 >> *XX.1ššššššXX.245ššššš4 uššš63ššš64šš377šššš0.591šš-169.54šš88.424 >> *XX.1ššššššXX.245ššššš4 uššš58ššš64šš377šššš0.591šš-169.54šš92.949 >> *XX.1ššššššXX.245ššššš4 uššš55ššš64šš377šššš0.591šš-169.54 111.512 >> *XX.1ššššššXX.245ššššš4 uššš50ššš64šš377šššš0.591šš-169.54 140.827 >> *XX.1ššššššXX.245ššššš4 uššš45ššš64šš377šššš0.591šš-169.54 177.360 >> *XX.1ššššššXX.245ššššš4 uššš43ššš64šš377šššš0.591šš-169.54 219.057 >> šXX.1šššššš.STEP.šššš16 ušš588ššš64šššš0šššš0.000šššš0.000ššš0.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 Serve