Date: Sun, 10 Apr 2011 15:37:59 +0200 From: Fabian Keil <freebsd-listen@fabiankeil.de> To: FreeBSD Current <freebsd-current@freebsd.org> Subject: panic: _mtx_lock_sleep: recursed on non-recursive mutex process lock @ /usr/src/sys/kern/kern_exit.c:912 Message-ID: <20110410153759.025aa4e2@fabiankeil.de>
next in thread | raw e-mail | index | archive | help
--Sig_/4Y4l7W31jqEr+83ZrQmmKDx
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: quoted-printable
The following panic seems to be reliably reproducible with sources
from yesterday (and today) by running claws-mail in X, switching to
the console and trying to attach gdb to it with 'gdb -p $(pgrep claws-mail)=
'.
gdb somehow fails to attach, and after leaving gdb the panic occurs.
fk@r500 /usr/crash $cat info.0=20
Dump header from device /dev/ada0s1b
Architecture: amd64 =20
Architecture Version: 2 =20
Dump Length: 347676672B (331 MB)
Blocksize: 512 =20
Dumptime: Sat Apr 9 22:48:15 2011
Hostname: r500.local =20
Magic: FreeBSD Kernel Dump =20
Version String: FreeBSD 9.0-CURRENT #284 r+1c500d9: Sat Apr 9 15:44:51 C=
EST 2011
fk@r500.local:/usr/obj/usr/src/sys/ZOEY
Panic String: _mtx_lock_sleep: recursed on non-recursive mutex process lo=
ck @ /usr/src/sys/kern/kern_exit.c:912
Dump Parity: 1557143341
Bounds: 0
Dump Status: good
fk@r500 /usr/crash $kgdb /boot/kernel/kernel vmcore.0=20
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 condition=
s.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "amd64-marcel-freebsd"...
Unread portion of the kernel message buffer:
panic: _mtx_lock_sleep: recursed on non-recursive mutex process lock @ /usr=
/src/sys/kern/kern_exit.c:912
cpuid =3D 0
KDB: enter: panic
panic: from debugger
cpuid =3D 0
Uptime: 3m48s
Physical memory: 1974 MB
Dumping 331 MB: 316 300 284 268 252 236 220 204 188 172 156 140 124 108 92 =
76 60 44 28 12
Reading symbols from /boot/kernel/zfs.ko...Reading symbols from /boot/kerne=
l/zfs.ko.symbols...done.
done.
[...]
Loaded symbols for /boot/kernel/drm.ko
#0 doadump () at /usr/src/sys/kern/kern_shutdown.c:250
250 if (textdump_pending)
(kgdb) where
#0 doadump () at /usr/src/sys/kern/kern_shutdown.c:250
#1 0xffffffff80531fb7 in kern_reboot (howto=3D260) at /usr/src/sys/kern/ke=
rn_shutdown.c:418
#2 0xffffffff80531a51 in panic (fmt=3DVariable "fmt" is not available.
) at /usr/src/sys/kern/kern_shutdown.c:591
#3 0xffffffff803202b7 in db_panic (addr=3DVariable "addr" is not available.
) at /usr/src/sys/ddb/db_command.c:478
#4 0xffffffff80320761 in db_command (last_cmdp=3D0xffffffff80c9fb60, cmd_t=
able=3DVariable "cmd_table" is not available.
) at /usr/src/sys/ddb/db_command.c:445
#5 0xffffffff803209b0 in db_command_loop () at /usr/src/sys/ddb/db_command=
.c:498
#6 0xffffffff80322a99 in db_trap (type=3DVariable "type" is not available.
) at /usr/src/sys/ddb/db_main.c:229
#7 0xffffffff80567ba1 in kdb_trap (type=3D3, code=3D0, tf=3D0xffffff800001=
7740) at /usr/src/sys/kern/subr_kdb.c:533
#8 0xffffffff807cee06 in trap (frame=3D0xffffff8000017740) at /usr/src/sys=
/amd64/amd64/trap.c:590
#9 0xffffffff807b9303 in calltrap () at /usr/src/sys/amd64/amd64/exception=
.S:228
#10 0xffffffff805679fb in kdb_enter (why=3D0xffffffff80955faf "panic", msg=
=3D0xa <Address 0xa out of bounds>) at cpufunc.h:63
#11 0xffffffff80531a60 in panic (fmt=3DVariable "fmt" is not available.
) at /usr/src/sys/kern/kern_shutdown.c:574
#12 0xffffffff805222f9 in _mtx_lock_sleep (m=3DVariable "m" is not availabl=
e.
) at /usr/src/sys/kern/kern_mutex.c:341
#13 0xffffffff805223a5 in _mtx_lock_flags (m=3DVariable "m" is not availabl=
e.
) at /usr/src/sys/kern/kern_mutex.c:203
#14 0xffffffff80503789 in proc_reparent (child=3D0xfffffe001290a000, parent=
=3D0xfffffe0012e48900) at /usr/src/sys/kern/kern_exit.c:912
#15 0xffffffff80503ed8 in kern_wait (td=3D0xffffff8000017adc, pid=3DVariabl=
e "pid" is not available.
) at /usr/src/sys/kern/kern_exit.c:708
#16 0xffffffff805043e5 in wait4 (td=3DVariable "td" is not available.
) at /usr/src/sys/kern/kern_exit.c:653
#17 0xffffffff805751ab in syscallenter (td=3D0xfffffe00028838c0, sa=3D0xfff=
fff8000017bb0) at /usr/src/sys/kern/subr_trap.c:344
#18 0xffffffff807ce8bc in syscall (frame=3D0xffffff8000017c50) at /usr/src/=
sys/amd64/amd64/trap.c:910
#19 0xffffffff807b95cd in Xfast_syscall () at /usr/src/sys/amd64/amd64/exce=
ption.S:384
#20 0x000000000040cb8c in ?? ()
Previous frame inner to this frame (corrupt stack?)
(kgdb) f 14
#14 0xffffffff80503789 in proc_reparent (child=3D0xfffffe001290a000, parent=
=3D0xfffffe0012e48900) at /usr/src/sys/kern/kern_exit.c:912
912 PROC_LOCK(parent);
(kgdb) p *child
$2 =3D {p_list =3D {le_next =3D 0x0, le_prev =3D 0xffffffff80cba328}, p_thr=
eads =3D {tqh_first =3D 0xfffffe001287c000, tqh_last =3D 0xfffffe001287c010=
}, p_slock =3D {lock_object =3D {
lo_name =3D 0xffffffff80954527 "process slock", lo_flags =3D 720896, =
lo_data =3D 0, lo_witness =3D 0x0}, mtx_lock =3D 4}, p_ucred =3D 0xfffffe00=
427b5a00, p_fd =3D 0x0,=20
p_fdtol =3D 0x0, p_stats =3D 0xfffffe0005d82800, p_limit =3D 0x0, p_limco=
=3D {c_links =3D {sle =3D {sle_next =3D 0x0}, tqe =3D {tqe_next =3D 0x0, t=
qe_prev =3D 0x0}}, c_time =3D 0, c_arg =3D 0x0,=20
c_func =3D 0, c_lock =3D 0xfffffe001290a0f8, c_flags =3D 0, c_cpu =3D 0=
}, p_sigacts =3D 0xfffffe0042634000, p_flag =3D 268460034, p_state =3D PRS_=
ZOMBIE, p_pid =3D 3515, p_hash =3D {
le_next =3D 0x0, le_prev =3D 0xffffff8000222dd8}, p_pglist =3D {le_next=
=3D 0x0, le_prev =3D 0xfffffe004a876790}, p_pptr =3D 0xfffffe0002881900, p=
_sibling =3D {
le_next =3D 0xfffffe0042640900, le_prev =3D 0xfffffe00028819f0}, p_chil=
dren =3D {lh_first =3D 0x0}, p_mtx =3D {lock_object =3D {lo_name =3D 0xffff=
ffff8095451a "process lock",=20
lo_flags =3D 21168128, lo_data =3D 0, lo_witness =3D 0x0}, mtx_lock =
=3D 18446741874728777920}, p_ksi =3D 0xfffffe0005c60150, p_sigqueue =3D {sq=
_signals =3D {__bits =3D {0, 0, 0, 0}},=20
sq_kill =3D {__bits =3D {0, 0, 0, 0}}, sq_list =3D {tqh_first =3D 0x0, =
tqh_last =3D 0xfffffe001290a140}, sq_proc =3D 0xfffffe001290a000, sq_flags =
=3D 1}, p_oppid =3D 0,=20
p_vmspace =3D 0xffffffff80cb7760, p_swtick =3D 21105, p_realtimer =3D {it=
_interval =3D {tv_sec =3D 0, tv_usec =3D 0}, it_value =3D {tv_sec =3D 0, tv=
_usec =3D 0}}, p_ru =3D {ru_utime =3D {
tv_sec =3D 0, tv_usec =3D 0}, ru_stime =3D {tv_sec =3D 0, tv_usec =3D=
0}, ru_maxrss =3D 21044, ru_ixrss =3D 544640, ru_idrss =3D 334244, ru_isrs=
s =3D 27264, ru_minflt =3D 2745,=20
ru_majflt =3D 2158, ru_nswap =3D 0, ru_inblock =3D 3, ru_oublock =3D 0,=
ru_msgsnd =3D 134, ru_msgrcv =3D 103, ru_nsignals =3D 0, ru_nvcsw =3D 473,=
ru_nivcsw =3D 533}, p_rux =3D {
rux_runtime =3D 2346291660, rux_uticks =3D 119, rux_sticks =3D 29, rux_=
iticks =3D 0, rux_uu =3D 948699, rux_su =3D 223223, rux_tu =3D 1171923}, p_=
crux =3D {rux_runtime =3D 0,=20
rux_uticks =3D 0, rux_sticks =3D 0, rux_iticks =3D 0, rux_uu =3D 0, rux=
_su =3D 0, rux_tu =3D 0}, p_profthreads =3D 0, p_exitthreads =3D 0, p_trace=
flag =3D 0, p_tracevp =3D 0x0,=20
p_tracecred =3D 0x0, p_textvp =3D 0x0, p_lock =3D 0, p_sigiolst =3D {slh_=
first =3D 0x0}, p_sigparent =3D 20, p_sig =3D 0, p_code =3D 0, p_stops =3D =
0, p_stype =3D 0, p_step =3D 0 '\0',=20
p_pfsflags =3D 0 '\0', p_nlminfo =3D 0x0, p_aioinfo =3D 0x0, p_singlethre=
ad =3D 0x0, p_suspcount =3D 0, p_xthread =3D 0xfffffe001287c000, p_boundary=
_count =3D 0, p_pendingcnt =3D 0,=20
p_itimers =3D 0x0, p_magic =3D 3203398350, p_osrel =3D 900034, p_comm =3D=
"claws-mail\000\000\000\000\000\000\000\000\000", p_pgrp =3D 0xfffffe004a8=
76780,=20
p_sysent =3D 0xffffffff80c6b320, p_args =3D 0xfffffe0005c8b3c0, p_cpulimi=
t =3D 9223372036854775807, p_nice =3D 0 '\0', p_fibnum =3D 0, p_xstat =3D 9=
, p_klist =3D {kl_list =3D {
slh_first =3D 0x0}, kl_lock =3D 0, kl_unlock =3D 0, kl_assert_locked =
=3D 0xffffffff804fd960 <knlist_mtx_assert_locked>,=20
kl_assert_unlocked =3D 0xffffffff804fd940 <knlist_mtx_assert_unlocked>,=
kl_lockarg =3D 0x0}, p_numthreads =3D 1, p_md =3D {md_ldt =3D 0x0, md_ldt_=
sd =3D {sd_lolimit =3D 0,=20
sd_lobase =3D 0, sd_type =3D 0, sd_dpl =3D 0, sd_p =3D 0, sd_hilimit =
=3D 0, sd_xx0 =3D 0, sd_gran =3D 0, sd_hibase =3D 0, sd_xx1 =3D 0, sd_mbz =
=3D 0, sd_xx2 =3D 0}}, p_itcallout =3D {
c_links =3D {sle =3D {sle_next =3D 0x0}, tqe =3D {tqe_next =3D 0x0, tqe=
_prev =3D 0x0}}, c_time =3D 0, c_arg =3D 0x0, c_func =3D 0, c_lock =3D 0x0,=
c_flags =3D 16, c_cpu =3D 0}, p_acflag =3D 16,=20
p_peers =3D 0x0, p_leader =3D 0xfffffe001290a000, p_emuldata =3D 0x0, p_l=
abel =3D 0x0, p_sched =3D 0xfffffe001290a480, p_ktr =3D {stqh_first =3D 0x0=
, stqh_last =3D 0xfffffe001290a430},=20
p_mqnotifier =3D {lh_first =3D 0x0}, p_dtrace =3D 0xfffffe0005c7a740, p_p=
wait =3D {cv_description =3D 0xffffffff80954fbe "ppwait", cv_waiters =3D 0}=
, p_dbgwait =3D {
cv_description =3D 0xffffffff80954fc5 "dbgwait", cv_waiters =3D 0}, p_p=
rev_runtime =3D 0, p_racct =3D 0x0}
(kgdb) p *parent
$3 =3D {p_list =3D {le_next =3D 0xfffffe004261b000, le_prev =3D 0xffffffff8=
0cba320}, p_threads =3D {tqh_first =3D 0xfffffe0005e0d8c0, tqh_last =3D 0xf=
ffffe0005e0d8d0}, p_slock =3D {
lock_object =3D {lo_name =3D 0xffffffff80954527 "process slock", lo_fla=
gs =3D 720896, lo_data =3D 0, lo_witness =3D 0x0}, mtx_lock =3D 4}, p_ucred=
=3D 0xfffffe00427b5a00,=20
p_fd =3D 0xfffffe00128b1c00, p_fdtol =3D 0x0, p_stats =3D 0xfffffe001290c=
800, p_limit =3D 0xfffffe00427b5300, p_limco =3D {c_links =3D {sle =3D {sle=
_next =3D 0x0}, tqe =3D {tqe_next =3D 0x0,=20
tqe_prev =3D 0x0}}, c_time =3D 0, c_arg =3D 0x0, c_func =3D 0, c_lo=
ck =3D 0xfffffe0012e489f8, c_flags =3D 0, c_cpu =3D 0}, p_sigacts =3D 0xfff=
ffe0012e9c000, p_flag =3D 268451842,=20
p_state =3D PRS_NORMAL, p_pid =3D 3407, p_hash =3D {le_next =3D 0x0, le_p=
rev =3D 0xffffff8000222a78}, p_pglist =3D {le_next =3D 0x0, le_prev =3D 0xf=
ffffe0005e59310},=20
p_pptr =3D 0xfffffe004261b000, p_sibling =3D {le_next =3D 0x0, le_prev =
=3D 0xfffffe004261b0f0}, p_children =3D {lh_first =3D 0x0}, p_mtx =3D {lock=
_object =3D {
lo_name =3D 0xffffffff8095451a "process lock", lo_flags =3D 21168128,=
lo_data =3D 0, lo_witness =3D 0x0}, mtx_lock =3D 18446741874728777920}, p_=
ksi =3D 0xfffffe0005c5eb60,=20
p_sigqueue =3D {sq_signals =3D {__bits =3D {0, 0, 0, 0}}, sq_kill =3D {__=
bits =3D {0, 0, 0, 0}}, sq_list =3D {tqh_first =3D 0x0, tqh_last =3D 0xffff=
fe0012e48a40},=20
sq_proc =3D 0xfffffe0012e48900, sq_flags =3D 1}, p_oppid =3D 0, p_vmspa=
ce =3D 0xfffffe00128c5310, p_swtick =3D 12384, p_realtimer =3D {it_interval=
=3D {tv_sec =3D 0, tv_usec =3D 0},=20
it_value =3D {tv_sec =3D 0, tv_usec =3D 0}}, p_ru =3D {ru_utime =3D {tv=
_sec =3D 0, tv_usec =3D 0}, ru_stime =3D {tv_sec =3D 0, tv_usec =3D 0}, ru_=
maxrss =3D 0, ru_ixrss =3D 0, ru_idrss =3D 0,=20
ru_isrss =3D 0, ru_minflt =3D 0, ru_majflt =3D 0, ru_nswap =3D 0, ru_in=
block =3D 0, ru_oublock =3D 0, ru_msgsnd =3D 0, ru_msgrcv =3D 0, ru_nsignal=
s =3D 0, ru_nvcsw =3D 0, ru_nivcsw =3D 0},=20
p_rux =3D {rux_runtime =3D 1633285860, rux_uticks =3D 63, rux_sticks =3D =
44, rux_iticks =3D 0, rux_uu =3D 482021, rux_su =3D 336649, rux_tu =3D 8186=
71}, p_crux =3D {rux_runtime =3D 770335510,=20
rux_uticks =3D 11, rux_sticks =3D 39, rux_iticks =3D 0, rux_uu =3D 8494=
7, rux_su =3D 301176, rux_tu =3D 386124}, p_profthreads =3D 0, p_exitthread=
s =3D 0, p_traceflag =3D 0,=20
p_tracevp =3D 0x0, p_tracecred =3D 0x0, p_textvp =3D 0xfffffe00427ae780, =
p_lock =3D 0, p_sigiolst =3D {slh_first =3D 0x0}, p_sigparent =3D 20, p_sig=
=3D 0, p_code =3D 0, p_stops =3D 0,=20
p_stype =3D 0, p_step =3D 0 '\0', p_pfsflags =3D 0 '\0', p_nlminfo =3D 0x=
0, p_aioinfo =3D 0x0, p_singlethread =3D 0x0, p_suspcount =3D 0, p_xthread =
=3D 0x0, p_boundary_count =3D 0,=20
p_pendingcnt =3D 0, p_itimers =3D 0x0, p_magic =3D 3203398350, p_osrel =
=3D 900025, p_comm =3D "bash", '\0' <repeats 15 times>, p_pgrp =3D 0xfffffe=
0005e59300,=20
p_sysent =3D 0xffffffff80c6b320, p_args =3D 0xfffffe0002ba2880, p_cpulimi=
t =3D 9223372036854775807, p_nice =3D 0 '\0', p_fibnum =3D 0, p_xstat =3D 0=
, p_klist =3D {kl_list =3D {
slh_first =3D 0x0}, kl_lock =3D 0xffffffff804fd660 <knlist_mtx_lock>,=
kl_unlock =3D 0xffffffff804fd680 <knlist_mtx_unlock>,=20
kl_assert_locked =3D 0xffffffff804fd960 <knlist_mtx_assert_locked>, kl_=
assert_unlocked =3D 0xffffffff804fd940 <knlist_mtx_assert_unlocked>, kl_loc=
karg =3D 0xfffffe0012e489f8},=20
p_numthreads =3D 1, p_md =3D {md_ldt =3D 0x0, md_ldt_sd =3D {sd_lolimit =
=3D 0, sd_lobase =3D 0, sd_type =3D 0, sd_dpl =3D 0, sd_p =3D 0, sd_hilimit=
=3D 0, sd_xx0 =3D 0, sd_gran =3D 0,=20
sd_hibase =3D 0, sd_xx1 =3D 0, sd_mbz =3D 0, sd_xx2 =3D 0}}, p_itcall=
out =3D {c_links =3D {sle =3D {sle_next =3D 0x0}, tqe =3D {tqe_next =3D 0x0=
, tqe_prev =3D 0x0}}, c_time =3D 0,=20
c_arg =3D 0x0, c_func =3D 0, c_lock =3D 0x0, c_flags =3D 16, c_cpu =3D =
0}, p_acflag =3D 0, p_peers =3D 0x0, p_leader =3D 0xfffffe0012e48900, p_emu=
ldata =3D 0x0, p_label =3D 0x0,=20
p_sched =3D 0xfffffe0012e48d80, p_ktr =3D {stqh_first =3D 0x0, stqh_last =
=3D 0xfffffe0012e48d30}, p_mqnotifier =3D {lh_first =3D 0x0}, p_dtrace =3D =
0xfffffe0005d85b80, p_pwait =3D {
cv_description =3D 0xffffffff80954fbe "ppwait", cv_waiters =3D 0}, p_db=
gwait =3D {cv_description =3D 0xffffffff80954fc5 "dbgwait", cv_waiters =3D =
0}, p_prev_runtime =3D 0,=20
p_racct =3D 0x0}
I'm not sure if switching to the console first matters.
Before the panic, the states of gdb and claws-mail were:
fk@r500 ~ $procstat -kk $(pgrep claws-mail)
PID TID COMM TDNAME KSTACK =
=20
15813 100528 claws-mail initial thread mi_switch+0x21d thread_suspe=
nd_switch+0x103 ptracestop+0x7a cursig+0x4af ast+0x198 doreti_ast+0x1f=20
fk@r500 ~ $procstat -kk $(pgrep gdb)
PID TID COMM TDNAME KSTACK =
=20
15823 100928 gdb - mi_switch+0x21d sleepq_switc=
h+0x123 sleepq_catch_signals+0x2a2 sleepq_wait_sig+0x16 _cv_wait_sig+0x14c =
tty_wait+0x48 ttydisc_read+0xd4 ttydev_read+0xab devfs_read_f+0x88 dofilere=
ad+0xa1 kern_readv+0x60 read+0x55 syscallenter+0x1cb syscall+0x4c Xfast_sys=
call+0xdd=20
I believe I also reproduced the problem with a kernel from Tuesday,
but dumping core from ddb failed so I can't check.
I cannot reproduce the panic with a kernel from 2011-03-12
which I haven't deleted yet, but didn't try to bisect it further.
gdb can't attach to claws-mail either, but the panic doesn't occur:
fk@r500 ~ $gdb -p $(pgrep claws-mail)
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 condition=
s.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "amd64-marcel-freebsd".
Attaching to process 3432
/usr/src/gnu/usr.bin/gdb/libgdb/../../../../contrib/gdb/gdb/solib-svr4.c:14=
44: i
nternal-error: legacy_fetch_link_map_offsets called without legacy link_map=
supp
ort enabled.
A problem internal to GDB has been detected,
further debugging may prove unreliable.
Quit this debugging session? (y or n) y
/usr/src/gnu/usr.bin/gdb/libgdb/../../../../contrib/gdb/gdb/solib-svr4.c:14=
44: i
nternal-error: legacy_fetch_link_map_offsets called without legacy link_map=
supp
ort enabled.
A problem internal to GDB has been detected,
further debugging may prove unreliable.
Create a core file of GDB? (y or n) n
In related news, the kernel from yesterday also seems to panic/hang/whatever
when claws-mail segfaults due to an invalid memory access, but as I was run=
ning
X, I got no core dumps for those problems either.
Fabian
--Sig_/4Y4l7W31jqEr+83ZrQmmKDx
Content-Type: application/pgp-signature; name=signature.asc
Content-Disposition: attachment; filename=signature.asc
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.17 (FreeBSD)
iEYEARECAAYFAk2hssMACgkQBYqIVf93VJ0bJQCeJwg50nhOvOXneJOKmkSHwlR5
b/QAnAhWDnDvo45HlOe+wpGcKGixfp9m
=Epdi
-----END PGP SIGNATURE-----
--Sig_/4Y4l7W31jqEr+83ZrQmmKDx--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20110410153759.025aa4e2>