Re: make test under lang/perl5.14 causes panic: blockable sleep lock (sleep mutex) process lock @ /usr/src/sys/ia64/ia64/trap.c:562

On Mon, Aug 15, 2011 at 06:34:51PM +0100, Anton Shterenlikht wrote:
> On Fri, Aug 12, 2011 at 05:45:55PM -0700, Marcel Moolenaar wrote:
> > 
> > On Aug 12, 2011, at 7:19 AM, Anton Shterenlikht wrote:
> > 
> > > On ia64 r221488
> > 
> > Please update to at least r223700, as that was a major stability fix.
> 
> UZI> uname -a
> FreeBSD mech-as221.men.bris.ac.uk 9.0-BETA1 FreeBSD 9.0-BETA1 #5 r224876: Mon Aug 15 12:06:05 BST 2011     root_at_mech-as221.men.bris.ac.uk:/usr/obj/usr/src/sys/UZI  ia64
> UZI> 
> 
> make test run with no panic once (though lots of errors,
> I should probably let the perl team know), and
> panicked on the second run:
> 
> # make test
> 
> *skip many tests*
> 
> op/64bitint.t ..................................................... ok 
> op/alarm.t ........................................................ Write failed: Broken pipe
> 
> 
> isitmychild: rmatrix mismatch between process lock (index 8) and sigacts (index 166): w_rmatrix[8][166] == 1 but w_rmatrix[166][8] == 4
> KDB: stack backtrace:
> panic: blockable sleep lock (sleep mutex) process lock _at_ /usr/src/sys/ia64/ia64/trap.c:562
> cpuid = 1
> KDB: enter: panic
> [ thread pid 64967 tid 100400 ]
> Stopped at      kdb_enter+0x92: [I2]    addl r14=0xffffffffffe211b0,gp ;;
> db> 
> 
> db> show thread
> Thread 100400 at 0xe0000000121eb9e0:
>  proc (pid 64967): 0xe0000000121de000
>  name: perl
>  stack: 0xa000000097206000-0xa00000009720dfff
>  flags: 0x4  pflags: 0
>  state: RUNNING (CPU 1)
>  priority: 194
>  container lock: sched lock 1 (0x9ffc000000a73780)
> db> 
> 
> db> show proc
> Process 64967 (perl) at 0xe0000000121de000:
>  state: NORMAL
>  uid: 0  gids: 0, 5
>  parent: pid 63774 at 0xe00000001194c468
>  ABI: FreeBSD ELF64
>  arguments: ./perl
>  threads: 1
> 100400                   Run     CPU 1                       perl
> db> 
> 
> db> bt
> Tracing pid 64967 tid 100400 td 0xe0000000121eb9e0
> kdb_enter(0x9ffc00000095b7e0, 0x9ffc00000095b7e0, 0x9ffc000000375110, 0x793) at kdb_enter+0x92
> panic(0x9ffc000000964638, 0x9ffc000000959f18, 0x9ffc000000959ef8, 0x9ffc00000099caa8, 0x232, 0x9ffc00000099caa8) at panic+0x2e0
> witness_checkorder(0xe0000000121de0f8, 0x9, 0x9ffc00000099caa8, 0x232, 0x0) at witness_checkorder+0x1b0
> _mtx_lock_flags(0xe0000000121de0f8, 0x0, 0x9ffc00000099caa8, 0x232, 0x9ffc00000081d160, 0x716, 0xa00000009720d258) at _mtx_lock_flags+0x130
> trap(0x14, 0xa00000009720c400) at trap+0x940
> ivt_Data_TLB() at ivt_Data_TLB+0x1d0
> --- trapframe at 0xa00000009720c400
> uma_zalloc_arg(0xe0000040fed6fb00, 0x0, 0x1) at uma_zalloc_arg+0x121
> malloc(0x9, 0x9ffc000000a1f9f0, 0x1) at malloc+0x290
> unw_alloc(0x10c0, 0x9ffc0000007d8a10) at unw_alloc+0x210
> uwx_init(0x0, 0x9ffc000000820590, 0x28a, 0x9ffc000000c27330) at uwx_init+0x70
> unw_create_from_pcb(0xa00000009720c750, 0xa00000009720c7f0, 0x9ffc0000007fe680) at unw_create_from_pcb+0x20
> db_backtrace(0xe0000000121eb9e0, 0xa00000009720c7f0, 0xffffffffffffffff) at db_backtrace+0x20
> db_trace_self(0x9ffc000000101100) at db_trace_self+0x40
> db_trace_self_wrapper(0x9ffc0000003e3620) at db_trace_self_wrapper+0x70
> kdb_backtrace(0x9ffc000000a484c0, 0x9ffc00000040ef60, 0x410, 0x9ffc000000c27330) at kdb_backtrace+0xc0
> _isitmyx(0xa000000000202400, 0xa000000000207300, 0x1, 0x9ffc000000964de8) at _isitmyx+0x1c0
> isitmychild(0xa000000000202400, 0xa000000000207300, 0x9ffc000000412cb0, 0x999, 0x9ffc00000095b8e8) at isitmychild+0x30
> witness_checkorder(0xe000000011d75ca8, 0x9, 0x9ffc000000be9f90, 0x288, 0x0) at witness_checkorder+0x5e0
> _mtx_lock_flags(0xe000000011d75ca8, 0x0, 0x9ffc00000095b8e8, 0x288) at _mtx_lock_flags+0x130
> kern_sigaction(0xe0000000121de000, 0xe, 0x0, 0xa00000009720d380, 0x9ffc00000095b8e8) at kern_sigaction+0x90
> sigaction(0xe0000000121eb9e0, 0xa00000009720d4e8, 0x0, 0xa00000009720d380) at sigaction+0xb0
> syscallenter(0xe0000000121eb9e0, 0xa00000009720d3a0, 0xa00000009720d3a8) at syscallenter+0x4e0
> syscall(0xa00000009720d4c8, 0xe0000000121eb9e0, 0x7fffffffffffe1a0, 0x9ffc000000818520, 0x8, 0x120bc9930) at syscall+0x60
> epc_syscall_return() at epc_syscall_return
> db> 

