From owner-freebsd-fs@FreeBSD.ORG Sat Oct 23 16:10:13 2010 Return-Path: Delivered-To: freebsd-fs@hub.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 98F261065760 for ; Sat, 23 Oct 2010 16:10:13 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [IPv6:2001:4f8:fff6::28]) by mx1.freebsd.org (Postfix) with ESMTP id 6C69D8FC16 for ; Sat, 23 Oct 2010 16:10:13 +0000 (UTC) Received: from freefall.freebsd.org (localhost [127.0.0.1]) by freefall.freebsd.org (8.14.4/8.14.4) with ESMTP id o9NGADLx044164 for ; Sat, 23 Oct 2010 16:10:13 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.14.4/8.14.4/Submit) id o9NGADp7044163; Sat, 23 Oct 2010 16:10:13 GMT (envelope-from gnats) Date: Sat, 23 Oct 2010 16:10:13 GMT Message-Id: <201010231610.o9NGADp7044163@freefall.freebsd.org> To: freebsd-fs@FreeBSD.org From: "Bartosz Nowicki" Cc: Subject: Re: kern/151648: [zfs] disk wait bug X-BeenThere: freebsd-fs@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list Reply-To: Bartosz Nowicki List-Id: Filesystems List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 23 Oct 2010 16:10:13 -0000 The following reply was made to PR kern/151648; it has been noted by GNATS. From: "Bartosz Nowicki" To: "Andriy Gapon" , bug-followup@freebsd.org Cc: Subject: Re: kern/151648: [zfs] disk wait bug Date: Sat, 23 Oct 2010 17:43:36 +0200 Dnia 23-10-2010 o 10:58:59 Andriy Gapon napisał(a): > Please provide procstat -kk -a output. I would rather not reveal all processes (production OS, many user accounts), but discovered that it's not only when using nginx. Problem also appears when trying to access /usr/home directory: # truss -o ls.truss -f ls /usr/home 95580: __sysctl(0x7fffffffdde0,0x2,0x7fffffffddfc,0x7fffffffddf0,0x0,0x0) = 0 (0x0) 95580: mmap(0x0,656,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 34365190144 (0x800533000) 95580: munmap(0x800533000,656) = 0 (0x0) 95580: __sysctl(0x7fffffffde50,0x2,0x80063d6c8,0x7fffffffde48,0x0,0x0) = 0 (0x0) 95580: mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34365190144 (0x800533000) 95580: issetugid(0x800534015,0x80052eb04,0x800649ef0,0x800649ec0,0x5511,0x0) = 0 (0x0) 95580: open("/etc/libmap.conf",O_RDONLY,0666) ERR#2 'No such file or directory' 95580: open("/var/run/ld-elf.so.hints",O_RDONLY,057) = 3 (0x3) 95580: read(3,"Ehnt\^A\0\0\0\M^@\0\0\0\M^S\0\0"...,128) = 128 (0x80) 95580: lseek(3,0x80,SEEK_SET) = 128 (0x80) 95580: read(3,"/lib:/usr/lib:/usr/lib/compat:/u"...,147) = 147 (0x93) 95580: close(3) = 0 (0x0) 95580: access("/lib/libutil.so.8",0) = 0 (0x0) 95580: open("/lib/libutil.so.8",O_RDONLY,030752640) = 3 (0x3) 95580: fstat(3,{ mode=-r--r--r-- ,inode=4120,size=62688,blksize=62976 }) = 0 (0x0) 95580: pread(0x3,0x80063c580,0x1000,0x0,0x101010101010101,0x8080808080808080) = 4096 (0x1000) 95580: mmap(0x0,1110016,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34366332928 (0x80064a000) 95580: mmap(0x80064a000,53248,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE,3,0x0) = 34366332928 (0x80064a000) 95580: mmap(0x800756000,12288,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED,3,0xc000) = 34367430656 (0x800756000) 95580: close(3) = 0 (0x0) 95580: access("/lib/libncurses.so.8",0) = 0 (0x0) 95580: open("/lib/libncurses.so.8",O_RDONLY,030752640) = 3 (0x3) 95580: fstat(3,{ mode=-r--r--r-- ,inode=4114,size=313128,blksize=131072 }) = 0 (0x0) 95580: pread(0x3,0x80063c580,0x1000,0x0,0x101010101010101,0x8080808080808080) = 4096 (0x1000) 95580: mmap(0x0,1359872,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34367442944 (0x800759000) 95580: mmap(0x800759000,270336,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE,3,0x0) = 34367442944 (0x800759000) 95580: mmap(0x80089b000,36864,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED,3,0x42000) = 34368761856 (0x80089b000) 95580: mprotect(0x8008a4000,4096,PROT_READ|PROT_WRITE) = 0 (0x0) 95580: close(3) = 0 (0x0) 95580: access("/lib/libc.so.7",0) = 0 (0x0) 95580: open("/lib/libc.so.7",O_RDONLY,030752640) = 3 (0x3) 95580: fstat(3,{ mode=-r--r--r-- ,inode=4104,size=1254032,blksize=131072 }) = 0 (0x0) 95580: pread(0x3,0x80063c580,0x1000,0x0,0x101010101010101,0x8080808080808080) = 4096 (0x1000) 95580: mmap(0x0,2330624,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34368802816 (0x8008a5000) 95580: mmap(0x8008a5000,1036288,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE,3,0x0) = 34368802816 (0x8008a5000) 95580: mmap(0x800aa2000,131072,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED,3,0xfd000) = 34370887680 (0x800aa2000) 95580: mprotect(0x800ac2000,114688,PROT_READ|PROT_WRITE) = 0 (0x0) 95580: close(3) = 0 (0x0) 95580: sysarch(0x81,0x7fffffffded0,0x800538188,0x0,0xffffffffffa8c550,0x8008c0e78) = 0 (0x0) 95580: mmap(0x0,1408,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 34365222912 (0x80053b000) 95580: munmap(0x80053b000,1408) = 0 (0x0) 95580: mmap(0x0,4240,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 34365222912 (0x80053b000) 95580: munmap(0x80053b000,4240) = 0 (0x0) 95580: mmap(0x0,10096,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 34365222912 (0x80053b000) 95580: munmap(0x80053b000,10096) = 0 (0x0) 95580: mmap(0x0,43696,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 34365222912 (0x80053b000) 95580: munmap(0x80053b000,43696) = 0 (0x0) 95580: sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0) 95580: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0) 95580: __sysctl(0x7fffffffde60,0x2,0x506b00,0x7fffffffde58,0x0,0x0) = 0 (0x0) 95580: sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0) 95580: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0) 95580: sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0) 95580: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0) 95580: sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0) 95580: sigprocmask(SIG_SETMASK,0x0,0x0) = 0 (0x0) 95580: open("/usr/share/locale/pl_PL.ISO8859-2/LC_COLLATE",O_RDONLY,0666) = 3 (0x3) 95580: fstat(3,{ mode=-r--r--r-- ,inode=73575,size=4642,blksize=5120 }) = 0 (0x0) 95580: __sysctl(0x7fffffffd4d0,0x2,0x800ac85c8,0x7fffffffd4c8,0x0,0x0) = 0 (0x0) 95580: __sysctl(0x7fffffffd400,0x2,0x7fffffffd390,0x7fffffffd3f8,0x800994c60,0xc) = 0 (0x0) 95580: __sysctl(0x7fffffffd390,0x2,0x800ac87d0,0x7fffffffd450,0x0,0x0) = 0 (0x0) 95580: readlink("/etc/malloc.conf",0x7fffffffd4f0,1024) ERR#2 'No such file or directory' 95580: issetugid(0x800993919,0x7fffffffd4f0,0xffffffffffffffff,0x0,0x2,0x0) = 0 (0x0) 95580: break(0x600000) = 0 (0x0) 95580: __sysctl(0x7fffffffd780,0x2,0x7fffffffd79c,0x7fffffffd790,0x0,0x0) = 0 (0x0) 95580: mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34371133440 (0x800ade000) 95580: mmap(0x800cde000,1187840,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34373230592 (0x800cde000) 95580: munmap(0x800ade000,1187840) = 0 (0x0) 95580: read(3,"1.2\n\0\0\0\0\0\0\0\0\0\^A\0\0\0"...,5120) = 4642 (0x1222) 95580: close(3) = 0 (0x0) 95580: open("/usr/share/locale/pl_PL.ISO8859-2/LC_CTYPE",O_RDONLY,0666) = 3 (0x3) 95580: fstat(3,{ mode=-r--r--r-- ,inode=75239,size=3168,blksize=4096 }) = 0 (0x0) 95580: fstat(3,{ mode=-r--r--r-- ,inode=75239,size=3168,blksize=4096 }) = 0 (0x0) 95580: lseek(3,0x0,SEEK_CUR) = 0 (0x0) 95580: lseek(3,0x0,SEEK_SET) = 0 (0x0) 95580: read(3,"RuneMag1NONE\0\0\0\0\0\0\0\0\0\0"...,4096) = 3168 (0xc60) 95580: close(3) = 0 (0x0) 95580: open("/usr/share/locale/pl_PL.ISO8859-2/LC_MONETARY",O_RDONLY,013720646000) = 3 (0x3) 95580: fstat(3,{ mode=-r--r--r-- ,inode=75444,size=35,blksize=4096 }) = 0 (0x0) 95580: read(3,"PLN \nz\M-3\n,\n \n3;3\n\n-\n2\n"...,35) = 35 (0x23) 95580: close(3) = 0 (0x0) 95580: open("/usr/share/locale/pl_PL.ISO8859-2/LC_NUMERIC",O_RDONLY,00) = 3 (0x3) 95580: fstat(3,{ mode=-r--r--r-- ,inode=75762,size=8,blksize=4096 }) = 0 (0x0) 95580: read(3,",\n \n3;3\n",8) = 8 (0x8) 95580: close(3) = 0 (0x0) 95580: open("/usr/share/locale/pl_PL.ISO8859-2/LC_MESSAGES",O_RDONLY,036764463000) = 3 (0x3) 95580: fstat(3,{ mode=-r--r--r-- ,inode=75608,size=26,blksize=4096 }) = 0 (0x0) 95580: read(3,"^[tTyY].*\n^[nN].*\ntak\nnie\n",26) = 26 (0x1a) 95580: close(3) = 0 (0x0) 95580: ioctl(1,TIOCGETA,0xffffdf10) = 0 (0x0) 95580: ioctl(1,TIOCGWINSZ,0xffffdf70) = 0 (0x0) 95580: getuid() = 0 (0x0) 95580: stat("/usr/home",{ mode=drwxr-xr-x ,inode=3,size=269,blksize=17408 }) = 0 (0x0) 95580: open(".",O_RDONLY,00) = 3 (0x3) 95580: fchdir(0x3,0x19,0x0,0x2,0x0,0x0) = 0 (0x0) 95580: stat("/usr/home",{ mode=drwxr-xr-x ,inode=3,size=269,blksize=17408 }) # mount mydevil on / (zfs, local) devfs on /dev (devfs, local, multilabel) mydevil/tmp on /tmp (zfs, local, nosuid) mydevil/usr on /usr (zfs, local) mydevil/usr/home on /usr/home (zfs, local) mydevil/usr/ports on /usr/ports (zfs, local, nosuid) mydevil/usr/ports/distfiles on /usr/ports/distfiles (zfs, local, noexec, nosuid) mydevil/usr/ports/packages on /usr/ports/packages (zfs, local, noexec, nosuid) mydevil/usr/src on /usr/src (zfs, local, noexec, nosuid) mydevil/var on /var (zfs, local) mydevil/var/crash on /var/crash (zfs, local, noexec, nosuid) mydevil/var/db on /var/db (zfs, local, noexec, nosuid) mydevil/var/db/pkg on /var/db/pkg (zfs, local, nosuid) mydevil/var/empty on /var/empty (zfs, local, noexec, nosuid, read-only) mydevil/var/mail on /var/mail (zfs, local, noexec, nosuid) mydevil/var/run on /var/run (zfs, local, noexec, nosuid) mydevil/var/tmp on /var/tmp (zfs, local, nosuid) devfs on /var/named/dev (devfs, local, multilabel) mydevil/var/log on /var/log (zfs, local, noexec, nosuid) truss and ls: # ps lp 95579 95580 UID PID PPID CPU PRI NI VSZ RSS MWCHAN STAT TT TIME COMMAND 0 95579 95562 0 55 10 5784 1236 wait IN+ 117 0:00,01 truss -o ls.truss -f ls /usr/home 0 95580 95579 0 55 10 8200 1432 zfs DNX 117 0:00,00 ls /usr/home # procstat -kk 95579 PID TID COMM TDNAME KSTACK 95579 102312 truss - mi_switch+0x176 sleepq_catch_signals+0x309 sleepq_wait_sig+0xc _sleep+0x25d kern_wait+0x6ef wait4+0x33 syscall+0x1cd Xfast_syscall+0xe2 # procstat -kk 95580 PID TID COMM TDNAME KSTACK 95580 101995 ls - mi_switch+0x176 sleepq_wait+0x3b __lockmgr_args+0x642 vop_stdlock+0x39 VOP_LOCK1_APV+0x46 _vn_lock+0x44 zfs_root+0x7c lookup+0x996 namei+0x518 vn_open_cred+0x390 kern_openat+0x165 syscall+0x1cd Xfast_syscall+0xe2 If it isn't enough I will send full output. -- mydevil.net - niebiańskie konta shell