From owner-freebsd-current@freebsd.org Thu Nov 24 22:45:56 2016 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 61989C54558 for ; Thu, 24 Nov 2016 22:45:56 +0000 (UTC) (envelope-from rmacklem@uoguelph.ca) Received: from na01-bl2-obe.outbound.protection.outlook.com (mail-bl2on0067.outbound.protection.outlook.com [65.55.169.67]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)) (Client CN "mail.protection.outlook.com", Issuer "Microsoft IT SSL SHA2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id C3B0B152; Thu, 24 Nov 2016 22:45:54 +0000 (UTC) (envelope-from rmacklem@uoguelph.ca) Received: from YTXPR01MB0189.CANPRD01.PROD.OUTLOOK.COM (10.165.218.133) by YTXPR01MB0192.CANPRD01.PROD.OUTLOOK.COM (10.165.218.136) with Microsoft SMTP Server (version=TLS1_2, cipher=TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384_P384) id 15.1.734.8; Thu, 24 Nov 2016 22:45:52 +0000 Received: from YTXPR01MB0189.CANPRD01.PROD.OUTLOOK.COM ([10.165.218.133]) by YTXPR01MB0189.CANPRD01.PROD.OUTLOOK.COM ([10.165.218.133]) with mapi id 15.01.0734.014; Thu, 24 Nov 2016 22:45:52 +0000 From: Rick Macklem To: Alan Somers CC: Konstantin Belousov , FreeBSD CURRENT Subject: Re: NFSv4 performance degradation with 12.0-CURRENT client Thread-Topic: NFSv4 performance degradation with 12.0-CURRENT client Thread-Index: AQHSRhIPtzL8Jj0C/0q6PJtKKLQgMaDn2GqAgAA8DvaAAGR2gIAAPUCR Date: Thu, 24 Nov 2016 22:45:51 +0000 Message-ID: References: <20161124090811.GO54029@kib.kiev.ua> , In-Reply-To: Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: authentication-results: spf=none (sender IP is ) smtp.mailfrom=rmacklem@uoguelph.ca; x-microsoft-exchange-diagnostics: 1; YTXPR01MB0192; 7:B+T3xELcAzR+RWF4UOq+Dx6hg0pf7HBouNN1bF6iVhUG85qUQPhzA56dNs2gz885OmHm8V5uA8JkKWmlj+ybmqq2nIatlN/h6q6ieHDkYFd8kVW7FIEmSLJQLSJpKsse9ACSmQG4kqvrXRg2EsrSJUu/gbSvDwbZhr/WlskIWELpbJkTNZEM5TZNwbXeux+2u8D+/SK7Iuqtl/U9lFU42tzit+4EgzMhce5QrfplP416+YNMLM7CjbAEPffJcjq4CiOst45IlNanFEh6rdjFX/HK84JXz38exHkHCbnhU/V5yUm94ALVCjCNRcJgWDVysYodrfuQdsAw8C0KWGHO6EMY04o30b92GHHZkb9qQKA= x-ms-office365-filtering-correlation-id: 23e8d186-abc7-4f68-e939-08d414bba4c2 x-microsoft-antispam: UriScan:;BCL:0;PCL:0;RULEID:(22001);SRVR:YTXPR01MB0192; x-microsoft-antispam-prvs: x-exchange-antispam-report-test: UriScan:(158342451672863); x-exchange-antispam-report-cfa-test: BCL:0; PCL:0; RULEID:(6060326)(6045199)(6040361)(2401047)(5005006)(8121501046)(3002001)(10201501046)(6061324)(6041248)(2016111802025)(20161123555025)(20161123564025)(20161123560025)(20161123562025)(6043046); SRVR:YTXPR01MB0192; BCL:0; PCL:0; RULEID:; SRVR:YTXPR01MB0192; x-forefront-prvs: 0136C1DDA4 x-forefront-antispam-report: SFV:NSPM; SFS:(10009020)(6009001)(7916002)(24454002)(199003)(189002)(8676002)(39060400001)(86362001)(39380400001)(189998001)(39410400001)(81166006)(97736004)(74482002)(8936002)(229853002)(38730400001)(6506003)(4326007)(2906002)(7846002)(305945005)(74316002)(68736007)(81156014)(9686002)(102836003)(3660700001)(92566002)(3280700002)(50986999)(54356999)(77096005)(76176999)(101416001)(2900100001)(106356001)(122556002)(106116001)(105586002)(33656002)(7696004)(93886004)(5660300001)(110136003)(6916009)(39400400001)(2950100002)(39450400002); DIR:OUT; SFP:1101; SCL:1; SRVR:YTXPR01MB0192; H:YTXPR01MB0189.CANPRD01.PROD.OUTLOOK.COM; FPR:; SPF:None; PTR:InfoNoRecords; A:1; MX:1; LANG:en; received-spf: None (protection.outlook.com: uoguelph.ca does not designate permitted sender hosts) spamdiagnosticoutput: 1:99 spamdiagnosticmetadata: NSPM Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable MIME-Version: 1.0 X-OriginatorOrg: uoguelph.ca X-MS-Exchange-CrossTenant-originalarrivaltime: 24 Nov 2016 22:45:51.9417 (UTC) X-MS-Exchange-CrossTenant-fromentityheader: Hosted X-MS-Exchange-CrossTenant-id: be62a12b-2cad-49a1-a5fa-85f4f3156a7d X-MS-Exchange-Transport-CrossTenantHeadersStamped: YTXPR01MB0192 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: Thu, 24 Nov 2016 22:45:56 -0000 asomers@gmail.com wrote: [stuff snipped] >I've reproduced the issue on stock FreeBSD 12, and I've also learned >that nullfs is a required factor. Doing the buildworld directly on >the NFS mount doesn't cause any slowdown, but doing a buildworld on >the nullfs copy of the NFS mount does. The slowdown affects the base >NFS mount as well as the nullfs copy. Here is the nfsstat output for >both server and client duing "ls -al" on the client: > >nfsstat -e -s -z If you do this again, avoid using "-z" and I think you'll see the Opens (be= low Server:) going up and up... > >Server Info: > Getattr Setattr Lookup Readlink Read Write Create R= emove > 800 0 121 0 0 2 0 = 0 > Rename Link Symlink Mkdir Rmdir Readdir RdirPlus A= ccess > 0 0 0 0 0 0 0 = 8 > Mknod Fsstat Fsinfo PathConf Commit LookupP SetClId SetC= lIdCf > 0 0 0 0 1 3 0 = 0 > Open OpenAttr OpenDwnGr OpenCfrm DelePurge DeleRet GetFH = Lock > 0 0 0 0 0 0 123 = 0 > LockT LockU Close Verify NVerify PutFH PutPubFH PutR= ootFH > 0 0 0 0 0 674 0 = 0 > Renew RestoreFH SaveFH Secinfo RelLckOwn V4Create > 0 0 0 0 0 0 >Server: >Retfailed Faults Clients > 0 0 0 >OpenOwner Opens LockOwner Locks Delegs > 0 0 0 0 0 Oops, I think this is an nfsstats bug. I don't normally use "-z", so I didn= 't notice it clears these counts and it probably should not, since they are "how many= of these that are currently allocated". I'll check this. (Not relevant to this issue, but needs fixin.;-) >Server Cache Stats: > Inprog Idem Non-idem Misses CacheSize TCPPeak > 0 0 0 674 16738 16738 > >nfsstat -e -c -z >Client Info: >Rpc Counts: > Getattr Setattr Lookup Readlink Read Write Create Re= move > 60 0 119 0 0 0 0 = 0 > Rename Link Symlink Mkdir Rmdir Readdir RdirPlus A= ccess > 0 0 0 0 0 0 0 = 3 > Mknod Fsstat Fsinfo PathConf Commit SetClId SetClIdCf = Lock > 0 0 0 0 0 0 0 = 0 > LockT LockU Open OpenCfr > 0 0 0 0 >OpenOwner Opens LockOwner Locks Delegs LocalOwn LocalOpen Loca= lLOwn > 5638 141453 0 0 0 0 0 = 0 Ok, I think this shows us the problem. 141453 opens is a lot and the client= would have to chek these every time another open is done (there goes all that CPU;-). Now, why has this occurred? Well, the NFSv4 client can't close NFSv4 Opens on a vnode until that vnode'= s v_usecount goes to 0. This is because mmap'd files might do I/O after the f= ile descriptor is closed. Now, hopefully Kostik will know something about nullfs and can help with th= is. My guess is that nullfs ends up acquiring a refcnt on the NFS vnode so the v_usecount doesn't go to 0 and, therefore, the client never closes the NFSv= 4 Opens. Kostik, do you know if this is the case and whether or not it can be change= d? >LocalLock > 0 >Rpc Info: >TimedOut Invalid X Replies Retries Requests > 0 0 0 0 662 >Cache Info: >Attr Hits Misses Lkup Hits Misses BioR Hits Misses BioW Hits M= isses > 1275 58 837 121 0 0 0 = 0 >BioRLHits Misses BioD Hits Misses DirE Hits Misses > 1 0 6 0 1 0 > [more stuff snipped] >What role could nullfs be playing? As noted above, my hunch is that is acquiring a refcnt on the NFS client vn= ode such that the v_usecount doesn't go to zero (at least for a long time) and witho= ut a VOP_INACTIVE() on the NFSv4 vnode, the NFSv4 Opens don't get closed and accumulate. (If that isn't correct, it is somehow interfering with the client Closing t= he NFSv4 Opens in some other way.) rick