Re: Crash when issueing shutdown -r now

From: Gelsema, P \(Patrick\) <"Gelsema,>
Date: Fri, 20 Apr 2007 00:05:02 +0200 (CEST)
On Thu, April 19, 2007 16:17, Scott Long wrote:
> Dag-Erling Smørgrav wrote:
>> "Gelsema, P \(Patrick\)" <gelsemap_at_superhero.nl> writes:
>>> On Thu, April 19, 2007 14:05, Dag-Erling Smørgrav wrote:
>>>> Do you have an Adaptec SCSI controller, and if so, do you use it?
>>> I do have an Adaptec SCSI Controller, and yes I use it. I boot from it.
>>
>> OK.  There's a known locking bug in the ahd driver.  You might try
>> reverting your source tree to a pre-MPSAFE-CAM version; try
>> 2007/04/14.
>>
>> DES
>
> Actually, just hang on for a few more hours and I'll have a fix
> committed.  Oddly, this problem only shows up on amd64, though it's
> a major deadlock risk on any platform.  I'm a bit disappointed in how
> serious of a problem it is.
>
> Scott
>

Hi Scott,

I did notice some commits regarding CAM code so I did a cvsup, rebuild
world and kernel and rebooted.

The first LOR after reboot seems to be gone. All the actions I performed
to create the first LOR do not throw one anymore. So this one seems to be
ok. Thanks for that!

The second LOR when rebooting/shutting down is still there in a slightly
altered form. Seems to be the same type of problem as the first LOR. See
excerpt from logs below.

Rgds,

Patrick

