Bug 226436 - panic: spin lock held too long
Summary: panic: spin lock held too long
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: CURRENT
Hardware: amd64 Any
: --- Affects Only Me
Assignee: freebsd-bugs (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-03-07 22:05 UTC by vidwer+fbsdbugs
Modified: 2018-03-08 08:43 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description vidwer+fbsdbugs 2018-03-07 22:05:18 UTC
Build: 12.0-CURRENT r330622
hardware: amd64

Unread portion of the kernel message buffer:
spin lock 0xffffffff81e07ca0 (smp rendezvous) held by 0xfffff80022aca000 (tid 100432) too long
timeout stopping cpus
panic: spin lock held too long
cpuid = 2
time = 1520449386
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe004b88b1d0
vpanic() at vpanic+0x18d/frame 0xfffffe004b88b230
panic() at panic+0x43/frame 0xfffffe004b88b290
_mtx_lock_indefinite_check() at _mtx_lock_indefinite_check+0x8c/frame 0xfffffe004b88b2b0
_mtx_lock_spin_cookie() at _mtx_lock_spin_cookie+0xd5/frame 0xfffffe004b88b320
__mtx_lock_spin_flags() at __mtx_lock_spin_flags+0xd8/frame 0xfffffe004b88b360
smp_targeted_tlb_shootdown() at smp_targeted_tlb_shootdown+0xd8/frame 0xfffffe004b88b3e0
smp_masked_invlpg_range() at smp_masked_invlpg_range+0x42/frame 0xfffffe004b88b410
pmap_invalidate_range() at pmap_invalidate_range+0x291/frame 0xfffffe004b88b470
vunmapbuf() at vunmapbuf+0x2e/frame 0xfffffe004b88b490
cam_periph_unmapmem() at cam_periph_unmapmem+0x17b/frame 0xfffffe004b88b4d0
passsendccb() at passsendccb+0x179/frame 0xfffffe004b88b530
passdoioctl() at passdoioctl+0xe7/frame 0xfffffe004b88b5e0
passioctl() at passioctl+0x22/frame 0xfffffe004b88b620
devfs_ioctl() at devfs_ioctl+0xcb/frame 0xfffffe004b88b670
VOP_IOCTL_APV() at VOP_IOCTL_APV+0xd9/frame 0xfffffe004b88b6a0
vn_ioctl() at vn_ioctl+0x124/frame 0xfffffe004b88b7b0
devfs_ioctl_f() at devfs_ioctl_f+0x1f/frame 0xfffffe004b88b7d0
kern_ioctl() at kern_ioctl+0x2b9/frame 0xfffffe004b88b830
sys_ioctl() at sys_ioctl+0x15c/frame 0xfffffe004b88b900
amd64_syscall() at amd64_syscall+0x79b/frame 0xfffffe004b88ba30
fast_syscall_common() at fast_syscall_common+0x101/frame 0xfffffe004b88ba30
--- syscall (54, FreeBSD ELF64, sys_ioctl), rip = 0x800a06dfa, rsp = 0x7fffffffa1d8, rbp = 0x7fffffffa6e0 ---
KDB: enter: panic

__curthread () at ./machine/pcpu.h:230
230		__asm("movq %%gs:%1,%0" : "=r" (td)

(kgdb) 
#7  0xffffffff80f8c868 in trap (frame=0xfffffe004b88b100) at /usr/src/sys/amd64/amd64/trap.c:547
547				if (kdb_trap(type, dr6, frame))
(kgdb) 
#8  <signal handler called>
(kgdb) 
#9  kdb_enter (why=0xffffffff811fb341 "panic", msg=<optimized out>) at /usr/src/sys/kern/subr_kdb.c:479
479			kdb_why = KDB_WHY_UNSET;
(kgdb) 
#10 0xffffffff80ad3e4a in vpanic (fmt=<optimized out>, ap=0xfffffe004b88b270) at /usr/src/sys/kern/kern_shutdown.c:801
801			kdb_enter(KDB_WHY_PANIC, "panic");
(kgdb) 
#11 0xffffffff80ad3ed3 in panic (fmt=0xffffffff81be33f8 <cnputs_mtx> "-N\034\201\377\377\377\377") at /usr/src/sys/kern/kern_shutdown.c:739
739		vpanic(fmt, ap);
(kgdb) 
#12 0xffffffff80ab3e4c in _mtx_lock_indefinite_check (m=0xffffffff81e07ca0 <smp_ipi_mtx>, ldap=<optimized out>) at /usr/src/sys/kern/kern_mutex.c:1227
1227			panic("spin lock held too long");
(kgdb) 
#13 0xffffffff80ab3775 in _mtx_lock_spin_cookie (c=0xffffffff81e07cb8 <smp_ipi_mtx+24>, v=18446735278198267904, opts=<optimized out>, file=<optimized out>, line=<optimized out>) at /usr/src/sys/kern/kern_mutex.c:752
752					_mtx_lock_indefinite_check(m, &lda);
(kgdb) 
#14 0xffffffff80ab3628 in __mtx_lock_spin_flags (c=0xffffffff81e07cb8 <smp_ipi_mtx+24>, opts=0, file=0xffffffff8112f150 "/usr/src/sys/x86/x86/mp_x86.c", line=1535) at /usr/src/sys/kern/kern_mutex.c:320
320			_mtx_lock_spin(m, v, opts, file, line);
(kgdb) 
#15 0xffffffff810f8de8 in smp_targeted_tlb_shootdown (mask=..., vector=246, pmap=0xffffffff81e5d4f0 <kernel_pmap_store>, addr1=<optimized out>, addr2=18446741875586338816) at /usr/src/sys/x86/x86/mp_x86.c:1535

1535		mtx_lock_spin(&smp_ipi_mtx);
(kgdb) 
#16 0xffffffff810f9172 in smp_masked_invlpg_range (mask=..., addr1=<optimized out>, addr2=18, pmap=<optimized out>) at /usr/src/sys/x86/x86/mp_x86.c:1594
1594			smp_targeted_tlb_shootdown(mask, IPI_INVLRNG, pmap,
(kgdb) 
#17 0xffffffff80f770e1 in pmap_invalidate_range (pmap=0xffffffff81e5d4f0 <kernel_pmap_store>, sva=18446741875586334720, eva=18446741875586338816) at /usr/src/sys/amd64/amd64/pmap.c:1771
1771		smp_masked_invlpg_range(*mask, sva, eva, pmap);
(kgdb) 
#18 0xffffffff80b8664e in vunmapbuf (bp=0xfffffe0000e33cc0) at /usr/src/sys/kern/vfs_bio.c:4781
4781			pmap_qremove(trunc_page((vm_offset_t)bp->b_data), npages);
(kgdb) 
#19 0xffffffff803362eb in cam_periph_unmapmem (ccb=<optimized out>, mapinfo=0xfffffe004b88b4e0) at /usr/src/sys/cam/cam_periph.c:1046
1046			vunmapbuf(mapinfo->bp[i]);
(kgdb) 
#20 0xffffffff8036fdd9 in passsendccb (periph=0xfffff8000363c900, ccb=0xfffff8001c6b2000, inccb=0xfffff8001e97d800) at /usr/src/sys/cam/scsi/scsi_pass.c:2255
2255		cam_periph_unmapmem(ccb, &mapinfo);
(kgdb) 
#21 0xffffffff8036ea77 in passdoioctl (dev=<optimized out>, cmd=<optimized out>, addr=0xfffff8001e97d800 "", flag=<optimized out>, td=<optimized out>) at /usr/src/sys/cam/scsi/scsi_pass.c:1847
1847			error = passsendccb(periph, ccb, inccb);
(kgdb) 
#22 0xffffffff8036e5c2 in passioctl (dev=0xfffff800037d4000, cmd=3303020802, addr=0xfffff8001e97d800 "", flag=3, td=0xfffff80022ac9000) at /usr/src/sys/cam/scsi/scsi_pass.c:1766
1766		if ((error = passdoioctl(dev, cmd, addr, flag, td)) == ENOTTY) {
(kgdb) 
#23 0xffffffff8099e5eb in devfs_ioctl (ap=0xfffffe004b88b6b8) at /usr/src/sys/fs/devfs/devfs_vnops.c:807
807		error = dsw->d_ioctl(dev, com, ap->a_data, ap->a_fflag, td);
(kgdb) 
#24 0xffffffff81102dc9 in VOP_IOCTL_APV (vop=<optimized out>, a=0xfffffe004b88b6b8) at vnode_if.c:1067
1067			rc = vop->vop_ioctl(a);
(kgdb) 
#25 0xffffffff80bb3e74 in VOP_IOCTL (vp=<optimized out>, command=<optimized out>, data=<optimized out>, fflag=18, cred=<optimized out>, td=<optimized out>) at ./vnode_if.h:448
448		return (VOP_IOCTL_APV(vp->v_op, &a));
(kgdb) 
#26 vn_ioctl (fp=0xfffff800224122d0, com=<optimized out>, data=0xfffff8001e97d800, active_cred=0xfffff8001e7fa000, td=0x278) at /usr/src/sys/kern/vfs_vnops.c:1507
1507			return (VOP_IOCTL(vp, com, data, fp->f_flag,
(kgdb) 
#27 0xffffffff8099ec8f in devfs_ioctl_f (fp=0xffffffff81be33f8 <cnputs_mtx>, com=128, data=0xfffffe004b88b0c0, cred=0x80, td=0xfffff80022ac9000) at /usr/src/sys/fs/devfs/devfs_vnops.c:765
765		error = vnops.fo_ioctl(fp, com, data, cred, td);
(kgdb) 
#28 0xffffffff80b3f129 in fo_ioctl (fp=<optimized out>, com=<optimized out>, active_cred=0x80, td=<optimized out>, data=<optimized out>) at /usr/src/sys/sys/file.h:325
325		return ((*fp->f_ops->fo_ioctl)(fp, com, data, active_cred, td));
(kgdb) 
#29 kern_ioctl (td=0xfffff80022ac9000, fd=<optimized out>, com=<optimized out>, data=0xfffffe004b88b0c0 "") at /usr/src/sys/kern/sys_generic.c:838
838		error = fo_ioctl(fp, com, data, td->td_ucred, td);
(kgdb) 
#30 0xffffffff80b3edfc in sys_ioctl (td=0xfffff80022ac9000, uap=0xfffff80022ac93b8) at /usr/src/sys/kern/sys_generic.c:747
747		error = kern_ioctl(td, uap->fd, com, data);
(kgdb) 
#31 0xffffffff80f8de2b in syscallenter (td=0xfffff80022ac9000) at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:134
134			error = (sa->callp->sy_call)(td, sa->args);
(kgdb) 
#32 amd64_syscall (td=0xfffff80022ac9000, traced=0) at /usr/src/sys/amd64/amd64/trap.c:935
935		error = syscallenter(td);
(kgdb) 
#33 0xffffffff80f68a0d in fast_syscall_common () at /usr/src/sys/amd64/amd64/exception.S:480
480		call	amd64_syscall
(kgdb) 
#34 0x0000000000000003 in ?? ()
(kgdb) 
#35 0x00000000c4e01902 in ?? ()
(kgdb) 
#36 0x00007fffffffa1e0 in ?? ()
(kgdb) 
#37 0x00007fffffffa1e0 in ?? ()
(kgdb) 
#38 0x00000000000004e0 in ?? ()
(kgdb) 
#39 0x0000000000000000 in ?? ()
(kgdb) 
Initial frame selected; you cannot go up.

(kgdb) bt
#0  __curthread () at ./machine/pcpu.h:230
#1  doadump (textdump=0) at /usr/src/sys/kern/kern_shutdown.c:347
#2  0xffffffff8040a96b in db_dump (dummy=<optimized out>, dummy2=<unavailable>, dummy3=<unavailable>, dummy4=<unavailable>) at /usr/src/sys/ddb/db_command.c:574
#3  0xffffffff8040a739 in db_command (last_cmdp=<optimized out>, cmd_table=<optimized out>, dopager=<optimized out>) at /usr/src/sys/ddb/db_command.c:481
#4  0xffffffff8040a4b4 in db_command_loop () at /usr/src/sys/ddb/db_command.c:534
#5  0xffffffff8040d6df in db_trap (type=<optimized out>, code=<optimized out>) at /usr/src/sys/ddb/db_main.c:250
#6  0xffffffff80b19333 in kdb_trap (type=3, code=-61456, tf=<optimized out>) at /usr/src/sys/kern/subr_kdb.c:697
#7  0xffffffff80f8c868 in trap (frame=0xfffffe004b88b100) at /usr/src/sys/amd64/amd64/trap.c:547
#8  <signal handler called>
#9  kdb_enter (why=0xffffffff811fb341 "panic", msg=<optimized out>) at /usr/src/sys/kern/subr_kdb.c:479
#10 0xffffffff80ad3e4a in vpanic (fmt=<optimized out>, ap=0xfffffe004b88b270) at /usr/src/sys/kern/kern_shutdown.c:801
#11 0xffffffff80ad3ed3 in panic (fmt=0xffffffff81be33f8 <cnputs_mtx> "-N\034\201\377\377\377\377") at /usr/src/sys/kern/kern_shutdown.c:739
#12 0xffffffff80ab3e4c in _mtx_lock_indefinite_check (m=0xffffffff81e07ca0 <smp_ipi_mtx>, ldap=<optimized out>) at /usr/src/sys/kern/kern_mutex.c:1227
#13 0xffffffff80ab3775 in _mtx_lock_spin_cookie (c=0xffffffff81e07cb8 <smp_ipi_mtx+24>, v=18446735278198267904, opts=<optimized out>, file=<optimized out>, line=<optimized out>) at /usr/src/sys/kern/kern_mutex.c:752
#14 0xffffffff80ab3628 in __mtx_lock_spin_flags (c=0xffffffff81e07cb8 <smp_ipi_mtx+24>, opts=0, file=0xffffffff8112f150 "/usr/src/sys/x86/x86/mp_x86.c", line=1535) at /usr/src/sys/kern/kern_mutex.c:320
#15 0xffffffff810f8de8 in smp_targeted_tlb_shootdown (mask=..., vector=246, pmap=0xffffffff81e5d4f0 <kernel_pmap_store>, addr1=<optimized out>, addr2=18446741875586338816) at /usr/src/sys/x86/x86/mp_x86.c:1535
#16 0xffffffff810f9172 in smp_masked_invlpg_range (mask=..., addr1=<optimized out>, addr2=18, pmap=<optimized out>) at /usr/src/sys/x86/x86/mp_x86.c:1594
#17 0xffffffff80f770e1 in pmap_invalidate_range (pmap=0xffffffff81e5d4f0 <kernel_pmap_store>, sva=18446741875586334720, eva=18446741875586338816) at /usr/src/sys/amd64/amd64/pmap.c:1771
#18 0xffffffff80b8664e in vunmapbuf (bp=0xfffffe0000e33cc0) at /usr/src/sys/kern/vfs_bio.c:4781
#19 0xffffffff803362eb in cam_periph_unmapmem (ccb=<optimized out>, mapinfo=0xfffffe004b88b4e0) at /usr/src/sys/cam/cam_periph.c:1046
#20 0xffffffff8036fdd9 in passsendccb (periph=0xfffff8000363c900, ccb=0xfffff8001c6b2000, inccb=0xfffff8001e97d800) at /usr/src/sys/cam/scsi/scsi_pass.c:2255
#21 0xffffffff8036ea77 in passdoioctl (dev=<optimized out>, cmd=<optimized out>, addr=0xfffff8001e97d800 "", flag=<optimized out>, td=<optimized out>) at /usr/src/sys/cam/scsi/scsi_pass.c:1847
#22 0xffffffff8036e5c2 in passioctl (dev=0xfffff800037d4000, cmd=3303020802, addr=0xfffff8001e97d800 "", flag=3, td=0xfffff80022ac9000) at /usr/src/sys/cam/scsi/scsi_pass.c:1766
#23 0xffffffff8099e5eb in devfs_ioctl (ap=0xfffffe004b88b6b8) at /usr/src/sys/fs/devfs/devfs_vnops.c:807
#24 0xffffffff81102dc9 in VOP_IOCTL_APV (vop=<optimized out>, a=0xfffffe004b88b6b8) at vnode_if.c:1067
#25 0xffffffff80bb3e74 in VOP_IOCTL (vp=<optimized out>, command=<optimized out>, data=<optimized out>, fflag=18, cred=<optimized out>, td=<optimized out>) at ./vnode_if.h:448
#26 vn_ioctl (fp=0xfffff800224122d0, com=<optimized out>, data=0xfffff8001e97d800, active_cred=0xfffff8001e7fa000, td=0x278) at /usr/src/sys/kern/vfs_vnops.c:1507
#27 0xffffffff8099ec8f in devfs_ioctl_f (fp=0xffffffff81be33f8 <cnputs_mtx>, com=128, data=0xfffffe004b88b0c0, cred=0x80, td=0xfffff80022ac9000) at /usr/src/sys/fs/devfs/devfs_vnops.c:765
#28 0xffffffff80b3f129 in fo_ioctl (fp=<optimized out>, com=<optimized out>, active_cred=0x80, td=<optimized out>, data=<optimized out>) at /usr/src/sys/sys/file.h:325
#29 kern_ioctl (td=0xfffff80022ac9000, fd=<optimized out>, com=<optimized out>, data=0xfffffe004b88b0c0 "") at /usr/src/sys/kern/sys_generic.c:838
#30 0xffffffff80b3edfc in sys_ioctl (td=0xfffff80022ac9000, uap=0xfffff80022ac93b8) at /usr/src/sys/kern/sys_generic.c:747
#31 0xffffffff80f8de2b in syscallenter (td=0xfffff80022ac9000) at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:134
#32 amd64_syscall (td=0xfffff80022ac9000, traced=0) at /usr/src/sys/amd64/amd64/trap.c:935
#33 0xffffffff80f68a0d in fast_syscall_common () at /usr/src/sys/amd64/amd64/exception.S:480
#34 0x0000000000000003 in ?? ()
#35 0x00000000c4e01902 in ?? ()
#36 0x00007fffffffa1e0 in ?? ()
#37 0x00007fffffffa1e0 in ?? ()
#38 0x00000000000004e0 in ?? ()
#39 0x0000000000000000 in ?? ()
(kgdb) up
#1  doadump (textdump=0) at /usr/src/sys/kern/kern_shutdown.c:347
347		dumptid = curthread->td_tid;
(kgdb) 
#2  0xffffffff8040a96b in db_dump (dummy=<optimized out>, dummy2=<unavailable>, dummy3=<unavailable>, dummy4=<unavailable>) at /usr/src/sys/ddb/db_command.c:574
574		error = doadump(false);
(kgdb) 
#3  0xffffffff8040a739 in db_command (last_cmdp=<optimized out>, cmd_table=<optimized out>, dopager=<optimized out>) at /usr/src/sys/ddb/db_command.c:481
481		    (*cmd->fcn)(addr, have_addr, count, modif);
(kgdb) 
#4  0xffffffff8040a4b4 in db_command_loop () at /usr/src/sys/ddb/db_command.c:534
534		    db_command(&db_last_command, &db_cmd_table, /* dopager */ 1);
(kgdb) 
#5  0xffffffff8040d6df in db_trap (type=<optimized out>, code=<optimized out>) at /usr/src/sys/ddb/db_main.c:250
250			db_command_loop();
(kgdb) 
#6  0xffffffff80b19333 in kdb_trap (type=3, code=-61456, tf=<optimized out>) at /usr/src/sys/kern/subr_kdb.c:697
697			handled = be->dbbe_trap(type, code);

(kgdb) tid 100432
(kgdb) bt
#0  cpustop_handler () at /usr/src/sys/x86/x86/mp_x86.c:1324
#1  0xffffffff810f8934 in ipi_nmi_handler () at /usr/src/sys/x86/x86/mp_x86.c:1280
#2  0xffffffff80f8c589 in trap (frame=0xfffffe000358bf30) at /usr/src/sys/amd64/amd64/trap.c:188
#3  <signal handler called>
#4  smp_targeted_tlb_shootdown (mask=..., vector=246, pmap=0xffffffff81e5d4f0 <kernel_pmap_store>, addr1=<optimized out>, addr2=<optimized out>) at /usr/src/sys/x86/x86/mp_x86.c:1558
#5  0xffffffff810f9172 in smp_masked_invlpg_range (mask=..., addr1=<optimized out>, addr2=18446744071593589760, pmap=<optimized out>) at /usr/src/sys/x86/x86/mp_x86.c:1594
#6  0xffffffff80f770e1 in pmap_invalidate_range (pmap=0xffffffff81e5d4f0 <kernel_pmap_store>, sva=18446741875731156992, eva=18446741875731161088) at /usr/src/sys/amd64/amd64/pmap.c:1771
#7  0xffffffff80f7ae57 in pmap_remove_ptes (pmap=0xffffffff81e5d4f0 <kernel_pmap_store>, sva=18446741875731161088, eva=18446741875731173376, pde=0xfffff80003006f90, free=0xfffffe004b8816c0, lockp=0xfffffe004b8816d8) at /usr/src/sys/amd64/amd64/pmap.c:4086
#8  0xffffffff80f79334 in pmap_remove (pmap=0xffffffff81e5d4f0 <kernel_pmap_store>, sva=18446741875731156992, eva=18446741875731173376) at /usr/src/sys/amd64/amd64/pmap.c:4222
#9  0xffffffff80dfaca1 in vm_map_delete (map=0xfffff800035e0828, start=<optimized out>, end=18446741875731173376) at /usr/src/sys/vm/vm_map.c:3161
#10 0xffffffff80dfe101 in vm_map_remove (map=0xfffff800035e0828, start=18446741875731156992, end=18446741875731173376) at /usr/src/sys/vm/vm_map.c:3188
#11 0xffffffff80b4376f in pipe_free_kmem (cpipe=<optimized out>) at /usr/src/sys/kern/sys_pipe.c:1638
#12 pipeclose (cpipe=0xfffff80022cc68e8) at /usr/src/sys/kern/sys_pipe.c:1703
#13 0xffffffff80b4321a in pipe_dtor (dpipe=<optimized out>) at /usr/src/sys/kern/sys_pipe.c:390
#14 pipe_close (fp=0xfffff80184b742d0, td=<optimized out>) at /usr/src/sys/kern/sys_pipe.c:1575
#15 0xffffffff80a80585 in fo_close (fp=<optimized out>, td=<optimized out>) at /usr/src/sys/sys/file.h:348
#16 _fdrop (fp=<optimized out>, td=<optimized out>) at /usr/src/sys/kern/kern_descrip.c:2893
#17 closef (fp=0xfffff80184b742d0, td=0xfffff80022aca000) at /usr/src/sys/kern/kern_descrip.c:2474
#18 0xffffffff80a7d800 in closefp (fdp=0xfffff80022a7f450, fd=3, fp=0xfffff80184b742d0, td=0xfffff80022aca000, holdleaders=0) at /usr/src/sys/kern/kern_descrip.c:1195
#19 0xffffffff80f8de2b in syscallenter (td=0xfffff80022aca000) at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:134
#20 amd64_syscall (td=0xfffff80022aca000, traced=0) at /usr/src/sys/amd64/amd64/trap.c:935
#21 0xffffffff80f68a0d in fast_syscall_common () at /usr/src/sys/amd64/amd64/exception.S:480
#22 0x0000000000000003 in ?? ()
#23 0x00007fffffffe840 in ?? ()
#24 0x0000000000000080 in ?? ()
#25 0x0000000000000000 in ?? ()
(kgdb)
Comment 1 vidwer+fbsdbugs 2018-03-08 08:43:37 UTC
The machine was idling, except for the detail it could have been, or has finished,  two SMART tests (smartct -t long ada[01]).

The backtrace text looks different to what is written here: https://lists.freebsd.org/pipermail/freebsd-stable/2017-May/087125.html