From mboxrd@z Thu Jan 1 00:00:00 1970 From: Idan Kedar Subject: Re: NFS: What is this delay for? Date: Sun, 26 Aug 2012 17:56:30 +0300 Message-ID: References: <201208242319.DGI64563.OtLMOFSFQJHFOV@I-love.SAKURA.ne.jp> Mime-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Cc: linux-fsdevel@vger.kernel.org To: Tetsuo Handa Return-path: Received: from mail-pb0-f46.google.com ([209.85.160.46]:39096 "EHLO mail-pb0-f46.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753443Ab2HZO5L (ORCPT ); Sun, 26 Aug 2012 10:57:11 -0400 Received: by pbbrr13 with SMTP id rr13so6085857pbb.19 for ; Sun, 26 Aug 2012 07:57:10 -0700 (PDT) In-Reply-To: <201208242319.DGI64563.OtLMOFSFQJHFOV@I-love.SAKURA.ne.jp> Sender: linux-fsdevel-owner@vger.kernel.org List-ID: On Fri, Aug 24, 2012 at 5:19 PM, Tetsuo Handa wrote: > Hello. > > I noticed a strange delay when I was running a test program for > http://serverfault.com/questions/235059/vfs-file-max-limit-1231582-reached . > > ---------- test program start ---------- > #include > #include > #include > #include > #include > #include > > int main(int argc, char *argv[]) { > while (1) { > struct flock lock = { }; > int fd = open("/mnt/file", O_CREAT | O_RDWR, 0600); > lock.l_type = F_WRLCK; > lock.l_whence = SEEK_SET; > if (fcntl(fd, F_SETLK, &lock)) { > int err = errno; > fprintf(stderr, "Error %d\n", err); > return 1; > } > close(fd); > fprintf(stderr, "."); > } > } > ---------- test program end ---------- > > When above program is executed after "service nfs start", above program sleeps > for about 90-100 seconds at the first fcntl() attempt. But after once the first > '.' is printed, above program never sleeps even after above program was > re-executed. > > # cat /etc/exports > /mountdir *(rw,all_squash,sync,fsid=0) > # service nfs start > # mount -t nfs 127.0.0.1:/mountdir /mnt/ > # time ./a.out > > sysrq on 3.6.0-rc2-00400-g23dcfa6 kernel shows: > > [ 728.514014] a.out S 00000000 5656 4400 3765 0x00000080 > [ 728.514014] d9a0dd7c 00000046 d9a0dcf0 00000000 00000001 dcf0aec8 00000023 00000000 > [ 728.514014] 00000000 dcf0aa60 c17d2220 c17d2220 9fac0f21 000000a8 c17d2220 c17d2220 > [ 728.514014] 9fa96cf7 000000a8 dcf0aa60 000000a8 9fac0995 dcf0aa60 00000000 00000000 > [ 728.514014] Call Trace: > [ 728.514014] [] ? _raw_spin_unlock_irqrestore+0x35/0x60 > [ 728.514014] [] schedule+0x1e/0x50 > [ 728.514014] [] schedule_timeout+0xea/0x170 > [ 728.514014] [] ? lock_timer_base+0x50/0x50 > [ 728.514014] [] nlmclnt_call+0x97/0x1f0 > [ 728.514014] [] ? wake_up_bit+0x30/0x30 > [ 728.514014] [] nlmclnt_proc+0x22e/0x6f0 > [ 728.514014] [] ? local_clock+0x4e/0x60 > [ 728.514014] [] nfs3_proc_lock+0x1a/0x20 > [ 728.514014] [] do_setlk+0xc9/0xf0 > [ 728.514014] [] nfs_lock+0x98/0x170 > [ 728.514014] [] ? nfs_flock+0x90/0x90 > [ 728.514014] [] vfs_lock_file+0x21/0x50 > [ 728.514014] [] do_lock_file_wait+0x4a/0xd0 > [ 728.514014] [] ? might_fault+0x46/0xa0 > [ 728.514014] [] ? _copy_from_user+0x34/0x80 > [ 728.514014] [] fcntl_setlk+0xce/0x2c0 > [ 728.514014] [] ? trace_hardirqs_on+0xb/0x10 > [ 728.514014] [] do_fcntl+0x1e2/0x5f0 > [ 728.514014] [] sys_fcntl64+0x83/0xd0 > [ 728.514014] [] sysenter_do_call+0x12/0x32 > > Same result for CentOS 6.3's 2.6.32-279.5.1.el6.i686 kernel: > > a.out S 00000286 0 1290 1160 0x00000080 > df4d1aa0 00000086 e0d20aac 00000286 00000007 df57c24c dcd94544 0000ad6f > 00000000 df8393c0 0000001e d1daf53c 0000001e c0b25680 c0b25680 df4d1d48 > c0b25680 c0b21024 c0b25680 df4d1d48 de01e000 00000246 e0d25b24 e0d3dd88 > Call Trace: > [] ? xs_sendpages+0x1cc/0x240 [sunrpc] > [] ? rpc_wake_up_next+0xc4/0x180 [sunrpc] > [] ? __wake_up+0x42/0x60 > [] ? rpc_release_client+0x7b/0x90 [sunrpc] > [] ? lock_timer_base+0x27/0x50 > [] ? schedule_timeout+0x12c/0x250 > [] ? mempool_free+0x81/0x90 > [] ? process_timeout+0x0/0x10 > [] ? nlmclnt_call+0xd6/0x290 [lockd] > [] ? autoremove_wake_function+0x0/0x40 > [] ? nlmclnt_proc+0x219/0x760 [lockd] > [] ? wake_up_bit+0x13/0x30 > [] ? do_setlk+0xbe/0xe0 [nfs] > [] ? nfs_lock+0xb3/0x1b0 [nfs] > [] ? do_filp_open+0x635/0xb00 > [] ? cache_alloc_refill+0x172/0x510 > [] ? nfs_lock+0x0/0x1b0 [nfs] > [] ? vfs_lock_file+0x22/0x50 > [] ? do_lock_file_wait+0x4b/0xd0 > [] ? fcntl_setlk+0xff/0x1e0 > [] ? do_fcntl+0x92/0x440 > [] ? audit_syscall_entry+0x21c/0x240 > [] ? sys_fcntl64+0x5a/0xd0 > [] ? sysenter_do_call+0x12/0x28 > > I wonder what this sleeping period is for. > -- > To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html After the NFS server restarts it has a grace period of 90 seconds, for recovery purposes. You can read about it online. You can also look it up on the NFS 4.1 RFC 5661: http://tools.ietf.org/rfcmarkup?doc=5661 -- idank