From owner-freebsd-current@freebsd.org Fri Oct 20 17:20:14 2017 Return-Path: Delivered-To: freebsd-current@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 DA459E3B472; Fri, 20 Oct 2017 17:20:14 +0000 (UTC) (envelope-from bsam@passap.ru) Received: from forward102j.mail.yandex.net (forward102j.mail.yandex.net [IPv6:2a02:6b8:0:801:2::102]) (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 7BDDD837C4; Fri, 20 Oct 2017 17:20:11 +0000 (UTC) (envelope-from bsam@passap.ru) Received: from mxback13j.mail.yandex.net (mxback13j.mail.yandex.net [IPv6:2a02:6b8:0:1619::88]) by forward102j.mail.yandex.net (Yandex) with ESMTP id C1179560560C; Fri, 20 Oct 2017 20:20:07 +0300 (MSK) Received: from smtp1j.mail.yandex.net (smtp1j.mail.yandex.net [2a02:6b8:0:801::ab]) by mxback13j.mail.yandex.net (nwsmtp/Yandex) with ESMTP id CTJIjMd24C-K7faKnAg; Fri, 20 Oct 2017 20:20:07 +0300 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=passap.ru; s=mail; t=1508520007; bh=gP3qVzWMC8Hr5UFe9Rdetfpko3h0tO5kTA5xixVF2bU=; h=Subject:To:References:From:Message-ID:Date:In-Reply-To; b=dhPIuXJD99ty+usMvKJ7yJ9TMzcr++ppeHJlRuZW3AlBfFAyo0wKcBXlqmCIItiOw 6L2RoAlsnUB8UTX5nwe/At0e/Du2KyefTsscSvnwmWX4185kqMuX2Vo0+q/NHANxpu fzJxx2auTe+2ocFrLccxeNgFy77U1Pyb3plChoVc= Received: by smtp1j.mail.yandex.net (nwsmtp/Yandex) with ESMTPSA id vNW5MEB0Yn-K7w0FMN1; Fri, 20 Oct 2017 20:20:07 +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=1508520007; bh=gP3qVzWMC8Hr5UFe9Rdetfpko3h0tO5kTA5xixVF2bU=; h=Subject:To:References:From:Message-ID:Date:In-Reply-To; b=dhPIuXJD99ty+usMvKJ7yJ9TMzcr++ppeHJlRuZW3AlBfFAyo0wKcBXlqmCIItiOw 6L2RoAlsnUB8UTX5nwe/At0e/Du2KyefTsscSvnwmWX4185kqMuX2Vo0+q/NHANxpu fzJxx2auTe+2ocFrLccxeNgFy77U1Pyb3plChoVc= 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> From: Boris Samorodov Message-ID: <76ff7afb-3d3a-96f6-1275-89472ff5683d@passap.ru> Date: Fri, 20 Oct 2017 20:20:06 +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: <1508517160.1383.63.camel@freebsd.org> Content-Type: text/plain; charset=koi8-r Content-Language: en-US Content-Transfer-Encoding: 8bit X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 20 Oct 2017 17:20:15 -0000 (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. -- WBR, Boris Samorodov (bsam) FreeBSD Committer, http://www.FreeBSD.org The Power To Serve