Apr 19 23:51:13 hulk syslogd: kernel boot file is /boot/kernel/kernel
Apr 19 23:51:13 hulk kernel: Waiting (max 60 seconds) for system process
`vnlru' to stop...done
Apr 19 23:51:13 hulk kernel: Waiting (max 60 seconds) for system process
`bufdaemon' to stop...done
Apr 19 23:51:13 hulk kernel: Waiting (max 60 seconds) for system process
`syncer' to stop...
Apr 19 23:51:13 hulk kernel: Syncing disks, vnodes remaining...1 1 0 0 done
Apr 19 23:51:13 hulk kernel: All buffers synced.
Apr 19 23:51:13 hulk kernel: Uptime: 6m26s
Apr 19 23:51:13 hulk kernel: lock order reversal: (sleepable after
non-sleepable)
Apr 19 23:51:13 hulk kernel: 1st 0xffffff007b3e6358 ahd_lock (ahd_lock) _at_
/usr/src/sys/cam/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: 2nd 0xffffffff8097cb00 module subsystem sx
lock (module subsystem sx lock) _at_ /usr
/src/sys/kern/kern_module.c:103
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_checkorder() at witness_checkorder+0x4f9
Apr 19 23:51:13 hulk kernel: _sx_slock() at _sx_slock+0x3a
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x47
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg: zone "16" with the following
non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg() at uma_zalloc_arg+0x292
Apr 19 23:51:13 hulk kernel: malloc() at malloc+0xa3
Apr 19 23:51:13 hulk kernel: g_modevent() at g_modevent+0x52
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg: zone "16" with the following
non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg() at uma_zalloc_arg+0x292
Apr 19 23:51:13 hulk kernel: malloc() at malloc+0xa3
Apr 19 23:51:13 hulk kernel: g_modevent() at g_modevent+0x52
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg: zone "16" with the following
non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg() at uma_zalloc_arg+0x292
Apr 19 23:51:13 hulk kernel: malloc() at malloc+0xa3
Apr 19 23:51:13 hulk kernel: g_modevent() at g_modevent+0x52
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg: zone "16" with the following
non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg() at uma_zalloc_arg+0x292
Apr 19 23:51:13 hulk kernel: malloc() at malloc+0xa3
Apr 19 23:51:13 hulk kernel: g_modevent() at g_modevent+0x52
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg: zone "16" with the following
non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg() at uma_zalloc_arg+0x292
Apr 19 23:51:13 hulk kernel: malloc() at malloc+0xa3
Apr 19 23:51:13 hulk kernel: g_modevent() at g_modevent+0x52
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg: zone "16" with the following
non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg() at uma_zalloc_arg+0x292
Apr 19 23:51:13 hulk kernel: malloc() at malloc+0xa3
Apr 19 23:51:13 hulk kernel: g_modevent() at g_modevent+0x52
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: Waiting on "ATA request done" with the
following non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: _cv_timedwait() at _cv_timedwait+0x9e
Apr 19 23:51:13 hulk kernel: _sema_timedwait() at _sema_timedwait+0x48
Apr 19 23:51:13 hulk kernel: ata_queue_request() at ata_queue_request+0x43a
Apr 19 23:51:13 hulk kernel: ata_controlcmd() at ata_controlcmd+0x89
Apr 19 23:51:13 hulk kernel: bus_generic_shutdown() at
bus_generic_shutdown+0x18
Apr 19 23:51:13 hulk last message repeated 4 times
Apr 19 23:51:13 hulk kernel: acpi_shutdown() at acpi_shutdown+0x31
Apr 19 23:51:13 hulk kernel: bus_generic_shutdown() at
bus_generic_shutdown+0x18
Apr 19 23:51:13 hulk kernel: bus_generic_shutdown() at
bus_generic_shutdown+0x18
Apr 19 23:51:13 hulk kernel: root_bus_module_handler() at
root_bus_module_handler+0x1d
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: Waiting on "ATA request done" with the
following non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: _cv_timedwait() at _cv_timedwait+0x9e
Apr 19 23:51:13 hulk kernel: _sema_timedwait() at _sema_timedwait+0x48
Apr 19 23:51:13 hulk kernel: ata_queue_request() at ata_queue_request+0x43a
Apr 19 23:51:13 hulk kernel: ata_controlcmd() at ata_controlcmd+0x89
Apr 19 23:51:13 hulk kernel: bus_generic_shutdown() at
bus_generic_shutdown+0x18
Apr 19 23:51:13 hulk last message repeated 4 times
Apr 19 23:51:13 hulk kernel: acpi_shutdown() at acpi_shutdown+0x31
Apr 19 23:51:13 hulk kernel: bus_generic_shutdown() at
bus_generic_shutdown+0x18
Apr 19 23:51:13 hulk kernel: bus_generic_shutdown() at
bus_generic_shutdown+0x18
Apr 19 23:51:13 hulk kernel: root_bus_module_handler() at
root_bus_module_handler+0x1d
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: Waiting on "ATA request done" with the
following non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: _cv_timedwait() at _cv_timedwait+0x9e
Apr 19 23:51:13 hulk kernel: _sema_timedwait() at _sema_timedwait+0x48
Apr 19 23:51:13 hulk kernel: ata_queue_request() at ata_queue_request+0x43a
Apr 19 23:51:13 hulk kernel: ata_controlcmd() at ata_controlcmd+0x89
Apr 19 23:51:13 hulk kernel: bus_generic_shutdown() at
bus_generic_shutdown+0x18
Apr 19 23:51:13 hulk last message repeated 4 times
Apr 19 23:51:13 hulk kernel: acpi_shutdown() at acpi_shutdown+0x31
Apr 19 23:51:13 hulk kernel: bus_generic_shutdown() at
bus_generic_shutdown+0x18
Apr 19 23:51:13 hulk kernel: bus_generic_shutdown() at
bus_generic_shutdown+0x18
Apr 19 23:51:13 hulk kernel: root_bus_module_handler() at
root_bus_module_handler+0x1d
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg: zone "16" with the following
non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg() at uma_zalloc_arg+0x292
Apr 19 23:51:13 hulk kernel: malloc() at malloc+0xa3
Apr 19 23:51:13 hulk kernel: g_modevent() at g_modevent+0x52
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg: zone "16" with the following
non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg() at uma_zalloc_arg+0x292
Apr 19 23:51:13 hulk kernel: malloc() at malloc+0xa3
Apr 19 23:51:13 hulk kernel: g_modevent() at g_modevent+0x52
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg: zone "16" with the following
non-sleepable locks held:
Apr 19 23:51:13 hulk kernel: exclusive sleep mutex ahd_lock r = 0
(0xffffff007b3e6358) locked _at_ /usr/src/sys/c
am/cam_periph.c:559
Apr 19 23:51:13 hulk kernel: KDB: stack backtrace:
Apr 19 23:51:13 hulk kernel: db_trace_self_wrapper() at
db_trace_self_wrapper+0x3a
Apr 19 23:51:13 hulk kernel: witness_warn() at witness_warn+0x262
Apr 19 23:51:13 hulk kernel: uma_zalloc_arg() at uma_zalloc_arg+0x292
Apr 19 23:51:13 hulk kernel: malloc() at malloc+0xa3
Apr 19 23:51:13 hulk kernel: g_modevent() at g_modevent+0x52
Apr 19 23:51:13 hulk kernel: module_shutdown() at module_shutdown+0x5f
Apr 19 23:51:13 hulk kernel: boot() at boot+0x3f1
Apr 19 23:51:13 hulk kernel: reboot() at reboot+0x42
Apr 19 23:51:13 hulk kernel: syscall() at syscall+0x1f0
Apr 19 23:51:13 hulk kernel: Xfast_syscall() at Xfast_syscall+0xab
Apr 19 23:51:13 hulk kernel: --- syscall (55, FreeBSD ELF64, reboot), rip
= 0x40849c, rsp = 0x7fffffffe7d8, rb
p = 0x54 ---
Apr 19 23:51:13 hulk kernel:
Apr 19 23:51:13 hulk kernel: The operating system has halted.
Apr 19 23:51:13 hulk kernel: Please press any key to reboot.
Apr 19 23:51:13 hulk kernel:
Received on Thu Apr 19 2007 - 20:04:48 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:39:09 UTC