Re: ATA_CAM-ed mvsata(4) on OpenRD-client

Hi mav.

On Fri, 19 Feb 2010 22:36:12 +0200
Alexander Motin <mav_at_FreeBSD.org> wrote:
> > xpt_sim_opened() at 0xc0904048 = xpt_sim_opened+0x218
> > scp=0xc0904048 rlv=0xc0905940 (0xc0905940 = xpt_register_async+0xd0)
> >         rsp=0xc0d62d8c rfp=0xc0d62e34
> > xpt_register_async() at 0xc0905880 = xpt_register_async+0x10
> > scp=0xc0905880 rlv=0xc090d484 (0xc090d484 = ata_get_xport+0x2198)
> >         rsp=0xc0d62e38 rfp=0xc0d62e44
> >         r10=0x00000000 r9=0x00000000
> >         r8=0x005fffcc r7=0xc35593c0 r6=0xc0b62170 r5=0xc0be74d0
> >         r4=0x0000001c
> Even more unexpected. I've searched all sources for xpt_sim_opened()
> call and found only one place - in atapi-cam.c, which shouldn't be used
> in your case. You are using different sources, or there is a garbage in
> stack?

	I tried to printf-debug, so I got what's happen.
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
module_register_init: MOD_LOAD(elf32) called in
module_register_init: MOD_LOAD(elf32 on elf kernel/elf kernel) called out
module_register_init: MOD_LOAD(shell) called in
module_register_init: MOD_LOAD(shell on elf kernel/elf kernel) called out
module_register_init: MOD_LOAD(if_lo) called in
module_register_init: MOD_LOAD(if_lo on elf kernel/elf kernel) called out
lo0: bpf attached
[DEBUG] xpt_config called #4501_at_/usr/src/sys/cam/cam_xpt.c
[DEBUG] xpt_config #4532_at_/usr/src/sys/cam/cam_xpt.c
[DEBUG] xpt_config #4538_at_/usr/src/sys/cam/cam_xpt.c
[DEBUG] periphdriver_init(1), init = 1 #132_at_/usr/src/sys/cam/cam_periph.c
[DEBUG] periphdriver_init:, i = 0, driver_name = ada
[DEBUG] periphdriver_init:, i = 1, driver_name = probe
[DEBUG] periphdriver_init:, i = 2, driver_name = pmp
spin lock 0xc3789100 () held by 0xc3632348 (tid 0) too long
panic: spin lock held too long
KDB: enter: panic
[ thread pid 0 tid 100000 ]
Stopped at      0xc09dede0 = kdb_enter+0x48:    ldrb    r15, [r15, r15, ror r15]!
db> show lock 0xc3789100
 class: spin mutex
 name:
 flags: {SPIN, RECURSE}
 state: {OWNED}
 owner: 0xc3632348 (tid 0, pid 0, "")
 recursed: -251133952
db> bt
Tracing pid 0 tid 100000 td 0xc0be6ab0
kdb_enter() at 0xc09deda8 = kdb_enter+0x10
scp=0xc09deda8 rlv=0xc09b572c (0xc09b572c = panic+0xcc)
        rsp=0xc0d6ec10 rfp=0xc0d6ec24
        r4=0x00000100
panic() at 0xc09b5674 = panic+0x14
scp=0xc09b5674 rlv=0xc09a99fc (0xc09a99fc = _thread_lock_flags+0x170)
        rsp=0xc0d6ec38 rfp=0xc0d6ec80
_thread_lock_flags() at 0xc09a989c = _thread_lock_flags+0x10
scp=0xc09a989c rlv=0xc09ec7c0 (0xc09ec7c0 = turnstile_claim+0x16c)
        rsp=0xc0d6ec84 rfp=0xc0d6eca0
        r10=0xc0bf244c r9=0x00000000
        r8=0xc3562000 r7=0x00000044 r6=0xc3562000 r5=0xc3789100
        r4=0xc0b68548
turnstile_claim() at 0xc09ec768 = turnstile_claim+0x114
scp=0xc09ec768 rlv=0xc09ecad8 (0xc09ecad8 = turnstile_wait+0x23c)
        rsp=0xc0d6eca4 rfp=0xc0d6eccc
        r7=0xc0be6ab0 r6=0xc3789100
        r5=0xc0b68548 r4=0x00000000
