Re: macppc panic: vref used where vget required

2022-05-04 Thread Alexander Bluhm
On Wed, May 04, 2022 at 05:58:14PM +0200, Martin Pieuchot wrote:
> I don't understand the mechanism around UVM_VNODE_CANPERSIST.  I looked
> for missing uvm_vnp_uncache() and found the following two.  I doubt
> those are the one triggering the bug because they are in NFS & softdep.

It crashes while compiling clang.

c++ -O2 -pipe  -fno-ret-protector -std=c++14 -fvisibility-inlines-hidden 
-fno-exceptions -fno-rtti -Wall -W -Wno-unused-parameter -Wwrite-strings 
-Wcast-qual  -Wno-missing-field-initializers -pedantic -Wno-long-long  
-Wdelete-non-virtual-dtor -Wno-comment -fPIE  -MD -MP  
-I/usr/src/gnu/usr.bin/clang/liblldbPluginExpressionParser/../../../llvm/llvm/include
 -I/usr/src/gnu/usr.bin/clang/liblldbPluginExpressionParser/../include 
-I/usr/src/gnu/usr.bin/clang/liblldbPluginExpressionParser/obj  
-I/usr/src/gnu/usr.bin/clang/liblldbPluginExpressionParser/obj/../include 
-DNDEBUG -D__STDC_LIMIT_MACROS -D__STDC_CONSTANT_MACROS  -D__STDC_FORMAT_MACROS 
-DLLVM_PREFIX="/usr" 
-I/usr/src/gnu/usr.bin/clang/liblldbPluginExpressionParser/../../../llvm/lldb/include
  
-I/usr/src/gnu/usr.bin/clang/liblldbPluginExpressionParser/../../../llvm/lldb/source
 
-I/usr/src/gnu/usr.bin/clang/liblldbPluginExpressionParser/../../../llvm/clang/include
 -c 
/usr/src/gnu/usr.bin/clang/liblldbPluginExpressionParser/../../../llvm/lldb/source/Plugins/ExpressionParser/Clang/ClangExpressionParser.cpp
 -o ClangExpressionParser.o
Timeout, server ot26 not responding.

No softdep, but NFS client.  I use it to mount cvs mirror read-only.
This file system should not be used during make build.

/dev/wd0a on / type ffs (local)
/dev/wd0l on /home type ffs (local, nodev, nosuid)
/dev/wd0d on /tmp type ffs (local, nodev)
/dev/wd0f on /usr type ffs (local, nodev)
/dev/wd0g on /usr/X11R6 type ffs (local, nodev)
/dev/wd0h on /usr/local type ffs (local, nodev, wxallowed)
/dev/wd0k on /usr/obj type ffs (local, nodev, nosuid, wxallowed)
/dev/wd0j on /usr/src type ffs (local, nodev, nosuid)
/dev/wd0e on /var type ffs (local, nodev, nosuid)
regressmaster:/data/mirror/openbsd/cvs on /mount/openbsd/cvs type nfs (nodev, 
nosuid, read-only, v3, udp, intr, wsize=32768, rsize=32768, rdirsize=32768, 
timeo=100, retrans=101)
regressmaster:/data/mirror/openbsd/ftp on /mount/openbsd/ftp type nfs (nodev, 
nosuid, read-only, v3, udp, intr, wsize=32768, rsize=32768, rdirsize=32768, 
timeo=100, retrans=101)
regressmaster:/data/mirror/openbsd/distfiles on /mount/openbsd/distfiles type 
nfs (nodev, nosuid, read-only, v3, udp, intr, wsize=32768, rsize=32768, 
rdirsize=32768, timeo=100, retrans=101)

Should I test this diff?

