Date: Wed, 18 Apr 2007 09:19:18 +0400 (MSD) From: Maxim Konovalov <maxim@macomnet.ru> To: stable@freebsd.org Subject: Re: panic: spin lock held too long Message-ID: <20070418090701.N46799@mp2.macomnet.net> In-Reply-To: <20070410103918.N81063@mp2.macomnet.net> References: <20070410103918.N81063@mp2.macomnet.net>
next in thread | previous in thread | raw e-mail | index | archive | help
More info:
db> show pcpu
cpuid = 0
curthread = 0xceb11c00: pid 56619 "chmod"
curpcb = 0xebd33d90
fpcurthread = none
idlethread = 0xc92c9a80: pid 13 "idle: cpu0"
APIC ID = 0
currentldt = 0x50
spin locks held:
db> show locks
exclusive sleep mutex pmap r = 0 (0xc0a83880) locked @
/usr/src/sys/i386/i386/pmap.c:1577
exclusive sleep mutex vm page queue mutex r = 0 (0xc0a5dc80) locked @
/usr/src/sys/i386/i386/pmap.c:1575
exclusive sx user map r = 0 (0xc1068404) locked @
/usr/src/sys/vm/vm_kern.c:466
db>
pid ppid pgrp uid state wmesg wchan cmd
56619 86677 11094 0 R CPU 0 chmod
41930 763 763 5002 R cvsupd
36987 763 763 5002 R CPU 2 cvsupd
86677 11122 11094 0 S wait 0xc9c44430 find
11122 11096 11094 0 S wait 0xc9c45000 sh
...
db> trace 56619
Tracing pid 56619 tid 100190 td 0xceb11c00
kdb_enter(c0937792) at kdb_enter+0x2b
siointr1(c9448c00,c0a6ade0,0,c093759e,56e,...) at siointr1+0xd5
siointr(c9448c00) at siointr+0x21
intr_execute_handlers(c92bf4c8,ebd33aa4,4,ebd33aec,c087b853,...) at
intr_execute_handlers+0xe1
lapic_handle_intr(3a) at lapic_handle_intr+0x2e
Xapic_isr1() at Xapic_isr1+0x33
--- interrupt, eip = 0xc06a9714, esp = 0xebd33ae8, ebp = 0xebd33aec ---
stop_cpus(e,c093c45b) at stop_cpus+0x3c
cpu_reset(f4240,c09158a5,ebd33b48,c068a863,0,...) at cpu_reset+0x35
shutdown_reset(0,104,c92ab00c,0,c09156e5,...) at shutdown_reset+0x1c
boot(104,104,ceb11c00,3938700,c0a07bc0,...) at boot+0x55b
panic(c0914b59,c0a07bc0,c9ff2300,c0914b30,c0918a17,...) at panic+0x175
_mtx_lock_spin(c0a07bc0,ceb11c00,0,c093ad3f,3f8) at _mtx_lock_spin+0xa9
_mtx_lock_spin_flags(c0a07bc0,0,c093ad3f,3f8,e65e8000,...) at _mtx_lock_spin_flags+0xb6
smp_tlb_shootdown(f4,e65e8000,0) at smp_tlb_shootdown+0x3e
smp_invlpg(e65e8000) at smp_invlpg+0x1b
pmap_invalidate_page(c0a83880,e65e8000) at pmap_invalidate_page+0x32
pmap_remove_pte(c0a83880,bff997a0,e65e8000) at pmap_remove_pte+0x5d
pmap_remove(c0a83880,e65e8000,e662a000) at pmap_remove+0x114
vm_map_delete(c10683c0,e65e8000,e662a000,c10683c0,c093133c,1d2) at vm_map_delete+0x159
kmem_free_wakeup(c10683c0,e65e8000,41400,0,ebd33cdc,...) at kmem_free_wakeup+0x38
exec_free_args(ebd33cb4,e65e8000,e65e8000,e65e8055,e65e80d9,...) at exec_free_args+0x1e
execve(ceb11c00,ebd33d04) at execve+0x41
syscall(3b,3b,3b,0,0,...) at syscall+0x22f
Xint0x80_syscall() at Xint0x80_syscall+0x1f
--- syscall (0, FreeBSD ELF32, nosys), eip = 0x2804db38, esp =
0xbfbfee08, ebp = 0 ---
db> show locks 56619
exclusive sleep mutex pmap r = 0 (0xc0a83880) locked @
/usr/src/sys/i386/i386/pmap.c:1577
exclusive sleep mutex vm page queue mutex r = 0 (0xc0a5dc80) locked @
/usr/src/sys/i386/i386/pmap.c:1575
db> trace 36987
Tracing pid 36987 tid 100125 td 0xc9ff2300
ipi_nmi_handler(c0a09120,0,0,6a0,c9ff0c90,...) at ipi_nmi_handler+0x5b
trap(c0008,28,e4230028,e4238000,e4238000,...) at trap+0x3d
calltrap() at calltrap+0x5
--- trap 0x13, eip = 0xc0887916, esp = 0xebc93680, ebp = 0xebc93684
---
smp_tlb_shootdown(f5,e4238000,e4239000) at smp_tlb_shootdown+0x72
smp_invlpg_range(e4238000,e4239000) at smp_invlpg_range+0x1c
pmap_invalidate_range(c0a83880,e4238000,e4239000,c23406c0,ebc936ec,...)
at pmap_invalidate_range+0x47
pmap_qremove(e4238000,1,0,e423a000,0,...) at pmap_qremove+0x3d
vm_hold_free_pages(dd41a4a0,e4238000,e423a000) at
vm_hold_free_pages+0xba
allocbuf(dd41a4a0,0) at allocbuf+0x16e
getnewbuf(0,0,2000,10000) at getnewbuf+0x371
getblk(ccb79770,0,0,2000,0,...) at getblk+0x397
breadn(ccb79770,0,0,2000,0,...) at breadn+0x31
bread(ccb79770,0,0,2000,0,ebc93818) at bread+0x20
ffs_blkatoff(ccb79770,0,0,0,ebc93884) at ffs_blkatoff+0x9e
ufs_lookup(ebc93924) at ufs_lookup+0x2cd
VOP_CACHEDLOOKUP_APV(c09cf4a0,ebc93924) at VOP_CACHEDLOOKUP_APV+0x7e
vfs_cache_lookup(ebc939c4) at vfs_cache_lookup+0xb2
VOP_LOOKUP_APV(c09cf4a0,ebc939c4) at VOP_LOOKUP_APV+0x87
lookup(ebc93bcc) at lookup+0x490
namei(ebc93bcc) at namei+0x376
vn_open_cred(ebc93bcc,ebc93ccc,0,c9c30380,5,...) at vn_open_cred+0x277
vn_open(ebc93bcc,ebc93ccc,0,5) at vn_open+0x1e
kern_open(c9ff2300,8270898,0,1,0,...) at kern_open+0xb6
open(c9ff2300,ebc93d04) at open+0x1a
syscall(3b,3b,81e003b,bfbfedc8,bfbfed94,...) at syscall+0x22f
Xint0x80_syscall() at Xint0x80_syscall+0x1f
--- syscall (5, FreeBSD ELF32, open), eip = 0x281a1aef, esp =
0x81e2980, ebp = 0x81e29cc ---
db> show locks 36987
exclusive sleep mutex vm object (kernel object) r = 0 (0xc0a5dae0)
locked @ /usr/src/sys/kern/vfs_bio.c:3573
On Tue, 10 Apr 2007, 10:43+0400, Maxim Konovalov wrote:
> Hi,
>
> A week old -stable panic trace inlined below. The kernel config file
> is SMP + KDB/DDB options. Any help to debug futher is appreciated.
>
> Unread portion of the kernel message buffer:
> spin lock smp rendezvous held by 0xca78ed80 for > 5 seconds
> panic: spin lock held too long
> cpuid = 2
> Uptime: 14h25m47s
> Dumping 3967 MB (3 chunks)
> chunk 0: 1MB (159 pages) ... ok
> chunk 1: 3966MB (1015280 pages) 3950 3934 3918 3902 3886 3870 3854 3838 3822 3806 3790 3774 3758 3742 3726 3710 3694 3678 3662 3646 3630 3614 3598 3582 3566 3550 3534 3518 3502 3486 3470 3454 3438 3422 3406 3390 3374 3358 3342 3326 3310 3294 3278 3262 3246 3230 3214 3198 3182 3166 3150 3134 3118 3102 3086 3070 3054 3038 3022 3006 2990 2974 2958 2942 2926 2910 2894 2878 2862 2846 2830 2814 2798 2782 2766 2750 2734 2718 2702 2686 2670 2654 2638 2622 2606 2590 2574 2558 2542 2526 2510 2494 2478 2462 2446 2430 2414 2398 2382 2366 2350 2334 2318 2302 2286 2270 2254 2238 2222 2206 2190 2174 2158 2142 2126 2110 2094 2078 2062 2046 2030 2014 1998 1982 1966 1950 1934 1918 1902 1886 1870 1854 1838 1822 1806 1790 1774 1758 1742 1726 1710 1694 1678 1662 1646 1630 1614 1598 1582 1566 1550 1534 1518 1502 1486 1470 1454 1438 1422 1406 1390 1374 1358 1342 1326 1310 1294 1278 1262 1246 1230 1214 1198 1182 1166 1150 1134 1118 1102 1086 1070 1054 1038 1022 1006 990 974 958 942 926 910 894 !
878 862 846 830 814 798 782 766 750 734 718 702 686 670 654 638 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 ... ok
> chunk 2: 1MB (128 pages)
>
> #0 doadump () at pcpu.h:165
> 165 pcpu.h: No such file or directory.
> in pcpu.h
> gdb% bt full
> #0 doadump () at pcpu.h:165
> No locals.
> #1 0xc0695bca in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:409
> first_buf_printf = 1
> #2 0xc0695f21 in panic (fmt=0xc093434c "spin lock held too long")
> at /usr/src/sys/kern/kern_shutdown.c:565
> td = (struct thread *) 0xcaabdd80
> bootopt = 260
> newpanic = 1
> ap = 0xcaabdd80 "\030¢ùÏ ýxÊ"
> buf = "spin lock held too long", '\0' <repeats 232 times>
> #3 0xc068ceb5 in _mtx_lock_spin (m=0xc0a1c840, tid=3400260992, opts=0,
> file=0x0, line=0) at /usr/src/sys/kern/kern_mutex.c:633
> i = 60000000
> #4 0xc08ab8d2 in smp_tlb_shootdown (vector=244, addr1=0, addr2=0)
> at /usr/src/sys/i386/i386/mp_machdep.c:1016
> _tid = 3400260992
> ncpu = 3
> __func__ = "smp_tlb_shootdown"
> #5 0xc08abb13 in smp_invlpg (addr=3880742912)
> at /usr/src/sys/i386/i386/mp_machdep.c:1083
> No locals.
> #6 0xc08ae8ea in pmap_invalidate_page (pmap=0x0, va=3880742912)
> at /usr/src/sys/i386/i386/pmap.c:536
> other_cpus = 0
> #7 0xc08afd46 in pmap_remove_pte (pmap=0xc0a51d80, ptq=0x0, va=3880742912)
> at /usr/src/sys/i386/i386/pmap.c:1519
> oldpte = 686364003
> m = 0xbff9d3dc
> #8 0xc08aff38 in pmap_remove (pmap=0xc0a51d80, sva=3880742912, eva=3881013248)
> at /usr/src/sys/i386/i386/pmap.c:1639
> pdirindex = 0
> pdnxt = 3881013248
> ptpaddr = 0
> ---Type <return> to continue, or q <return> to quit---
> pte = (pt_entry_t *) 0xbff9d3dc
> anyvalid = 0
> #9 0xc080e3ed in vm_map_delete (map=0xc14683c0, start=3242623936,
> end=3881013248) at /usr/src/sys/vm/vm_map.c:2363
> next = 0xc14683c0
> entry = 0xd0041088
> first_entry = 0xd0041088
> #10 0xc080bb66 in kmem_free_wakeup (map=0xc14683c0, addr=3880742912, size=0)
> at /usr/src/sys/vm/vm_kern.c:467
> No locals.
> #11 0xc067b17a in exec_free_args (args=0xed9ddcb4)
> at /usr/src/sys/kern/kern_exec.c:1062
> No locals.
> #12 0xc0679a81 in execve (td=0xcaabdd80, uap=0x0)
> at /usr/src/sys/kern/kern_exec.c:190
> error = 0
> args = {
> buf = 0xe74f7000 <Address 0xe74f7000 out of bounds>,
> begin_argv = 0xe74f7000 <Address 0xe74f7000 out of bounds>,
> begin_envv = 0xe74f701d <Address 0xe74f701d out of bounds>,
> endp = 0xe74f716b <Address 0xe74f716b out of bounds>,
> fname = 0xe7537000 "/usr/libexec/ftpd",
> stringspace = 261781,
> argc = 7,
> envc = 9
> }
> #13 0xc08b4e0f in syscall (frame=
> {tf_fs = 59, tf_es = 59, tf_ds = 59, tf_edi = 0, tf_esi = 0, tf_ebp = 0, tf_isp = 0, tf_ebx = 0, tf_edx = 0, tf_ecx = 0, tf_eax = 0, tf_trapno = 0, tf_err = 0, tf_eip = 671484728, tf_cs = 51, tf_eflags = 514, tf_esp = -1077940896, tf_ss = 59}) at /usr/src/sys/i386/i386/trap.c:983
> params = 0xbfbfdb60 <Address 0xbfbfdb60 out of bounds>
> callp = (struct sysent *) 0xc09a5fa4
> td = (struct thread *) 0xcaabdd80
> ---Type <return> to continue, or q <return> to quit---
> p = (struct proc *) 0xcff9a218
> orig_tf_eflags = 514
> sticks = 0
> error = 0
> narg = 3
> args = {134582464, 134627384, 134587136, 0, 0, 0, 0, -805723624}
> code = 59
> #14 0xc089f0ef in Xint0x80_syscall () at /usr/src/sys/i386/i386/exception.s:200
> No locals.
> #15 0x00000033 in ?? ()
> No symbol table info available.
> gdb%
>
> Script done on Tue Apr 10 10:33:02 2007
>
>
--
Maxim Konovalov
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20070418090701.N46799>