Re: bin/50350: rump/rumpkern/t_sp/stress_{long,short} fail on Core 2 Quad

[Andreas Gustafsson <gson%gson.org@localhost>]

The following reply was made to PR bin/50350; it has been noted by GNATS.

From: Andreas Gustafsson <gson%gson.org@localhost>
To: "J. Hannken-Illjes" <hannken%eis.cs.tu-bs.de@localhost>
Cc: gnats-bugs%NetBSD.org@localhost
Subject: Re: bin/50350: rump/rumpkern/t_sp/stress_{long,short} fail on Core 2 Quad
Date: Fri, 8 Mar 2019 10:24:36 +0200

 J. Hannken-Illjes wrote:
 > I'm quite sure the fstrans commit only triggers a hidden bug here.
 
 That's what I thought, too, but now that I've looked at the rumpkern
 process with gdb, I'm not so sure anymore.
 
 Here's what I did:
 
   Build a release from 2019.03.07.11.09.48 sources with -V MKDEBUG=yes COPTS=-g
   Boot it and log in
   # cd /usr/tests/rump/rumpkern/
   # ./t_sp stress_short
   (let it run for a couple of minutes)
   ^Z
   # bg
   # gdb rump_server
   (gdb) attach <pid of rump_server_process>
   (gdb) info threads
 
 This showed a total of 162 LWPs, most of which were
 sleeping in ___lwp_park60, but one was in rumpns_membar_sync()
 called from fstrans_alloc_lwp_info():
 
   (gdb) thread 108
   #0  0x000076b82d6aaa17 in rumpns_membar_sync () from /usr/lib/librump.so.0
   #1  0x000076b82c634b13 in fstrans_alloc_lwp_info (mp=mp@entry=0x76b82d5ac000)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_trans.c:341
   #2  0x000076b82c6352e9 in fstrans_get_lwp_info (do_alloc=true,
       mp=0x76b82d5ac000)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_trans.c:410
   #3  _fstrans_start (wait=1, lock_type=FSTRANS_SHARED, mp=0x76b82d5ac000)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_trans.c:454
   #4  fstrans_start (mp=0x76b82d5ac000)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_trans.c:492
   #5  0x000076b82d65f3ff in vop_pre (vp=0x76b82c501d20, vp=0x76b82c501d20,
       op=FST_YES, mpsafe=<synthetic pointer>, mp=<synthetic pointer>)
       at /usr/src/lib/librump/../../sys/rump/../kern/vnode_if.c:77
   #6  VOP_LOCK (vp=0x76b82c501d20, flags=<optimized out>)
       at /usr/src/lib/librump/../../sys/rump/../kern/vnode_if.c:1281
   #7  0x000076b82c62f442 in vn_lock (vp=0x76b82c501d20, flags=131074)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_vnops.c:1043
   #8  0x000076b82c642215 in namei_start (startdir_ret=0x76b819ccfba8, isnfsd=0,
       state=0x76b819ccfc50)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_lookup.c:681
   #9  namei_oneroot (isnfsd=0, inhibitmagic=0, neverfollow=0,
       state=0x76b819ccfc50)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_lookup.c:1156
   #10 namei_tryemulroot (state=state@entry=0x76b819ccfc50,
       neverfollow=neverfollow@entry=0, inhibitmagic=inhibitmagic@entry=0,
       isnfsd=isnfsd@entry=0)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_lookup.c:1510
   #11 0x000076b82c6446f2 in namei (ndp=0x76b819ccfdc8)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_lookup.c:1546
   #12 0x000076b82c62fcf3 in vn_open (ndp=0x76b819ccfdc8, fmode=3, cmode=0)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_vnops.c:176
   #13 0x000076b82c63995a in do_open (l=l@entry=0x76b82d105000, dvp=0x0,
       pb=0x76b82d591240, open_flags=open_flags@entry=2,
       open_mode=open_mode@entry=0, fd=fd@entry=0x76b819ccfeec)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_syscalls.c:1590
   #14 0x000076b82c639aa9 in do_sys_openat (l=0x76b82d105000,
       fdat=fdat@entry=-100, path=<optimized out>, flags=2, mode=0,
       fd=fd@entry=0x76b819ccfeec)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_syscalls.c:1674
   #15 0x000076b82c639bfc in sys_open (l=<optimized out>, uap=<optimized out>,
       retval=0x76b819ccff10)
       at /usr/src/lib/librumpvfs/../../sys/rump/../kern/vfs_syscalls.c:1695
   #16 0x000076b82da01359 in sy_call (rval=0x76b819ccff10, uap=0x76b82b99f0c0,
       l=0x76b82d105000, sy=0x76b82d8eec38 <rumpns_sysent+120>)
       at /usr/src/sys/rump/kern/lib/libsysproxy/../../../../sys/syscallvar.h:65
   #17 sy_invoke (code=5, rval=0x76b819ccff10, uap=0x76b82b99f0c0,
       l=0x76b82d105000, sy=0x76b82d8eec38 <rumpns_sysent+120>)
       at /usr/src/sys/rump/kern/lib/libsysproxy/../../../../sys/syscallvar.h:94
   #18 hyp_syscall (num=5, arg=0x76b82b99f0c0, retval=0x76b819ccff90)
       at /usr/src/sys/rump/kern/lib/libsysproxy/sysproxy.c:72
   #19 0x000076b82d206bd0 in rumpsyscall (regrv=0x76b819ccff80,
       data=0x76b82b99f0c0, sysnum=5)
       at /usr/src/lib/librumpuser/rumpuser_sp.c:267
   #20 serv_handlesyscall (rhdr=0x76b82b9a3308, rhdr=0x76b82b9a3308,
       data=0x76b82b99f0c0 "\265\031\340\322", spc=0x76b82d40c3b0)
       at /usr/src/lib/librumpuser/rumpuser_sp.c:690
   #21 serv_workbouncer (arg=<optimized out>)
       at /usr/src/lib/librumpuser/rumpuser_sp.c:773
   #22 0x000076b82ce0b7d8 in pthread__create_tramp (cookie=0x76b81db2c000)
       at /usr/src/lib/libpthread/pthread.c:593
   #23 0x000076b82ca8b350 in ?? () from /usr/lib/libc.so.12
 
 fstrans_alloc_lwp_info() was looping over the fstrans_fli_head list,
 and tracing it manually, I was unable to get to the end of the list,
 so I wrote a gdb loop to print the entire list:
 
   set pager off
   set var $n = fstrans_fli_head.lh_first
   while $n
       set var $n = $n->fli_list.le_next
       print $n
   end
 
 This printed:
 
   $608 = (struct fstrans_lwp_info *) 0x76b8193b0740
   $609 = (struct fstrans_lwp_info *) 0x76b8193b0790
   $610 = (struct fstrans_lwp_info *) 0x76b8193b07e0
   [...]
   $218906 = (struct fstrans_lwp_info *) 0x76b82d53cd20
   $218907 = (struct fstrans_lwp_info *) 0x76b82d53ce10
   $218908 = (struct fstrans_lwp_info *) 0x0
 
 Thats 218,300 elements.  Is the list really supposed to get that large?
 -- 
 Andreas Gustafsson, gson%gson.org@localhost