Re: 2.6.34rc4 NFS writeback regression (bisected): client oftenfails to delete things it just created

From: Trond Myklebust
Date: Mon Apr 19 2010 - 09:10:43 EST

On Sun, 2010-04-18 at 22:09 +0100, Nix wrote:
> On 18 Apr 2010, Trond Myklebust outgrape:
> > OK. Next question is how these files are being written. If you 'strace'
> > the process, do you see ordinary write() calls being used, or is the
> > file perhaps being written via mmap()?
>
> (strace output is at
> <http://www.esperi.org.uk/~nix/temporary/strace-kdelibs-nfs-EBUSY.log.lzma>
> if you want to look for yourself, but it's about 70Mb unlzmaed, so I can
> understand if you run very fast in the opposite direction...)
>
> The files are all ELF object files:
>
> build/CMakeFiles/CMakeTmp/CMakeFiles/cmTryCompileExec.dir/.nfs000000000031c7510000159b: ELF 64-bit LSB relocatable, x86-64, version 1 (SYSV), stripped
>
> ... which means they're being written by gas, and that writes them out
> with write() (it's easy to spot gas writing things out, because one
> of the first things it writes is an ELF note of the general form
> "GCC: (GNU) 4.4.4" which is very rare elsewhere in an strace dump.)
>
> A complete as run looks like this (I think this is one of the failing
> ones, only of course it's cmake's subsequent recursive unlink()/rmdir()
> that fails: I speculate that the non-failing ones only work because they
> ran early enough that writeback had completed for them...):
>
> 23109 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fafe3703000
> 23109 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fafe3682000
> 23109 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fafe3601000
> 23109 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fafe29f7000
> 23109 stat("CMakeFiles/cmTryCompileExec.dir/src.cxx.o", 0x7fffe1073b40) = -1 ENOENT (No such file or directory)
> 23109 open("CMakeFiles/cmTryCompileExec.dir/src.cxx.o", O_RDWR|O_CREAT|O_TRUNC, 0666) = 3
> 23109 fcntl(3, F_GETFD) = 0
> 23109 fcntl(3, F_SETFD, FD_CLOEXEC) = 0
> 23109 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fafe2976000
> 23109 brk(0x1006000) = 0x1006000
> 23109 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fafe28f5000
> 23109 open("/tmp/ccybr1Xe.s", O_RDONLY) = 4
> 23109 fstat(4, {st_mode=S_IFREG|0600, st_size=356, ...}) = 0
> 23109 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fafe37b3000
> 23109 read(4, "\t.file\t\"src.cxx\"\n\t.text\n.globl m"..., 4096) = 356
> 23109 read(4, "", 28672) = 0
> 23109 read(4, "", 32768) = 0
> 23109 read(4, "", 32768) = 0
> 23109 close(4) = 0
> 23109 munmap(0x7fafe37b3000, 4096) = 0
> 23109 brk(0x102a000) = 0x102a000
> 23109 fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
> 23109 mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fafe27f5000
> 23109 lseek(3, 0, SEEK_SET) = 0
> 23109 read(3, "", 1184) = 0
> 23109 lseek(3, 1184, SEEK_CUR) = 1184
> 23109 write(3, "\0src.cxx\0main\0", 14) = 14
> 23109 lseek(3, 0, SEEK_SET) = 0
> 23109 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576) = 1198
> 23109 lseek(3, -1134, SEEK_CUR) = 64
> 23109 write(3, "UH\211\345\270\0\0\0\0\311\303", 11) = 11
> 23109 lseek(3, 0, SEEK_SET) = 0
> 23109 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576) = 1198
> 23109 lseek(3, -1122, SEEK_CUR) = 76
> 23109 write(3, "\0GCC: (GNU) 4.4.4 20100308 (prer"..., 40) = 40
> 23109 lseek(3, 0, SEEK_SET) = 0
> 23109 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576) = 1198
> 23109 lseek(3, -1078, SEEK_CUR) = 120
> 23109 write(3, "\24\0\0\0\0\0\0\0\1zR\0\1x\20\1\33\f\7\10\220\1\0\0\34\0\0\0\34\0\0\0"..., 56) = 56
> 23109 lseek(3, 0, SEEK_SET) = 0
> 23109 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576) = 1198
> 23109 lseek(3, 2, SEEK_CUR) = 1200
> 23109 write(3, " \0\0\0\0\0\0\0\2\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0", 24) = 24
> 23109 lseek(3, 0, SEEK_SET) = 0
> 23109 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576) = 1224
> 23109 lseek(3, -256, SEEK_CUR) = 968
> 23109 write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\4\0\361\377"..., 216) = 216
> 23109 lseek(3, 0, SEEK_SET) = 0
> 23109 read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1048576) = 1224
> 23109 lseek(3, -1048, SEEK_CUR) = 176
> 23109 write(3, "\0.symtab\0.strtab\0.shstrtab\0.text"..., 84) = 84
> 23109 lseek(3, 0, SEEK_SET) = 0
> 23109 write(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\1\0>\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 64) = 64
> 23109 lseek(3, 0, SEEK_SET) = 0
> 23109 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\1\0>\0\1\0\0\0\0\0\0\0\0\0\0\0"..., 1048576) = 1224
> 23109 brk(0x1021000) = 0x1021000
> 23109 lseek(3, -960, SEEK_CUR) = 264
> 23109 write(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 704) = 704
> 23109 close(3) = 0
> 23109 munmap(0x7fafe27f5000, 1048576) = 0
> 23109 exit_group(0) = ?
>
> However, this can't be the whole picture, because this does *not* fail:
>
> mkdir foo; (cd foo; echo 'int main (void) {}' | c++ -x c++ -c -o foo.o -pipe -); rm -r foo
>
> So it's something more than just as.
>
> I wonder if the failures are caused by ld -r invocations?
>
> ... no, there are none: the relict files must therefore be the result of
> 'as' runs. It's a shame I can't tell what they were called before they
> were deleted...

Hmm... Could you please try reverting commit
2c61be0a9478258f77b66208a0c4b1f5f8161c3c (NFS: Ensure that the WRITE and
COMMIT RPC calls are always uninterruptible). I wonder if that
introduced a new race...

Cheers
Trond
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/