Re: Locked up nfsd after avg_at_ sendfile patch

on 13/10/2010 19:17 Sam Fourman Jr. said the following:
> full procstat -kk -a
> 
> http://www.puffybsd.com/fnfs.txt

It seems that thread 100281 is stuck waiting on zio and other threads are waiting
on it (because it set zilog->zl_writer and hasn't unset it) or other stuck threads
in chain:

 1081 100281 nfsd             nfsd: service    mi_switch+0x176
sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 zil_commit+0x3df
zfs_freebsd_fsync+0xd6 VOP_FSYNC_APV+0x6c nfsvno_fsync+0xb7
nfsrvd_commit+0xe3 nfsrvd_dorpc+0x39d nfssvc_program+0x447
svc_run_internal+0x6e9 svc_thread_start+0xb fork_exit+0x11b
fork_trampoline+0xe

Here's the zio that the thread waits on:
(kgdb) p *zio
$2 = {io_bookmark = {zb_objset = 0, zb_object = 0, zb_level = 0, zb_blkid = 0},
io_prop = {zp_checksum = ZIO_CHECKSUM_INHERIT, zp_compress = ZIO_COMPRESS_INHERIT,
zp_type = DMU_OT_NONE,
    zp_level = 0 '\0', zp_ndvas = 0 '\0'}, io_type = ZIO_TYPE_NULL, io_child_type
= ZIO_CHILD_LOGICAL, io_cmd = 0, io_priority = 0 '\0', io_reexecute = 0 '\0',
io_state = "\001", io_txg = 0,
  io_spa = 0xffffff00056c6000, io_bp = 0x0, io_bp_copy = {blk_dva = {{dva_word =
{0, 0}}, {dva_word = {0, 0}}, {dva_word = {0, 0}}}, blk_prop = 0, blk_pad = {0, 0,
0}, blk_birth = 0, blk_fill = 0,
    blk_cksum = {zc_word = {0, 0, 0, 0}}}, io_parent_list = {list_size = 48,
list_offset = 16, list_head = {list_next = 0xffffff00081aa0e8, list_prev =
0xffffff00081aa0e8}}, io_child_list = {
    list_size = 48, list_offset = 32, list_head = {list_next = 0xffffff0005fdc080,
list_prev = 0xffffff00082d84a0}}, io_walk_link = 0x0, io_logical = 0x0,
io_transform_stack = 0x0, io_ready = 0,
  io_done = 0, io_private = 0x0, io_bp_orig = {blk_dva = {{dva_word = {0, 0}},
{dva_word = {0, 0}}, {dva_word = {0, 0}}}, blk_prop = 0, blk_pad = {0, 0, 0},
blk_birth = 0, blk_fill = 0, blk_cksum = {
      zc_word = {0, 0, 0, 0}}}, io_data = 0x0, io_size = 0, io_vd = 0x0, io_vsd =
0x0, io_vsd_free = 0, io_offset = 0, io_deadline = 0, io_offset_node = {avl_child
= {0x0, 0x0}, avl_pcb = 0},
  io_deadline_node = {avl_child = {0x0, 0x0}, avl_pcb = 0}, io_vdev_tree = 0x0,
io_flags = 1, io_stage = ZIO_STAGE_CHECKSUM_VERIFY, io_pipeline = 33792,
io_orig_flags = 1,
  io_orig_stage = ZIO_STAGE_OPEN, io_orig_pipeline = 33792, io_error = 0,
io_child_error = {0, 0, 0}, io_children = {{0, 0}, {0, 0}, {0, 31}}, io_stall =
0xffffff00081aa288, io_gang_leader = 0x0,
  io_gang_tree = 0x0, io_executor = 0xffffff006b2d7450, io_waiter =
0xffffff006b2d7450, io_lock = {lock_object = {lo_name = 0xffffffff80c29a8b
"zio->io_lock", lo_flags = 40960000, lo_data = 0,
      lo_witness = 0x0}, sx_lock = 1}, io_cv = {cv_description =
0xffffffff80c29a9a "zio->io_cv)", cv_waiters = 1}, io_ena = 0, io_task = {ost_task
= {ta_running = 0x0, ta_link = {stqe_next = 0x0},
      ta_pending = 0, ta_priority = 0, ta_func = 0, ta_context = 0x0}, ost_func =
0, ost_arg = 0x0, ost_magic = 0}}

As you can see io_executor is not NULL and:
(kgdb) p *(struct thread*)zio->io_executor
$6 = {td_lock = 0xffffffff808eb2b8, td_proc = 0xffffff006b50c000, td_plist =
{tqe_next = 0xffffff006b2d78a0, tqe_prev = 0xffffff006b2d7010}, td_runq =
{tqe_next = 0x0,
    tqe_prev = 0xffffffff808d1308}, td_slpq = {tqe_next = 0x0, tqe_prev =
0xffffff000876a200}, td_lockq = {tqe_next = 0x0, tqe_prev = 0xffffff8233ffca40},
td_hash = {le_next = 0x0,
    le_prev = 0xffffff800022bdc8}, td_cpuset = 0xffffff00022cbdc8, td_sel = 0x0,
td_sleepqueue = 0x0, td_turnstile = 0xffffff006b035c00, td_umtxq =
0xffffff006b2cf700, td_tid = 100281,
  td_sigqueue = {sq_signals = {__bits = {0, 0, 0, 0}}, sq_kill = {__bits = {0, 0,
0, 0}}, sq_list = {tqh_first = 0x0, tqh_last = 0xffffff006b2d7500}, sq_proc =
0xffffff006b50c000, sq_flags = 1},
  td_flags = 524292, td_inhibitors = 2, td_pflags = 2097152, td_dupfd = 0,
td_sqqueue = 0, td_wchan = 0xffffff00081aa2d8, td_wmesg = 0xffffffff80c29a9a
"zio->io_cv)", td_lastcpu = 1 '\001',
  td_oncpu = 255 '�', td_owepreempt = 0 '\0', td_tsqueue = 0 '\0', td_locks =
-15929, td_rw_rlocks = 0, td_lk_slocks = 0, td_blocked = 0x0, td_lockname = 0x0,
td_contested = {lh_first = 0x0},
  td_sleeplocks = 0x0, td_intr_nesting_level = 0, td_pinned = 0, td_ucred =
0xffffff00022cda00, td_estcpu = 0, td_slptick = 1335552, td_blktick = 0, td_ru =
{ru_utime = {tv_sec = 0, tv_usec = 0},
    ru_stime = {tv_sec = 0, tv_usec = 0}, ru_maxrss = 1016, ru_ixrss = 9024,
ru_idrss = 1723584, ru_isrss = 72192, ru_minflt = 0, ru_majflt = 0, ru_nswap = 0,
ru_inblock = 0, ru_oublock = 0,
    ru_msgsnd = 59877, ru_msgrcv = 478009, ru_nsignals = 0, ru_nvcsw = 531964,
ru_nivcsw = 939}, td_rux = {rux_runtime = 14928141752, rux_uticks = 0, rux_sticks
= 564, rux_iticks = 0, rux_uu = 0,
    rux_su = 0, rux_tu = 0}, td_incruntime = 0, td_runtime = 14928141752,
td_pticks = 564, td_sticks = 0, td_iticks = 0, td_uticks = 0, td_intrval = 0,
td_oldsigmask = {__bits = {0, 0, 0, 0}},
  td_sigmask = {__bits = {0, 0, 0, 0}}, td_generation = 532903, td_sigstk = {ss_sp
= 0x0, ss_size = 0, ss_flags = 0}, td_xsig = 0, td_profil_addr = 0,
td_profil_ticks = 0,
  td_name = "nfsd: service\000\000\000\000\000\000", td_fpop = 0x0, td_dbgflags =
0, td_dbgksi = {ksi_link = {tqe_next = 0x0, tqe_prev = 0x0}, ksi_info = {si_signo
= 0, si_errno = 0, si_code = 0,
      si_pid = 0, si_uid = 0, si_status = 0, si_addr = 0x0, si_value = {sival_int
= 0, sival_ptr = 0x0, sigval_int = 0, sigval_ptr = 0x0}, _reason = {_fault =
{_trapno = 0}, _timer = {_timerid = 0,
          _overrun = 0}, _mesgq = {_mqd = 0}, _poll = {_band = 0}, __spare__ =
{__spare1__ = 0, __spare2__ = {0, 0, 0, 0, 0, 0, 0}}}}, ksi_flags = 0, ksi_sigq =
0x0}, td_ng_outbound = 0, td_osd = {
    osd_nslots = 1, osd_slots = 0xffffff0005e888a0, osd_next = {le_next =
0xffffff006b2d7bc0, le_prev = 0xffffffff808c9850}}, td_map_def_user = 0x0,
td_rqindex = 32 ' ', td_base_pri = 160 '�',
  td_priority = 128 '\200', td_pri_class = 3 '\003', td_user_pri = 128 '\200',
td_base_user_pri = 128 '\200', td_pcb = 0xffffff8234001d00, td_state =
TDS_INHIBITED, td_retval = {0, 0},
  td_slpcallout = {c_links = {sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0,
tqe_prev = 0xffffff80002ac7e0}}, c_time = 1340542, c_arg = 0xffffff006b2d7450,
    c_func = 0xffffffff803dcdd0 <sleepq_timeout>, c_lock = 0x0, c_flags = 16,
c_cpu = 1}, td_frame = 0xffffff8234001c40, td_kstack_obj = 0xffffff006b3d4288,
td_kstack = 18446743533416079360,
  td_kstack_pages = 4, td_critnest = 1, td_md = {md_spinlock_count = 1,
md_saved_flags = 582}, td_sched = 0xffffff006b2d7870, td_ar = 0x0, td_lprof =
{{lh_first = 0x0}, {lh_first = 0x0}},
  td_dtrace = 0xffffff000869a300, td_errno = 0, td_vnet = 0x0, td_vnet_lpush =
0x0, td_intr_frame = 0x0}