turnstile_wait() at 0xc09ec8ac = turnstile_wait+0x10
scp=0xc09ec8ac rlv=0xc09a9568 (0xc09a9568 = _mtx_lock_sleep+0x11c)
        rsp=0xc0d6ecd0 rfp=0xc0d6ed00
        r10=0xc0b4aa58 r9=0x00000000
        r8=0x00000000 r7=0x00000000 r6=0xc0be6ab0 r5=0xc3562000
        r4=0xc35fe974
_mtx_lock_sleep() at 0xc09a945c = _mtx_lock_sleep+0x10
scp=0xc09a945c rlv=0xc09a9650 (0xc09a9650 = _mtx_lock_flags+0x88)
        rsp=0xc0d6ed04 rfp=0xc0d6ed2c
        r10=0xc0d6ed60 r9=0xc0903a68
        r8=0x00000000 r7=0x000007c7 r6=0xc0b4aa58 r5=0x00000000
        r4=0xc35fe974
_mtx_lock_flags() at 0xc09a95d8 = _mtx_lock_flags+0x10
scp=0xc09a95d8 rlv=0xc0903e98 (0xc0903e98 = xpt_unlock_buses+0x148)
        rsp=0xc0d6ed30 rfp=0xc0d6ed58
        r8=0xc0be33fc r7=0xc090e838
        r6=0xc3788880 r5=0xc0b4aa58 r4=0xc3788b80
xpt_unlock_buses() at 0xc0903e28 = xpt_unlock_buses+0xd8
scp=0xc0903e28 rlv=0xc0903f54 (0xc0903f54 = xpt_unlock_buses+0x204)
        rsp=0xc0d6ed5c rfp=0xc0d6ed78
        r10=0xc0be3410 r9=0xc0b4aa58
        r8=0x00000000 r7=0xc090e838 r6=0x00000080 r5=0x00000000
        r4=0x00000001
xpt_unlock_buses() at 0xc0903f34 = xpt_unlock_buses+0x1e4
scp=0xc0903f34 rlv=0xc0905d5c (0xc0905d5c = xpt_register_async+0xd0)
        rsp=0xc0d6ed7c rfp=0xc0d6ee24
xpt_register_async() at 0xc0905c9c = xpt_register_async+0x10
scp=0xc0905c9c rlv=0xc090e818 (0xc090e818 = ata_get_xport+0x2d54)
        rsp=0xc0d6ee28 rfp=0xc0d6ee34
        r10=0x00000000 r9=0x00000000
        r8=0x005fffcc r7=0xc3584460 r6=0xc0b4aa58 r5=0x00000002
        r4=0x00000008
ata_get_xport() at 0xc090e808 = ata_get_xport+0x2d44
scp=0xc090e808 rlv=0xc09008a4 (0xc09008a4 = periphdriver_init+0x9c)
        rsp=0xc0d6ee38 rfp=0xc0d6ee50
periphdriver_init() at 0xc0900818 = periphdriver_init+0x10
scp=0xc0900818 rlv=0xc0904620 (0xc0904620 = xpt_alloc_ccb+0xbc)
        rsp=0xc0d6ee54 rfp=0xc0d6ee74
        r5=0xc0b4ab9c r4=0x00000000
xpt_alloc_ccb() at 0xc09045a0 = xpt_alloc_ccb+0x3c
scp=0xc09045a0 rlv=0xc09d4e84 (0xc09d4e84 = vaccess_acl_posix1e+0x628)
        rsp=0xc0d6ee78 rfp=0xc0d6eee0
        r6=0xc0b660a4 r5=0xc0bebfe0
        r4=0x00000000
vaccess_acl_posix1e() at 0xc09d4e2c = vaccess_acl_posix1e+0x5d0
scp=0xc09d4e2c rlv=0xc097dac4 (0xc097dac4 = mi_startup+0xdc)
        rsp=0xc0d6eee4 rfp=0xc0d6eef4
        r7=0x00900040 r6=0x00000002
        r5=0x0090004c r4=0xc0b82d94
mi_startup() at 0xc097d9f8 = mi_startup+0x10
scp=0xc097d9f8 rlv=0xc09000e4 (0xc09000e4 = btext+0xe4)
        rsp=0xc0d6eef8 rfp=0x00000000
        r4=0x00900124
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -

	I disabled all Giant lock, and added printf-debug code to
	cam/cam_xpt.c, cam/cam_periph.c.  As result, varnished on pmp
	driver.  I'll try to research where varnish point on pmp.

	Thank you.