Hello all,
On moving an application that uses file locking from NFSv3 to NFSV4, we found that file lock/unlock times can vary wildly when lock contention is present. Our application has multiple files that have to be locked in the remote filesystem. When multiple instances (as few as 2) of the application components are running and sharing these files we are seeing lock delays in seconds as opposed to milli/microseconds.
We can reproduce this in multiple Linux versions (At least SuSE 11, SuSE 12, Ubuntu 14.04, Red Hat 7.x), and multiple NFS servers (Linux, Solaris, NetApp) and the issue only occurs on NFSv4 mounts. Mounting the exact same filesystem via NFSv3 eliminates the issue. We're reasonably certain that this is not a client configuration issue as additional customers are coming out of the woodwork reporting the problem. We're also reasonably certain that this is not a server issue since it's happening across multiple server platforms.
To reproduce this outside of our application, a coworker wrote a simple lock test program (attached). When one instance of this program is run on an affected host, the lock times are < 1000us. If you then start a second instance of the application, the lock wait times have reached as long as 3 MINUTES. Unlocking doesn't take anywhere near as long, where the maximum observed unlock time being about 23 ms.
Process we used to prove this:
1) Compiled the attached source.
2) Mounted a remote filesystem via NFSv4 (example: /mnt/nfsv4)
3) Created a temp file with 777 permissions. (/mnt/nfsv4/foo)
4) Ran one instance of the tool, redirecting the output to /tmp:
./lock1 /mnt/nfsv4/foo >> /tmp/zz1 &
5) Checked lock times after 20 seconds:
sort -rn -k3 < /tmp/zz1 | more
6) Started a second instance of the tool
./lock1 /mnt/nfsv4/foo >> /tmp/zz2 &
7) Check the lock times again, using both files:
sort -rn -k3 < /tmp/zz1 | more
sort -rn -k3 < /tmp/zz2 | more
What we saw was lock calls moving from the < 1000 us range to (as my coworker put it) "integral numbers of seconds." Not every lock stalls for integral numbers of seconds, but enough of them do to stall our application. Even the small percentage of > 1 second lock/unlock calls causes problems as we do a lot of file locking.
Any/all diagnostic assistance would be greatly appreciated.
::DISCLAIMER::
----------------------------------------------------------------------------------------------------------------------------------------------------
The contents of this e-mail and any attachment(s) are confidential and intended for the named recipient(s) only.
E-mail transmission is not guaranteed to be secure or error-free as information could be intercepted, corrupted,
lost, destroyed, arrive late or incomplete, or may contain viruses in transmission. The e mail and its contents
(with or without referred errors) shall therefore not attach any liability on the originator or HCL or its affiliates.
Views or opinions, if any, presented in this email are solely those of the author and may not necessarily reflect the
views or opinions of HCL or its affiliates. Any form of reproduction, dissemination, copying, disclosure, modification,
distribution and / or publication of this message without the prior written consent of authorized representative of
HCL is strictly prohibited. If you have received this email in error please delete it and notify the sender immediately.
Before opening any email and/or attachments, please check them for viruses and other defects.
----------------------------------------------------------------------------------------------------------------------------------------------------
#include <stdio.h>
#include <fcntl.h>
#include <unistd.h>
#include <sys/types.h>
#include <sys/time.h>
#define MAXBUF 4096
main(argc, argv)
int argc;
char *argv[];
{
int i;
int fd;
pid_t pid;
int sleep_time;
int time_taken=0;
char buffer[MAXBUF];
struct timeval t1, t2;
setbuf(stdout, NULL);
/* Populate new block */
for(i=0; i<MAXBUF; i++)
buffer[i]='c';
/* a single arg - the filename*/
if (argc != 2){
fprintf(stderr, "usage: %s <file>\n", argv[0]);
_exit(2);
}
/* Check arg is a file can open r/w */
if ((fd=open(argv[1], O_RDWR, 0777)) <0) {
fprintf(stderr, "could not create/open %s \n", argv[1]);
_exit(1);
}
/* Loop forever */
while(1){
/* Reset file pointer to start of file */
if (lseek(fd, 0, SEEK_SET) < 0) {
fprintf(stderr, "could not seek to beginning of %s\n", argv[1]);
_exit(1);
}
/* Lock entire file for exclusive access and time how long it takes to get lock*/
gettimeofday(&t1, NULL);
if (lockf(fd, F_LOCK, 0) < 0) {
fprintf(stderr, "could not lock whole file %s\n", argv[1]);
_exit(1);
}
gettimeofday(&t2, NULL);
time_taken=(t2.tv_sec - t1.tv_sec)*1000000 + (t2.tv_usec - t1.tv_usec);
printf("lockf() took %d us\n", time_taken);
/* Unlock file and time how long that takes*/
gettimeofday(&t1, NULL);
if (lockf(fd, F_ULOCK, 0) < 0) {
fprintf(stderr, "could not unlock file %s\n", argv[1]);
_exit(1);
}
gettimeofday(&t2, NULL);
time_taken=(t2.tv_sec - t1.tv_sec)*1000000 + (t2.tv_usec - t1.tv_usec);
printf("unlock() took %d us\n", time_taken);
}
_exit(0);
}
