From owner-freebsd-bugs@freebsd.org Wed Mar 23 12:54:10 2016 Return-Path: Delivered-To: freebsd-bugs@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 B24D0ADADDF for ; Wed, 23 Mar 2016 12:54:10 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from kenobi.freebsd.org (kenobi.freebsd.org [IPv6:2001:1900:2254:206a::16:76]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 983B515BB for ; Wed, 23 Mar 2016 12:54:10 +0000 (UTC) (envelope-from bugzilla-noreply@freebsd.org) Received: from bugs.freebsd.org ([127.0.1.118]) by kenobi.freebsd.org (8.15.2/8.15.2) with ESMTP id u2NCsAu2047798 for ; Wed, 23 Mar 2016 12:54:10 GMT (envelope-from bugzilla-noreply@freebsd.org) From: bugzilla-noreply@freebsd.org To: freebsd-bugs@FreeBSD.org Subject: [Bug 208238] [Hyper-V] TSC frequency is not correctly detected: "calcru: runtime went backwards" Date: Wed, 23 Mar 2016 12:54:10 +0000 X-Bugzilla-Reason: AssignedTo X-Bugzilla-Type: new X-Bugzilla-Watch-Reason: None X-Bugzilla-Product: Base System X-Bugzilla-Component: kern X-Bugzilla-Version: 11.0-CURRENT X-Bugzilla-Keywords: X-Bugzilla-Severity: Affects Some People X-Bugzilla-Who: decui@microsoft.com X-Bugzilla-Status: New X-Bugzilla-Resolution: X-Bugzilla-Priority: --- X-Bugzilla-Assigned-To: freebsd-bugs@FreeBSD.org X-Bugzilla-Flags: X-Bugzilla-Changed-Fields: bug_id short_desc product version rep_platform op_sys bug_status bug_severity priority component assigned_to reporter Message-ID: Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable X-Bugzilla-URL: https://bugs.freebsd.org/bugzilla/ Auto-Submitted: auto-generated MIME-Version: 1.0 X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 23 Mar 2016 12:54:10 -0000 https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=3D208238 Bug ID: 208238 Summary: [Hyper-V] TSC frequency is not correctly detected: "calcru: runtime went backwards" Product: Base System Version: 11.0-CURRENT Hardware: Any OS: Any Status: New Severity: Affects Some People Priority: --- Component: kern Assignee: freebsd-bugs@FreeBSD.org Reporter: decui@microsoft.com I can easily get a large number of messages in the system log similar to th= is: # dmesg | grep backwards calcru: runtime went backwards from 5188 usec to 2727 usec for pid 770 (cro= n) calcru: runtime went backwards from 2944 usec to 1488 usec for pid 766 (sendmail) calcru: runtime went backwards from 2497 usec to 1262 usec for pid 766 (sendmail) It looks this is caused by the wrongly-detected TSC frequency and I made th= is patch to address this: https://github.com/dcui/freebsd/commit/07acbd8a3771adba9ac0fca807ec629ff05a= 807c " use hyper-v time counter (rather than i8254) to calibrate TSC The i8254 PIT counter emulated by Hyper-V is not reliable. In probe_tsc_freq() -> DELAY -> init_ops.early_delay() -> i8254_delay(), getit() can return these values when it is invoked 10 times: 1 pit count0 =3D 228 2 pit count0 =3D 131 3 pit count0 =3D 34 4 pit count0 =3D 65473 <-- this is a normal wrap-around. 5 pit count0 =3D 65375 6 pit count0 =3D 65278 7 pit count0 =3D 65180 8 pit count0 =3D 65388 <-- this is bad! 9 pit count0 =3D 65290 10 pit count0 =3D 65193 For the 8th time, the 'delta' in i8254_delay() is < 0 while it shouldn't, so the later "delta +=3D i8254_max_count;" and "ticks_left -=3D delta" will cause i8254_delay() to wait shorter than expected, and finally probe_tsc_freq() get a smaller 'tsc_freq'. A smaller 'tsc_freq' can cause time inaccuracy in dtrace. It can also cause warnings like calcru: runtime went backwards from 50 usec to 25 usec for pid 0 (kernel) calcru: runtime went backwards from 1471 usec to 743 usec for pid 0 (kernel) calcru: runtime went backwards from 40 usec to 20 usec for pid 0 (kernel) calcru: runtime went backwards from 18 usec to 9 usec for pid 0 (kernel) calcru: runtime went backwards from 46204978 usec to 23362331 usec for pid 0 (kernel) We use Hyper-V time counter, which is much more reliable than i8254, to calibrate TSC. " --=20 You are receiving this mail because: You are the assignee for the bug.=