It's the same thread td_tid = 100281 - quite expected.

So, zio is in this stage and state:
p zio->io_stage
$7 = ZIO_STAGE_CHECKSUM_VERIFY
(kgdb) p zio->io_stall
$9 = (uint64_t *) 0xffffff00081aa288
(kgdb) p *zio->io_stall
$10 = 31
(kgdb) p zio->io_children
$11 = {{0, 0}, {0, 0}, {0, 31}}
(kgdb) p zio->io_child_type
$12 = ZIO_CHILD_LOGICAL

Further walking child zio hierarchy we reach the one that looks like this:
$59 = {io_bookmark = {zb_objset = 400, zb_object = 0, zb_level = -1, zb_blkid =
22437}, io_prop = {zp_checksum = ZIO_CHECKSUM_INHERIT, zp_compress =
ZIO_COMPRESS_INHERIT, zp_type = DMU_OT_NONE,
    zp_level = 0 '\0', zp_ndvas = 0 '\0'}, io_type = ZIO_TYPE_WRITE, io_child_type
= ZIO_CHILD_VDEV, io_cmd = 0, io_priority = 0 '\0', io_reexecute = 0 '\0',
io_state = "\001", io_txg = 0,
  io_spa = 0xffffff00056c6000, io_bp = 0xffffff01acdbaa30, io_bp_copy = {blk_dva =
{{dva_word = {12884902144, 1678614837}}, {dva_word = {0, 0}}, {dva_word = {0,
0}}}, blk_prop = 9225910817809957119,
    blk_pad = {0, 0, 0}, blk_birth = 236695, blk_fill = 0, blk_cksum = {zc_word =
{15569186404091016741, 3408946246337318984, 400, 22437}}}, io_parent_list =
{list_size = 48, list_offset = 16,
    list_head = {list_next = 0xffffff000826b7c0, list_prev = 0xffffff000826b7c0}},
io_child_list = {list_size = 48, list_offset = 32, list_head = {list_next =
0xffffff00080aca98,
      list_prev = 0xffffff00080aca98}}, io_walk_link = 0x0, io_logical =
0xffffff0008b8d660, io_transform_stack = 0x0, io_ready = 0, io_done =
0xffffffff80b99ab0 <vdev_mirror_child_done>,
  io_private = 0xffffff00b5f469a8, io_bp_orig = {blk_dva = {{dva_word =
{12884902144, 1678614837}}, {dva_word = {0, 0}}, {dva_word = {0, 0}}}, blk_prop =
9225910817809957119, blk_pad = {0, 0, 0},
    blk_birth = 236695, blk_fill = 0, blk_cksum = {zc_word =
{15569186404091016741, 3408946246337318984, 400, 22437}}}, io_data =
0xffffff80e6565000, io_size = 131072, io_vd = 0xffffff00084cd000,
  io_vsd = 0x0, io_vsd_free = 0, io_offset = 859454990848, io_deadline = 20883,
io_offset_node = {avl_child = {0x0, 0x0}, avl_pcb = 18446742974333891893},
io_deadline_node = {avl_child = {0x0, 0x0},
    avl_pcb = 1}, io_vdev_tree = 0xffffff00084cd578, io_flags = 179, io_stage =
ZIO_STAGE_VDEV_IO_START, io_pipeline = 47104, io_orig_flags = 131, io_orig_stage =
ZIO_STAGE_READY,
  io_orig_pipeline = 47104, io_error = 0, io_child_error = {0, 0, 0}, io_children
= {{0, 0}, {0, 0}, {0, 0}}, io_stall = 0x0, io_gang_leader = 0x0, io_gang_tree = 0x0,
  io_executor = 0xffffff000875a8a0, io_waiter = 0x0, io_lock = {lock_object =
{lo_name = 0xffffffff80c29a8b "zio->io_lock", lo_flags = 40960000, lo_data = 0,
lo_witness = 0x0}, sx_lock = 1},
  io_cv = {cv_description = 0xffffffff80c29a9a "zio->io_cv)", cv_waiters = 0},
io_ena = 0, io_task = {ost_task = {ta_running = 0x0, ta_link = {stqe_next = 0x0},
ta_pending = 0, ta_priority = 0,
      ta_func = 0, ta_context = 0x0}, ost_func = 0, ost_arg = 0x0, ost_magic = 0}}


