* nfsd blocked @ 2021-12-02 2:56 Carl Karsten 2021-12-02 7:06 ` Carl Karsten 2021-12-02 7:38 ` Carl Karsten 0 siblings, 2 replies; 4+ messages in thread From: Carl Karsten @ 2021-12-02 2:56 UTC (permalink / raw) To: overlayfs there is overlayfs in the middle of the stack dump, so I think this is the place to post. happy to post it somewhere else if directed. currently very reproducible - 3 times in a row, rebooting both clent and server between. tt may be related to me setting nfsvers=3. I plan on testing this guess, but it may be a while. hours or maybe a day or 2. I tried to pin down the file operation client side, but that hasn't happened yet either. client and server Details: server: raspberry pi v3, pi@rpi-cb-1f-f7:~$ uname -a Linux rpi-cb-1f-f7 5.10.63-v7+ #1488 SMP Thu Nov 18 16:14:44 GMT 2021 armv7l GNU/Linux pi@rpi-cb-1f-f7:~$ cat /etc/exports /srv/nfs/rpi/bullseye/root/merged *(rw,sync,no_subtree_check,no_root_squash,fsid=2) pi@rpi-cb-1f-f7:~$ findmnt /srv/nfs/rpi/bullseye/root/merged | cat TARGET SOURCE FSTYPE OPTIONS /srv/nfs/rpi/bullseye/root/merged overlay overlay rw,relatime,lowerdir=/srv/nfs/rpi/bullseye/root/setup:/srv/nfs/rpi/bullseye/root/base,upperdir=/srv/nfs/rpi/bullseye/root/updates,workdir=/srv/nfs/rpi/bullseye/root/work,index=on,nfs_export=on pi@rpi-cb-1f-f7:~$ findmnt / TARGET SOURCE FSTYPE OPTIONS / /dev/mmcblk0p2 ext4 rw,noatime client: also a pi: pi@raspberrypi:~ $ uname -a Linux raspberrypi 5.10.63-v8+ #1488 SMP PREEMPT Thu Nov 18 16:16:16 GMT 2021 aarch64 GNU/Linux root@raspberrypi:~# cat /etc/fstab # proc /proc proc defaults 0 0 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged / nfs defaults,auto,rw,nfsvers=3 0 0 root@raspberrypi:~# findmnt /|cat / 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged nfs rw,relatime,vers=3,rsize=4096,wsize=4096,namlen=255,hard,nolock,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.21.0.1,mountvers=3,mountproto=tcp,local_lock=all,addr=10.21.0.1 on the client, I run apt autoremove --assume-yes [ 1103.834869] INFO: task nfsd:1029 blocked for more than 122 seconds. [ 1103.834889] Tainted: G C 5.10.63-v7+ #1488 [ 1103.834901] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 1103.834915] task:nfsd state:D stack: 0 pid: 1029 ppid: 2 flags:0x00000000 [ 1103.834945] Backtrace: [ 1103.834992] [<809f9df0>] (__schedule) from [<809fa7c8>] (schedule+0x68/0xe4) [ 1103.835015] r10:00000000 r9:86f67d4c r8:8fc134a0 r7:00000002 r6:00000001 r5:86dc4d80 [ 1103.835029] r4:ffffe000 [ 1103.835056] [<809fa760>] (schedule) from [<8017bcac>] (rwsem_down_write_slowpath+0x318/0x518) [ 1103.835072] r5:ffffe000 r4:8fc13490 [ 1103.835094] [<8017b994>] (rwsem_down_write_slowpath) from [<809fd700>] (down_write+0x6c/0x70) [ 1103.835116] r10:7f0f2df4 r9:00000000 r8:8c696bb0 r7:82ba73d0 r6:85d00600 r5:8fc13490 [ 1103.835129] r4:8fc13490 [ 1103.835195] [<809fd694>] (down_write) from [<7f6676b8>] (ovl_dir_release+0x34/0x70 [overlay]) [ 1103.835211] r5:8fc13490 r4:96d1eb80 [ 1103.835267] [<7f667684>] (ovl_dir_release [overlay]) from [<803359f0>] (__fput+0x90/0x25c) [ 1103.835286] r7:82ba73d0 r6:000a841d r5:8fc13408 r4:85d00600 [ 1103.835307] [<80335960>] (__fput) from [<80335c24>] (delayed_fput+0x4c/0x58) [ 1103.835328] r9:8fc13408 r8:00000122 r7:00000100 r6:80f05008 r5:86f67e34 r4:85d00180 [ 1103.835348] [<80335bd8>] (delayed_fput) from [<80335c4c>] (flush_delayed_fput+0x1c/0x20) [ 1103.835363] r5:86f67e34 r4:00000001 [ 1103.835570] [<80335c30>] (flush_delayed_fput) from [<7f0c7ec4>] (nfsd_file_close_inode_sync+0x180/0x188 [nfsd]) [ 1103.835916] [<7f0c7d44>] (nfsd_file_close_inode_sync [nfsd]) from [<7f0c065c>] (nfsd_unlink+0x230/0x270 [nfsd]) [ 1103.835938] r8:ffffc000 r7:92419068 r6:86f44000 r5:937dd3b8 r4:86fa0008 [ 1103.836285] [<7f0c042c>] (nfsd_unlink [nfsd]) from [<7f0ca3f4>] (nfsd3_proc_remove+0x80/0xd8 [nfsd]) [ 1103.836308] r9:00000018 r8:96dd5000 r7:86f44000 r6:86fa0008 r5:86fa0000 r4:86f38000 [ 1103.836650] [<7f0ca374>] (nfsd3_proc_remove [nfsd]) from [<7f0b973c>] (nfsd_dispatch+0xc8/0x14c [nfsd]) [ 1103.836669] r7:96dd5014 r6:7f0f2df4 r5:86f45000 r4:86f44000 [ 1103.836856] [<7f0b9674>] (nfsd_dispatch [nfsd]) from [<809ca22c>] (svc_process_common+0x374/0x70c) [ 1103.836878] r9:86f45000 r8:86f45a20 r7:86f44000 r6:80f05008 r5:00000014 r4:86f44184 [ 1103.836901] [<809c9eb8>] (svc_process_common) from [<809ca69c>] (svc_process+0xd8/0xec) [ 1103.836923] r10:856abcfc r9:86f44000 r8:81016540 r7:7f100bc4 r6:816cae00 r5:bab24000 [ 1103.836937] r4:86f44000 [ 1103.837120] [<809ca5c4>] (svc_process) from [<7f0b9100>] (nfsd+0xf4/0x164 [nfsd]) [ 1103.837135] r5:00057e40 r4:86f44000 [ 1103.837321] [<7f0b900c>] (nfsd [nfsd]) from [<80143790>] (kthread+0x170/0x174) [ 1103.837342] r9:86f44000 r8:7f0b900c r7:86f66000 r6:00000000 r5:892b9580 r4:847acbc0 [ 1103.837364] [<80143620>] (kthread) from [<801000ec>] (ret_from_fork+0x14/0x28) [ 1103.837378] Exception stack(0x86f67fb0 to 0x86f67ff8) [ 1103.837396] 7fa0: 00000000 00000000 00000000 00000000 [ 1103.837415] 7fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 1103.837434] 7fe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ 1103.837454] r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80143620 [ 1103.837467] r4:892b9580 -- Carl K ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: nfsd blocked 2021-12-02 2:56 nfsd blocked Carl Karsten @ 2021-12-02 7:06 ` Carl Karsten 2021-12-02 7:38 ` Carl Karsten 1 sibling, 0 replies; 4+ messages in thread From: Carl Karsten @ 2021-12-02 7:06 UTC (permalink / raw) To: overlayfs strace close(15) = 0 write(13, "\nStart-Date: 2021-12-02 06:56:5"..., 132) = 132 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xf72d90a8) = 901 wait4(901, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 901 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=901, si_uid=0, si_status=0, si_utime=2, si_stime=2} --- clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xf72d90a8) = 902 wait4(902, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 902 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=902, si_uid=0, si_status=0, si_utime=2, si_stime=1} --- ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0 openat(AT_FDCWD, "/dev/ptmx", O_RDWR|O_NOCTTY) = 15 statfs("/dev/pts", {f_type=DEVPTS_SUPER_MAGIC, f_bsize=4096, f_blocks=0, f_bfree=0, f_bavail=0, f_files=0, f_ffree=0, f_fsid={val=[0, 0]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_NOSUID|ST_NOEXEC|ST_RELATIME}) = 0 ioctl(15, TIOCSPTLCK, [0]) = 0 ioctl(15, TCGETS, {B38400 opost isig icanon echo ...}) = 0 ioctl(15, TIOCGPTN, [1]) = 0 stat64("/dev/pts/1", {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x1), ...}) = 0 ioctl(15, TCGETS, {B38400 opost isig icanon echo ...}) = 0 ioctl(15, TIOCGPTN, [1]) = 0 stat64("/dev/pts/1", {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x1), ...}) = 0 getuid32() = 0 openat(AT_FDCWD, "/etc/group", O_RDONLY|O_CLOEXEC) = 16 _llseek(16, 0, [0], SEEK_CUR) = 0 fstat64(16, {st_mode=S_IFREG|0644, st_size=762, ...}) = 0 read(16, "root:x:0:\ndaemon:x:1:\nbin:x:2:\ns"..., 4096) = 762 close(16) = 0 ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0 ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0 ioctl(1, TIOCGWINSZ, {ws_row=28, ws_col=110, ws_xpixel=0, ws_ypixel=0}) = 0 ioctl(15, TIOCSWINSZ, {ws_row=28, ws_col=110, ws_xpixel=0, ws_ypixel=0}) = 0 ioctl(15, TCGETS, {B38400 opost isig icanon echo ...}) = 0 ioctl(15, SNDCTL_TMR_START or TCSETS, {B38400 opost isig icanon echo ...}) = 0 ioctl(15, TCGETS, {B38400 opost isig icanon echo ...}) = 0 rt_sigprocmask(SIG_BLOCK, [TTOU], [], 8) = 0 ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0 ioctl(0, SNDCTL_TMR_CONTINUE or TCSETSF, {B38400 -opost isig -icanon -echo ...}) = 0 ioctl(0, TCGETS, {B38400 -opost isig -icanon -echo ...}) = 0 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 openat(AT_FDCWD, "/dev/pts/1", O_RDWR|O_NOCTTY|O_LARGEFILE|O_CLOEXEC) = 16 ioctl(1, TIOCGWINSZ, {ws_row=28, ws_col=110, ws_xpixel=0, ws_ypixel=0}) = 0 write(1, "\n", 1) = 1 write(1, "\0337\33[0;27r\338\33[1A", 15) = 15 ioctl(15, TIOCGWINSZ, {ws_row=28, ws_col=110, ws_xpixel=0, ws_ypixel=0}) = 0 ioctl(15, TIOCSWINSZ, {ws_row=27, ws_col=110, ws_xpixel=0, ws_ypixel=0}) = 0 pipe([17, 18]) = 0 rt_sigaction(SIGQUIT, {sa_handler=SIG_IGN, sa_mask=[QUIT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0xf776cda0}, {sa_handler=SIG_DFL, sa_mask=[QUIT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0xf776cda0}, 8) = 0 rt_sigaction(SIGINT, {sa_handler=0xf7b425fc, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0xf776cda0}, {sa_handler=SIG_DFL, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0xf776cda0}, 8) = 0 rt_sigaction(SIGHUP, {sa_handler=SIG_IGN, sa_mask=[HUP], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0xf776cda0}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xf72d90a8) = 903 close(18) = 0 rt_sigprocmask(SIG_BLOCK, [], [], 8) = 0 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [17], left {tv_sec=0, tv_nsec=28968682}) read(17, "status: libfuse2:armhf: half-ins"..., 1024) = 39 ioctl(1, TIOCGWINSZ, {ws_row=28, ws_col=110, ws_xpixel=0, ws_ypixel=0}) = 0 write(1, "\0337\33[28;0f\33[42m\33[30mProgress: [ 5"..., 45) = 45 write(1, " [##############################"..., 92) = 92 write(1, "\338", 2) = 2 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=30205081}) read(15, "(Reading database ... \r", 1024) = 23 write(1, "(Reading database ... \r", 23) = 23 write(5, "(Reading database ... \r", 23) = 23 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=5882690}) read(15, "(Reading database ... 5%\r", 1024) = 25 write(1, "(Reading database ... 5%\r", 25) = 25 write(5, "(Reading database ... 5%\r", 25) = 25 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=10230422}) read(15, "(Reading database ... 10%\r", 1024) = 26 write(1, "(Reading database ... 10%\r", 26) = 26 write(5, "(Reading database ... 10%\r", 26) = 26 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=45862892}) read(15, "(Reading database ... 15%\r", 1024) = 26 write(1, "(Reading database ... 15%\r", 26) = 26 write(5, "(Reading database ... 15%\r", 26) = 26 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=30138674}) read(15, "(Reading database ... 20%\r", 1024) = 26 write(1, "(Reading database ... 20%\r", 26) = 26 write(5, "(Reading database ... 20%\r", 26) = 26 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=10269380}) read(15, "(Reading database ... 25%\r", 1024) = 26 write(1, "(Reading database ... 25%\r", 26) = 26 write(5, "(Reading database ... 25%\r", 26) = 26 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=5309987}) read(15, "(Reading database ... 30%\r", 1024) = 26 write(1, "(Reading database ... 30%\r", 26) = 26 write(5, "(Reading database ... 30%\r", 26) = 26 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=2216674}) read(15, "(Reading database ... 35%\r", 1024) = 26 write(1, "(Reading database ... 35%\r", 26) = 26 write(5, "(Reading database ... 35%\r", 26) = 26 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=8630745}) read(15, "(Reading database ... 40%\r", 1024) = 26 write(1, "(Reading database ... 40%\r", 26) = 26 write(5, "(Reading database ... 40%\r", 26) = 26 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=12330669}) read(15, "(Reading database ... 45%\r", 1024) = 26 write(1, "(Reading database ... 45%\r", 26) = 26 write(5, "(Reading database ... 45%\r", 26) = 26 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=49975053}) read(15, "(Reading database ... 50%\r(Readi"..., 1024) = 360 write(1, "(Reading database ... 50%\r(Readi"..., 360) = 360 write(5, "(Reading database ... 50%\r(Readi"..., 360) = 360 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [15], left {tv_sec=0, tv_nsec=38900960}) read(15, "Removing libfuse2:armhf (2.9.9-5"..., 1024) = 39 write(1, "Removing libfuse2:armhf (2.9.9-5"..., 39) = 39 write(5, "Removing libfuse2:armhf (2.9.9-5"..., 39) = 39 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [17], left {tv_sec=0, tv_nsec=49974896}) read(17, "processing: remove: libfuse2:arm"..., 1024) = 35 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 1 (in [17], left {tv_sec=0, tv_nsec=42313593}) read(17, "status: libc-bin: triggers-pendi"..., 1024) = 35 wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 pselect6(18, [0 15 17], NULL, NULL, {tv_sec=0, tv_nsec=50000000}, {[], 8}) = 0 (Timeout) wait4(903, 0xff9c6574, WNOHANG, NULL) = 0 On Wed, Dec 1, 2021 at 6:56 PM Carl Karsten <carl@nextdayvideo.com> wrote: > > there is overlayfs in the middle of the stack dump, so I think this is > the place to post. happy to post it somewhere else if directed. > > currently very reproducible - 3 times in a row, rebooting both clent > and server between. > > tt may be related to me setting nfsvers=3. I plan on testing this > guess, but it may be a while. hours or maybe a day or 2. > > I tried to pin down the file operation client side, but that hasn't > happened yet either. > > client and server Details: > > server: raspberry pi v3, > pi@rpi-cb-1f-f7:~$ uname -a > Linux rpi-cb-1f-f7 5.10.63-v7+ #1488 SMP Thu Nov 18 16:14:44 GMT 2021 > armv7l GNU/Linux > > pi@rpi-cb-1f-f7:~$ cat /etc/exports > /srv/nfs/rpi/bullseye/root/merged > *(rw,sync,no_subtree_check,no_root_squash,fsid=2) > > pi@rpi-cb-1f-f7:~$ findmnt /srv/nfs/rpi/bullseye/root/merged | cat > TARGET SOURCE FSTYPE OPTIONS > /srv/nfs/rpi/bullseye/root/merged overlay overlay > rw,relatime,lowerdir=/srv/nfs/rpi/bullseye/root/setup:/srv/nfs/rpi/bullseye/root/base,upperdir=/srv/nfs/rpi/bullseye/root/updates,workdir=/srv/nfs/rpi/bullseye/root/work,index=on,nfs_export=on > > pi@rpi-cb-1f-f7:~$ findmnt / > TARGET SOURCE FSTYPE OPTIONS > / /dev/mmcblk0p2 ext4 rw,noatime > > client: also a pi: > pi@raspberrypi:~ $ uname -a > Linux raspberrypi 5.10.63-v8+ #1488 SMP PREEMPT Thu Nov 18 16:16:16 > GMT 2021 aarch64 GNU/Linux > > root@raspberrypi:~# cat /etc/fstab > # proc /proc proc defaults 0 0 > 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged / nfs defaults,auto,rw,nfsvers=3 0 0 > > root@raspberrypi:~# findmnt /|cat > / 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged nfs > rw,relatime,vers=3,rsize=4096,wsize=4096,namlen=255,hard,nolock,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.21.0.1,mountvers=3,mountproto=tcp,local_lock=all,addr=10.21.0.1 > > on the client, I run > apt autoremove --assume-yes > > > > > [ 1103.834869] INFO: task nfsd:1029 blocked for more than 122 seconds. > [ 1103.834889] Tainted: G C 5.10.63-v7+ #1488 > [ 1103.834901] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 1103.834915] task:nfsd state:D stack: 0 pid: 1029 > ppid: 2 flags:0x00000000 > [ 1103.834945] Backtrace: > [ 1103.834992] [<809f9df0>] (__schedule) from [<809fa7c8>] (schedule+0x68/0xe4) > [ 1103.835015] r10:00000000 r9:86f67d4c r8:8fc134a0 r7:00000002 > r6:00000001 r5:86dc4d80 > [ 1103.835029] r4:ffffe000 > [ 1103.835056] [<809fa760>] (schedule) from [<8017bcac>] > (rwsem_down_write_slowpath+0x318/0x518) > [ 1103.835072] r5:ffffe000 r4:8fc13490 > [ 1103.835094] [<8017b994>] (rwsem_down_write_slowpath) from > [<809fd700>] (down_write+0x6c/0x70) > [ 1103.835116] r10:7f0f2df4 r9:00000000 r8:8c696bb0 r7:82ba73d0 > r6:85d00600 r5:8fc13490 > [ 1103.835129] r4:8fc13490 > [ 1103.835195] [<809fd694>] (down_write) from [<7f6676b8>] > (ovl_dir_release+0x34/0x70 [overlay]) > [ 1103.835211] r5:8fc13490 r4:96d1eb80 > [ 1103.835267] [<7f667684>] (ovl_dir_release [overlay]) from > [<803359f0>] (__fput+0x90/0x25c) > [ 1103.835286] r7:82ba73d0 r6:000a841d r5:8fc13408 r4:85d00600 > [ 1103.835307] [<80335960>] (__fput) from [<80335c24>] (delayed_fput+0x4c/0x58) > [ 1103.835328] r9:8fc13408 r8:00000122 r7:00000100 r6:80f05008 > r5:86f67e34 r4:85d00180 > [ 1103.835348] [<80335bd8>] (delayed_fput) from [<80335c4c>] > (flush_delayed_fput+0x1c/0x20) > [ 1103.835363] r5:86f67e34 r4:00000001 > [ 1103.835570] [<80335c30>] (flush_delayed_fput) from [<7f0c7ec4>] > (nfsd_file_close_inode_sync+0x180/0x188 [nfsd]) > [ 1103.835916] [<7f0c7d44>] (nfsd_file_close_inode_sync [nfsd]) from > [<7f0c065c>] (nfsd_unlink+0x230/0x270 [nfsd]) > [ 1103.835938] r8:ffffc000 r7:92419068 r6:86f44000 r5:937dd3b8 r4:86fa0008 > [ 1103.836285] [<7f0c042c>] (nfsd_unlink [nfsd]) from [<7f0ca3f4>] > (nfsd3_proc_remove+0x80/0xd8 [nfsd]) > [ 1103.836308] r9:00000018 r8:96dd5000 r7:86f44000 r6:86fa0008 > r5:86fa0000 r4:86f38000 > [ 1103.836650] [<7f0ca374>] (nfsd3_proc_remove [nfsd]) from > [<7f0b973c>] (nfsd_dispatch+0xc8/0x14c [nfsd]) > [ 1103.836669] r7:96dd5014 r6:7f0f2df4 r5:86f45000 r4:86f44000 > [ 1103.836856] [<7f0b9674>] (nfsd_dispatch [nfsd]) from [<809ca22c>] > (svc_process_common+0x374/0x70c) > [ 1103.836878] r9:86f45000 r8:86f45a20 r7:86f44000 r6:80f05008 > r5:00000014 r4:86f44184 > [ 1103.836901] [<809c9eb8>] (svc_process_common) from [<809ca69c>] > (svc_process+0xd8/0xec) > [ 1103.836923] r10:856abcfc r9:86f44000 r8:81016540 r7:7f100bc4 > r6:816cae00 r5:bab24000 > [ 1103.836937] r4:86f44000 > [ 1103.837120] [<809ca5c4>] (svc_process) from [<7f0b9100>] > (nfsd+0xf4/0x164 [nfsd]) > [ 1103.837135] r5:00057e40 r4:86f44000 > [ 1103.837321] [<7f0b900c>] (nfsd [nfsd]) from [<80143790>] > (kthread+0x170/0x174) > [ 1103.837342] r9:86f44000 r8:7f0b900c r7:86f66000 r6:00000000 > r5:892b9580 r4:847acbc0 > [ 1103.837364] [<80143620>] (kthread) from [<801000ec>] > (ret_from_fork+0x14/0x28) > [ 1103.837378] Exception stack(0x86f67fb0 to 0x86f67ff8) > [ 1103.837396] 7fa0: 00000000 > 00000000 00000000 00000000 > [ 1103.837415] 7fc0: 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 > [ 1103.837434] 7fe0: 00000000 00000000 00000000 00000000 00000013 00000000 > [ 1103.837454] r10:00000000 r9:00000000 r8:00000000 r7:00000000 > r6:00000000 r5:80143620 > [ 1103.837467] r4:892b9580 > > > -- > Carl K -- Carl K ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: nfsd blocked 2021-12-02 2:56 nfsd blocked Carl Karsten 2021-12-02 7:06 ` Carl Karsten @ 2021-12-02 7:38 ` Carl Karsten 2021-12-03 23:28 ` Carl Karsten 1 sibling, 1 reply; 4+ messages in thread From: Carl Karsten @ 2021-12-02 7:38 UTC (permalink / raw) To: overlayfs vers=4.2 no help after 5 min, client dmesg: [ 328.673438] nfs: server 10.21.0.1 not responding, still trying pi@raspberrypi:~ $ findmnt / TARGET SOURCE FSTYPE OPTIONS / 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged nfs4 rw,relatime,vers=4.2,rsize=4096,wsize=4096,namlen=25 server: [ 612.314809] INFO: task nfsd:1034 blocked for more than 122 seconds. [ 612.314820] Tainted: G C 5.10.63-v7+ #1488 [ 612.314825] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 612.314832] task:nfsd state:D stack: 0 pid: 1034 ppid: 2 flags:0x00000000 [ 612.314847] Backtrace: [ 612.314872] [<809f9df0>] (__schedule) from [<809fa7c8>] (schedule+0x68/0xe4) [ 612.314882] r10:00000000 r9:89353d04 r8:8c393100 r7:00000002 r6:00000001 r5:82996c80 [ 612.314888] r4:ffffe000 [ 612.314902] [<809fa760>] (schedule) from [<8017bcac>] (rwsem_down_write_slowpath+0x318/0x518) [ 612.314909] r5:ffffe000 r4:8c3930f0 [ 612.314919] [<8017b994>] (rwsem_down_write_slowpath) from [<809fd700>] (down_write+0x6c/0x70) [ 612.314929] r10:86f991a0 r9:00000000 r8:8c233ee0 r7:86e64490 r6:93c56c00 r5:8c3930f0 [ 612.314934] r4:8c3930f0 [ 612.314967] [<809fd694>] (down_write) from [<7f5ae6b8>] (ovl_dir_release+0x34/0x70 [overlay]) [ 612.314974] r5:8c3930f0 r4:8eb98ac0 [ 612.314999] [<7f5ae684>] (ovl_dir_release [overlay]) from [<803359f0>] (__fput+0x90/0x25c) [ 612.315007] r7:86e64490 r6:000a841d r5:8c393068 r4:93c56c00 [ 612.315016] [<80335960>] (__fput) from [<80335c24>] (delayed_fput+0x4c/0x58) [ 612.315026] r9:8c393068 r8:00000122 r7:00000100 r6:80f05008 r5:89353dec r4:93c56e40 [ 612.315036] [<80335bd8>] (delayed_fput) from [<80335c4c>] (flush_delayed_fput+0x1c/0x20) [ 612.315042] r5:89353dec r4:00000001 [ 612.315146] [<80335c30>] (flush_delayed_fput) from [<7f0c7ec4>] (nfsd_file_close_inode_sync+0x180/0x188 [nfsd]) [ 612.315295] [<7f0c7d44>] (nfsd_file_close_inode_sync [nfsd]) from [<7f0c065c>] (nfsd_unlink+0x230/0x270 [nfsd]) [ 612.315304] r8:00008000 r7:9346d068 r6:86f42000 r5:93445440 r4:89290038 [ 612.315451] [<7f0c042c>] (nfsd_unlink [nfsd]) from [<7f0d0ccc>] (nfsd4_remove+0x5c/0x114 [nfsd]) [ 612.315461] r9:00000000 r8:86f43a20 r7:86f43000 r6:86f42000 r5:86f991c0 r4:89290038 [ 612.315610] [<7f0d0c70>] (nfsd4_remove [nfsd]) from [<7f0d06f4>] (nfsd4_proc_compound+0x3f4/0x648 [nfsd]) [ 612.315617] r6:86f98000 r5:86f42000 r4:89290000 [ 612.315766] [<7f0d0300>] (nfsd4_proc_compound [nfsd]) from [<7f0b973c>] (nfsd_dispatch+0xc8/0x14c [nfsd]) [ 612.315776] r10:7f0f3890 r9:00000018 r8:8ea15000 r7:8ea15014 r6:7f0f3890 r5:86f43000 [ 612.315782] r4:86f42000 [ 612.315862] [<7f0b9674>] (nfsd_dispatch [nfsd]) from [<809ca22c>] (svc_process_common+0x374/0x70c) [ 612.315871] r9:86f43000 r8:86f43a20 r7:86f42000 r6:80f05008 r5:00000014 r4:86f42184 [ 612.315882] [<809c9eb8>] (svc_process_common) from [<809ca69c>] (svc_process+0xd8/0xec) [ 612.315891] r10:86c85cfc r9:86f42000 r8:81016540 r7:7f100bc4 r6:816aa800 r5:bab24000 [ 612.315897] r4:86f42000 [ 612.315976] [<809ca5c4>] (svc_process) from [<7f0b9100>] (nfsd+0xf4/0x164 [nfsd]) [ 612.315982] r5:00057e40 r4:86f42000 [ 612.316062] [<7f0b900c>] (nfsd [nfsd]) from [<80143790>] (kthread+0x170/0x174) [ 612.316072] r9:86f42000 r8:7f0b900c r7:89352000 r6:00000000 r5:89090200 r4:89256880 [ 612.316082] [<80143620>] (kthread) from [<801000ec>] (ret_from_fork+0x14/0x28) [ 612.316089] Exception stack(0x89353fb0 to 0x89353ff8) [ 612.316097] 3fa0: 00000000 00000000 00000000 00000000 [ 612.316105] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000 [ 612.316113] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000 [ 612.316122] r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80143620 [ 612.316128] r4:89090200 On Wed, Dec 1, 2021 at 6:56 PM Carl Karsten <carl@nextdayvideo.com> wrote: > > there is overlayfs in the middle of the stack dump, so I think this is > the place to post. happy to post it somewhere else if directed. > > currently very reproducible - 3 times in a row, rebooting both clent > and server between. > > tt may be related to me setting nfsvers=3. I plan on testing this > guess, but it may be a while. hours or maybe a day or 2. > > I tried to pin down the file operation client side, but that hasn't > happened yet either. > > client and server Details: > > server: raspberry pi v3, > pi@rpi-cb-1f-f7:~$ uname -a > Linux rpi-cb-1f-f7 5.10.63-v7+ #1488 SMP Thu Nov 18 16:14:44 GMT 2021 > armv7l GNU/Linux > > pi@rpi-cb-1f-f7:~$ cat /etc/exports > /srv/nfs/rpi/bullseye/root/merged > *(rw,sync,no_subtree_check,no_root_squash,fsid=2) > > pi@rpi-cb-1f-f7:~$ findmnt /srv/nfs/rpi/bullseye/root/merged | cat > TARGET SOURCE FSTYPE OPTIONS > /srv/nfs/rpi/bullseye/root/merged overlay overlay > rw,relatime,lowerdir=/srv/nfs/rpi/bullseye/root/setup:/srv/nfs/rpi/bullseye/root/base,upperdir=/srv/nfs/rpi/bullseye/root/updates,workdir=/srv/nfs/rpi/bullseye/root/work,index=on,nfs_export=on > > pi@rpi-cb-1f-f7:~$ findmnt / > TARGET SOURCE FSTYPE OPTIONS > / /dev/mmcblk0p2 ext4 rw,noatime > > client: also a pi: > pi@raspberrypi:~ $ uname -a > Linux raspberrypi 5.10.63-v8+ #1488 SMP PREEMPT Thu Nov 18 16:16:16 > GMT 2021 aarch64 GNU/Linux > > root@raspberrypi:~# cat /etc/fstab > # proc /proc proc defaults 0 0 > 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged / nfs defaults,auto,rw,nfsvers=3 0 0 > > root@raspberrypi:~# findmnt /|cat > / 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged nfs > rw,relatime,vers=3,rsize=4096,wsize=4096,namlen=255,hard,nolock,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.21.0.1,mountvers=3,mountproto=tcp,local_lock=all,addr=10.21.0.1 > > on the client, I run > apt autoremove --assume-yes > > > > > [ 1103.834869] INFO: task nfsd:1029 blocked for more than 122 seconds. > [ 1103.834889] Tainted: G C 5.10.63-v7+ #1488 > [ 1103.834901] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 1103.834915] task:nfsd state:D stack: 0 pid: 1029 > ppid: 2 flags:0x00000000 > [ 1103.834945] Backtrace: > [ 1103.834992] [<809f9df0>] (__schedule) from [<809fa7c8>] (schedule+0x68/0xe4) > [ 1103.835015] r10:00000000 r9:86f67d4c r8:8fc134a0 r7:00000002 > r6:00000001 r5:86dc4d80 > [ 1103.835029] r4:ffffe000 > [ 1103.835056] [<809fa760>] (schedule) from [<8017bcac>] > (rwsem_down_write_slowpath+0x318/0x518) > [ 1103.835072] r5:ffffe000 r4:8fc13490 > [ 1103.835094] [<8017b994>] (rwsem_down_write_slowpath) from > [<809fd700>] (down_write+0x6c/0x70) > [ 1103.835116] r10:7f0f2df4 r9:00000000 r8:8c696bb0 r7:82ba73d0 > r6:85d00600 r5:8fc13490 > [ 1103.835129] r4:8fc13490 > [ 1103.835195] [<809fd694>] (down_write) from [<7f6676b8>] > (ovl_dir_release+0x34/0x70 [overlay]) > [ 1103.835211] r5:8fc13490 r4:96d1eb80 > [ 1103.835267] [<7f667684>] (ovl_dir_release [overlay]) from > [<803359f0>] (__fput+0x90/0x25c) > [ 1103.835286] r7:82ba73d0 r6:000a841d r5:8fc13408 r4:85d00600 > [ 1103.835307] [<80335960>] (__fput) from [<80335c24>] (delayed_fput+0x4c/0x58) > [ 1103.835328] r9:8fc13408 r8:00000122 r7:00000100 r6:80f05008 > r5:86f67e34 r4:85d00180 > [ 1103.835348] [<80335bd8>] (delayed_fput) from [<80335c4c>] > (flush_delayed_fput+0x1c/0x20) > [ 1103.835363] r5:86f67e34 r4:00000001 > [ 1103.835570] [<80335c30>] (flush_delayed_fput) from [<7f0c7ec4>] > (nfsd_file_close_inode_sync+0x180/0x188 [nfsd]) > [ 1103.835916] [<7f0c7d44>] (nfsd_file_close_inode_sync [nfsd]) from > [<7f0c065c>] (nfsd_unlink+0x230/0x270 [nfsd]) > [ 1103.835938] r8:ffffc000 r7:92419068 r6:86f44000 r5:937dd3b8 r4:86fa0008 > [ 1103.836285] [<7f0c042c>] (nfsd_unlink [nfsd]) from [<7f0ca3f4>] > (nfsd3_proc_remove+0x80/0xd8 [nfsd]) > [ 1103.836308] r9:00000018 r8:96dd5000 r7:86f44000 r6:86fa0008 > r5:86fa0000 r4:86f38000 > [ 1103.836650] [<7f0ca374>] (nfsd3_proc_remove [nfsd]) from > [<7f0b973c>] (nfsd_dispatch+0xc8/0x14c [nfsd]) > [ 1103.836669] r7:96dd5014 r6:7f0f2df4 r5:86f45000 r4:86f44000 > [ 1103.836856] [<7f0b9674>] (nfsd_dispatch [nfsd]) from [<809ca22c>] > (svc_process_common+0x374/0x70c) > [ 1103.836878] r9:86f45000 r8:86f45a20 r7:86f44000 r6:80f05008 > r5:00000014 r4:86f44184 > [ 1103.836901] [<809c9eb8>] (svc_process_common) from [<809ca69c>] > (svc_process+0xd8/0xec) > [ 1103.836923] r10:856abcfc r9:86f44000 r8:81016540 r7:7f100bc4 > r6:816cae00 r5:bab24000 > [ 1103.836937] r4:86f44000 > [ 1103.837120] [<809ca5c4>] (svc_process) from [<7f0b9100>] > (nfsd+0xf4/0x164 [nfsd]) > [ 1103.837135] r5:00057e40 r4:86f44000 > [ 1103.837321] [<7f0b900c>] (nfsd [nfsd]) from [<80143790>] > (kthread+0x170/0x174) > [ 1103.837342] r9:86f44000 r8:7f0b900c r7:86f66000 r6:00000000 > r5:892b9580 r4:847acbc0 > [ 1103.837364] [<80143620>] (kthread) from [<801000ec>] > (ret_from_fork+0x14/0x28) > [ 1103.837378] Exception stack(0x86f67fb0 to 0x86f67ff8) > [ 1103.837396] 7fa0: 00000000 > 00000000 00000000 00000000 > [ 1103.837415] 7fc0: 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 > [ 1103.837434] 7fe0: 00000000 00000000 00000000 00000000 00000013 00000000 > [ 1103.837454] r10:00000000 r9:00000000 r8:00000000 r7:00000000 > r6:00000000 r5:80143620 > [ 1103.837467] r4:892b9580 > > > -- > Carl K -- Carl K ^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: nfsd blocked 2021-12-02 7:38 ` Carl Karsten @ 2021-12-03 23:28 ` Carl Karsten 0 siblings, 0 replies; 4+ messages in thread From: Carl Karsten @ 2021-12-03 23:28 UTC (permalink / raw) To: overlayfs using nfs 4 doesn't help. chroot on the server (so no nfs) doesn't get stuck: root@rpi-cb-1f-f7:~# chroot /srv/nfs/rpi/bullseye/root/merged root@rpi-cb-1f-f7:/# ls bin boot dev etc home lib lost+found media mnt opt proc root run sbin srv sys tmp usr var root@rpi-cb-1f-f7:/# dpkg --configure -a Processing triggers for libc-bin (2.31-13+rpt2+rpi1+deb11u2) ... root@rpi-cb-1f-f7:/# apt autoremove --assume-yes Reading package lists... Done Building dependency tree... Done Reading state information... Done The following packages will be REMOVED: libfuse2 0 upgraded, 0 newly installed, 1 to remove and 0 not upgraded. 1 not fully installed or removed. After this operation, 288 kB disk space will be freed. E: Can not write log (Is /dev/pts mounted?) - posix_openpt (2: No such file or directory) (Reading database ... 45003 files and directories currently installed.) Removing libfuse2:armhf (2.9.9-5) ... Processing triggers for libc-bin (2.31-13+rpt2+rpi1+deb11u2) ... On Wed, Dec 1, 2021 at 11:38 PM Carl Karsten <carl@nextdayvideo.com> wrote: > > vers=4.2 no help > > after 5 min, client dmesg: > > [ 328.673438] nfs: server 10.21.0.1 not responding, still trying > pi@raspberrypi:~ $ findmnt / > TARGET SOURCE FSTYPE OPTIONS > / 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged nfs4 > rw,relatime,vers=4.2,rsize=4096,wsize=4096,namlen=25 > > server: > > [ 612.314809] INFO: task nfsd:1034 blocked for more than 122 seconds. > [ 612.314820] Tainted: G C 5.10.63-v7+ #1488 > [ 612.314825] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > disables this message. > [ 612.314832] task:nfsd state:D stack: 0 pid: 1034 > ppid: 2 flags:0x00000000 > [ 612.314847] Backtrace: > [ 612.314872] [<809f9df0>] (__schedule) from [<809fa7c8>] (schedule+0x68/0xe4) > [ 612.314882] r10:00000000 r9:89353d04 r8:8c393100 r7:00000002 > r6:00000001 r5:82996c80 > [ 612.314888] r4:ffffe000 > [ 612.314902] [<809fa760>] (schedule) from [<8017bcac>] > (rwsem_down_write_slowpath+0x318/0x518) > [ 612.314909] r5:ffffe000 r4:8c3930f0 > [ 612.314919] [<8017b994>] (rwsem_down_write_slowpath) from > [<809fd700>] (down_write+0x6c/0x70) > [ 612.314929] r10:86f991a0 r9:00000000 r8:8c233ee0 r7:86e64490 > r6:93c56c00 r5:8c3930f0 > [ 612.314934] r4:8c3930f0 > [ 612.314967] [<809fd694>] (down_write) from [<7f5ae6b8>] > (ovl_dir_release+0x34/0x70 [overlay]) > [ 612.314974] r5:8c3930f0 r4:8eb98ac0 > [ 612.314999] [<7f5ae684>] (ovl_dir_release [overlay]) from > [<803359f0>] (__fput+0x90/0x25c) > [ 612.315007] r7:86e64490 r6:000a841d r5:8c393068 r4:93c56c00 > [ 612.315016] [<80335960>] (__fput) from [<80335c24>] (delayed_fput+0x4c/0x58) > [ 612.315026] r9:8c393068 r8:00000122 r7:00000100 r6:80f05008 > r5:89353dec r4:93c56e40 > [ 612.315036] [<80335bd8>] (delayed_fput) from [<80335c4c>] > (flush_delayed_fput+0x1c/0x20) > [ 612.315042] r5:89353dec r4:00000001 > [ 612.315146] [<80335c30>] (flush_delayed_fput) from [<7f0c7ec4>] > (nfsd_file_close_inode_sync+0x180/0x188 [nfsd]) > [ 612.315295] [<7f0c7d44>] (nfsd_file_close_inode_sync [nfsd]) from > [<7f0c065c>] (nfsd_unlink+0x230/0x270 [nfsd]) > [ 612.315304] r8:00008000 r7:9346d068 r6:86f42000 r5:93445440 r4:89290038 > [ 612.315451] [<7f0c042c>] (nfsd_unlink [nfsd]) from [<7f0d0ccc>] > (nfsd4_remove+0x5c/0x114 [nfsd]) > [ 612.315461] r9:00000000 r8:86f43a20 r7:86f43000 r6:86f42000 > r5:86f991c0 r4:89290038 > [ 612.315610] [<7f0d0c70>] (nfsd4_remove [nfsd]) from [<7f0d06f4>] > (nfsd4_proc_compound+0x3f4/0x648 [nfsd]) > [ 612.315617] r6:86f98000 r5:86f42000 r4:89290000 > [ 612.315766] [<7f0d0300>] (nfsd4_proc_compound [nfsd]) from > [<7f0b973c>] (nfsd_dispatch+0xc8/0x14c [nfsd]) > [ 612.315776] r10:7f0f3890 r9:00000018 r8:8ea15000 r7:8ea15014 > r6:7f0f3890 r5:86f43000 > [ 612.315782] r4:86f42000 > [ 612.315862] [<7f0b9674>] (nfsd_dispatch [nfsd]) from [<809ca22c>] > (svc_process_common+0x374/0x70c) > [ 612.315871] r9:86f43000 r8:86f43a20 r7:86f42000 r6:80f05008 > r5:00000014 r4:86f42184 > [ 612.315882] [<809c9eb8>] (svc_process_common) from [<809ca69c>] > (svc_process+0xd8/0xec) > [ 612.315891] r10:86c85cfc r9:86f42000 r8:81016540 r7:7f100bc4 > r6:816aa800 r5:bab24000 > [ 612.315897] r4:86f42000 > [ 612.315976] [<809ca5c4>] (svc_process) from [<7f0b9100>] > (nfsd+0xf4/0x164 [nfsd]) > [ 612.315982] r5:00057e40 r4:86f42000 > [ 612.316062] [<7f0b900c>] (nfsd [nfsd]) from [<80143790>] > (kthread+0x170/0x174) > [ 612.316072] r9:86f42000 r8:7f0b900c r7:89352000 r6:00000000 > r5:89090200 r4:89256880 > [ 612.316082] [<80143620>] (kthread) from [<801000ec>] > (ret_from_fork+0x14/0x28) > [ 612.316089] Exception stack(0x89353fb0 to 0x89353ff8) > [ 612.316097] 3fa0: 00000000 > 00000000 00000000 00000000 > [ 612.316105] 3fc0: 00000000 00000000 00000000 00000000 00000000 > 00000000 00000000 00000000 > [ 612.316113] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000 > [ 612.316122] r10:00000000 r9:00000000 r8:00000000 r7:00000000 > r6:00000000 r5:80143620 > [ 612.316128] r4:89090200 > > > On Wed, Dec 1, 2021 at 6:56 PM Carl Karsten <carl@nextdayvideo.com> wrote: > > > > there is overlayfs in the middle of the stack dump, so I think this is > > the place to post. happy to post it somewhere else if directed. > > > > currently very reproducible - 3 times in a row, rebooting both clent > > and server between. > > > > tt may be related to me setting nfsvers=3. I plan on testing this > > guess, but it may be a while. hours or maybe a day or 2. > > > > I tried to pin down the file operation client side, but that hasn't > > happened yet either. > > > > client and server Details: > > > > server: raspberry pi v3, > > pi@rpi-cb-1f-f7:~$ uname -a > > Linux rpi-cb-1f-f7 5.10.63-v7+ #1488 SMP Thu Nov 18 16:14:44 GMT 2021 > > armv7l GNU/Linux > > > > pi@rpi-cb-1f-f7:~$ cat /etc/exports > > /srv/nfs/rpi/bullseye/root/merged > > *(rw,sync,no_subtree_check,no_root_squash,fsid=2) > > > > pi@rpi-cb-1f-f7:~$ findmnt /srv/nfs/rpi/bullseye/root/merged | cat > > TARGET SOURCE FSTYPE OPTIONS > > /srv/nfs/rpi/bullseye/root/merged overlay overlay > > rw,relatime,lowerdir=/srv/nfs/rpi/bullseye/root/setup:/srv/nfs/rpi/bullseye/root/base,upperdir=/srv/nfs/rpi/bullseye/root/updates,workdir=/srv/nfs/rpi/bullseye/root/work,index=on,nfs_export=on > > > > pi@rpi-cb-1f-f7:~$ findmnt / > > TARGET SOURCE FSTYPE OPTIONS > > / /dev/mmcblk0p2 ext4 rw,noatime > > > > client: also a pi: > > pi@raspberrypi:~ $ uname -a > > Linux raspberrypi 5.10.63-v8+ #1488 SMP PREEMPT Thu Nov 18 16:16:16 > > GMT 2021 aarch64 GNU/Linux > > > > root@raspberrypi:~# cat /etc/fstab > > # proc /proc proc defaults 0 0 > > 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged / nfs defaults,auto,rw,nfsvers=3 0 0 > > > > root@raspberrypi:~# findmnt /|cat > > / 10.21.0.1:/srv/nfs/rpi/bullseye/root/merged nfs > > rw,relatime,vers=3,rsize=4096,wsize=4096,namlen=255,hard,nolock,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.21.0.1,mountvers=3,mountproto=tcp,local_lock=all,addr=10.21.0.1 > > > > on the client, I run > > apt autoremove --assume-yes > > > > > > > > > > [ 1103.834869] INFO: task nfsd:1029 blocked for more than 122 seconds. > > [ 1103.834889] Tainted: G C 5.10.63-v7+ #1488 > > [ 1103.834901] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > > disables this message. > > [ 1103.834915] task:nfsd state:D stack: 0 pid: 1029 > > ppid: 2 flags:0x00000000 > > [ 1103.834945] Backtrace: > > [ 1103.834992] [<809f9df0>] (__schedule) from [<809fa7c8>] (schedule+0x68/0xe4) > > [ 1103.835015] r10:00000000 r9:86f67d4c r8:8fc134a0 r7:00000002 > > r6:00000001 r5:86dc4d80 > > [ 1103.835029] r4:ffffe000 > > [ 1103.835056] [<809fa760>] (schedule) from [<8017bcac>] > > (rwsem_down_write_slowpath+0x318/0x518) > > [ 1103.835072] r5:ffffe000 r4:8fc13490 > > [ 1103.835094] [<8017b994>] (rwsem_down_write_slowpath) from > > [<809fd700>] (down_write+0x6c/0x70) > > [ 1103.835116] r10:7f0f2df4 r9:00000000 r8:8c696bb0 r7:82ba73d0 > > r6:85d00600 r5:8fc13490 > > [ 1103.835129] r4:8fc13490 > > [ 1103.835195] [<809fd694>] (down_write) from [<7f6676b8>] > > (ovl_dir_release+0x34/0x70 [overlay]) > > [ 1103.835211] r5:8fc13490 r4:96d1eb80 > > [ 1103.835267] [<7f667684>] (ovl_dir_release [overlay]) from > > [<803359f0>] (__fput+0x90/0x25c) > > [ 1103.835286] r7:82ba73d0 r6:000a841d r5:8fc13408 r4:85d00600 > > [ 1103.835307] [<80335960>] (__fput) from [<80335c24>] (delayed_fput+0x4c/0x58) > > [ 1103.835328] r9:8fc13408 r8:00000122 r7:00000100 r6:80f05008 > > r5:86f67e34 r4:85d00180 > > [ 1103.835348] [<80335bd8>] (delayed_fput) from [<80335c4c>] > > (flush_delayed_fput+0x1c/0x20) > > [ 1103.835363] r5:86f67e34 r4:00000001 > > [ 1103.835570] [<80335c30>] (flush_delayed_fput) from [<7f0c7ec4>] > > (nfsd_file_close_inode_sync+0x180/0x188 [nfsd]) > > [ 1103.835916] [<7f0c7d44>] (nfsd_file_close_inode_sync [nfsd]) from > > [<7f0c065c>] (nfsd_unlink+0x230/0x270 [nfsd]) > > [ 1103.835938] r8:ffffc000 r7:92419068 r6:86f44000 r5:937dd3b8 r4:86fa0008 > > [ 1103.836285] [<7f0c042c>] (nfsd_unlink [nfsd]) from [<7f0ca3f4>] > > (nfsd3_proc_remove+0x80/0xd8 [nfsd]) > > [ 1103.836308] r9:00000018 r8:96dd5000 r7:86f44000 r6:86fa0008 > > r5:86fa0000 r4:86f38000 > > [ 1103.836650] [<7f0ca374>] (nfsd3_proc_remove [nfsd]) from > > [<7f0b973c>] (nfsd_dispatch+0xc8/0x14c [nfsd]) > > [ 1103.836669] r7:96dd5014 r6:7f0f2df4 r5:86f45000 r4:86f44000 > > [ 1103.836856] [<7f0b9674>] (nfsd_dispatch [nfsd]) from [<809ca22c>] > > (svc_process_common+0x374/0x70c) > > [ 1103.836878] r9:86f45000 r8:86f45a20 r7:86f44000 r6:80f05008 > > r5:00000014 r4:86f44184 > > [ 1103.836901] [<809c9eb8>] (svc_process_common) from [<809ca69c>] > > (svc_process+0xd8/0xec) > > [ 1103.836923] r10:856abcfc r9:86f44000 r8:81016540 r7:7f100bc4 > > r6:816cae00 r5:bab24000 > > [ 1103.836937] r4:86f44000 > > [ 1103.837120] [<809ca5c4>] (svc_process) from [<7f0b9100>] > > (nfsd+0xf4/0x164 [nfsd]) > > [ 1103.837135] r5:00057e40 r4:86f44000 > > [ 1103.837321] [<7f0b900c>] (nfsd [nfsd]) from [<80143790>] > > (kthread+0x170/0x174) > > [ 1103.837342] r9:86f44000 r8:7f0b900c r7:86f66000 r6:00000000 > > r5:892b9580 r4:847acbc0 > > [ 1103.837364] [<80143620>] (kthread) from [<801000ec>] > > (ret_from_fork+0x14/0x28) > > [ 1103.837378] Exception stack(0x86f67fb0 to 0x86f67ff8) > > [ 1103.837396] 7fa0: 00000000 > > 00000000 00000000 00000000 > > [ 1103.837415] 7fc0: 00000000 00000000 00000000 00000000 00000000 > > 00000000 00000000 00000000 > > [ 1103.837434] 7fe0: 00000000 00000000 00000000 00000000 00000013 00000000 > > [ 1103.837454] r10:00000000 r9:00000000 r8:00000000 r7:00000000 > > r6:00000000 r5:80143620 > > [ 1103.837467] r4:892b9580 > > > > > > -- > > Carl K > > > > -- > Carl K -- Carl K ^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2021-12-03 23:29 UTC | newest] Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2021-12-02 2:56 nfsd blocked Carl Karsten 2021-12-02 7:06 ` Carl Karsten 2021-12-02 7:38 ` Carl Karsten 2021-12-03 23:28 ` Carl Karsten
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).