illumos gate

Bayard Bell added a comment - 05/Aug/13 8:21 PM

Have had a quick look at vmdump.5. Jason has given us a useful means of understanding the pathology here by starting with "the smb_oplock_acquire() thread", so let's follow him on that, as we agree that smb_oplock_acquire() has the interesting characteristic of acquiring the oplock mutex and exclusive control of the vnode's mandatory lock in smb_oplock_acquire():

stack pointer for thread ffffff00f6ee4c60: ffffff00f6ee4610
[ ffffff00f6ee4610 _resume_from_idle+0xf1() ]
  ffffff00f6ee4640 swtch+0x145()
  ffffff00f6ee46f0 turnstile_block+0x760(0, 1, ffffff2246643d78, fffffffffbc08ef0, 0, 0)
  ffffff00f6ee4760 rw_enter_sleep+0x205(ffffff2246643d78, 1)
  ffffff00f6ee47d0 smb_lock_range_access+0x4f(ffffff2256ae96c0, ffffff2246643cc8, 0, ffffffffffffffff, 1)
  ffffff00f6ee4840 smb_range_check+0x5c(ffffff2256ae96c0, ffffff2246643cc8, 0, ffffffffffffffff, 1)
  ffffff00f6ee48a0 smb_oplock_acquire+0xfe(ffffff2256ae96c0, ffffff2246643cc8, fffffff67abf5978)
  ffffff00f6ee49c0 smb_open_subr+0xc89(ffffff2256ae96c0)
  ffffff00f6ee4a00 smb_common_open+0x78(ffffff2256ae96c0)
  ffffff00f6ee4ae0 smb_com_nt_create_andx+0x10f(ffffff2256ae96c0)
  ffffff00f6ee4b80 smb_dispatch_request+0x4a6(ffffff2256ae96c0)
  ffffff00f6ee4bb0 smb_session_worker+0x6c(ffffff2256ae96c0)
  ffffff00f6ee4c40 taskq_d_thread+0xb1(fffffff6f154d548)
  ffffff00f6ee4c50 thread_start+8()

Lo and behold, we are deadlocked with smb_lock_range() called from smb_com_locking_andx(), which has the same vnode and smb_node_t in its stack trace as we do, where the rwlock on which we're sleeping is again a non-exclusive hold on the vnode mandatory lock:

> ffffff2246643cc8::print -atx smb_node_t n_oplock.ol_mutex | ::mutex
            ADDR  TYPE             HELD MINSPL OLDSPL WAITERS
ffffff2246643e70 adapt ffffff00f6ee4c60      -      -     yes
> ffffff2246643cc8::print smb_node_t n_lock_list vp
n_lock_list = {
    n_lock_list.ll_lock = {
        _opaque = [ 0xffffff00f72a1c65 ]
    }
    n_lock_list.ll_list = {
        list_size = 0xc0
        list_offset = 0x10
        list_head = {
            list_next = 0xffffff24b82e0c50
            list_prev = 0xffffff24b82e0c50
        }
    }
    n_lock_list.ll_count = 0x1
    n_lock_list.ll_wrop = 0xa3
    n_lock_list.ll_mutex = {
        _opaque = [ 0 ]
    }
    n_lock_list.ll_deleteq = {
        list_size = 0x28
        list_offset = 0x8
        list_head = {
            list_next = 0xffffff2246643dc8
            list_prev = 0xffffff2246643dc8
        }
    }
    n_lock_list.ll_deleteq_count = 0
    n_lock_list.ll_flushing = 0 (0)
}
vp = 0xffffff355177e640
> ffffff355177e640::print vnode_t v_nbllock | ::rwlock
            ADDR      OWNER/COUNT FLAGS          WAITERS
ffffff355177e6a0        READERS=1  B011 ffffff00f72a1c60 (W)
                                     ||
                 WRITE_WANTED -------+|
                  HAS_WAITERS --------+

