Panic on shutdown in kern/turnstile.c:243 - propagate_priority

Tue Mar 15 10:07:51 PST 2005

A Panic happend to me on shutdown. It seem's to be a `this shouldn't happen'
scenario in subr_turnstile.c:propagate_priority(...) :
        /*
         * If we aren't blocked on a lock, we should be.
         */
        KASSERT(TD_ON_LOCK(td), (	/*We weren't ;(*/
            "process %d(%s):%d holds %s but isn't blocked on a lock\n",
            td->td_proc->p_pid, td->td_proc->p_comm, td->td_state,
            ts->ts_lockobj->lo_name));

        /*
         * Pick up the lock that td is blocked on.
         */
        ts = td->td_blocked;		/* oopppsssss */
        MPASS(ts != NULL);
        tc = TC_LOOKUP(ts->ts_lockobj);

I didn't have INVARIANTS, so the KASSERT wasn't there :(, system panicked
on dereferencing NULL ptr. Now I'd like to send a pr with at least what 
kassert produces, but ts->ts_lockobj->lo_name is no longer there in the
saved core. How to find the offending lock? Or should I send the PR with
only data below?

The kernel was GENERIC with:
options        SCHED_ULE
options        DDB
options        KDB
options        KDB_TRACE
options        DDB_NUMSYM
options        KDB_UNATTENDED

makeoptions            DEBUG=-g
makeoptions            MODULES_OVERRIDE="linux sound/sound acpi/acpi sound/driver/emu10k1"
..and some drivers disabled for hw I don't have.

Xorg uses uses nVidia driver from nvidia.com

-----------------------------------------
kernel trap 12 with interrupts disabled

Fatal trap 12: page fault while in kernel mode
fault virtual address   = 0x24
fault code              = supervisor read, page not present
instruction pointer     = 0x8:0xc05116e7
stack pointer           = 0x10:0xc7cb8c30
frame pointer           = 0x10:0xc7cb8c44
code segment            = base 0x0, limit 0xfffff, type 0x1b
                        = DPL 0, pres 1, def32 1, gran 1
processor eflags        = resume, IOPL = 0
current process         = 3 (g_up)
panic: from debugger
KDB: stack backtace:
Uptime: 4h5m34s
Dumping 127 MB

root at lolownia[/var/crash]:> cat info.0 
Good dump found on device /dev/ad5s1b
  Architecture: i386
  Architecture version: 1
  Dump length: 134152192B (127 MB)
  Blocksize: 512
  Dumptime: Sun Mar 13 16:54:10 2005
  Hostname: lolownia
  Versionstring: FreeBSD 5.4-PRERELEASE #5: Sat Mar 12 16:01:05 CET 2005
    lol at lolownia:/usr/src/sys/i386/compile/ROBAL
  Panicstring: from debugger
  Bounds: 0

GDB will not be able to debug user-mode threads: /usr/lib/libthread_db.so: Undefined symbol "ps_pglobal_lookup"]
GNU gdb 6.1.1 [FreeBSD]
(...)
This GDB was configured as "i386-marcel-freebsd".
doadump () at pcpu.h:159
(kgdb) bt
#0  doadump () at pcpu.h:159
#1  0xc04f27b5 in boot (howto=260) at ../../../kern/kern_shutdown.c:410
#2  0xc04f2a9c in panic (fmt=0xc067d3e8 "from debugger")
    at ../../../kern/kern_shutdown.c:566
#3  0xc0443ff5 in db_panic (addr=-1068427545, have_addr=0, count=-1, 
    modif=0xc7cb8a88 "") at ../../../ddb/db_command.c:435
#4  0xc0443f8c in db_command (last_cmdp=0xc06dbfe4, cmd_table=0x0, 
    aux_cmd_tablep=0xc06a7990, aux_cmd_tablep_end=0xc06a7994)
    at ../../../ddb/db_command.c:349
#5  0xc0444054 in db_command_loop () at ../../../ddb/db_command.c:455
#6  0xc0445be9 in db_trap (type=12, code=0) at ../../../ddb/db_main.c:221
#7  0xc050a51a in kdb_trap (type=12, code=0, tf=0xc7cb8bf0)
    at ../../../kern/subr_kdb.c:418
#8  0xc0654c71 in trap_fatal (frame=0xc7cb8bf0, eva=36)
    at ../../../i386/i386/trap.c:804
#9  0xc0654411 in trap (frame=
      {tf_fs = 24, tf_es = -1049952240, tf_ds = 16, tf_edi = -1049863440, tf_esi = -1049130256, tf_ebp = -942961596, tf_isp = -942961636, tf_ebx = -1049863440, tf_edx = -1048125876, tf_ecx = -1066432512, tf_eax = 0, tf_trapno = 12, tf_err = 0, tf_eip = -1068427545, tf_cs = 8, tf_eflags = 65683, tf_esp = 76, tf_ss = 0})
    at ../../../i386/i386/trap.c:247
#10 0xc0644afa in calltrap () at ../../../i386/i386/exception.s:140
#11 0x00000018 in ?? ()
#12 0xc16b0010 in ?? ()
#13 0x00000010 in ?? ()
#14 0xc16c5af0 in ?? ()
#15 0xc1778af0 in ?? ()
#16 0xc7cb8c44 in ?? ()
#17 0xc7cb8c1c in ?? ()
#18 0xc16c5af0 in ?? ()
#19 0xc186de4c in ?? ()
#20 0xc06f8800 in vm_page_queue_free_mtx ()
#21 0x00000000 in ?? ()
#22 0x0000000c in ?? ()
#23 0x00000000 in ?? ()
#24 0xc05116e7 in propagate_priority (td=0xc1778af0)
    at ../../../kern/subr_turnstile.c:243