Its executor:
(kgdb) p *(struct thread *)$59->io_executor
$61 = {td_lock = 0xffffffff808eb038, td_proc = 0xffffffff808c67a0, td_plist =
{tqe_next = 0xffffff000875d000, tqe_prev = 0xffffff000875a460}, td_runq =
{tqe_next = 0x0,
    tqe_prev = 0xffffffff808d0598}, td_slpq = {tqe_next = 0xffffff000875d000,
tqe_prev = 0xffffff000875a480}, td_lockq = {tqe_next = 0x0, tqe_prev =
0xffffff8000074af0}, td_hash = {le_next = 0x0,
    le_prev = 0xffffff800022ba40}, td_cpuset = 0xffffff00022cbdc8, td_sel = 0x0,
td_sleepqueue = 0x0, td_turnstile = 0xffffff000875c180, td_umtxq =
0xffffff000876f180, td_tid = 100168,
  td_sigqueue = {sq_signals = {__bits = {0, 0, 0, 0}}, sq_kill = {__bits = {0, 0,
0, 0}}, sq_list = {tqh_first = 0x0, tqh_last = 0xffffff000875a950}, sq_proc =
0xffffffff808c67a0, sq_flags = 1},
  td_flags = 524292, td_inhibitors = 2, td_pflags = 2097152, td_dupfd = 0,
td_sqqueue = 0, td_wchan = 0xffffff0005e91280, td_wmesg = 0xffffffff8068e670 "-",
td_lastcpu = 0 '\0', td_oncpu = 255 '�',
  td_owepreempt = 0 '\0', td_tsqueue = 0 '\0', td_locks = 391, td_rw_rlocks = 0,
td_lk_slocks = 0, td_blocked = 0x0, td_lockname = 0x0, td_contested = {lh_first =
0x0}, td_sleeplocks = 0x0,
  td_intr_nesting_level = 0, td_pinned = 0, td_ucred = 0xffffff00022ce000,
td_estcpu = 0, td_slptick = 1335656, td_blktick = 0, td_ru = {ru_utime = {tv_sec =
0, tv_usec = 0}, ru_stime = {tv_sec = 0,
      tv_usec = 0}, ru_maxrss = 0, ru_ixrss = 0, ru_idrss = 0, ru_isrss = 0,
ru_minflt = 0, ru_majflt = 0, ru_nswap = 0, ru_inblock = 0, ru_oublock = 0,
ru_msgsnd = 0, ru_msgrcv = 0,
    ru_nsignals = 0, ru_nvcsw = 9402, ru_nivcsw = 34}, td_rux = {rux_runtime =
630351495, rux_uticks = 0, rux_sticks = 19, rux_iticks = 0, rux_uu = 0, rux_su =
0, rux_tu = 0}, td_incruntime = 0,
  td_runtime = 630351495, td_pticks = 19, td_sticks = 0, td_iticks = 0, td_uticks
= 0, td_intrval = 0, td_oldsigmask = {__bits = {0, 0, 0, 0}}, td_sigmask = {__bits
= {0, 0, 0, 0}},
  td_generation = 9436, td_sigstk = {ss_sp = 0x0, ss_size = 0, ss_flags = 0},
td_xsig = 0, td_profil_addr = 0, td_profil_ticks = 0, td_name =
"zio_write_intr_high", td_fpop = 0x0, td_dbgflags = 0,
  td_dbgksi = {ksi_link = {tqe_next = 0x0, tqe_prev = 0x0}, ksi_info = {si_signo =
0, si_errno = 0, si_code = 0, si_pid = 0, si_uid = 0, si_status = 0, si_addr =
0x0, si_value = {sival_int = 0,
        sival_ptr = 0x0, sigval_int = 0, sigval_ptr = 0x0}, _reason = {_fault =
{_trapno = 0}, _timer = {_timerid = 0, _overrun = 0}, _mesgq = {_mqd = 0}, _poll =
{_band = 0}, __spare__ = {
          __spare1__ = 0, __spare2__ = {0, 0, 0, 0, 0, 0, 0}}}}, ksi_flags = 0,
ksi_sigq = 0x0}, td_ng_outbound = 0, td_osd = {osd_nslots = 0, osd_slots = 0x0,
osd_next = {le_next = 0x0,
      le_prev = 0x0}}, td_map_def_user = 0x0, td_rqindex = 17 '\021', td_base_pri
= 68 'D', td_priority = 68 'D', td_pri_class = 3 '\003', td_user_pri = 128 '\200',
td_base_user_pri = 128 '\200',
  td_pcb = 0xffffff8233dc8d00, td_state = TDS_INHIBITED, td_retval = {0, 0},
td_slpcallout = {c_links = {sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0,
tqe_prev = 0x0}}, c_time = 0, c_arg = 0x0,
    c_func = 0, c_lock = 0x0, c_flags = 16, c_cpu = 0}, td_frame =
0xffffff8233dc8c40, td_kstack_obj = 0xffffff0008733360, td_kstack =
18446743533413748736, td_kstack_pages = 4, td_critnest = 1,
  td_md = {md_spinlock_count = 1, md_saved_flags = 582}, td_sched =
0xffffff000875acc0, td_ar = 0x0, td_lprof = {{lh_first = 0x0}, {lh_first = 0x0}},
td_dtrace = 0xffffff00086d2300, td_errno = 0,
  td_vnet = 0x0, td_vnet_lpush = 0x0, td_intr_frame = 0x0}

This thread is:
procstat -kk -a | fgrep 100168
    0 100168 kernel           zio_write_intr_h mi_switch+0x176 sleepq_wait+0x42
_sleep+0x317 taskqueue_thread_loop+0xdc fork_exit+0x11b fork_trampoline+0xe

So, the last executor of the zio is zio_write_intr_high taskqueue thread.

That's where i got stuck.

-- 
Andriy Gapon