During normal usage, nginx www server stopped responding. Problem looks like ZFS issue: # ps lU www UID PID PPID CPU PRI NI VSZ RSS MWCHAN STAT TT TIME COMMAND 80 3645 67746 0 54 10 46012 33764 kqread SN ?? 0:00,06 nginx: worker process (nginx) 80 8410 1 0 54 10 46012 34120 zfs DN ?? 0:01,14 nginx: worker process (nginx) 80 15225 67746 0 54 10 46012 33388 zfs DN ?? 0:02,50 nginx: worker process (nginx) 80 15226 67746 0 54 10 46012 33372 zfs DN ?? 0:00,47 nginx: worker process (nginx) 80 18427 1 0 54 10 46012 34160 zfs DN ?? 6:51,11 nginx: worker process (nginx) 80 22955 67746 0 54 10 46012 33416 zfs DN ?? 0:01,07 nginx: worker process (nginx) 80 22956 67746 0 54 10 46012 33400 zfs DN ?? 0:00,68 nginx: worker process (nginx) 80 26904 67746 0 54 10 46012 33776 zfs DN ?? 0:00,53 nginx: worker process (nginx) 80 26905 67746 0 54 10 46012 33424 zfs DN ?? 0:00,96 nginx: worker process (nginx) 80 29355 1 0 54 10 46012 34136 zfs DN ?? 0:38,33 nginx: worker process (nginx) 80 29356 1 0 54 10 46012 34144 zfs DN ?? 0:40,52 nginx: worker process (nginx) 80 43125 67746 0 54 10 46012 33700 zfs DN ?? 0:00,15 nginx: worker process (nginx) 80 94412 67746 0 54 10 46012 33724 zfs DN ?? 0:00,01 nginx: worker process (nginx) # procstat -k 26904 PID TID COMM TDNAME KSTACK 26904 100390 nginx - mi_switch sleepq_wait __lockmgr_args vop_stdlock VOP_LOCK1_APV _vn_lock vget cache_lookup vfs_cache_lookup VOP_LOOKUP_APV lookup namei vn_open_cred kern_openat syscall Xfast_syscall # procstat -k 29355 PID TID COMM TDNAME KSTACK 29355 102233 nginx - mi_switch sleepq_wait __lockmgr_args vop_stdlock VOP_LOCK1_APV _vn_lock vget cache_lookup vfs_cache_lookup VOP_LOOKUP_APV lookup namei vn_open_cred kern_openat syscall Xfast_syscall Processes are also immportal. Kill gives no result. # kill -9 29355 # ps lp 29355 UID PID PPID CPU PRI NI VSZ RSS MWCHAN STAT TT TIME COMMAND 80 29355 1 0 54 10 46012 34136 zfs DN ?? 0:38,33 nginx: worker process (nginx) How-To-Repeat: Start nginx server, wait several hours.
Responsible Changed From-To: freebsd-bugs->freebsd-fs Over to maintainer(s).
Please provide procstat -kk -a output. -- Andriy Gapon
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
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 on 23/10/2010 18:43 Bartosz Nowicki said the following: > 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. [snip] > If it isn't enough I will send full output. I believe that the threads you showed so far are "secondary victims". I think that there should be a primary victim that got stuck while holding some locks and now other threads get stuck on those locks. Could you please check in procstat -kk -a if there are any threads in zio_wait call. Also, you can send the full output to me privately. - -- Andriy Gapon -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.16 (FreeBSD) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ iQEcBAEBAgAGBQJMw+qLAAoJEHSlLSemUf4vbmcH+gIQuRqqs/UQBmiYaIFQFMk0 BsmPxPxr0N8gI7s7m2wlumYxnLv8Yvi8+0h0+GwHvdpHzz8xGe5W9/FO3ONt9dc/ jCPzbGd9kMypHASTDKgsGowIg3q07TICjKkKquJ3eIxS4BItHMRYmjQLceYISXZ6 qkCzUIqyUWCkSa6Ja+0/8LbJvxAce+Fp5Msc/A8Fjls85QM81sSWqFWEGluYCbFN /SkGSIWJrOWEgLxiyMNyrlMgVHj3ASfaUwb9eN7VCcGQjVZwYSJ15gnHnjjSRpJ6 Osk69wk3Wowddm+vaacrijWrHCnN/+fJ83d3fVCeUvlQ/dADhfiM8wEm6AtarY8= =H+hR -----END PGP SIGNATURE-----
on 24/10/2010 23:10 Bartosz Nowicki said the following: > Dnia 24-10-2010 o 10:12:59 Andriy Gapon <avg@freebsd.org> napisaÅ(a): > >> I believe that the threads you showed so far are "secondary victims". >> I think that there should be a primary victim that got stuck while holding some >> locks and now other threads get stuck on those locks. >> >> Could you please check in procstat -kk -a if there are any threads in zio_wait >> call. Also, you can send the full output to me privately. > > Hi Andriy, > There are no threads in zio_wait state. Full output from procstat attached. Please try upgrading to a more recent version of stable/8, particularly you want revision r213924 from 2010-10-16. Please let us know if that helps. Thank you! -- Andriy Gapon
For bugs matching the following criteria: Status: In Progress Changed: (is less than) 2014-06-01 Reset to default assignee and clear in-progress tags. Mail being skipped