misc/166340: Process under FreeBSD 9.0 hangs in uninterruptable sleep with apparently no syscall (empty wchan)

Wed Mar 28 13:40:12 UTC 2012

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

From: Christian Esken <Christian.Esken at trivago.com>
To: bug-followup at freebsd.org
Cc: Konstantin Belousov <kostikbel at gmail.com>, avg at freebsd.org
Subject: Re: misc/166340: Process under FreeBSD 9.0 hangs in uninterruptable
 sleep with apparently no syscall (empty wchan)
Date: Wed, 28 Mar 2012 15:30:29 +0200

 --=-KhwYlamRji7Rmc2IYneE
 Content-Type: text/plain; charset="UTF-8"
 Content-Transfer-Encoding: 7bit

 Yes. It sounds like a good idea to get a consistent "snapshot" of
 everything. So here it is. pid = 2527

 # ps -o user,pid,ppid,pending,caught,ignored,blocked,stat,wchan 2527
 USER     PID  PPID  PENDING   CAUGHT  IGNORED  BLOCKED STAT WCHAN
 nobody  2527  2525        0 80005006 79f88010        0 D    -     

 # ps -o pid,paddr 2527
   PID PADDR
  2527 fffffe025a476488

 # procstat -kk 2527
   PID    TID COMM             TDNAME           KSTACK
  2527 101206 serelog          -                mi_switch+0x2eb
 sleepq_check_timeout+0x9f sleepq_timedwait_sig+0x20 _sleep+0x2a1
 soreceive_generic+0xea9 kern_recvit+0x1c4 recvit+0x21 sys_recvfrom+0x82
 amd64_syscall+0x478 Xfast_syscall+0xf7 

 The kgdb data is attached.

 The smallest ktr trace I could produce is approximately 200MB. It's
 still rather big, so if you want a filtered version I would need to know
 how exactly this should be done (I haven't found a way to filter for a
 pid).
 Posting the full 200MB as followup is surely not appreciated, so I can
 either upload/send it somewhere or will find a place where you can
 download it. Any favored solution for you, Konstantin? We can use direct
 mail if preferred for discussing the details.

  Christian

 --=-KhwYlamRji7Rmc2IYneE
 Content-Disposition: attachment; filename="kgdb.2527.txt"
 Content-Type: text/plain; name="kgdb.2527.txt"; charset="UTF-8"
 Content-Transfer-Encoding: 7bit

 (kgdb) p *(struct proc *)0xfffffe025a476488
 $1 = {p_list = {le_next = 0xfffffe01a3f44910, le_prev = 0xfffffe02c73f8488}, p_threads = {tqh_first = 0xfffffe004edc0480, tqh_last = 0xfffffe004edc0490}, p_slock = {lock_object = {
       lo_name = 0xffffffff80d3f62c "process slock", lo_flags = 720896, lo_data = 0, lo_witness = 0xffffff8000689f80}, mtx_lock = 4}, p_ucred = 0xfffffe021f48d000, p_fd = 0xfffffe026f3bc600, p_fdtol = 0x0, 
   p_stats = 0xfffffe018e9c6a00, p_limit = 0xfffffe004ed0fb00, p_limco = {c_links = {sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0x0}}, c_time = 0, c_arg = 0x0, c_func = 0, c_lock = 0xfffffe025a476580, 
     c_flags = 0, c_cpu = 0}, p_sigacts = 0xfffffe035ebe5000, p_flag = 268452096, p_state = PRS_NORMAL, p_pid = 2527, p_hash = {le_next = 0x0, le_prev = 0xffffff80006aaef8}, p_pglist = {le_next = 0x0, 
     le_prev = 0xfffffe01a3827790}, p_pptr = 0xfffffe0008353910, p_sibling = {le_next = 0xfffffe004e8a6910, le_prev = 0xfffffe01b9f639f0}, p_children = {lh_first = 0x0}, p_mtx = {lock_object = {
       lo_name = 0xffffffff80d3f61f "process lock", lo_flags = 21168128, lo_data = 0, lo_witness = 0xffffff8000688400}, mtx_lock = 4}, p_ksi = 0xfffffe004e0f10e0, p_sigqueue = {sq_signals = {__bits = {16384, 0, 0, 0}}, 
     sq_kill = {__bits = {0, 0, 0, 0}}, sq_list = {tqh_first = 0xfffffe02f5841540, tqh_last = 0xfffffe0287f372a0}, sq_proc = 0xfffffe025a476488, sq_flags = 1}, p_oppid = 0, p_dbg_child = 0, p_vmspace = 0xfffffe018e5d7000, 
   p_swtick = 340601, p_realtimer = {it_interval = {tv_sec = 0, tv_usec = 0}, it_value = {tv_sec = 0, tv_usec = 0}}, p_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 = 0, ru_nivcsw = 0}, p_rux = {
     rux_runtime = 798780190, rux_uticks = 12, rux_sticks = 45, rux_iticks = 0, rux_uu = 84077, rux_su = 315289, rux_tu = 399367}, p_crux = {rux_runtime = 0, rux_uticks = 0, rux_sticks = 0, rux_iticks = 0, rux_uu = 0, 
     rux_su = 0, rux_tu = 0}, p_profthreads = 0, p_exitthreads = 0, p_traceflag = 0, p_tracevp = 0x0, p_tracecred = 0x0, p_textvp = 0xfffffe007d9de000, p_lock = 0, p_sigiolst = {slh_first = 0x0}, p_sigparent = 20, 
   p_sig = 0, p_code = 0, p_stops = 0, p_stype = 0, p_step = 0 '\0', p_pfsflags = 0 '\0', p_nlminfo = 0x0, p_aioinfo = 0x0, p_singlethread = 0x0, p_suspcount = 0, p_xthread = 0x0, p_boundary_count = 0, p_pendingcnt = 2, 
   p_itimers = 0x0, p_procdesc = 0x0, p_magic = 3203398350, p_osrel = 900044, p_comm = "serelog", '\0' <repeats 12 times>, p_pgrp = 0xfffffe01a3827780, p_sysent = 0xffffffff810f1380, p_args = 0xfffffe020cf38300, 
   p_cpulimit = 9223372036854775807, p_nice = 0 '\0', p_fibnum = 0, p_xstat = 0, p_klist = {kl_list = {slh_first = 0x0}, kl_lock = 0xffffffff807f6ce0 <knlist_mtx_lock>, kl_unlock = 0xffffffff807f6d00 <knlist_mtx_unlock>, 
     kl_assert_locked = 0xffffffff807f6fe0 <knlist_mtx_assert_locked>, kl_assert_unlocked = 0xffffffff807f6fc0 <knlist_mtx_assert_unlocked>, kl_lockarg = 0xfffffe025a476580}, p_numthreads = 1, p_md = {md_ldt = 0x0, 
     md_ldt_sd = {sd_lolimit = 0, sd_lobase = 0, sd_type = 0, sd_dpl = 0, sd_p = 0, sd_hilimit = 0, sd_xx0 = 0, sd_gran = 0, sd_hibase = 0, sd_xx1 = 0, sd_mbz = 0, sd_xx2 = 0}}, p_itcallout = {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}, p_acflag = 0, p_peers = 0x0, p_leader = 0xfffffe025a476488, p_emuldata = 0x0, 
   p_label = 0x0, p_sched = 0xfffffe025a476910, p_ktr = {stqh_first = 0x0, stqh_last = 0xfffffe025a4768c0}, p_mqnotifier = {lh_first = 0x0}, p_dtrace = 0x0, p_pwait = {cv_description = 0xffffffff80d4021d "ppwait", 
     cv_waiters = 0}, p_dbgwait = {cv_description = 0xffffffff80d40224 "dbgwait", cv_waiters = 0}, p_prev_runtime = 0, p_racct = 0x0}
 (kgdb) p/x *(((struct proc *)0xfffffe025a476488)->p_threads.tqh_first)
 $2 = {td_lock = 0xffffffff81179740, td_proc = 0xfffffe025a476488, td_plist = {tqe_next = 0x0, tqe_prev = 0xfffffe025a476498}, td_runq = {tqe_next = 0x0, tqe_prev = 0xffffffff81179968}, td_slpq = {tqe_next = 0x0, 
     tqe_prev = 0xfffffe01f7993280}, td_lockq = {tqe_next = 0x0, tqe_prev = 0xffffff800029a5f0}, td_hash = {le_next = 0x0, le_prev = 0xffffff80006b4ab0}, td_cpuset = 0xfffffe0008349dc8, td_sel = 0xfffffe020cfbe980, 
   td_sleepqueue = 0xfffffe01f7993280, td_turnstile = 0xfffffe030ac39a80, td_umtxq = 0xfffffe004e47a100, td_tid = 0x18b56, td_sigqueue = {sq_signals = {__bits = {0x0, 0x0, 0x0, 0x0}}, sq_kill = {__bits = {0x0, 0x0, 0x0, 
         0x0}}, sq_list = {tqh_first = 0x0, tqh_last = 0xfffffe004edc0530}, sq_proc = 0xfffffe025a476488, sq_flags = 0x1}, td_lend_user_pri = 0xff, td_flags = 0x20814, td_inhibitors = 0x2, td_pflags = 0x0, td_dupfd = 0x0, 
   td_sqqueue = 0x0, td_wchan = 0x0, td_wmesg = 0x0, td_lastcpu = 0x2, td_oncpu = 0xff, td_owepreempt = 0x0, td_tsqueue = 0xff, td_locks = 0x1, td_rw_rlocks = 0x0, td_lk_slocks = 0x0, td_blocked = 0x0, td_lockname = 0x0, 
   td_contested = {lh_first = 0x0}, td_sleeplocks = 0xffffffff812e1ee8, td_intr_nesting_level = 0x0, td_pinned = 0x0, td_ucred = 0xfffffe021f48d000, td_estcpu = 0x0, td_slptick = 0x0, td_blktick = 0x0, 
   td_swvoltick = 0x603cc, td_ru = {ru_utime = {tv_sec = 0x0, tv_usec = 0x0}, ru_stime = {tv_sec = 0x0, tv_usec = 0x0}, ru_maxrss = 0x17a0, ru_ixrss = 0x67c4, ru_idrss = 0x15af8, ru_isrss = 0x1c80, ru_minflt = 0x1e4, 
     ru_majflt = 0x0, ru_nswap = 0x0, ru_inblock = 0x0, ru_oublock = 0x0, ru_msgsnd = 0x294, ru_msgrcv = 0x526, ru_nsignals = 0x0, ru_nvcsw = 0xe8e, ru_nivcsw = 0x23c}, td_rux = {rux_runtime = 0x2f9c6b1e, 
     rux_uticks = 0xc, rux_sticks = 0x2d, rux_iticks = 0x0, rux_uu = 0x1486d, rux_su = 0x4cf99, rux_tu = 0x61807}, td_incruntime = 0x0, td_runtime = 0x2f9c6b1e, td_pticks = 0x0, td_sticks = 0x0, td_iticks = 0x0, 
   td_uticks = 0x0, td_intrval = 0x0, td_oldsigmask = {__bits = {0x0, 0x0, 0x0, 0x0}}, td_sigmask = {__bits = {0x0, 0x0, 0x0, 0x0}}, td_generation = 0x10ca, td_sigstk = {ss_sp = 0x0, ss_size = 0x0, ss_flags = 0x4}, 
   td_xsig = 0x0, td_profil_addr = 0x0, td_profil_ticks = 0x0, td_name = {0x73, 0x65, 0x72, 0x65, 0x6c, 0x6f, 0x67, 0x0 <repeats 13 times>}, td_fpop = 0x0, td_dbgflags = 0x0, td_dbgksi = {ksi_link = {tqe_next = 0x0, 
       tqe_prev = 0x0}, ksi_info = {si_signo = 0x0, si_errno = 0x0, si_code = 0x0, si_pid = 0x0, si_uid = 0x0, si_status = 0x0, si_addr = 0x0, si_value = {sival_int = 0x0, sival_ptr = 0x0, sigval_int = 0x0, 
         sigval_ptr = 0x0}, _reason = {_fault = {_trapno = 0x0}, _timer = {_timerid = 0x0, _overrun = 0x0}, _mesgq = {_mqd = 0x0}, _poll = {_band = 0x0}, __spare__ = {__spare1__ = 0x0, __spare2__ = {0x0, 0x0, 0x0, 0x0, 
             0x0, 0x0, 0x0}}}}, ksi_flags = 0x0, ksi_sigq = 0x0}, td_ng_outbound = 0x0, td_osd = {osd_nslots = 0x0, osd_slots = 0x0, osd_next = {le_next = 0x0, le_prev = 0x0}}, td_map_def_user = 0x0, td_dbg_forked = 0x0, 
   td_rqindex = 0x1e, td_base_pri = 0x7b, td_priority = 0x7b, td_pri_class = 0x3, td_user_pri = 0x7b, td_base_user_pri = 0x7b, td_pcb = 0xffffff8465698d10, td_state = 0x1, td_retval = {0x0, 0x4}, td_slpcallout = {
     c_links = {sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xffffff800078d8d0}}, c_time = 0x33ca8d, c_arg = 0xfffffe004edc0480, c_func = 0xffffffff80870e60, c_lock = 0x0, c_flags = 0x16, c_cpu = 0x2}, 
   td_frame = 0xffffff8465698c50, td_kstack_obj = 0xfffffe026f851510, td_kstack = 0xffffff8465695000, td_kstack_pages = 0x4, td_critnest = 0x1, td_md = {md_spinlock_count = 0x1, md_saved_flags = 0x246}, 
   td_sched = 0xfffffe004edc08a8, td_ar = 0x0, td_lprof = {{lh_first = 0x0}, {lh_first = 0x0}}, td_dtrace = 0x0, td_errno = 0x0, td_vnet = 0x0, td_vnet_lpush = 0x0, td_intr_frame = 0x0}

 --=-KhwYlamRji7Rmc2IYneE--