> ffffff2246643cc8::print smb_node_t n_lock_list.ll_lock | ::rwlock
            ADDR      OWNER/COUNT FLAGS          WAITERS
ffffff2246643d78 ffffff00f72a1c60  B101 ffffff00f6a86c60 (R)
                                    | | ffffff00f7085c60 (R)
                 WRITE_LOCKED ------+ | ffffff00f6ba2c60 (R)
                  HAS_WAITERS --------+ ffffff00f6f53c60 (R)
                                        ffffff00f6ccec60 (R)
                                        ffffff00f605cc60 (R)
                                        ffffff00f61cec60 (R)
                                        ffffff00f4997c60 (R)
                                        ffffff00f61a6c60 (R)
                                        ffffff00f62b3c60 (R)
                                        ffffff00f6ee4c60 (R)
> ffffff00f72a1c60::findstack -v
stack pointer for thread ffffff00f72a1c60: ffffff00f72a1580
[ ffffff00f72a1580 _resume_from_idle+0xf1() ]
  ffffff00f72a15b0 swtch+0x145()
  ffffff00f72a1660 turnstile_block+0x760(0, 0, ffffff355177e6a0, fffffffffbc08ef0, 0, 0)
  ffffff00f72a16d0 rw_enter_sleep+0x1a3(ffffff355177e6a0, 0)
  ffffff00f72a16f0 nbl_start_crit+0x19(ffffff355177e640, 0)
  ffffff00f72a1790 fs_frlock+0x229(ffffff355177e640, 2a, ffffff00f72a1960, 10002, 0, ffffff00f72a18e0, ffffffdd8032bc20, ffffffffc0101fb0)
  ffffff00f72a1830 zfs_frlock+0xd9(ffffff355177e640, 2a, ffffff00f72a1960, 10002, 0, ffffff00f72a18e0, ffffffdd8032bc20, ffffffffc0101fb0)
  ffffff00f72a18c0 fop_frlock+0x8c(ffffff355177e640, 2a, ffffff00f72a1960, 10002, 0, ffffff00f72a18e0, ffffffdd8032bc20, ffffffffc0101fb0)
  ffffff00f72a1950 smb_vop_frlock+0x7d(ffffff355177e640, ffffffdd8032bc20, 10002, ffffff00f72a1960)
  ffffff00f72a19e0 smb_fsop_frlock+0xdf(ffffff2246643cc8, ffffffcadad2dc00, 0, ffffffdd8032bc20)
  ffffff00f72a1a70 smb_lock_range+0x1b2(ffffff2256e75ce0, 7fffffa7, 14, 0, 65)
  ffffff00f72a1ae0 smb_com_locking_andx+0x318(ffffff2256e75ce0)
  ffffff00f72a1b80 smb_dispatch_request+0x4a6(ffffff2256e75ce0)
  ffffff00f72a1bb0 smb_session_worker+0x6c(ffffff2256e75ce0)
  ffffff00f72a1c40 taskq_d_thread+0xb1(fffffffe54eef460)
  ffffff00f72a1c50 thread_start+8()

Meanwhile, we again have a load of people trying to cash out before the zombie apocalypse by calling smb_oplock_break(), as well as some fresh braaaaains arriving who can't even make it off the dock here on zombie island:

> ffffff21ec9d5368::turnstile
            ADDR             SOBJ  WTRS EPRI             ITOR          PRIOINV
