Date: Sat, 23 Oct 2010 16:10:13 GMT From: "Bartosz Nowicki" <b.nowicki@admin.net.pl> To: freebsd-fs@FreeBSD.org Subject: Re: kern/151648: [zfs] disk wait bug Message-ID: <201010231610.o9NGADp7044163@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
The following reply was made to PR kern/151648; it has been noted by GNATS.
From: "Bartosz Nowicki" <b.nowicki@admin.net.pl>
To: "Andriy Gapon" <avg@icyb.net.ua>, 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 <avg@icyb.net.ua> 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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201010231610.o9NGADp7044163>