Re: uvn_fp2 [was: Help with issue with mpt(4) driver]

[Brian Buhrow <buhrow%nfbcal.org@localhost>]

        Hello.  Ok, I feel like I'm finally making a little sense of this
confusion.For those of you who don't remember the tale, our problem seems
to be that processes get stuck in uvn_fp2, waiting for a page to be
unlocked.  At first I thought this had to do with some changes I've been
making to the mpt(4)  driver to help make it more robust in the face of
errors from the LSI hardware itself.  In order to test my changes, I've
been running a number of concurrent processes which read all the files on a
raid set (with the components of the raid set residing on scsi disks
attached to my test LSI hardware.)  At some point, sometimes right away,
sometimes after a number of days, these processes get stuck.  All but one
get stuck in "tstile", which I've now learned is a generic blocking state
and doesn't really provide a description of the problem.  The remaining
process gets stuck in "uvn_fp2".  Chuck says this happens when uvm_findpage()
wants to return  a page that's already locked elsewhere.  Ok, my reading of
the code so far confirms all this is true.  On my test system, the
filesystem holding all of this mess is something other than the root
filesystem, meaning when this train comes to a grinding halt, I'm still
left with a working machine.  So, I put a copy of the kernel with full
debugging symbols on the machine and run gdb against the live system to see
if I can look into the problem as it happens.

        My first thought was that perhaps the mpt(4) driver was losing a
request somewhere.  After considerable code inspection, a lot of debugging
code in the mpt(4) driver, and a bunch more error checking in the mpt(4)
code as well, I'm pretty confident the problem is not a lost request to the
mpt(4) driver.  To further support this theory, I finally was able to get
gdb to  show me the relevant portions of data concerning the findpage()
routine near where it waits for the page to be unlocked.  What I found is
that the page has absolutely been unlocked at some point, but the process
waiting in "uvn_fp2" was never awakened for some reason.  Now, this process
has been orphaned and the world has gone on while this process sleeps
waiting for an event that already passed.  My question is, how could this
happen?  One thought is that perhaps the lock address, the one which would
be signaled when the wakeup event occurs is wrong and so the notification
event is simply sent to the wrong place.  I don't like this theory, however,
because if it were true, I think this problem should happen much more
consistently than it does.  Another thought is that perhaps the wakeup
event occurs when the interupt level is too high and so the signaling can't
happen until the interrupt level drops to a reasonable level.  Then, for
some reason, when the interrupt level drops, the wakeup never arrives.  I
think this is called an interrupt inversion problem in technical terms.  I
like this idea more, since it seems to support the symptom of seeing other
machines get "stuck" for indeterminate periods of time during heavy i/o
with processes getting stuck in "uvn_fp2" for long, but not forever,
periods of time.
        
        Can anyone comment on whether this is even possible?  If so, anyone
have ideas on how to go about debugging it?    Below is some gdb output
that I hope will be helpful in showing the state of the world as it appears
while the problem presents itself.  I'll note that the mpt(4) queues are
all clear and the disks are functioning normally.  Any ideas would be
greatly appreciated.
-thanks
-Brian

(This is with NetBSD-5.1 using the following version of uvm_vnode.c)

/*      $NetBSD: uvm_vnode.c,v 1.90 2008/01/02 11:49:21 ad Exp $        */


Script started on Mon Jan 28 23:29:26 2013
testbox# ps -l -p 16246
UID   PID  PPID   CPU PRI NI  VSZ RSS WCHAN   STAT TTY      TIME COMMAND
  0 16246 24837 30347  78  0 1096 632 uvn_fp2 D    ttyp0 0:00.16 md5 ./mary/.sp
testbox# ps -o laddr -p 16246
   LADDR
d2a8f520
testbox# gdb /netbsd.gdb
GNU gdb 6.5
Copyright (C) 2006 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386--netbsdelf"...
(gdb) target kvm /dev/mem
#0  0xc043e728 in mi_switch (l=0xc0a43f40)
    at ../../../../kern/kern_synch.c:765
765     ../../../../kern/kern_synch.c: No such file or directory.
        in ../../../../kern/kern_synch.c
(gdb) kvm proc 0xd2a8f520
#0  0xc043e728 in mi_switch (l=0xd2a8f520)
    at ../../../../kern/kern_synch.c:765
765     in ../../../../kern/kern_synch.c
(gdb) bt
#0  0xc043e728 in mi_switch (l=0xd2a8f520)
    at ../../../../kern/kern_synch.c:765
#1  0xc043b4cb in sleepq_block (timo=0, catch=false)
    at ../../../../kern/kern_sleepq.c:269
#2  0xc043f89d in mtsleep (ident=0xc40c4cd0, priority=516, 
    wmesg=0xc09be97b "uvn_fp2", timo=0, mtx=0xd37c6684)
    at ../../../../kern/kern_synch.c:238
#3  0xc03e70d2 in uvn_findpage (uobj=0xd37c6684, offset=18808832, 
    pgp=0xd15376e4, flags=0) at ../../../../uvm/uvm_vnode.c:286
