From owner-freebsd-stable@freebsd.org Wed Nov 2 06:06:06 2016 Return-Path: Delivered-To: freebsd-stable@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 D87C3C2A9DF for ; Wed, 2 Nov 2016 06:06:06 +0000 (UTC) (envelope-from jason.harmening@gmail.com) Received: from mail-pf0-x230.google.com (mail-pf0-x230.google.com [IPv6:2607:f8b0:400e:c00::230]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 75BD21442 for ; Wed, 2 Nov 2016 06:06:06 +0000 (UTC) (envelope-from jason.harmening@gmail.com) Received: by mail-pf0-x230.google.com with SMTP id i88so5605386pfk.2 for ; Tue, 01 Nov 2016 23:06:06 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=subject:to:references:cc:from:message-id:date:user-agent :mime-version:in-reply-to; bh=/W2a5PPp9i92PTkCCJ1Or35to43IkUhRv8IiArfmu/A=; b=FtX+1hUna9MSQ4K9fv1trUPCznvba/XHKtOialwRT1ub3VVv8g4IvprgF2Rmsbh9zc zFJY08L+/teVRMI/F5ckQ1tRCAQ2GESONFztTSphH2lZOdQ4GwWIHoseXrKMdY20y3lk 0RYKB/a4UyoxrFUGy35DL1wPJojuTgmwNo0hmFQcG9oWaw0weMUXCEFUl2SyRFBgPTcp H9cK61aWBBu2/q7alRQqHQDHNdQ8BERm1jIyzFaBa/+WG7uydEDMCQznmd/b2nv1Zblu DrpN9BBb36LZLmvC9gjNRhamHwMInmw+ZYZ47ewSK7sTSmrFvFu9AM3DSAh94tb59ToL oKnA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:subject:to:references:cc:from:message-id:date :user-agent:mime-version:in-reply-to; bh=/W2a5PPp9i92PTkCCJ1Or35to43IkUhRv8IiArfmu/A=; b=fSc1Bl9Wq5Tx+MFQmTBneDcikUQ2MhhhXTXIFe+w6CPonTln2Q5NU2mYxLAAJlshN3 hEFcD8w6k7cf03Y2eOw2xB5ZlnERzxy8etMRn0Uzqpq58VIuLcG9XTu9PzivtxdKDRdW si2bdS/TABzO4vObm3+GmntmPaV1ehe38etokpYw943q0OMVdbXXB3ndT7vLvlmRCqto 2gnWMEW5nFPS7WhwHwH0WHW3LjIJBtRHZ3x3ljh2eW3J/wMlaSDgydfj5ir1xqcYFgJR V0fwwfNUbCp7dtWGhMUYuBoYQVBf1IKZCr/NJ7CW1NvzsVnSZeXU08EGLF6Wu6Fief/I U4lQ== X-Gm-Message-State: ABUngver6SvUuZTVHtmplH9Lj5N778/62l7wLoF+P1WTCglW4hPvQrKOnhCUK1Wb8fK/NQ== X-Received: by 10.99.65.133 with SMTP id o127mr3017557pga.73.1478066765929; Tue, 01 Nov 2016 23:06:05 -0700 (PDT) Received: from corona.austin.rr.com (c-67-188-30-11.hsd1.ca.comcast.net. [67.188.30.11]) by smtp.googlemail.com with ESMTPSA id 21sm1116234pfs.88.2016.11.01.23.06.04 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Tue, 01 Nov 2016 23:06:04 -0700 (PDT) Subject: Re: huge nanosleep variance on 11-stable To: Kevin Oberman References: <6167392c-c37a-6e39-aa22-ca45435d6088@gmail.com> <1c3f4599-8aef-471a-3a39-49d913f1a4e5@gmail.com> Cc: FreeBSD-STABLE Mailing List From: Jason Harmening Message-ID: <3788515b-d271-ea9f-81b9-860111f7e7d4@gmail.com> Date: Tue, 1 Nov 2016 23:13:05 -0700 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:45.0) Gecko/20100101 Thunderbird/45.4.0 MIME-Version: 1.0 In-Reply-To: Content-Type: multipart/signed; micalg=pgp-sha512; protocol="application/pgp-signature"; boundary="IpLW9Sv2BaXgt9dpDtmHLHCBwHOrCMbg3" X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 02 Nov 2016 06:06:07 -0000 This is an OpenPGP/MIME signed message (RFC 4880 and 3156) --IpLW9Sv2BaXgt9dpDtmHLHCBwHOrCMbg3 Content-Type: multipart/mixed; boundary="nsjwe146cwW3gEQWPVm1UJoa6sXL5Ki1W"; protected-headers="v1" From: Jason Harmening To: Kevin Oberman Cc: FreeBSD-STABLE Mailing List Message-ID: <3788515b-d271-ea9f-81b9-860111f7e7d4@gmail.com> Subject: Re: huge nanosleep variance on 11-stable References: <6167392c-c37a-6e39-aa22-ca45435d6088@gmail.com> <1c3f4599-8aef-471a-3a39-49d913f1a4e5@gmail.com> In-Reply-To: --nsjwe146cwW3gEQWPVm1UJoa6sXL5Ki1W Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable On 11/01/16 22:49, Kevin Oberman wrote: > On Tue, Nov 1, 2016 at 10:16 PM, Jason Harmening > > wrote: >=20 >=20 >=20 > On 11/01/16 20:45, Kevin Oberman wrote: > > On Tue, Nov 1, 2016 at 2:36 PM, Jason Harmening > > > >> wrote: > > > > Sorry, that should be ~*30ms* to get 30fps, though the > variance is still > > up to 500ms for me either way. > > > > On 11/01/16 14:29, Jason Harmening wrote: > > > repro code is at http://pastebin.com/B68N4AFY if anyone's > interested. > > > > > > On 11/01/16 13:58, Jason Harmening wrote: > > >> Hi everyone, > > >> > > >> I recently upgraded my main amd64 server from 10.3-stable > > (r302011) to > > >> 11.0-stable (r308099). It went smoothly except for one bi= g > issue: > > >> certain applications (but not the system as a whole) > respond very > > >> sluggishly, and video playback of any kind is extremely ch= oppy. > > >> > > >> The system is under very light load, and I see no evidence= of > > abnormal > > >> interrupt latency or interrupt load. More interestingly, = if I > > place the > > >> system under full load (~0.0% idle) the problem > *disappears* and > > >> playback/responsiveness are smooth and quick. > > >> > > >> Running ktrace on some of the affected apps points me at > the problem: > > >> huge variance in the amount of time spent in the nanosleep= > system > > call. > > >> A sleep of, say, 5ms might take anywhere from 5ms to ~500m= s > from > > entry > > >> to return of the syscall. OTOH, anything CPU-bound or tha= t > waits on > > >> condvars or I/O interrupts seems to work fine, so this doe= sn't > > seem to > > >> be an issue with overall system latency. > > >> > > >> I can repro this with a simple program that just does a 3m= s > > usleep in a > > >> tight loop (i.e. roughly the amount of time a video player= > would > > sleep > > >> between frames @ 30fps). At light load ktrace will show > the huge > > >> nanosleep variance; under heavy load every nanosleep will > complete in > > >> almost exactly 3ms. > > >> > > >> FWIW, I don't see this on -current, although right now all= my > > -current > > >> images are VMs on different HW so that might not mean anyt= hing. > > I'm not > > >> aware of any recent timer- or scheduler- specific changes,= > so I'm > > >> wondering if perhaps the recent IPI or taskqueue changes > might be > > >> somehow to blame. > > >> > > >> I'm not especially familiar w/ the relevant parts of the > kernel, > > so any > > >> guidance on where I should focus my debugging efforts woul= d > be much > > >> appreciated. > > >> > > >> Thanks, > > >> Jason > > > > > > This is likely off track, but this is a behavior I have noticed s= ince > > moving to 11, though it might have started in 10.3-STABLE before > moving > > to head before 11 went to beta. I can't explain any way nanosleep= > could > > be involved, but I saw annoying lock-ups similar to yours. I also= no > > longer see them. > > > > I eliminated the annoyance by change scheduler from ULE to 4BSD. = That > > was it, but I have not seen the issue since. I'd be very interest= ed in > > whether the scheduler is somehow impacting timing functions or it= 's s > > different issue. I've felt that there was something off in ULE fo= r > some > > time, but it was not until these annoying hiccups convinced me to= try > > going back to 4BSD. > > > > Tip o' the hat to Doug B. for his suggestions that ULE may have i= ssues > > that impacted interactivity. >=20 > I figured it out: r282678 (which was never MFCed to 10-stable) adde= d > support for the MWAIT instruction on the idle path for Intel CPUs t= hat > claim to support it. >=20 > While my CPU (2009-era Xeon 5500) advertises support for it in its > feature mask and ACPI C-state entries, the cores don't seem to resp= ond > very quickly to interrupts while idling in MWAIT. Disabling mwait = in > acpi_cpu.c and falling back to the old "sti; hlt" mechanism for C1 > completely fixes the responsiveness issues. >=20 > So if your CPU is of a similar vintage, it may not be ULE's fault. >=20 >=20 > You are almost certainly correct. My system is circa 2011; i5-2520M, > Sandy Bridge. While it might have the same issue, I'd be surprised. It'= s > possible, but probably completely different from what you are seeing. > Reports of the problem I was seeing definitely pre-date 11, but 11 made= > things much worse, so it could be a combination of things. And I can't > see how ULE could have anything to do with this issue. >=20 > Congratulations on some really good sleuthing to find this. It might be worth a shot just to see if this has any impact on the issue you were seeing with ULE. I agree that it doesn't seem likely the choice of scheduler would have an impact on an issue like this. But it's possible that 4BSD might schedule threads across cores such that a given core is less likely to be idle on delivery of a timer interrupt for a given workload. --nsjwe146cwW3gEQWPVm1UJoa6sXL5Ki1W-- --IpLW9Sv2BaXgt9dpDtmHLHCBwHOrCMbg3 Content-Type: application/pgp-signature; name="signature.asc" Content-Description: OpenPGP digital signature Content-Disposition: attachment; filename="signature.asc" -----BEGIN PGP SIGNATURE----- iQF8BAEBCgBmBQJYGYPxXxSAAAAAAC4AKGlzc3Vlci1mcHJAbm90YXRpb25zLm9w ZW5wZ3AuZmlmdGhob3JzZW1hbi5uZXRENkY3MTQyREU0MTU4MTgyRkZDNUU2ODVC QjlGOEJGOTkyODQxRDFCAAoJELufi/mShB0bF1gIAOcbjNQQkPoU6I8inqAD/4eH /yRyzAZJh90aSk/0Hl2UlTfJTkZ8E8gHoG5teTVPKYn72lePymLdDDWw28zre5Rf PNEbMLT6iCj72TZdV3MWzDVRe62MCKBnDF3ggmil0At+kWoCtKno1onIuR4xvfJk hYA8DCfS0ZIlUTvT2thgBgPAb5II8M5Whrs6eZAW8FRkf5Rm7TdtcRI5Cox08a1N PFqlOBBNKZnYs3M0Q89rrHGa0i9dCB8Ir+xTOkgDvLU7xZitPeNVomGKu04raype T0mm6d+0EIWvMMpTfr2VgkOiwOS71dlOAxg8MTEKULwk7UQWlapC2CnsgZy+AZo= =2aYg -----END PGP SIGNATURE----- --IpLW9Sv2BaXgt9dpDtmHLHCBwHOrCMbg3--