Date: Mon, 20 Mar 2006 16:35:48 -0500 From: Kris Kennaway <kris@obsecurity.org> To: Kris Kennaway <kris@obsecurity.org> Cc: sparc64@FreeBSD.org Subject: Re: TODO list status update Message-ID: <20060320213548.GA77776@xor.obsecurity.org> In-Reply-To: <20060320173134.GA42022@xor.obsecurity.org> References: <441955A7.1020204@samsco.org> <20060316140435.K95579@newtrinity.zeist.de> <20060316190305.GA25561@xor.obsecurity.org> <20060320165139.D98160@newtrinity.zeist.de> <20060320173134.GA42022@xor.obsecurity.org>
next in thread | previous in thread | raw e-mail | index | archive | help
--UugvWAfsgieZRqgk Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable On Mon, Mar 20, 2006 at 12:31:34PM -0500, Kris Kennaway wrote: > > > Another problem is in hardclock: > > >=20 > > > panic: blockable sleep lock (sleep mutex) system map @ vm/vm_map.c:29= 95 > > > cpuid =3D 2 > > > KDB: enter: panic > > > [thread pid 35 tid 100037 ] > > > Stopped at kdb_enter+0x3c: ta %xcc, 1 > > > db> wh > > > Tracing pid 35 tid 100037 td 0xfffff803fe9faac0 > > > panic() at panic+0x164 > > > witness_checkorder() at witness_checkorder+0xc8 > > > _mtx_lock_flags() at _mtx_lock_flags+0x80 > > > _vm_map_lock_read() at _vm_map_lock_read+0x3c > > > vm_map_lookup() at vm_map_lookup+0x1c > > > vm_fault() at vm_fault+0x68 > > > trap_pfault() at trap_pfault+0x1a8 > > > trap() at trap+0x2b0 > > > -- fast data access mmu miss tar=3D0x18c0790000 %o7=3D0xc01c24d0 -- > > > witness_checkorder() at witness_checkorder+0x1c4 > > > _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0x7c > > > hardclock_cpu() at hardclock_cpu+0x20 > > > tick_hardclock() at tick_hardclock+0xc4 > > > -- interrupt level=3D0xe pil=3D0 %o7=3D0xc01c2f9c -- > >=20 > > Sorry, I'm missing the big picture to determine what's at > > fault here. Knowing what tick_hardclock() did interrupt > > probably would help. Shouldn't be the another page fault > > though as then PIL still would be set to 14 which in > > turn means tick interrupts are turned off in the first > > place. >=20 > I'll grab another trace next time it happens. Here's another panic: SMP: AP CPU #3 Launched! SMP: AP CPU #2 Launched! SMP: AP CPU #1 Launched! sssiinnlckkssched loc hhl bbb 0xfffff802be9e22d0fooo 55seconds spin lock sched lock held by 0xfffff802be9eb2d0 for > 5 seconds KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 hardclock() at hardclock+0x8 tick_hardclock() at tick_hardclock+0xac -- interrupt level=3D0xe pil=3D0 %o7=3D0xc01c4898 -- strncmp() at strncmp+0x54 witness_unlock() at witness_unlock+0x5c _mtx_unlock_flags() at _mtx_unlock_flags+0x7c fdinit() at fdinit+0xc0 fdcopy() at fdcopy+0x10 fork1() at fork1+0x768 kthread_create() at kthread_create+0x3c kproc_start() at kproc_start+0x24 mi_startup() at mi_startup+0x12c btext() at btext+0x34 panic: spin lock held too long cpuid =3D 0 KDB: enter: panic [thread pid 0 tid 0 ] Stopped at kdb_enter+0x3c: ta %xcc, 1 db> KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc018a278 -- _mtx_lock_spin() at _mtx_lock_spin+0x110 _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc cpu_mp_bootstrap() at cpu_mp_bootstrap+0xa8 mp_startup() at mp_startup+0xbc mtx_pool_destroy() at mtx_pool_destroy+0x8 KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc018a184 -- _mtx_lock_sleep() at _mtx_lock_sleep+0x140 _mtx_lock_flags() at _mtx_lock_flags+0xb8 start_init() at start_init+0x18 fork_exit() at fork_exit+0x94 fork_trampoline() at fork_trampoline+0x8 KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc018a278 -- _mtx_lock_spin() at _mtx_lock_spin+0x114 _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc ithread_loop() at ithread_loop+0xf0 fork_exit() at fork_exit+0x94 fork_trampoline() at fork_trampoline+0x8 KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc018a278 -- _mtx_lock_spin() at _mtx_lock_spin+0x114 _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc cpu_mp_bootstrap() at cpu_mp_bootstrap+0xa8 mp_startup() at mp_startup+0xbc KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc018a184 -- _mtx_lock_sleep() at _mtx_lock_sleep+0x140 _mtx_lock_flags() at _mtx_lock_flags+0xb8 ithread_execute_handlers() at ithread_execute_handlers+0x138 ithread_loop() at ithread_loop+0xa4 fork_exit() at fork_exit+0x94 fork_trampoline() at fork_trampoline+0x8 KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc018a278 -- _mtx_lock_spin() at _mtx_lock_spin+0x110 _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc cpu_mp_bootstrap() at cpu_mp_bootstrap+0xa8 mp_startup() at mp_startup+0xbc blk_dump() at blk_dump+0x10c KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc018a278 -- _mtx_lock_spin() at _mtx_lock_spin+0x114 _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc roundrobin() at roundrobin+0x18 softclock() at softclock+0x238 ithread_execute_handlers() at ithread_execute_handlers+0x144 ithread_loop() at ithread_loop+0xa4 fork_exit() at fork_exit+0x94 fork_trampoline() at fork_trampoline+0x8 KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc01acd24 -- cpu_switch() at cpu_switch+0xa0 tl_text_end() at tl_text_end+0xc KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc018a184 -- _mtx_lock_sleep() at _mtx_lock_sleep+0x12c _mtx_lock_flags() at _mtx_lock_flags+0xb8 vm_daemon() at vm_daemon+0x18 fork_exit() at fork_exit+0x94 fork_trampoline() at fork_trampoline+0x8 KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc02ed6c8 -- bzero() at bzero+0x68 uma_zalloc_internal() at uma_zalloc_internal+0xe0 uma_zcreate() at uma_zcreate+0x3c swap_pager_swap_init() at swap_pager_swap_init+0xf0 vm_pageout() at vm_pageout+0x26c fork_exit() at fork_exit+0x94 fork_trampoline() at fork_trampoline+0x8 KDB: stack backtrace: _mtx_lock_spin_flags() at _mtx_lock_spin_flags+0xdc hardclock_cpu() at hardclock_cpu+0x20 tick_hardclock() at tick_hardclock+0xc4 -- interrupt level=3D0xe pil=3D0 %o7=3D0xc018a184 -- _mtx_lock_sleep() at _mtx_lock_sleep+0x144 _mtx_lock_flags() at _mtx_lock_flags+0xb8 ithread_execute_handlers() at ithread_execute_handlers+0x138 ithread_loop() at ithread_loop+0xa4 fork_exit() at fork_exit+0x94 fork_trampoline() at fork_trampoline+0x8 These are traces from the other CPUs; I have it hacked to do kdb_backtrace() before trying to enter DDB, since this so often doesn't work. Remarkably, it did this time though: db> show witness Sleep locks: 0 ip6qlock -- last acquired @ netinet6/frag6.c:682 0 ipqlock -- last acquired @ netinet/ip_input.c:1069 0 if_afdata -- last acquired @ net/if.c:539 0 LED sx -- last acquired @ dev/led/led.c:249 2 unit# allocation -- last acquired @ kern/subr_unit.c:592 6 cdev -- last acquired @ kern/kern_conf.c:61 3 UMA zone -- last acquired @ vm/uma_core.c:1841 0 bio queue -- last acquired @ geom/geom_io.c:68 0 GEOM topology -- last acquired @ geom/geom_event.c:183 2 GEOM orphanage -- last acquired @ geom/geom_event.c:196 3 UMA zone -- (already displayed) 2 UMA lock -- last acquired @ vm/uma_core.c:1315 3 UMA zone -- (already displayed) 2 devstat -- last acquired @ kern/subr_devstat.c:83 1 Giant -- last acquired @ dev/ata/ata-all.c:527 2 filedesc structure -- last acquired @ kern/kern_descrip.c:1404 3 pipe mutex -- last acquired @ order list:0 4 sigio lock -- last acquired @ order list:0 5 process group -- last acquired @ kern/kern_fork.c:589 6 process lock -- last acquired @ kern/kern_fork.c:377 7 session -- last acquired @ kern/kern_fork.c:599 8 uidinfo hash -- last acquired @ kern/kern_resource.c:1039 9 uidinfo struct -- last acquired @ order list:0 10 allprison -- last acquired @ order list:0 9 sleep mtxpool -- last acquired @ kern/kern_resource.c:1147 7 sigacts -- last acquired @ kern/kern_kthread.c:98 9 sleep mtxpool -- (already displayed) 7 ktrace -- last acquired @ kern/kern_fork.c:617 3 accept -- last acquired @ order list:0 4 so_snd -- last acquired @ order list:0 5 so_rcv -- last acquired @ order list:0 6 sellck -- last acquired @ kern/sys_generic.c:1140 6 radix node head -- last acquired @ netinet/if_ether.c:136 7 rtentry -- last acquired @ order list:0 8 ifaddr -- last acquired @ order list:0 3 UMA zone -- (already displayed) 2 UMA lock -- (already displayed) 2 UMA boot pages -- last acquired @ vm/uma_core.c:917 2 eventhandler -- last acquired @ kern/subr_eventhandler.c:212 2 eventhandler list -- last acquired @ kern/subr_eventhandler.c:132 2 kobj -- last acquired @ kern/subr_kobj.c:307 2 kernel linker -- last acquired @ kern/kern_linker.c:470 2 system map -- last acquired @ vm/vm_map.c:1096 4 vm page queue mutex -- last acquired @ sparc64/sparc64/pmap.c:937 5 vnode interlock -- last acquired @ order list:0 6 cdev -- (already displayed) 5 pmap -- last acquired @ sparc64/sparc64/pmap.c:1289 3 kernel object -- last acquired @ vm/vm_object.c:444 4 vm page queue mutex -- (already displayed) 3 KMAP ENTRY -- last acquired @ vm/uma_core.c:1841 3 UMA zone -- (already displayed) 3 kmem object -- last acquired @ vm/vm_kern.c:397 4 vm page queue mutex -- (already displayed) 3 kernel object -- (already displayed) 6 process lock -- (already displayed) 2 vm object_list -- last acquired @ vm/vm_object.c:228 3 KMAP ENTRY -- (already displayed) 8 uidinfo hash -- (already displayed) 9 sleep mtxpool -- (already displayed) 4 vm page queue mutex -- (already displayed) 2 standard object -- last acquired @ vm/vm_glue.c:362 4 vm page queue mutex -- (already displayed) 2 TID lock -- last acquired @ kern/subr_unit.c:592 2 intr event -- last acquired @ kern/kern_intr.c:380 6 cdev -- (already displayed) 2 GEOM orphanage -- (already displayed) 2 taskqueue list -- last acquired @ kern/subr_taskqueue.c:125 2 rman head -- last acquired @ kern/subr_rman.c:172 2 rman -- last acquired @ kern/subr_rman.c:511 3 UMA zone -- (already displayed) 2 eeprom_mtx -- last acquired @ sparc64/sparc64/eeprom.c:184 2 devd -- last acquired @ kern/subr_bus.c:517 6 sellck -- (already displayed) 2 ttylist -- last acquired @ kern/tty.c:2842 2 unit# allocation -- (already displayed) 2 LED mtx -- last acquired @ dev/led/led.c:52 2 network driver -- last acquired @ dev/hme/if_hme.c:203 3 iommu -- last acquired @ sparc64/sparc64/iommu.c:1007 2 ifnet -- last acquired @ net/if.c:1170 2 bpf global lock -- last acquired @ net/bpf.c:1597 3 bpf interface lock -- last acquired @ order list:0 4 bpf cdev lock -- last acquired @ order list:0 2 ncr53c9x lock -- last acquired @ dev/esp/ncr53c9x.c:2143 3 UMA zone -- (already displayed) 3 iommu -- (already displayed) 3 CAM BIOQ lock -- last acquired @ cam/cam_xpt.c:4957 2 random reseed -- last acquired @ dev/random/yarrow.c:280 2 arc4_mtx -- last acquired @ libkern/arc4random.c:137 2 pseudofs -- last acquired @ fs/pseudofs/pseudofs_fileno.c:55 2 nfsd_mtx -- last acquired @ nfsserver/nfs_srvsock.c:812 4 so_snd -- (already displayed) 2 if_clone lock -- last acquired @ net/if_clone.c:161 2 if_cloners lock -- last acquired @ net/if_clone.c:245 2 domain list -- last acquired @ kern/uipc_domain.c:226 3 pfil_head_list lock -- last acquired @ net/pfil.c:114 2 PFil hook read/write mutex -- last acquired @ net/pfil.c:108 3 pfil_head_list lock -- (already displayed) 2 tcp -- last acquired @ netinet/tcp_subr.c:1409 3 tcpinp -- last acquired @ order list:0 4 so_snd -- (already displayed) 6 radix node head -- (already displayed) 2 lo_mtx -- last acquired @ net/if_loop.c:160 2 in6_addr_list -- last acquired @ netinet6/nd6.c:556 3 CAM BIOQ lock -- (already displayed) 2 devstat -- (already displayed) 2 taskqueue -- last acquired @ kern/subr_taskqueue.c:73 6 process lock -- (already displayed) 0 pbuf mutex -- last acquired @ vm/swap_pager.c:403 0 module subsystem sx lock -- last acquired @ kern/kern_module.c:115 0 kernel environment -- last acquired @ kern/kern_environment.c:291 0 user map -- last acquired @ vm/vm_map.c:2485 3 UMA zone -- (already displayed) 2 system map -- (already displayed) 2 vm object_list -- (already displayed) 2 standard object -- (already displayed) 4 vm page queue mutex -- (already displayed) 0 ddp_list_mtx -- last acquired @ order list:0 1 ddp_mtx -- last acquired @ order list:0 0 slip_mtx -- last acquired @ order list:0 1 slip sc_mtx -- last acquired @ order list:0 0 udp -- last acquired @ order list:0 1 udpinp -- last acquired @ order list:0 2 in_multi_mtx -- last acquired @ order list:0 3 igmp_mtx -- last acquired @ netinet/igmp.c:444 4 if_addr_mtx -- last acquired @ order list:0 4 so_snd -- (already displayed) 0 unp -- last acquired @ order list:0 4 so_snd -- (already displayed) 0 proctree -- last acquired @ kern/kern_fork.c:301 1 allproc -- last acquired @ kern/kern_fork.c:310 6 process lock -- (already displayed) 5 process group -- (already displayed) Spin locks: 0 ap boot -- last acquired @ order list:0 1 rm.mutex_mtx -- last acquired @ order list:0 2 hptlock -- last acquired @ order list:0 3 sio -- last acquired @ order list:0 4 uart_hwmtx -- last acquired @ dev/uart/uart_dev_z8530.c:401 5 sabtty -- last acquired @ order list:0 6 zstty -- last acquired @ order list:0 7 ng_node -- last acquired @ order list:0 8 ng_worklist -- last acquired @ order list:0 9 taskqueue_fast -- last acquired @ order list:0 10 intr table -- last acquired @ sparc64/sparc64/intr_machdep.c:294 11 sleepq chain -- last acquired @ kern/subr_sleepqueue.c:223 12 sched lock -- last acquired @ sparc64/sparc64/mp_machdep.c:366 13 turnstile chain -- last acquired @ kern/subr_turnstile.c:478 14 td_contested -- last acquired @ order list:0 15 callout -- last acquired @ kern/kern_timeout.c:293 16 entropy harvest mutex -- last acquired @ dev/random/rando= mdev_soft.c:256 17 allpmaps -- last acquired @ order list:0 18 vm page queue free mutex -- last acquired @ vm/vm_page.= c:792 19 icu -- last acquired @ order list:0 20 smp rendezvous -- last acquired @ order list:0 21 ipi -- last acquired @ order list:0 22 rtc_mtx -- last acquired @ order list:0 23 clk -- last acquired @ order list:0 24 mutex profiling lock -- last acquired @ order lis= t:0 25 kse zombie lock -- last acquired @ order list:0 26 ALD Queue -- last acquired @ order list:0 27 tw_osl_io_lock -- last acquired @ order list:0 28 tw_osl_q_lock -- last acquired @ order list:0 29 tw_cl_io_lock -- last acquired @ order list:0 30 tw_cl_intr_lock -- last acquired @ order li= st:0 31 tw_cl_gen_lock -- last acquired @ order li= st:0 15 callout -- (already displayed) 15 callout -- (already displayed) Locks which were never acquired: g_disk_done MD config lock arp_inq rts_inq addrsel_sxlock addrsel_lock scope6_lock ip6_inq rip tcp_hc_entry ip_inq pseudofs_vncache gif_mtx ppp_softc_list_mtx tunmtx msq sem semid Synch NFS reply posting NFS reqq lock nfs4dev state nfs4dev waitq nfs4dev newq nullhs dirhash list vfs hash Syncer mtx vnode_free_list mntid if send queue tty fast_taskqueue pt_mtx nfslock sf_bufs list lock ktrace_sx uma object p_peers bpin lock bdone lock buffer daemon lock needsbuffer lock runningbufspace lock buf queue lock umtxq_lock fifo mutex Name Cache UUID generator mutex lock so_glabel knlist lock for lockless objects encapmtx protect sysfilt_ops kqueue order rtsock route_cb lock mountlist rawcb Softdep Lock accept_filter_mtx securelevel mutex lock DEVFS ruleset lock acct_sx pmc shared lock fdesc filelist lock sysctl lock malloc phys_pager list dev_pager list dev_pager create swapdev swap_pager list vm map sleep mutex db> show locks exclusive sleep mutex filedesc structure r =3D 0 (0xfffff80002c89c48) locke= d @ kern/kern_descrip.c:1404 exclusive sleep mutex Giant r =3D 0 (0xc0710980) locked @ dev/ata/ata-all.c= :527 db> show alllocks Process 2 (g_event) thread 0xfffff802be9ea000 (100011) exclusive sx GEOM topology r =3D 0 (0xc044da50) locked @ geom/geom_event.c:= 183 Process 0 (swapper) thread 0xc044dfd8 (0) exclusive sleep mutex filedesc structure r =3D 0 (0xfffff80002c89c48) locke= d @ kern/kern_descrip.c:1404 exclusive sleep mutex Giant r =3D 0 (0xc0710980) locked @ dev/ata/ata-all.c= :527 db> show allpcpu Current CPU: 0 cpuid =3D 0 curthread =3D 0xc044dfd8: pid 0 "swapper" curpcb =3D 0xc0c17980 fpcurthread =3D none idlethread =3D 0xfffff802be9f1ae0: pid 21 "idle: cpu0" spin locks held: cpuid =3D -371328640 curthread =3D 0xfffff802be9f1830: pid 20 "idle: cpu1" curpcb =3D 0xc0080540 fpcurthread =3D [hung, grr] Kris --UugvWAfsgieZRqgk Content-Type: application/pgp-signature Content-Disposition: inline -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.2.2 (FreeBSD) iD8DBQFEHyA0Wry0BWjoQKURAgmYAJ0X0v2gC8NTyFoCoWErJMcotfQkSgCgyVAn Ol9gfL7D3gbkUF9Ekajh3q8= =tIav -----END PGP SIGNATURE----- --UugvWAfsgieZRqgk--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20060320213548.GA77776>