ffffff21ec9d5368 ffffff2246643e70  1073   99                0                0
> ::stacks -c mutex_vector_enter | ::stacks -c smb_oplock_break | ::findstack -v ! grep ^stack | wc -l
1072
> ffffff2246643e70::whatthread | ::stacks -c mutex_vector_enter | ::stacks -C smb_oplock_break | ::findstack -v
stack pointer for thread ffffff00f72ddc60: ffffff00f72dd9d0
[ ffffff00f72dd9d0 _resume_from_idle+0xf1() ]
  ffffff00f72dda00 swtch+0x145()
  ffffff00f72ddab0 turnstile_block+0x760(0, 0, ffffff2246643e70, fffffffffbc07d90, 0, 0)
  ffffff00f72ddb10 mutex_vector_enter+0x261(ffffff2246643e70)
  ffffff00f72ddb40 smb_oplock_broadcast+0x26(ffffff2246643cc8)
  ffffff00f72ddb60 smb_ofile_request_complete+0x24(ffffff353da30bf0)
  ffffff00f72ddb80 smb_request_free+0x23(ffffff253d465668)
  ffffff00f72ddbb0 smb_session_worker+0x91(ffffff253d465668)
  ffffff00f72ddc40 taskq_d_thread+0xb1(fffffff65dac5e08)
  ffffff00f72ddc50 thread_start+8()
> ffffff2246643e70::mutex
            ADDR  TYPE             HELD MINSPL OLDSPL WAITERS
ffffff2246643e70 adapt ffffff00f6ee4c60      -      -     yes
> ffffff00f6ee4c60::findstack -v
stack pointer for thread ffffff00f6ee4c60: ffffff00f6ee4610
[ ffffff00f6ee4610 _resume_from_idle+0xf1() ]
  ffffff00f6ee4640 swtch+0x145()
  ffffff00f6ee46f0 turnstile_block+0x760(0, 1, ffffff2246643d78, fffffffffbc08ef0, 0, 0)
  ffffff00f6ee4760 rw_enter_sleep+0x205(ffffff2246643d78, 1)
  ffffff00f6ee47d0 smb_lock_range_access+0x4f(ffffff2256ae96c0, ffffff2246643cc8, 0, ffffffffffffffff, 1)
  ffffff00f6ee4840 smb_range_check+0x5c(ffffff2256ae96c0, ffffff2246643cc8, 0, ffffffffffffffff, 1)
  ffffff00f6ee48a0 smb_oplock_acquire+0xfe(ffffff2256ae96c0, ffffff2246643cc8, fffffff67abf5978)
  ffffff00f6ee49c0 smb_open_subr+0xc89(ffffff2256ae96c0)
  ffffff00f6ee4a00 smb_common_open+0x78(ffffff2256ae96c0)
  ffffff00f6ee4ae0 smb_com_nt_create_andx+0x10f(ffffff2256ae96c0)
  ffffff00f6ee4b80 smb_dispatch_request+0x4a6(ffffff2256ae96c0)
  ffffff00f6ee4bb0 smb_session_worker+0x6c(ffffff2256ae96c0)
  ffffff00f6ee4c40 taskq_d_thread+0xb1(fffffff6f154d548)
  ffffff00f6ee4c50 thread_start+8()
> ffffff355177e640::whatthread | ::stacks -C smb_oplock_break | ::stacks -C nbl_start_crit | ::stacks -C smb_oplock_acquire | ::findstack -v
stack pointer for thread ffffff00f605cc60: ffffff00f605c890
[ ffffff00f605c890 _resume_from_idle+0xf1() ]
  ffffff00f605c8c0 swtch+0x145()
  ffffff00f605c970 turnstile_block+0x760(ffffff21ec9d96a0, 1, ffffff2246643d78, fffffffffbc08ef0, 0, 0)
  ffffff00f605c9e0 rw_enter_sleep+0x205(ffffff2246643d78, 1)
  ffffff00f605ca50 smb_lock_range_access+0x4f(ffffff2464d04958, ffffff2246643cc8, 4fd000, 8000, 0)
  ffffff00f605cab0 smb_common_read+0xba(ffffff2464d04958, ffffff23f689e000)
  ffffff00f605cae0 smb_com_read_andx+0x64(ffffff2464d04958)
  ffffff00f605cb80 smb_dispatch_request+0x4a6(ffffff2464d04958)
  ffffff00f605cbb0 smb_session_worker+0x6c(ffffff2464d04958)
  ffffff00f605cc40 taskq_d_thread+0xb1(fffffffe52e84ad0)
  ffffff00f605cc50 thread_start+8()