#4  0xc03e7223 in uvn_findpages (uobj=0xd37c6684, offset=18808832, 
---Type <return> to continue, or q <return> to quit---
    npagesp=0xd153771c, pgs=0xd15376e4, flags=<value optimized out>)
    at ../../../../uvm/uvm_vnode.c:224
#5  0xc049eb1b in genfs_getpages (v=0xd1537760)
    at ../../../../miscfs/genfs/genfs_io.c:325
#6  0xc049a660 in VOP_GETPAGES (vp=0xd37c6684, offset=18808832, m=0xd15377c0, 
    count=0xd1537838, centeridx=0, access_type=1, advice=0, flags=6146)
    at ../../../../kern/vnode_if.c:1726
#7  0xc03d3ba5 in ubc_fault (ufi=0xd1537940, ign1=3504025600, 
    ign2=0xd1537900, ign3=1, ign4=0, access_type=1, flags=2)
    at ../../../../uvm/uvm_bio.c:372
---Type <return> to continue, or q <return> to quit---
#8  0xc03d5b32 in uvm_fault_internal (orig_map=0xc0ae8e00, vaddr=3504025600, 
    access_type=1, fault_flag=0) at ../../../../uvm/uvm_fault.c:1023
#9  0xc050023c in trap (frame=0xd1537a18)
    at ../../../../arch/i386/i386/trap.c:667
#10 0xc010cb30 in calltrap ()
#11 0xc01006d3 in copyout ()
Previous frame inner to this frame (corrupt stack?)
(gdb) frame 3
#3  0xc03e70d2 in uvn_findpage (uobj=0xd37c6684, offset=18808832, 
    pgp=0xd15376e4, flags=0) at ../../../../uvm/uvm_vnode.c:286
286     ../../../../uvm/uvm_vnode.c: No such file or directory.
        in ../../../../uvm/uvm_vnode.c
(gdb) print pg
$1 = (struct vm_page *) 0xc40c4cd0
(gdb) print *pg
$2 = {rb_node = {rb_nodes = {0x0, 0x0}, rb_info = 3275287704}, pageq = {
    queue = {tqe_next = 0xc338ec98, tqe_prev = 0xc1425ad4}, list = {
      le_next = 0xc338ec98, le_prev = 0xc1425ad4}}, listq = {queue = {
      tqe_next = 0xc338ec98, tqe_prev = 0xc24efd8c}, list = {
      le_next = 0xc338ec98, le_prev = 0xc24efd8c}}, uanon = 0x0, 
  uobject = 0xd37c6684, offset = 18808832, flags = 140, loan_count = 0, 
  wire_count = 0, pqflags = 512, phys_addr = 3140771840, mdpage = {mp_pp = {
      pp_lock = {u = {mtxa_owner = 1537}}, pp_u = {u_pte = {pte_ptp = 0x0, 
          pte_va = 3504025600}, u_head = {pvh_list = {lh_first = 0x0}}, 
        u_link = 0x0}, pp_flags = 1 '\001', pp_attrs = 7 '\a'}}}
(gdb) print (struct vnode) *0xd37c6684
$4 = {v_uobj = {vmobjlock = {u = {mtxa_owner = 0}}, pgops = 0xc07c5620, 
    memq = {tqh_first = 0xc4a58630, tqh_last = 0xc32bf94c}, uo_npages = 5048, 
    uo_refs = 5, rb_tree = {rbt_root = 0xc3f03db0, rbt_ops = 0xc07c5564, 
      rbt_minmax = {0xc4a58630, 0xc32bf938}}}, v_cv = {cv_opaque = {0x0, 
      0xd37c66ac}, cv_wmesg = 0xc099cd33 "vnode"}, v_size = 20676608, 
  v_writesize = 20676608, v_iflag = 0, v_vflag = 48, v_uflag = 33554432, 
  v_numoutput = 0, v_writecount = 0, v_holdcnt = 1, v_synclist_slot = 0, 
  v_mount = 0xd020f000, v_op = 0xc4ba1000, v_freelist = {
    tqe_next = 0xd37c65cc, tqe_prev = 0xd3161860}, v_freelisthd = 0x0, 
  v_mntvnodes = {tqe_next = 0xd37c65cc, tqe_prev = 0xd37c67b0}, 
---Type <return> to continue, or q <return> to quit---
  v_cleanblkhd = {lh_first = 0x0}, v_dirtyblkhd = {lh_first = 0x0}, 
  v_synclist = {tqe_next = 0x0, tqe_prev = 0x0}, v_dnclist = {
    lh_first = 0x0}, v_nclist = {lh_first = 0xd37c5780}, v_un = {
    vu_mountedhere = 0xd512c138, vu_socket = 0xd512c138, 
    vu_specnode = 0xd512c138, vu_fifoinfo = 0xd512c138, 
    vu_ractx = 0xd512c138}, v_type = VREG, v_tag = VT_UFS, v_lock = {
    vl_lock = {rw_owner = 19}, vl_canrecurse = 0, vl_recursecnt = 0}, 
  v_vnlock = 0xd37c6724, v_data = 0xd37c79f4, v_klist = {slh_first = 0x0}}
(gdb) quit
testbox# exit
testbox# exit

Script done on Mon Jan 28 23:36:59 2013