#25 0xc0511e90 in turnstile_wait (ts=0xc186de40, lock=0xc06f8800, 
    owner=0xc1778af0) at ../../../kern/subr_turnstile.c:556
#26 0xc04e9f09 in _mtx_lock_sleep (m=0xc06f8800, td=0xc16c5af0, opts=0, 
    file=0x0, line=0) at ../../../kern/kern_mutex.c:560
#27 0xc0608ae6 in swp_pager_async_iodone (bp=0xc3c600b0)
    at ../../../vm/swap_pager.c:1433
#28 0xc0539247 in bufdone (bp=0xc3c600b0) at ../../../kern/vfs_bio.c:3146
#29 0xc060a196 in swapgeom_done (bp2=0xc1f434a4) at ../../../vm/swap_pager.c:2353
#30 0xc0538ee6 in biodone (bp=0xc1f434a4) at ../../../kern/vfs_bio.c:3001
#31 0xc04bb15f in g_io_schedule_up (tp=0xc16c5af0) at ../../../geom/geom_io.c:491
#32 0xc04bb34a in g_up_procbody () at ../../../geom/geom_kern.c:92
#33 0xc04dd4dc in fork_exit (callout=0xc04bb330 <g_up_procbody>, arg=0x0, 
    frame=0xc7cb8d48) at ../../../kern/kern_fork.c:790
#34 0xc0644b5c in fork_trampoline () at ../../../i386/i386/exception.s:209

(kgdb) f 24
#24 0xc05116e7 in propagate_priority (td=0xc1778af0)
    at ../../../kern/subr_turnstile.c:243
243			ts = td->td_blocked;
(kgdb) list
238			    ts->ts_lockobj->lo_name));
239	
240			/*
241			 * Pick up the lock that td is blocked on.
242			 */
243			ts = td->td_blocked;
244			MPASS(ts != NULL);
245			tc = TC_LOOKUP(ts->ts_lockobj);
246			mtx_lock_spin(&tc->tc_lock);
247	
(kgdb) p  ts
$1 = (struct turnstile *) 0x0
(kgdb) p *td
$2 = {td_proc = 0xc199aa98, td_ksegrp = 0xc199b000, td_plist = {tqe_next = 0x0, 
    tqe_prev = 0xc199aaa8}, td_kglist = {tqe_next = 0x0, tqe_prev = 0xc199b00c}, 
  td_slpq = {tqe_next = 0x0, tqe_prev = 0xc1d6d540}, td_lockq = {tqe_next = 0x0, 
    tqe_prev = 0x0}, td_runq = {tqe_next = 0x0, tqe_prev = 0x0}, td_selq = {
    tqh_first = 0x0, tqh_last = 0xc1778b20}, td_sleepqueue = 0x0, 
  td_turnstile = 0xc176ca00, td_tid = 100067, td_flags = 0, td_inhibitors = 2, 
  td_pflags = 0, td_dupfd = 0, td_wchan = 0xc1b4c2cc, 
  td_wmesg = 0xc069c87f "user map", td_lastcpu = 0 '\0', td_oncpu = 255 '˙', 
  td_locks = -5174, td_blocked = 0x0, td_ithd = 0x0, td_lockname = 0x0, 
  td_contested = {lh_first = 0xc186de40}, td_sleeplocks = 0x0, 
  td_intr_nesting_level = 0, td_pinned = 0, td_mailbox = 0x0, 
  td_ucred = 0xc1c7a680, td_standin = 0x0, td_prticks = 0, td_upcall = 0x0, 
  td_sticks = 23590, td_uuticks = 0, td_usticks = 0, td_intrval = 0, 
  td_oldsigmask = {__bits = {0, 0, 0, 0}}, td_sigmask = {__bits = {4194304, 0, 
      0, 0}}, td_siglist = {__bits = {0, 0, 0, 0}}, td_waitset = 0x0, td_umtx = {
    tqe_next = 0x0, tqe_prev = 0x0}, td_generation = 1048882, td_sigstk = {
    ss_sp = 0x0, ss_size = 0, ss_flags = 4}, td_kflags = 0, td_xsig = 0, 
  td_profil_addr = 0, td_profil_ticks = 0, td_base_pri = 160 ' ', 
  td_priority = 76 'L', td_pcb = 0xc82deda0, td_state = TDS_INHIBITED, 
  td_retval = {0, 721322004}, td_slpcallout = {c_links = {sle = {
        sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xc3c42fb8}}, 
    c_time = 1475331, c_arg = 0xc1778af0, c_func = 0, c_flags = 8}, 
  td_frame = 0xc82ded48, td_kstack_obj = 0xc143ee70, td_kstack = 3358445568, 
  td_kstack_pages = 2, td_altkstack_obj = 0x0, td_altkstack = 0, 
  td_altkstack_pages = 0, td_critnest = 1, td_md = {md_savecrit = 582}, 
  td_sched = 0xc1778c44}
(kgdb) p td->td_inhibitors
$3 = 2
(kgdb) p *td->td_proc->p_comm
$6 = "Xorg\000\000r", '\0' <repeats 12 times>
(kgdb) p td->td_state
$7 = TDS_INHIBITED

Best regards to the FreeBSD Community,

-- 
m.