and again:

nic: blockable sleep lock (sleep mutex) process lock _at_ /usr/src/sys/ia64/ia64/trap.c:562
cpuid = 0
KDB: enter: panic
[ thread pid 9680 tid 100382 ]
Stopped at      kdb_enter+0x92: [I2]    addl r14=0xffffffffffe211b0,gp ;;
db> 

db> show thread
Thread 100382 at 0xe0000000119c48a0:
 proc (pid 9680): 0xe000000011e37608
 name: perl
 stack: 0xa000000097176000-0xa00000009717dfff
 flags: 0x4  pflags: 0
 state: RUNNING (CPU 0)
 priority: 177
 container lock: sched lock 0 (0x9ffc000000a72b00)
db> 

db> show proc
Process 9680 (perl) at 0xe000000011e37608:
 state: NORMAL
 uid: 0  gids: 0, 5
 parent: pid 9533 at 0xe000000011e36468
 ABI: FreeBSD ELF64
 arguments: ../../t/perl
 threads: 1
100382                   Run     CPU 0                       perl
db> 

db> bt
Tracing pid 9680 tid 100382 td 0xe0000000119c48a0
kdb_enter(0x9ffc00000095b7e0, 0x9ffc00000095b7e0, 0x9ffc000000375110, 0x793) at kdb_enter+0x92
panic(0x9ffc000000964638, 0x9ffc000000959f18, 0x9ffc000000959ef8, 0x9ffc00000099caa8, 0x232, 0x9ffc00000099caa8) at panic+0x2e0
witness_checkorder(0xe000000011e37700, 0x9, 0x9ffc00000099caa8, 0x232, 0x0) at witness_checkorder+0x1b0
_mtx_lock_flags(0xe000000011e37700, 0x0, 0x9ffc00000099caa8, 0x232, 0x9ffc00000081d160, 0x716, 0x120fa5660) at _mtx_lock_flags+0x130
trap(0x14, 0xa00000009717d000) at trap+0x940
ivt_Data_TLB() at ivt_Data_TLB+0x1d0
--- trapframe at 0xa00000009717d000
sleepq_add(0x9ffc000000a48388, 0x0, 0x9ffc00000095d0f8, 0x100, 0x0) at sleepq_add+0x530
_sleep(0x9ffc000000a48388, 0x0, 0x9ffc000000a5aa98, 0x9ffc00000095d0f8, 0x2) at _sleep+0x580
kern_nanosleep(0xe0000000119c48a0, 0xa00000009717d398, 0xa00000009717d380) at kern_nanosleep+0x220
nanosleep(0xe0000000119c48a0, 0xa00000009717d4e8, 0x0, 0x9ffc000000400cf0) at nanosleep+0xb0
syscallenter(0xe0000000119c48a0, 0xa00000009717d3a0, 0xa00000009717d3a8) at syscallenter+0x4e0
syscall(0xa00000009717d4c8, 0xe0000000119c48a0, 0x9ffc00000099caa8, 0x9ffc000000818520, 0x8, 0x0) at syscall+0x60
epc_syscall_return() at epc_syscall_return
db> 

Unofortunately, it's not exactly reproducible,
i.e. the panic happens at different test each
time.

Do let me know if there anything else I can
do to give you more useful information.

-- 
Anton Shterenlikht
Room 2.6, Queen's Building
Mech Eng Dept
Bristol University
University Walk, Bristol BS8 1TR, UK
Tel: +44 (0)117 331 5944
Fax: +44 (0)117 929 4423