From owner-freebsd-stable@FreeBSD.ORG Fri Jan 22 16:00:27 2010 Return-Path: Delivered-To: freebsd-stable@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 81C1910656F4; Fri, 22 Jan 2010 16:00:27 +0000 (UTC) (envelope-from to.my.trociny@gmail.com) Received: from mail-bw0-f213.google.com (mail-bw0-f213.google.com [209.85.218.213]) by mx1.freebsd.org (Postfix) with ESMTP id AD9BF8FC0C; Fri, 22 Jan 2010 16:00:26 +0000 (UTC) Received: by bwz5 with SMTP id 5so1223792bwz.3 for ; Fri, 22 Jan 2010 08:00:25 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:received:received:to:subject:references :organization:from:date:in-reply-to:message-id:user-agent :mime-version:content-type:content-transfer-encoding; bh=lR54PkQR1F2FsB9R46HknPl0T/g9NX1AZEceUOxri2w=; b=XoaJ0km04Yw873HEo+DH1UEOAtkQsZD/R/5cw79O/D1hlP3IajIYwIHJWMBGeDTtlo 1xoSwdUM4Oakzsn1kJulNdFrNWCisF9VzCKu/UtUBC9mVoOm65OY/qhTaDi2KEJkMDDu ewMXxBUxhP/DVIWQugFCF3pCq63Kd79icyc6U= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=to:subject:references:organization:from:date:in-reply-to:message-id :user-agent:mime-version:content-type:content-transfer-encoding; b=SCfXG+141KYQ4AFIvg2W9BWFKMqJDuvaoAZkxyi314oDPNn0/NpJM4YmgeitzSY36J j6H/s0VtcsnaYDwZIp/xtlynIF2eJeSl25VmbnZ55SR4E/5eHvB6/5Dx/0h8JTrh0ouZ 7JwCf1PWgKfvWKx0mj29T1Dfe+CSKd8GA2c50= Received: by 10.204.144.86 with SMTP id y22mr1757061bku.43.1264176025495; Fri, 22 Jan 2010 08:00:25 -0800 (PST) Received: from localhost (ms.singlescrowd.net [80.85.90.67]) by mx.google.com with ESMTPS id 15sm1029159bwz.4.2010.01.22.08.00.22 (version=TLSv1/SSLv3 cipher=RC4-MD5); Fri, 22 Jan 2010 08:00:23 -0800 (PST) To: freebsd-fs@FreeBSD.org, freebsd-stable@FreeBSD.org References: <86ocl272mb.fsf@kopusha.onet> <86tyuqnz9x.fsf@zhuzha.ua1> <86zl4awmon.fsf@zhuzha.ua1> <86vdeywmha.fsf@zhuzha.ua1> Organization: TOA Ukraine From: Mikolaj Golub Date: Fri, 22 Jan 2010 18:00:21 +0200 In-Reply-To: <86vdeywmha.fsf@zhuzha.ua1> (Mikolaj Golub's message of "Tue\, 19 Jan 2010 10\:02\:57 +0200") Message-ID: <86vdeuuo2y.fsf@zhuzha.ua1> User-Agent: Gnus/5.11 (Gnus v5.11) Emacs/22.3 (berkeley-unix) MIME-Version: 1.0 Content-Type: text/plain; charset=koi8-r Content-Transfer-Encoding: 8bit Cc: Subject: Re: FreeBSD NFS client/Linux NFS server issue X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 22 Jan 2010 16:00:27 -0000 On Tue, 19 Jan 2010 10:02:57 +0200 Mikolaj Golub wrote: > So, on some of our freebsd7.1 nfs clients (and it looks like we have had > similar case with 6.3), which have several nfs mounts to the same CentOS 5.3 > NFS server (mount options: rw,-3,-T,-s,-i,-r=32768,-w=32768,-o=noinet6), at > some moment the access to one of the NFS mount gets stuck, while the access to > the other mounts works ok. > > In all cases we have been observed so far the first gotten stuck process was > php script (or two) that was (were) writing to logs file (appending). In > tcpdump we see that every write to the file causes the sequence of the > following rpc: ACCESS - READ - WRITE - COMMIT. And at some moment this stops > after READ rpc call and successful reply. > > After this in tcpdump successful readdir/access/lookup/fstat calls are > observed from our other utilities, which just check the presence of some files > and they work ok (df also works). The php process at this state is in bo_wwait > invalidating buffer cache [1]. > > If at this time we try accessing the share with mc then it hangs acquiring the > vn_lock held by php process [2] and after this any operations with this NFS > share hang (df hangs too). > > If instead some other process is started that writes to some other file on > this share (append) then the first process "unfreezes" too (starting from > WRITE rpc, so there is no any retransmits). So it looks for me that the problem here is that eventually problem nfsmount ends up in this state: (kgdb) p *nmp $1 = {nm_mtx = {lock_object = {lo_name = 0xc0b808ee "NFSmount lock", lo_type = 0xc0b808ee "NFSmount lock", lo_flags = 16973824, lo_witness_data = {lod_list = { stqe_next = 0x0}, lod_witness = 0x0}}, mtx_lock = 4, mtx_recurse = 0}, nm_flag = 35399, nm_state = 1310720, nm_mountp = 0xc6b472cc, nm_numgrps = 16, nm_fh = "\001\000\000\000\000\223\000\000\001@\003\n", '\0' , nm_fhsize = 12, nm_rpcclnt = {rc_flag = 0, rc_wsize = 0, rc_rsize = 0, rc_name = 0x0, rc_so = 0x0, rc_sotype = 0, rc_soproto = 0, rc_soflags = 0, rc_timeo = 0, rc_retry = 0, rc_srtt = {0, 0, 0, 0}, rc_sdrtt = {0, 0, 0, 0}, rc_sent = 0, rc_cwnd = 0, rc_timeouts = 0, rc_deadthresh = 0, rc_authtype = 0, rc_auth = 0x0, rc_prog = 0x0, rc_proctlen = 0, rc_proct = 0x0}, nm_so = 0xc6e81d00, nm_sotype = 1, nm_soproto = 0, nm_soflags = 44, nm_nam = 0xc6948640, nm_timeo = 6000, nm_retry = 2, nm_srtt = {15, 15, 31, 52}, nm_sdrtt = {3, 3, 15, 15}, nm_sent = 0, nm_cwnd = 4096, nm_timeouts = 0, nm_deadthresh = 9, nm_rsize = 32768, nm_wsize = 32768, nm_readdirsize = 4096, nm_readahead = 1, nm_wcommitsize = 1177026, nm_acdirmin = 30, nm_acdirmax = 60, nm_acregmin = 3, nm_acregmax = 60, nm_verf = "Jë¾W\000\004oí", nm_bufq = {tqh_first = 0xda82dc70, tqh_last = 0xda8058e0}, nm_bufqlen = 2, nm_bufqwant = 0, nm_bufqiods = 1, nm_maxfilesize = 1099511627775, nm_rpcops = 0xc0c2b5bc, nm_tprintf_initial_delay = 12, nm_tprintf_delay = 30, nm_nfstcpstate = { rpcresid = 0, flags = 1, sock_send_inprog = 0}, nm_hostname = "172.30.10.92\000/var/www/app31", '\0' , nm_clientid = 0, nm_fsid = { val = {0, 0}}, nm_lease_time = 0, nm_last_renewal = 0} We have nonempty nm_bufq, nm_bufqiods = 1, but actually there is no nfsiod thread run for this mount, which is wrong -- nm_bufq will not be emptied until some other process starts writing to the nfsmount and starts nfsiod thread for this mount. Reviewing the code how it could happen I see the following path. Could someone confirm or disprove me? in nfs_bio.c:nfs_asyncio() we have: 1363 mtx_lock(&nfs_iod_mtx); ... 1374 /* 1375 * Find a free iod to process this request. 1376 */ 1377 for (iod = 0; iod < nfs_numasync; iod++) 1378 if (nfs_iodwant[iod]) { 1379 gotiod = TRUE; 1380 break; 1381 } 1382 1383 /* 1384 * Try to create one if none are free. 1385 */ 1386 if (!gotiod) { 1387 iod = nfs_nfsiodnew(); 1388 if (iod != -1) 1389 gotiod = TRUE; 1390 } Let's consider situation when new nfsiod is created. nfs_nfsiod.c:nfs_nfsiodnew() before creating nfssvc_iod thread unlocks nfs_iod_mtx: 179 mtx_unlock(&nfs_iod_mtx); 180 error = kthread_create(nfssvc_iod, nfs_asyncdaemon + i, NULL, RFHIGHPID, 181 0, "nfsiod %d", newiod); 182 mtx_lock(&nfs_iod_mtx); And nfs_nfsiod.c:nfssvc_iod() do the followin: 226 mtx_lock(&nfs_iod_mtx); ... 238 nfs_iodwant[myiod] = curthread->td_proc; 239 nfs_iodmount[myiod] = NULL; ... 244 error = msleep(&nfs_iodwant[myiod], &nfs_iod_mtx, PWAIT | PCATCH, 245 "-", timo); Let's at this moment another nfs_asyncio() request for another nfsmount has happened and this thread has locked nfs_iod_mtx. Then this thread will found nfs_iodwant[iod] in "for" loop and will use it. When the first thread actually has returned from nfs_nfsiodnew() it will insert buffer to nmp->nm_bufq but nfsiod will process other nmp. It looks like the fix for this situation would be to check nfs_iodwant[iod] after nfs_nfsiodnew(): --- nfs_bio.c.orig 2010-01-22 15:38:02.000000000 +0000 +++ nfs_bio.c 2010-01-22 15:39:58.000000000 +0000 @@ -1385,7 +1385,7 @@ again: */ if (!gotiod) { iod = nfs_nfsiodnew(); - if (iod != -1) + if ((iod != -1) && (nfs_iodwant[iod] == NULL)) gotiod = TRUE; } Described here scenario could be our case. We have 7 nfs mounts on the problem host. And by cront at the same time one or two scripts for every mount were started. So we had something like this in top (cron tasks started at 23:02): last pid: 64884; load averages: 0.28, 0.34, 0.24 up 0+22:15:41 23:02:04 300 processes: 6 running, 259 sleeping, 1 stopped, 17 zombie, 17 waiting CPU: 10.2% user, 0.0% nice, 7.6% system, 1.0% interrupt, 81.2% idle Mem: 174M Active, 2470M Inact, 221M Wired, 136M Cache, 112M Buf, 251M Free Swap: 8192M Total, 8192M Free 64793 app12 -1 0 23352K 11980K nfsreq 0 0:00 1.07% php 64789 app16 -1 0 21304K 11084K nfsreq 0 0:00 0.98% php 64784 app16 -1 0 19256K 9696K nfsreq 2 0:00 0.88% php 64768 app20 -1 0 19256K 9300K nfsreq 0 0:00 0.78% php 64759 app20 -1 0 18232K 8888K nfsreq 1 0:00 0.78% php 64722 app31 -1 0 20280K 9956K nfsreq 0 0:00 0.68% php 64781 app18 -1 0 19256K 9412K nfsreq 3 0:00 0.68% php 64778 app26 -1 0 18232K 8840K nfsreq 1 0:00 0.68% php 64800 app8 -1 0 18232K 8664K nfsreq 3 0:00 0.68% php 64728 app31 -1 0 18232K 8752K nfsreq 0 0:00 0.59% php 64795 app18 -1 0 18232K 8676K nfsreq 1 0:00 0.59% php 64777 app22 -1 0 18232K 8984K nfsreq 0 0:00 0.49% php 2342 app31 -4 0 22236K 7780K nfs 1 0:13 0.00% icoms_agent_cox215 58920 root 8 - 0K 8K - 2 0:08 0.00% nfsiod 0 2334 app31 -4 0 18908K 6356K nfs 1 0:05 0.00% icoms_agent_cox001 64297 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 1 64298 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 2 64303 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 3 64874 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 12 64870 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 9 64866 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 4 64873 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 11 64867 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 5 64869 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 8 64872 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 10 64868 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 7 64871 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 6 last pid: 64967; load averages: 0.42, 0.37, 0.25 up 0+22:15:46 23:02:09 295 processes: 7 running, 251 sleeping, 1 stopped, 19 zombie, 17 waiting CPU: 69.1% user, 0.0% nice, 8.3% system, 1.5% interrupt, 21.1% idle Mem: 376M Active, 2488M Inact, 226M Wired, 124M Cache, 106M Buf, 37M Free Swap: 8192M Total, 8192M Free 64793 app12 99 0 86840K 59968K CPU3 3 0:02 16.55% php 64768 app20 -1 0 57144K 38424K nfsreq 1 0:02 15.19% php 64722 app31 99 0 61240K 41228K CPU0 0 0:02 15.19% php 64781 app18 -1 0 54072K 35612K nfsreq 2 0:02 13.67% php 64789 app16 -1 0 48952K 31660K nfsreq 3 0:01 10.60% php 64777 app22 -1 0 43832K 27876K nfsreq 0 0:01 9.86% php 64784 app16 -1 0 45880K 29648K nfsreq 0 0:01 9.77% php 64759 app20 -7 0 36664K 22792K bo_wwa 0 0:01 8.25% php 64800 app8 -7 0 24376K 13596K bo_wwa 1 0:01 2.39% php 64795 app18 -7 0 23352K 12788K bo_wwa 3 0:00 1.37% php 58920 root -1 - 0K 8K nfsreq 2 0:08 0.00% nfsiod 0 64303 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 3 64866 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 4 64297 root -1 - 0K 8K nfsreq 2 0:00 0.00% nfsiod 1 64298 root -1 - 0K 8K nfsreq 3 0:00 0.00% nfsiod 2 64873 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 11 64868 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 7 64867 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 5 64871 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 6 64947 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 14 64950 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 17 64870 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 9 64869 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 8 64949 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 16 64874 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 12 64872 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 10 64952 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 19 64948 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 15 64951 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 18 64946 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 13 last pid: 64968; load averages: 0.54, 0.39, 0.26 up 0+22:15:51 23:02:14 289 processes: 7 running, 243 sleeping, 1 stopped, 21 zombie, 17 waiting CPU: 28.7% user, 0.0% nice, 8.8% system, 1.1% interrupt, 61.4% idle Mem: 404M Active, 2503M Inact, 224M Wired, 83M Cache, 107M Buf, 37M Free Swap: 8192M Total, 8192M Free 64793 app12 -1 0 148M 106M nfsreq 1 0:07 41.55% php 64722 app31 -7 0 61240K 41232K bo_wwa 1 0:03 14.26% php 64768 app20 -7 0 57144K 38424K bo_wwa 3 0:03 13.67% php 64781 app18 -7 0 54072K 35612K bo_wwa 0 0:02 11.18% php 64789 app16 -7 0 48952K 31660K bo_wwa 0 0:02 7.96% php 64784 app16 -7 0 45880K 29648K bo_wwa 0 0:02 7.76% php 64777 app22 -7 0 43832K 27876K bo_wwa 0 0:01 6.40% php 64759 app20 -7 0 36664K 22792K bo_wwa 0 0:01 4.79% php 58920 root -1 - 0K 8K nfsreq 2 0:08 0.00% nfsiod 0 64867 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 5 64873 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 11 64303 root -1 - 0K 8K nfsreq 0 0:00 0.00% nfsiod 3 64866 root -1 - 0K 8K nfsreq 1 0:00 0.00% nfsiod 4 64297 root -1 - 0K 8K nfsreq 0 0:00 0.00% nfsiod 1 64298 root -1 - 0K 8K nfsreq 3 0:00 0.00% nfsiod 2 64871 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 6 64868 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 7 64869 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 8 64947 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 14 64872 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 10 64874 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 12 64870 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 9 64949 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 16 64950 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 17 64948 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 15 64951 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 18 64946 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 13 64952 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 19 last pid: 64969; load averages: 0.50, 0.39, 0.25 up 0+22:15:56 23:02:19 269 processes: 6 running, 219 sleeping, 1 stopped, 26 zombie, 17 waiting CPU: 11.9% user, 0.0% nice, 5.8% system, 0.8% interrupt, 81.5% idle Mem: 264M Active, 2504M Inact, 232M Wired, 83M Cache, 112M Buf, 169M Free Swap: 8192M Total, 8192M Free 64793 app12 -1 0 148M 106M nfsreq 3 0:08 33.69% php 64789 app16 -7 0 48952K 31660K bo_wwa 0 0:02 4.98% php 64784 app16 -7 0 45880K 29648K bo_wwa 0 0:02 4.88% php 58920 root 8 - 0K 8K - 1 0:08 0.20% nfsiod 0 64867 root 8 - 0K 8K - 2 0:00 0.10% nfsiod 5 64303 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 3 64297 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 1 64873 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 11 64866 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 4 64871 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 6 64298 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 2 64868 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 7 64869 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 8 64947 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 14 64872 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 10 64874 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 12 64870 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 9 64949 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 16 64950 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 17 64948 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 15 64951 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 18 64946 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 13 64952 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 19 last pid: 64970; load averages: 0.46, 0.38, 0.25 up 0+22:16:02 23:02:25 263 processes: 5 running, 212 sleeping, 1 stopped, 28 zombie, 17 waiting CPU: 8.7% user, 0.0% nice, 3.1% system, 0.3% interrupt, 87.9% idle Mem: 160M Active, 2502M Inact, 232M Wired, 83M Cache, 112M Buf, 274M Free Swap: 8192M Total, 8192M Free 64789 app16 -7 0 48952K 31660K bo_wwa 0 0:02 3.27% php 64784 app16 -7 0 45880K 29648K bo_wwa 0 0:02 3.17% php 58920 root 8 - 0K 8K - 1 0:08 0.00% nfsiod 0 64867 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 5 64303 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 3 64297 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 1 64873 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 11 64866 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 4 64871 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 6 64298 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 2 64868 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 7 64869 root 8 - 0K 8K - 0 0:00 0.00% nfsiod 8 64947 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 14 64872 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 10 64874 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 12 64870 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 9 64949 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 16 64950 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 17 64948 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 15 64951 root 8 - 0K 8K - 3 0:00 0.00% nfsiod 18 64946 root 8 - 0K 8K - 2 0:00 0.00% nfsiod 13 64952 root 8 - 0K 8K - 1 0:00 0.00% nfsiod 19 And this two php processes were hanged until 23:05 another process started that write to another file on this nfs mount. -- Mikolaj Golub