> ffffff21ec9d96a0::turnstile
            ADDR             SOBJ  WTRS EPRI             ITOR          PRIOINV
ffffff21ec9d96a0 ffffff2246643d78    11   99                0                0

This last bit brings up full circle. We have 11 waiters for ol->ol_mutex, all waiting in smb_common_read(), which is a further effect of deadlocking the smb_oplock_acquire() thread:

> ffffff2246643d78::walk blocked | ::stacks -C smb_common_read | ::findstack -v
stack pointer for thread ffffff00f6ee4c60: ffffff00f6ee4610
[ ffffff00f6ee4610 _resume_from_idle+0xf1() ]
  ffffff00f6ee4640 swtch+0x145()
  ffffff00f6ee46f0 turnstile_block+0x760(0, 1, ffffff2246643d78, fffffffffbc08ef0, 0, 0)
  ffffff00f6ee4760 rw_enter_sleep+0x205(ffffff2246643d78, 1)
  ffffff00f6ee47d0 smb_lock_range_access+0x4f(ffffff2256ae96c0, ffffff2246643cc8, 0, ffffffffffffffff, 1)
  ffffff00f6ee4840 smb_range_check+0x5c(ffffff2256ae96c0, ffffff2246643cc8, 0, ffffffffffffffff, 1)
  ffffff00f6ee48a0 smb_oplock_acquire+0xfe(ffffff2256ae96c0, ffffff2246643cc8, fffffff67abf5978)
  ffffff00f6ee49c0 smb_open_subr+0xc89(ffffff2256ae96c0)
  ffffff00f6ee4a00 smb_common_open+0x78(ffffff2256ae96c0)
  ffffff00f6ee4ae0 smb_com_nt_create_andx+0x10f(ffffff2256ae96c0)
  ffffff00f6ee4b80 smb_dispatch_request+0x4a6(ffffff2256ae96c0)
  ffffff00f6ee4bb0 smb_session_worker+0x6c(ffffff2256ae96c0)
  ffffff00f6ee4c40 taskq_d_thread+0xb1(fffffff6f154d548)
  ffffff00f6ee4c50 thread_start+8()

This looks to line up with the smb_node_t's various counters (1086 total references, 13 opens, 1073 opening):

> ffffff2246643cc8::print -atxnode_t n_refcnt n_open_count n_opening_count
ffffff2246643cf4 uint32_t n_refcnt = 0x43e
ffffff2246643d08 uint32_t n_open_count = 0xd
ffffff2246643d0c uint32_t n_opening_count = 0x431

Gordon Ross added a comment - 29/Aug/13 8:56 PM

Existing lock order: (note - broken!)
*A: smb_oplock_acquire thread:
A1: The oplock mutex:
mutex_enter(&ol->ol_mutex);
A2: The vnode vp->vnbllock (reader)
nbl_start_crit(node->vp, RW_READER)
A3: The lock range list: node->n_lock_list
(via smb_range_check, smb_lock_range_access)
XXX: Block trying to get READER
*B: smb_locking_andx thread:
(smb_lock_range, smb_unlock_range)
B1: The lock range list: node->n_lock_list
B2: The vnode vp->vnbllock (reader)
nbl_start_crit(node->vp, RW_READER)
(via smb_fsop_frlock, smb_vop_frlock)
XXX: Block trying to get READER
Notes:
VOP_FRLOCK also does nbl_start_crit, and at a level
below what we can control. That would appear to
force the order to be node->n_lock_list and then
the FS level vp->vnbllock.
That also seems more sensible order because conceptually
the SMB locks are "built on top of" the FS-level locks.
That's the order smb_locking_andx is using now, but
unfortunately, several things in smbsrv violate that
ordering. Examples: delete, oplock, rename