From owner-freebsd-current@FreeBSD.ORG Wed Dec 21 03:15:28 2005 Return-Path: X-Original-To: current@freebsd.org Delivered-To: freebsd-current@FreeBSD.ORG Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 4C36916A41F for ; Wed, 21 Dec 2005 03:15:28 +0000 (GMT) (envelope-from rmtodd@ichotolot.servalan.com) Received: from mx2.synetsystems.com (mx2.synetsystems.com [216.226.140.79]) by mx1.FreeBSD.org (Postfix) with ESMTP id B26F143D55 for ; Wed, 21 Dec 2005 03:15:27 +0000 (GMT) (envelope-from rmtodd@ichotolot.servalan.com) Received: by mx2.synetsystems.com (Postfix, from userid 66) id 31ABC290; Tue, 20 Dec 2005 22:15:26 -0500 (EST) Received: from localhost ([127.0.0.1]:49259 helo=ichotolot.servalan.com) by servalan.servalan.com with esmtp (Exim 4.54 (FreeBSD)) id 1EotYU-0002db-1i for current@freebsd.org; Tue, 20 Dec 2005 20:18:14 -0600 To: current@freebsd.org Date: Tue, 20 Dec 2005 20:18:13 -0600 From: Richard Todd Message-Id: <20051221031526.31ABC290@mx2.synetsystems.com> Cc: Subject: Bug in latest rev kern_acct.c: panic: Trying sleep, but thread marked as sleeping prohibited X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 21 Dec 2005 03:15:28 -0000 I've been getting this panic a good bit recently after updating -current sources a couple days ago. The panic occurs in the acctwatch() callout routine run from the clock ithread, apparently when it tries to sleep on a lock (which is, I gather, verboten in ithreads.) The panics seemed to occur randomly but, on reflection, always occured when 1) there was a good bit of system activity and 2) I had just done something to allocate or free enough space on /usr to cause accounting to be either suspended or resumed. and thus would cause the acctwatch() routine to have to do something. "make clean; make" in a big port seemed to be fairly effective in triggering the bug. :-) My previous kernel, which dated from Oct 24, didn't have this problem, which helps point suspicion at the latest rev of kern_acct.c (rev 1.76, date: 2005/11/12 10:45:13) which involved a bunch of changes in the lock handling of kernel accounting. GNU gdb 6.1.1 [FreeBSD] Copyright 2004 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-marcel-freebsd". Unread portion of the kernel message buffer: panic: Trying sleep, but thread marked as sleeping prohibited cpuid = 1 KDB: stack backtrace: kdb_backtrace(100,c3b7f900,c3b7f900,c0976100,c096f6a8) at kdb_backtrace+0x29 panic(c08a19c6,0,c096f6a8,c0970598,d85f0a14) at panic+0x114 sleepq_add(c096f6a8,c0970598,c089a4ab,1,c0970598,0,c089a875,96) at sleepq_add+0x8c cv_wait_unlock(c096f6a8,c0970598,180,d85f0a4c,c096f680) at cv_wait_unlock+0x171 cv_wait(c096f6a8,c0970598,0,c3b7c480,c3ddb1c0) at cv_wait+0x36 _sx_xlock(c096f680,c089a5a2,180) at _sx_xlock+0x68 acctwatch(0) at acctwatch+0x20 softclock(0) at softclock+0x22b ithread_execute_handlers(c3b7e8b0,c3b7c480) at ithread_execute_handlers+0xe6 ithread_loop(c3b488a0,d85f0d38,c3b488a0,c065098c,0) at ithread_loop+0x67 fork_exit(c065098c,c3b488a0,d85f0d38) at fork_exit+0xa4 fork_trampoline() at fork_trampoline+0x8 --- trap 0x1, eip = 0, esp = 0xd85f0d6c, ebp = 0 --- Uptime: 49m58s Dumping 637 MB (2 chunks) chunk 0: 1MB (159 pages) ... ok chunk 1: 637MB (163072 pages) 622 606 590 574 558 542 526 510 494 478 462 446 430 414 398 382 366 350 334 318 302 286 270 254 238 222 206 190 174 158 142 126 110 94 78 62 46 30 14 #0 doadump () at pcpu.h:165 165 __asm __volatile("movl %%fs:0,%0" : "=r" (td)); (kgdb) bt #0 doadump () at pcpu.h:165 #1 0xc0663880 in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:399 #2 0xc0663b95 in panic ( fmt=0xc08a19c6 "Trying sleep, but thread marked as sleeping prohibited") at /usr/src/sys/kern/kern_shutdown.c:555 #3 0xc06830fc in sleepq_add (wchan=0xc096f6a8, lock=0xc0970598, wmesg=0x0, flags=1) at /usr/src/sys/kern/subr_sleepqueue.c:273 #4 0xc063dd31 in cv_wait_unlock (cvp=0xc096f6a8, mp=0xc0970598) at /usr/src/sys/kern/kern_condvar.c:152 #5 0xc063db9a in cv_wait (cvp=0xc096f6a8, mp=0xc0970598) at /usr/src/sys/kern/kern_condvar.c:112 #6 0xc06697cc in _sx_xlock (sx=0xc096f680, file=0xc089a5a2 "/usr/src/sys/kern/kern_acct.c", line=384) at /usr/src/sys/kern/kern_sx.c:188 #7 0xc063bcdc in acctwatch (a=0x0) at /usr/src/sys/kern/kern_acct.c:384 #8 0xc0670bf7 in softclock (dummy=0x0) at /usr/src/sys/kern/kern_timeout.c:290 #9 0xc06508c2 in ithread_execute_handlers (p=0xc3b7e8b0, ie=0xc3b7c480) at /usr/src/sys/kern/kern_intr.c:662 #10 0xc06509f3 in ithread_loop (arg=0xc3b488a0) at /usr/src/sys/kern/kern_intr.c:745 #11 0xc064fb54 in fork_exit (callout=0xc065098c , arg=0xc3b488a0, frame=0xd85f0d38) at /usr/src/sys/kern/kern_fork.c:790 #12 0xc081ac7c in fork_trampoline () at /usr/src/sys/i386/i386/exception.s:198 (kgdb) fr 9 #9 0xc06508c2 in ithread_execute_handlers (p=0xc3b7e8b0, ie=0xc3b7c480) at /usr/src/sys/kern/kern_intr.c:662 662 ih->ih_handler(ih->ih_argument); (kgdb) p *p $1 = {p_list = {le_next = 0xc3b7eadc, le_prev = 0xc3b7e684}, p_ksegrps = { tqh_first = 0xc3b81d80, tqh_last = 0xc3b81d84}, p_threads = { tqh_first = 0xc3b7f900, tqh_last = 0xc3b7f908}, p_suspended = { tqh_first = 0x0, tqh_last = 0xc3b7e8c8}, p_ucred = 0xc3b79100, p_fd = 0xc3b85200, p_fdtol = 0x0, p_stats = 0xc3b67a00, p_limit = 0xc3b7a100, p_sigacts = 0xc3b8c000, p_flag = 524, p_sflag = 1, p_state = PRS_NORMAL, p_pid = 12, p_hash = {le_next = 0x0, le_prev = 0xc3b73030}, p_pglist = {le_next = 0xc3b7eadc, le_prev = 0xc3b7e6d4}, p_pptr = 0xc096f0c0, p_sibling = { le_next = 0xc3b7eadc, le_prev = 0xc3b7e6e0}, p_children = { lh_first = 0x0}, p_mtx = {mtx_object = {lo_class = 0xc0931b24, lo_name = 0xc089df1e "process lock", lo_type = 0xc089df1e "process lock", lo_flags = 4390912, lo_witness_data = {lod_list = {stqe_next = 0xc0981260}, lod_witness = 0xc0981260}}, mtx_lock = 4, mtx_recurse = 0}, p_ksi = 0x0, p_sigqueue = {sq_signals = {__bits = {0, 0, 0, 0}}, sq_list = { tqh_first = 0x0, tqh_last = 0xc3b7e948}, sq_proc = 0xc3b7e8b0, sq_flags = 1}, p_oppid = 0, p_vmspace = 0xc096f460, p_swtime = 2986, p_realtimer = {it_interval = {tv_sec = 0, tv_usec = 0}, it_value = { tv_sec = 0, tv_usec = 0}}, p_rux = {rux_runtime = {sec = 59, frac = 4151612463131724764}, rux_uticks = 0, rux_sticks = 0, rux_iticks = 157, rux_uu = 0, rux_su = 191765, rux_iu = 58831433}, p_crux = {rux_runtime = {sec = 0, frac = 0}, rux_uticks = 0, rux_sticks = 0, rux_iticks = 0, rux_uu = 0, rux_su = 0, rux_iu = 0}, p_profthreads = 0, p_maxthrwaits = 0, p_traceflag = 0, p_tracevp = 0x0, p_tracecred = 0x0, p_textvp = 0x0, p_lock = 1 '\001', 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_procscopegrp = 0x0, p_pendingcnt = 0, p_itimers = 0x0, p_magic = 3203398350, p_comm = "swi4: clock sio\000\000\000\000", p_pgrp = 0xc096f600, p_sysent = 0xc092cb80, p_args = 0x0, p_cpulimit = 9223372036854775807, p_nice = 0 '\0', p_xstat = 0, p_klist = {kl_list = {slh_first = 0x0}, kl_lock = 0xc064b31c , kl_unlock = 0xc064b338 , kl_locked = 0xc064b354 , kl_lockarg = 0xc3b7e918}, p_numthreads = 1, p_numksegrps = 1, p_md = {md_ldt = 0x0}, 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_mtx = 0x0, c_flags = 16}, p_acflag = 1, p_ru = 0x0, p_peers = 0x0, p_leader = 0xc3b7e8b0, p_emuldata = 0x0, p_label = 0x0, p_sched = 0xc3b7eadc, p_ktr = {stqh_first = 0x0, stqh_last = 0xc3b7ead0}, p_mqnotifier = {lh_first = 0x0}} (kgdb) fr 7 #7 0xc063bcdc in acctwatch (a=0x0) at /usr/src/sys/kern/kern_acct.c:384 384 sx_xlock(&acct_sx); (kgdb) q