> Index: nfs/nfs_serv.c
> ===
> RCS file: /cvs/src/sys/nfs/nfs_serv.c,v
> retrieving revision 1.120
> diff -u -p -r1.120 nfs_serv.c
> --- nfs/nfs_serv.c11 Mar 2021 13:31:35 -  1.120
> +++ nfs/nfs_serv.c4 May 2022 15:29:06 -
> @@ -1488,6 +1488,9 @@ nfsrv_rename(struct nfsrv_descript *nfsd
>   error = -1;
>  out:
>   if (!error) {
> + if (tvp) {
> + (void)uvm_vnp_uncache(tvp);
> + }
>   error = VOP_RENAME(fromnd.ni_dvp, fromnd.ni_vp, _cnd,
>  tond.ni_dvp, tond.ni_vp, _cnd);
>   } else {
> Index: ufs/ffs/ffs_inode.c
> ===
> RCS file: /cvs/src/sys/ufs/ffs/ffs_inode.c,v
> retrieving revision 1.81
> diff -u -p -r1.81 ffs_inode.c
> --- ufs/ffs/ffs_inode.c   12 Dec 2021 09:14:59 -  1.81
> +++ ufs/ffs/ffs_inode.c   4 May 2022 15:32:15 -
> @@ -172,11 +172,12 @@ ffs_truncate(struct inode *oip, off_t le
>   if (length > fs->fs_maxfilesize)
>   return (EFBIG);
>  
> - uvm_vnp_setsize(ovp, length);
>   oip->i_ci.ci_lasta = oip->i_ci.ci_clen 
>   = oip->i_ci.ci_cstart = oip->i_ci.ci_lastw = 0;
>  
>   if (DOINGSOFTDEP(ovp)) {
> + uvm_vnp_setsize(ovp, length);
> + (void) uvm_vnp_uncache(ovp);
>   if (length > 0 || softdep_slowdown(ovp)) {
>   /*
>* If a file is only partially truncated, then



Re: macppc panic: vref used where vget required

2022-05-04 Thread Mark Kettenis
> Date: Wed, 4 May 2022 17:58:14 +0200
> From: Martin Pieuchot 
> 
> On 04/05/22(Wed) 09:16, Sebastien Marie wrote:
> > [...] 
> > we don't have any vclean label ("vclean (inactive)" or "vclean (active)"), 
> > so 
> > vclean() was not called in this timeframe.
> 
> So we are narrowing down the issue:
> 
> 1. A file is opened
> 2. Then mmaped
> 3. Some of its pages are swapped to disk

Hmm, why does this happen?  Is this because the mmap(2) was done using
MAP_PRIVATE?  But then what's the point of setting
UVM_VNODE_CANPERSIST?

> 4. The process die, closing the file
> 5. The reaper calls uvn_detach() on the vnode which has UVM_VNODE_CANPERSIST
>   . This release the last reference of the vnode without sync' the pages
>   -> the vnode ends up on the free list
> 6. The page daemon tries to sync the pages, grab a reference on the vnode
>   which has already been recycled.
> 
> I don't understand the mechanism around UVM_VNODE_CANPERSIST.  I looked
> for missing uvm_vnp_uncache() and found the following two.  I doubt
> those are the one triggering the bug because they are in NFS & softdep.
> 
> So my question is should UVM_VNODE_CANPERSIST be cleared at some point
> in this scenario?  If so, when?
> 
> What is the interaction between this flag and mmap pages which are on
> swap?  In other words, is it safe to call vrele(9) in uvn_detach() if
> uvn_flush() hasn't been called with PGO_FREE|PGO_ALLPAGES?  If yes, why?
> 
> What it this flag suppose to say?  Why is it always cleared before
> VOP_REMOVE() & VOP_RENAME()?
> 
> Index: nfs/nfs_serv.c
> ===
> RCS file: /cvs/src/sys/nfs/nfs_serv.c,v
> retrieving revision 1.120
> diff -u -p -r1.120 nfs_serv.c
> --- nfs/nfs_serv.c11 Mar 2021 13:31:35 -  1.120
> +++ nfs/nfs_serv.c4 May 2022 15:29:06 -
> @@ -1488,6 +1488,9 @@ nfsrv_rename(struct nfsrv_descript *nfsd
>   error = -1;
>  out:
>   if (!error) {
> + if (tvp) {
> + (void)uvm_vnp_uncache(tvp);
> + }
>   error = VOP_RENAME(fromnd.ni_dvp, fromnd.ni_vp, _cnd,
>  tond.ni_dvp, tond.ni_vp, _cnd);
>   } else {
> Index: ufs/ffs/ffs_inode.c
> ===
> RCS file: /cvs/src/sys/ufs/ffs/ffs_inode.c,v
> retrieving revision 1.81
> diff -u -p -r1.81 ffs_inode.c
> --- ufs/ffs/ffs_inode.c   12 Dec 2021 09:14:59 -  1.81
> +++ ufs/ffs/ffs_inode.c   4 May 2022 15:32:15 -
> @@ -172,11 +172,12 @@ ffs_truncate(struct inode *oip, off_t le
>   if (length > fs->fs_maxfilesize)
>   return (EFBIG);
>  
> - uvm_vnp_setsize(ovp, length);
>   oip->i_ci.ci_lasta = oip->i_ci.ci_clen 
>   = oip->i_ci.ci_cstart = oip->i_ci.ci_lastw = 0;
>  
>   if (DOINGSOFTDEP(ovp)) {
> + uvm_vnp_setsize(ovp, length);
> + (void) uvm_vnp_uncache(ovp);
>   if (length > 0 || softdep_slowdown(ovp)) {
>   /*
>* If a file is only partially truncated, then
> 
> 



Re: macppc panic: vref used where vget required

2022-05-04 Thread Martin Pieuchot
On 04/05/22(Wed) 09:16, Sebastien Marie wrote:
> [...] 
> we don't have any vclean label ("vclean (inactive)" or "vclean (active)"), so 
> vclean() was not called in this timeframe.

So we are narrowing down the issue:

1. A file is opened
2. Then mmaped
3. Some of its pages are swapped to disk
4. The process die, closing the file
5. The reaper calls uvn_detach() on the vnode which has UVM_VNODE_CANPERSIST
  . This release the last reference of the vnode without sync' the pages
  -> the vnode ends up on the free list
6. The page daemon tries to sync the pages, grab a reference on the vnode
  which has already been recycled.

I don't understand the mechanism around UVM_VNODE_CANPERSIST.  I looked
for missing uvm_vnp_uncache() and found the following two.  I doubt
those are the one triggering the bug because they are in NFS & softdep.

So my question is should UVM_VNODE_CANPERSIST be cleared at some point
in this scenario?  If so, when?

What is the interaction between this flag and mmap pages which are on
swap?  In other words, is it safe to call vrele(9) in uvn_detach() if
uvn_flush() hasn't been called with PGO_FREE|PGO_ALLPAGES?  If yes, why?

What it this flag suppose to say?  Why is it always cleared before
VOP_REMOVE() & VOP_RENAME()?

Index: nfs/nfs_serv.c
===
RCS file: /cvs/src/sys/nfs/nfs_serv.c,v
retrieving revision 1.120
diff -u -p -r1.120 nfs_serv.c
--- nfs/nfs_serv.c  11 Mar 2021 13:31:35 -  1.120
+++ nfs/nfs_serv.c  4 May 2022 15:29:06 -
@@ -1488,6 +1488,9 @@ nfsrv_rename(struct nfsrv_descript *nfsd
error = -1;
 out:
if (!error) {
+   if (tvp) {
+   (void)uvm_vnp_uncache(tvp);
+   }
error = VOP_RENAME(fromnd.ni_dvp, fromnd.ni_vp, _cnd,
   tond.ni_dvp, tond.ni_vp, _cnd);
} else {
Index: ufs/ffs/ffs_inode.c
===
RCS file: /cvs/src/sys/ufs/ffs/ffs_inode.c,v
retrieving revision 1.81
diff -u -p -r1.81 ffs_inode.c
--- ufs/ffs/ffs_inode.c 12 Dec 2021 09:14:59 -  1.81
+++ ufs/ffs/ffs_inode.c 4 May 2022 15:32:15 -
@@ -172,11 +172,12 @@ ffs_truncate(struct inode *oip, off_t le
if (length > fs->fs_maxfilesize)
return (EFBIG);
 
-   uvm_vnp_setsize(ovp, length);
oip->i_ci.ci_lasta = oip->i_ci.ci_clen 
= oip->i_ci.ci_cstart = oip->i_ci.ci_lastw = 0;
 
if (DOINGSOFTDEP(ovp)) {
+   uvm_vnp_setsize(ovp, length);
+   (void) uvm_vnp_uncache(ovp);
if (length > 0 || softdep_slowdown(ovp)) {
/*
 * If a file is only partially truncated, then



Re: macppc panic: vref used where vget required

2022-05-04 Thread Sebastien Marie
On Tue, May 03, 2022 at 07:52:16PM +0200, Alexander Bluhm wrote:
> On Mon, May 02, 2022 at 06:53:08AM +0200, Sebastien Marie wrote:
> > New diff, with new iteration on vnode_history_*() functions. I added a 
> > label in
> > the record function. I also changed when showing the stacktrace. powerpc has
> > poor backtrace support, but now it will at least print some infos even if no
> > stacktrace recorded (pid, ps_comm, label, v_usecount).
> >
> > I added a vnode_history_record() entry inside vclean(). We should have it in
> > both case:
> > - if vnode is already inactive (vp->v_usecount == 0) [trace already 
> > recorded]
> > - if vnode is still active (vp->v_usecount != 0) [trace previously not 
> > recorded]
> 
> http://bluhm.genua.de/release/results/2022-05-02T12%3A23%3A22Z/bsdcons-ot26.txt
> 
> [-- MARK -- Tue May  3 16:45:00 2022]
> uvn_io: start: 0x23b5a9c0, type VREG, use 0, write 0, hold 0, flags 
> (VBIOONFREELIST)
>   tag VT_UFS, ino 365327, on dev 0, 10 flags 0x100, effnlink 1, nlink 1
>   mode 0100660, owner 21, group 21, size 13647873
> ==> vnode_history_print 0x23b5a9c0, next=6
>  [0] c++[83314] vget, usecount 1>2
> #0  mtx_enter_try+0x5c
>  [1] c++[83314] vget, usecount 2>3
> #0  mtx_enter_try+0x5c
>  [2] c++[83314] vrele, usecount 3>2
> 
>  [3] c++[83314] vput, usecount 2>1
> 
>  [4] reaper[690] uvn_detach (UVM_VNODE_CANPERSIST), usecount 1>1
> #0  0xfffc
> #1  umidi_quirklist+0x148
> #2  uvn_detach+0x13c
> #3  uvm_unmap_detach+0x1a4
> #4  uvm_map_teardown+0x184
> #5  uvmspace_free+0x60
> #6  uvm_exit+0x30
> #7  reaper+0x138
> #8  fork_trampoline+0x14
>  [5] reaper[690] vrele, usecount 1>0
> 
>  [6>] c++[73867] vget, usecount 1>2
> #0  mtx_enter_try+0x5c
>  [7] c++[73867] vrele, usecount 2>1
> 
>  [8] c++[73867] vref, usecount 1>2
> 
>  [9] c++[73867] vput, usecount 2>1
> 

We have a bit more elements in the trace (because we don't rely anymore on 
stacktrace to show elements or not, and on powerpc stacktrace seems somehow 
creative).

we are recording inside a ring. the next entry would be 6 (next=6), so 6 is the 
older entry in the ring.

Reordered history is:
[6] c++[73867] vget, usecount 1>2
[7] c++[73867] vrele, usecount 2>1
[8] c++[73867] vref, usecount 1>2
[9] c++[73867] vput, usecount 2>1
[0] c++[83314] vget, usecount 1>2
[1] c++[83314] vget, usecount 2>3
[2] c++[83314] vrele, usecount 3>2
[3] c++[83314] vput, usecount 2>1
[4] reaper[690] uvn_detach (UVM_VNODE_CANPERSIST), usecount 1>1
[5] reaper[690] vrele, usecount 1>0

and next, we paniced in pagedaemon:

(from ps)
*93511  246215  0  0  7 0x14200pagedaemon

neither pid 73867 and 83314 are still alive at panic time (no entries in ps).

we don't have any vclean label ("vclean (inactive)" or "vclean (active)"), so 
vclean() was not called in this timeframe.

the two last entries seems to be from uvn_detach(), the code path is:

void
uvn_detach(struct uvm_object *uobj)
{
rw_enter(uobj->vmobjlock, RW_WRITE);
uobj->uo_refs--;

vp->v_flag &= ~VTEXT;

if (uvn->u_flags & UVM_VNODE_CANPERSIST) {
vnode_history_record("uvn_detach 
(UVM_VNODE_CANPERSIST)", vp, 0);
/* v_usecount=1 */

/* won't block */
uvn_flush(uobj, 0, 0, PGO_DEACTIVATE|PGO_ALLPAGES);
goto out;
}

out:
rw_exit(uobj->vmobjlock);
vrele(vp);
}

int
vrele(struct vnode *vp)
{
vp->v_usecount--;
vnode_history_record("vrele", vp, VH_DECR);
/* v_usecount: 1 -> 0 */

/* vp->v_usecount == 0 */
/* vp->v_writecount == 0 */

if (vn_lock(vp, LK_EXCLUSIVE | LK_IOP)) {
/* not here: we don't have vprint("vrele: cannot lock") 
in console */
}

VOP_INACTIVE(vp, p);

if (vp->v_usecount == 0 && !(vp->v_bioflag & VBIOONFREELIST))
vputonfreelist(vp);

return (1);
}

VOP_INACTIVE() will unlock the vnode. the vnode is VT_UFS, vop_inactive is 
ufs_inactive().

int
ufs_inactive(void *v)
{
if (ip->i_din1 == NULL || DIP(ip, mode) == 0)
/* branch not taken: we would ends in vclean() [via 
vrecycle() in out]
   and it isn't the case */
goto out;

if (DIP(ip, nlink) <= 0 && (vp->v_mount->mnt_flag & MNT_RDONLY) 
== 0) {
/* branch not taken: the branch would set
   DIP_ASSIGN(ip, mode, 0)
   and next we would ends in vclean() [via vrecycle() 
below]
   and it isn't the case. */

/*