Date: Wed, 13 Oct 2010 21:43:12 +0300 From: Andriy Gapon <avg@freebsd.org> To: "Sam Fourman Jr." <sfourman@gmail.com> Cc: FreeBSD Current <Current@freebsd.org>, Martin Matuska <mm@freebsd.org> Subject: Re: Locked up nfsd after avg@ sendfile patch Message-ID: <4CB5FDC0.6000701@freebsd.org> In-Reply-To: <AANLkTikmVUTg24B2V6YSvxpLTwTaK5ciRUiMCqy-SUwj@mail.gmail.com> References: <AANLkTiktB6XD9bH45YQ-3eW3CzVRSXZRFsXozVWM3YpC@mail.gmail.com> <4CB5D5E1.9080505@freebsd.org> <AANLkTimrfVx9yp8cz6o5aSKzFvuDsO4E3QyvMsN9Eq%2Bn@mail.gmail.com> <AANLkTikmVUTg24B2V6YSvxpLTwTaK5ciRUiMCqy-SUwj@mail.gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?4CB5FDC0.6000701>