NetBSD Problem Report #38335

From jarle@festningen.uninett.no  Sat Mar 29 21:57:01 2008
Return-Path: <jarle@festningen.uninett.no>
Received: from mail.netbsd.org (mail.netbsd.org [204.152.190.11])
	by narn.NetBSD.org (Postfix) with ESMTP id 789EB63B8BC
	for <gnats-bugs@gnats.NetBSD.org>; Sat, 29 Mar 2008 21:57:01 +0000 (UTC)
Message-Id: <20080329215658.3AE8180B63@festningen.uninett.no>
Date: Sat, 29 Mar 2008 22:56:58 +0100 (CET)
From: jarle@uninett.no
Reply-To: jarle@uninett.no
To: gnats-bugs@gnats.NetBSD.org
Subject: kernel freeze on alpha MP system
X-Send-Pr-Version: 3.95

>Number:         38335
>Category:       port-alpha
>Synopsis:       kernel freeze on alpha MP system
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    port-alpha-maintainer
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Sat Mar 29 22:00:01 +0000 2008
>Closed-Date:    
>Last-Modified:  Fri Feb 19 18:30:02 +0000 2010
>Originator:     Jarle Greipsland
>Release:        NetBSD -current
>Organization:

>Environment:


System: NetBSD sweetheart.urc.uninett.no 4.99.58 NetBSD 4.99.58 (GENERIC-$Revision: 1.314 $) #1: Sat Mar 29 20:46:15 CET 2008  jarle@sweetheart.urc.uninett.no:/usr/obj/sys/arch/alpha/compile/CS20.MP alpha
Architecture: alpha
Machine: alpha
>Description:
A -current alpha kernel on a CS20 dual processor system got stuck in the
kernel during a NetBSD build job.  After more than three minutes without
any response from the system, I managed to break into ddb, and gather some
data:

Stopped in pid 27607.1 (sh) at  netbsd:cpu_Debugger+0x4:        ret     zero,(ra
)
db{0}> trace
cpu_Debugger() at netbsd:cpu_Debugger+0x4
comintr() at netbsd:comintr+0x718
alpha_shared_intr_dispatch() at netbsd:alpha_shared_intr_dispatch+0x5c
sio_iointr() at netbsd:sio_iointr+0x38
interrupt() at netbsd:interrupt+0x1c0
XentInt() at netbsd:XentInt+0x1c
--- interrupt (from ipl 0) ---
rw_vector_exit() at netbsd:rw_vector_exit+0x90
vm_map_unlock_read() at netbsd:vm_map_unlock_read+0x1c
uvm_fault_internal() at netbsd:uvm_fault_internal+0x16c8
trap() at netbsd:trap+0x6c8
XentMM() at netbsd:XentMM+0x20
--- memory management fault ---
memcpy() at netbsd:memcpy+0x54
copyout() at netbsd:copyout+0x50
copyout_vmspace() at netbsd:copyout_vmspace+0x7c
uiomove() at netbsd:uiomove+0xec
ubc_uiomove() at netbsd:ubc_uiomove+0xc8
ffs_read() at netbsd:ffs_read+0x3a8
VOP_READ() at netbsd:VOP_READ+0xcc
vn_rdwr() at netbsd:vn_rdwr+0xd0
vmcmd_readvn() at netbsd:vmcmd_readvn+0x64
execve1() at netbsd:execve1+0x790
syscall_plain() at netbsd:syscall_plain+0x1c4
XentSys() at netbsd:XentSys+0x60
--- syscall (59) ---
--- user mode ---
db{0}> show reg
v0          0xf9
t0          0xfffffc0000686a74  db_fromconsole
t1          0x1
t2          0xff00
t3          0xfffffc00006c0088  cn_magic
t4          0x2
t5          0xa0b
t6          0
t7          0xfffffc00006e11e8  vm_physmem
s0          0xf9
s1          0xc6
s2          0xfffffe00004cd000
s3          0xfffffe00004cd070
s4          0xfffffe00004d5008
s5          0x7fd
s6          0xfffffc00006a6b60  idstate+0x1ec20
a0          0xfffffc00006ea690  tsp_configuration
a1          0xfffffd01fc0003fd
a2          0x5
a3          0xfffffe0013d0b298
a4          0x22
a5          0
t8          0xfffffc00006e11e8  vm_physmem
t9          0xfffffc00004e38ac  bt_hashhead+0x5c
t10         0x600f51dc
t11         0x1a5
ra          0xfffffc00003b1e78  comintr+0x718
t12         0xfffffc00005b7340  cpu_Debugger
at          0xfffffe0013d08000
gp          0xfffffc0000686b60  nfsrtton
sp          0xfffffe0013d0b1c8
pc          0xfffffc00005b7344  cpu_Debugger+0x4
ps          0x6
ai          0x1a5
pv          0xfffffc00005b7340  cpu_Debugger
netbsd:cpu_Debugger+0x4:        ret     zero,(ra)
db{0}> ps
 PID           PPID     PGRP        UID S   FLAGS LWPS          COMMAND    WAIT
>27607        11306    20939          0 2       0    1               sh
 11306         8909    20939          0 2       0    1               sh    wait
 8909          4701    20939          0 2  0x4000    1               sh  piperd
 4701         20692    20939          0 2  0x4000    1               sh    wait
 20692        20939    20939          0 2  0x4000    1          nbgmake    wait
 20939        11274    20939          0 2  0x4000    1               sh    wait
 11274        18129    18129          0 2  0x4000    1           nbmake  select
 18129        22431    18129          0 2  0x4000    1               sh    wait
 22431         5699     5699          0 2  0x4000    1           nbmake  select
 5699          3213     5699          0 2  0x4000    1               sh    wait
 3213          1188     1178          0 2  0x4000    1           nbmake  select
 1084           463     1084       1000 2  0x4000    1              top  select
 1188          1178     1178          0 2  0x4000    1               sh    wait
 1182           389     1182          0 2  0x4000    1             tail  kqueue
 1178           389     1178          0 2       0    1             tcsh   pause
 463            435      463       1000 2  0x4000    1             bash    wait
 435            443      443       1000 2  0x4000    1            xterm  select
 443            437      443       1000 2  0x4000    1              csh   pause
 437             66       66       1000 2   0x100    1             sshd  select
 66             248       66          0 2  0x4100    1             sshd   netio
 389            381      389          0 2  0x4000    1             tcsh   pause
 381            383      381       1000 2  0x4000    1             bash    wait
 383            294      294       1000 2  0x4000    1            xterm  select
 294            301      294       1000 2  0x4000    1              csh   pause
 301            327      327       1000 2   0x100    1             sshd  select
 327            248      327          0 2  0x4100    1             sshd   netio
 377            342      342         12 2  0x4100    1             qmgr  kqueue
 370            342      342         12 2  0x4100    1           pickup  kqueue
 369              1      369          0 2  0x4000    1            getty     tty
 372              1      372          0 2       0    1             cron nanoslp
 355              1      355          0 2       0    1            inetd  kqueue
 342              1      342          0 2  0x4100    1           master  kqueue
 248              1      248          0 2       0    1             sshd  select
 236              1      236          0 2       0    1             ntpd   pause
 156              1      156          0 2       0    1        mount_mfs  mfsidl
 73               1       73          0 2       0    1          syslogd  kqueue
 1                0        1          0 2  0x4001    1             init    wait
 0               -1        0          0 2 0x20002   25           system       *
db{0}> mach cpu 1 
Using CPU 1
db{0}> trace

CPU 0: fatal kernel trap:

CPU 0    trap entry = 0x4 (unaligned access fault)
CPU 0    a0         = 0xfffffc00006e110d
CPU 0    a1         = 0x29
CPU 0    a2         = 0xa
CPU 0    pc         = 0xfffffc00005b7b78
CPU 0    ra         = 0xfffffc0000399044
CPU 0    pv         = 0xfffffc00005b7ac0
CPU 0    curlwp     = 0xfffffc00391713a0
CPU 0        pid = 27607, comm = sh

Caught exception in ddb.
db{0}> show reg
v0          0
t0          0
t1          0
t2          0
t3          0xfffffe0013243880
t4          0
t5          0xfffffc00006ecdc8  kernel_pmap_store
t6          0xfffffc00006ece28  kernel_pmap_store+0x60
t7          0x1
s0          0x1
s1          0xfffffc003f815980
s2          0xfffffc00006e1135  uvm+0xd
s3          0xfffffc00006e1128  uvm
s4          0xfffffe00004a3c00
s5          0x1
s6          0xfffffe001324fdc0
a0          0
a1          0x1
a2          0xfffffe0013bae000
a3          0x1
a4          0
a5          0xfffffe0013bb1dcc
t8          0x80
t9          0x67
t10         0xffffffff
t11         0xfffffc003b1e9328
ra          0xfffffc000049e95c  idle_loop+0x12c
t12         0xfffffc00004cb360  sched_curcpu_runnable_p
at          0x3
gp          0xfffffc0000686b60  nfsrtton
sp          0xfffffc00006e1135  uvm+0xd
pc          0xfffffc000049e934  idle_loop+0x104
ps          0
ai          0xfffffc003b1e9328
pv          0xfffffc00004cb360  sched_curcpu_runnable_p
netbsd:idle_loop+0x104: ldq_u   t0,d(s3)


>How-To-Repeat:
Run an MP kernel on an alpha system?

>Fix:


>Release-Note:

>Audit-Trail:

State-Changed-From-To: open->feedback
State-Changed-By: dholland@NetBSD.org
State-Changed-When: Sat, 19 Sep 2009 21:51:28 +0000
State-Changed-Why:
A bunch of MP alpha fixes just went into -current; might want to give them a
try.


From: Jarle Greipsland <jarle@uninett.no>
To: gnats-bugs@NetBSD.org, dholland@NetBSD.org
Cc: port-alpha-maintainer@netbsd.org, netbsd-bugs@netbsd.org,
	gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Tue, 22 Sep 2009 19:00:07 +0200 (CEST)

 dholland@NetBSD.org writes:
 > Synopsis: kernel freeze on alpha MP system
 > 
 > State-Changed-From-To: open->feedback
 > State-Changed-By: dholland@NetBSD.org
 > State-Changed-When: Sat, 19 Sep 2009 21:51:28 +0000
 > State-Changed-Why:
 > A bunch of MP alpha fixes just went into -current; might want to give them a
 > try.
 The problem is still there.  I installed and booted GENERIC.MP,
 and built a full release.  During extraction of the newly built
 sets, the system wedged again.  This time I could not break into
 DDB from the console.

 I power-cycled the system, and started to extract the sets again.
 During extraction I noticed that the IO performance through the
 file system seemed abyssmal (according to 'systat vm').  The 'tar
 zxBpf' command consumed almost no CPU, but the disk IO hovered
 around 500KB/s.  Doing a plain dd from/to a single file on the
 same disk gets around 20-30MB/s.

 Also, right after root file system detection, the kernel complains:

 WARNING: negative runtime; monotonic clock has gone backwards

 I don't know if this might be related to the wedging or not.

 If you want me to dig out more information, please ask, and I'll
 see what I can do.
 					-jarle

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: Jarle Greipsland <jarle@uninett.no>
Cc: gnats-bugs@NetBSD.org, dholland@NetBSD.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Sat, 26 Sep 2009 11:04:37 -0600 (MDT)

 On Tue, 22 Sep 2009, Jarle Greipsland wrote:

 > The problem is still there.  I installed and booted GENERIC.MP,
 > and built a full release.  During extraction of the newly built
 > sets, the system wedged again.  This time I could not break into
 > DDB from the console.

    This was a CS20, according to the original PR?  If so, you can get
 into DDB using the halt switch [it's hidden in a small hole in the front
 panel to the right].  After the machine is halted, you can enter
 'continue', which will enter into a console trap.  The halt should
 show the PC of cpu 0 at the time of the halt, and I think that address
 should be related to the backtrace of cpu 0.  One problem will be that
 it's very likely cpu 1 is not halted, and is likely spinning with
 interrupts block so the IPI send by cpu 0 to halt will not occur and
 there won't be any register available [I'm not ever sure that works
 now even when the IPI can be delivered - I need to look into that].

 > Also, right after root file system detection, the kernel complains:
 >
 > WARNING: negative runtime; monotonic clock has gone backwards
 >
 > I don't know if this might be related to the wedging or not.

    Not very likely, I think.  I see this every MP boot, and it is related
 to using the the PCC timecounter.  I haven't figured out exactly how that
 is supposed to work on an MP system yet.

 > If you want me to dig out more information, please ask, and I'll
 > see what I can do.

    The problem is likely some kind of locking deadlock, which I've gotten
 a few times.  I've been trying to debug a problem with the TLB shootdown
 code where it gets a corrupted pool_cache entry and ends up with a
 list that links to itself.  You can try this patch I'm using to attempt
 to detect this and work around it:

 @@ -3700,6 +3700,12 @@ pmap_tlb_shootdown(pmap_t pmap, vaddr_t
                   * don't really have to do anything else.
                   */
                  mutex_spin_enter(&pq->pq_lock);
 +/**/           if (pj && pj == pq->pq_head.tqh_first) {
 +/**/                   printf("Whoa!  pool_cache_get returned an in-use 
 entry! ci_index %d pj %p\n",
 +                           self->ci_index,  pj);
 +/**/                   /*panic("Oops");*/
 +/**/                   pj = NULL;      /* XXX */
 +/**/           }
                  pq->pq_pte |= pte;
                  if (pq->pq_tbia) {
                          mutex_spin_exit(&pq->pq_lock);

    An alternative workaround is to set PMAP_TLB_SHOOTDOWN_MAXJOBS to 0, 
 which will invalidate all tlbs instead of trying to invalidate
 single entries.

 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: Jarle Greipsland <jarle@uninett.no>
To: mhitch@lightning.msu.montana.edu
Cc: gnats-bugs@NetBSD.org, dholland@NetBSD.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Thu, 01 Oct 2009 13:34:50 +0200 (CEST)

 "Michael L. Hitch" <mhitch@lightning.msu.montana.edu> writes:
 >    This was a CS20, according to the original PR?  If so, you can get
 > into DDB using the halt switch [it's hidden in a small hole in the front
 > panel to the right].  After the machine is halted, you can enter
 > 'continue', which will enter into a console trap.  The halt should
 > show the PC of cpu 0 at the time of the halt, and I think that address
 > should be related to the backtrace of cpu 0.

 Annotated console log:
 [ I pressed the halt switch here ]
 halted CPU 0
 CPU 1 is not halted

 halt code = 1
 operator initiated halt
 PC = fffffc0000736b08
 P00>>>continue^U
 P00>>>help
 [ ... some help text here ... ]
 P00>>>halt 1
 P00>>>continue 

 continuing CPU 0
 CP - RESTORE_TERM routine to be called
 panic: user requested console halt
 cpu0: Begin traceback...
 alpha trace requires known PC =eject=
 cpu0: End traceback...
 WARNING: Unable to halt secondary CPUs (0x3)

 dumping to dev 8,1 offset 2097597
 dump i/o error


 sd0(esiop0:0:0:0): polling command not done
 panic: scsipi_execute_xs
 cpu0: Begin traceback...
 alpha trace requires known PC =eject=
 cpu0: End traceback...
 WARNING: Unable to halt secondary CPUs (0x3)

 dumping to dev 8,1 offset 2097597
 dump device not ready


 rebooting...

 CP - RESTORE_TERM exited with hlt_req = 3, r0 = 00000001.00000000

 halted CPU 0

 halt code = 0
 PC = fffffc0000736b08
 P00>>>cont
 Slot context is not valid
 P00>>>boot^U
 P00>>>init
 Initializing...
 .
 !1024 Meg of system memory
 initializing GCT/FRU at 1d4000
 Testing the System
 Testing the Memory
 Testing the Disks (read only)
 Testing ei* devices.

 API CS20D 833 MHz Console A5.8-81, 08-MAY-2001 00:09:13

 [ .. end of console log .. ]
 This seems less helpful than I had imagined; oh well.  I hope you
 can make some kind of sense out of it.  According to gdb, the PC
 is somewhere in pmap_do_tlb_shootdown (offset +296 in the listing
 below):

 (gdb) x/60i pmap_do_tlb_shootdown
 0xfffffc00007369e0 <pmap_do_tlb_shootdown>:     ldah    gp,80(t12)
 0xfffffc00007369e4 <pmap_do_tlb_shootdown+4>:   lda     gp,-31544(gp)
 0xfffffc00007369e8 <pmap_do_tlb_shootdown+8>:   lda     sp,-64(sp)
 0xfffffc00007369ec <pmap_do_tlb_shootdown+12>:  stq     ra,0(sp)
 0xfffffc00007369f0 <pmap_do_tlb_shootdown+16>:  stq     s0,8(sp)
 0xfffffc00007369f4 <pmap_do_tlb_shootdown+20>:  stq     s1,16(sp)
 0xfffffc00007369f8 <pmap_do_tlb_shootdown+24>:  stq     s2,24(sp)
 0xfffffc00007369fc <pmap_do_tlb_shootdown+28>:  stq     s3,32(sp)
 0xfffffc0000736a00 <pmap_do_tlb_shootdown+32>:  lda     t0,48(sp)
 0xfffffc0000736a04 <pmap_do_tlb_shootdown+36>:  ldq     s1,456(a0)
 0xfffffc0000736a08 <pmap_do_tlb_shootdown+40>:  stq     t0,56(sp)
 0xfffffc0000736a0c <pmap_do_tlb_shootdown+44>:  ldah    t0,4(gp)
 0xfffffc0000736a10 <pmap_do_tlb_shootdown+48>:  lda     t0,-25256(t0)
 0xfffffc0000736a14 <pmap_do_tlb_shootdown+52>:  ldq     t12,14240(gp)
 0xfffffc0000736a18 <pmap_do_tlb_shootdown+56>:  sll     s1,0x6,t2
 0xfffffc0000736a1c <pmap_do_tlb_shootdown+60>:  stq     zero,48(sp)
 0xfffffc0000736a20 <pmap_do_tlb_shootdown+64>:  lda     t1,1
 0xfffffc0000736a24 <pmap_do_tlb_shootdown+68>:  addq    t2,t0,s0
 0xfffffc0000736a28 <pmap_do_tlb_shootdown+72>:  lda     s3,16(s0)
 0xfffffc0000736a2c <pmap_do_tlb_shootdown+76>:  sll     t1,s1,s2
 0xfffffc0000736a30 <pmap_do_tlb_shootdown+80>:  mov     s3,a0
 0xfffffc0000736a34 <pmap_do_tlb_shootdown+84>:  jsr     ra,(t12),0xfffffc0000735b80 <pmap_do_reactivate+96>
 0xfffffc0000736a38 <pmap_do_tlb_shootdown+88>:  ldah    gp,80(ra)
 0xfffffc0000736a3c <pmap_do_tlb_shootdown+92>:  lda     gp,-31632(gp)
 0xfffffc0000736a40 <pmap_do_tlb_shootdown+96>:  ldq     t1,0(s0)
 0xfffffc0000736a44 <pmap_do_tlb_shootdown+100>: beq     t1,0xfffffc0000736a6c <pmap_do_tlb_shootdown+140>
 0xfffffc0000736a48 <pmap_do_tlb_shootdown+104>: ldq     t0,56(sp)
 0xfffffc0000736a4c <pmap_do_tlb_shootdown+108>: stq     t1,0(t0)
 0xfffffc0000736a50 <pmap_do_tlb_shootdown+112>: ldq     t0,56(sp)
 0xfffffc0000736a54 <pmap_do_tlb_shootdown+116>: ldq     t1,0(s0)
 0xfffffc0000736a58 <pmap_do_tlb_shootdown+120>: stq     t0,8(t1)
 0xfffffc0000736a5c <pmap_do_tlb_shootdown+124>: ldq     t2,8(s0)
 0xfffffc0000736a60 <pmap_do_tlb_shootdown+128>: stq     zero,0(s0)
 0xfffffc0000736a64 <pmap_do_tlb_shootdown+132>: stq     s0,8(s0)
 0xfffffc0000736a68 <pmap_do_tlb_shootdown+136>: stq     t2,56(sp)
 0xfffffc0000736a6c <pmap_do_tlb_shootdown+140>: ldl     t0,40(s0)
 0xfffffc0000736a70 <pmap_do_tlb_shootdown+144>: beq     t0,0xfffffc0000736a9c <pmap_do_tlb_shootdown+188>
 0xfffffc0000736a74 <pmap_do_tlb_shootdown+148>: ldl     t0,32(s0)
 0xfffffc0000736a78 <pmap_do_tlb_shootdown+152>: and     t0,0x10,t0
 0xfffffc0000736a7c <pmap_do_tlb_shootdown+156>: sextl   t0,t0
 0xfffffc0000736a80 <pmap_do_tlb_shootdown+160>: beq     t0,0xfffffc0000736b84 <pmap_do_tlb_shootdown+420>
 0xfffffc0000736a84 <pmap_do_tlb_shootdown+164>: lda     a0,-2
 0xfffffc0000736a88 <pmap_do_tlb_shootdown+168>: clr     a1
 0xfffffc0000736a8c <pmap_do_tlb_shootdown+172>: call_pal        0x33
 0xfffffc0000736a90 <pmap_do_tlb_shootdown+176>: stl     zero,40(s0)
 0xfffffc0000736a94 <pmap_do_tlb_shootdown+180>: stl     zero,32(s0)
 0xfffffc0000736a98 <pmap_do_tlb_shootdown+184>: br      0xfffffc0000736b14 <pmap_do_tlb_shootdown+308>
 0xfffffc0000736a9c <pmap_do_tlb_shootdown+188>: ldq     t3,48(sp)
 0xfffffc0000736aa0 <pmap_do_tlb_shootdown+192>: beq     t3,0xfffffc0000736b10 <pmap_do_tlb_shootdown+304>
 0xfffffc0000736aa4 <pmap_do_tlb_shootdown+196>: sll     s1,0x4,t2
 0xfffffc0000736aa8 <pmap_do_tlb_shootdown+200>: ldah    t0,4(gp)
 0xfffffc0000736aac <pmap_do_tlb_shootdown+204>: lda     t0,-30440(t0)
 0xfffffc0000736ab0 <pmap_do_tlb_shootdown+208>: addq    t2,t0,t5
 0xfffffc0000736ab4 <pmap_do_tlb_shootdown+212>: br      0xfffffc0000736af0 <pmap_do_tlb_shootdown+272>
 0xfffffc0000736ab8 <pmap_do_tlb_shootdown+216>: nop     
 0xfffffc0000736abc <pmap_do_tlb_shootdown+220>: unop    
 0xfffffc0000736ac0 <pmap_do_tlb_shootdown+224>: ldq     t1,24(t3)
 0xfffffc0000736ac4 <pmap_do_tlb_shootdown+228>: addq    t2,t1,t4
 0xfffffc0000736ac8 <pmap_do_tlb_shootdown+232>: ldq     t0,64(t1)
 0xfffffc0000736acc <pmap_do_tlb_shootdown+236>: and     s2,t0,t0
 (gdb) x/80i pmap_do_tlb_shootdown
 0xfffffc00007369e0 <pmap_do_tlb_shootdown>:     ldah    gp,80(t12)
 0xfffffc00007369e4 <pmap_do_tlb_shootdown+4>:   lda     gp,-31544(gp)
 0xfffffc00007369e8 <pmap_do_tlb_shootdown+8>:   lda     sp,-64(sp)
 0xfffffc00007369ec <pmap_do_tlb_shootdown+12>:  stq     ra,0(sp)
 0xfffffc00007369f0 <pmap_do_tlb_shootdown+16>:  stq     s0,8(sp)
 0xfffffc00007369f4 <pmap_do_tlb_shootdown+20>:  stq     s1,16(sp)
 0xfffffc00007369f8 <pmap_do_tlb_shootdown+24>:  stq     s2,24(sp)
 0xfffffc00007369fc <pmap_do_tlb_shootdown+28>:  stq     s3,32(sp)
 0xfffffc0000736a00 <pmap_do_tlb_shootdown+32>:  lda     t0,48(sp)
 0xfffffc0000736a04 <pmap_do_tlb_shootdown+36>:  ldq     s1,456(a0)
 0xfffffc0000736a08 <pmap_do_tlb_shootdown+40>:  stq     t0,56(sp)
 0xfffffc0000736a0c <pmap_do_tlb_shootdown+44>:  ldah    t0,4(gp)
 0xfffffc0000736a10 <pmap_do_tlb_shootdown+48>:  lda     t0,-25256(t0)
 0xfffffc0000736a14 <pmap_do_tlb_shootdown+52>:  ldq     t12,14240(gp)
 0xfffffc0000736a18 <pmap_do_tlb_shootdown+56>:  sll     s1,0x6,t2
 0xfffffc0000736a1c <pmap_do_tlb_shootdown+60>:  stq     zero,48(sp)
 0xfffffc0000736a20 <pmap_do_tlb_shootdown+64>:  lda     t1,1
 0xfffffc0000736a24 <pmap_do_tlb_shootdown+68>:  addq    t2,t0,s0
 0xfffffc0000736a28 <pmap_do_tlb_shootdown+72>:  lda     s3,16(s0)
 0xfffffc0000736a2c <pmap_do_tlb_shootdown+76>:  sll     t1,s1,s2
 0xfffffc0000736a30 <pmap_do_tlb_shootdown+80>:  mov     s3,a0
 0xfffffc0000736a34 <pmap_do_tlb_shootdown+84>:  jsr     ra,(t12),0xfffffc0000735b80 <pmap_do_reactivate+96>
 0xfffffc0000736a38 <pmap_do_tlb_shootdown+88>:  ldah    gp,80(ra)
 0xfffffc0000736a3c <pmap_do_tlb_shootdown+92>:  lda     gp,-31632(gp)
 0xfffffc0000736a40 <pmap_do_tlb_shootdown+96>:  ldq     t1,0(s0)
 0xfffffc0000736a44 <pmap_do_tlb_shootdown+100>: beq     t1,0xfffffc0000736a6c <pmap_do_tlb_shootdown+140>
 0xfffffc0000736a48 <pmap_do_tlb_shootdown+104>: ldq     t0,56(sp)
 0xfffffc0000736a4c <pmap_do_tlb_shootdown+108>: stq     t1,0(t0)
 0xfffffc0000736a50 <pmap_do_tlb_shootdown+112>: ldq     t0,56(sp)
 0xfffffc0000736a54 <pmap_do_tlb_shootdown+116>: ldq     t1,0(s0)
 0xfffffc0000736a58 <pmap_do_tlb_shootdown+120>: stq     t0,8(t1)
 0xfffffc0000736a5c <pmap_do_tlb_shootdown+124>: ldq     t2,8(s0)
 0xfffffc0000736a60 <pmap_do_tlb_shootdown+128>: stq     zero,0(s0)
 0xfffffc0000736a64 <pmap_do_tlb_shootdown+132>: stq     s0,8(s0)
 0xfffffc0000736a68 <pmap_do_tlb_shootdown+136>: stq     t2,56(sp)
 0xfffffc0000736a6c <pmap_do_tlb_shootdown+140>: ldl     t0,40(s0)
 0xfffffc0000736a70 <pmap_do_tlb_shootdown+144>: beq     t0,0xfffffc0000736a9c <pmap_do_tlb_shootdown+188>
 0xfffffc0000736a74 <pmap_do_tlb_shootdown+148>: ldl     t0,32(s0)
 0xfffffc0000736a78 <pmap_do_tlb_shootdown+152>: and     t0,0x10,t0
 0xfffffc0000736a7c <pmap_do_tlb_shootdown+156>: sextl   t0,t0
 0xfffffc0000736a80 <pmap_do_tlb_shootdown+160>: beq     t0,0xfffffc0000736b84 <pmap_do_tlb_shootdown+420>
 0xfffffc0000736a84 <pmap_do_tlb_shootdown+164>: lda     a0,-2
 0xfffffc0000736a88 <pmap_do_tlb_shootdown+168>: clr     a1
 0xfffffc0000736a8c <pmap_do_tlb_shootdown+172>: call_pal        0x33
 0xfffffc0000736a90 <pmap_do_tlb_shootdown+176>: stl     zero,40(s0)
 0xfffffc0000736a94 <pmap_do_tlb_shootdown+180>: stl     zero,32(s0)
 0xfffffc0000736a98 <pmap_do_tlb_shootdown+184>: br      0xfffffc0000736b14 <pmap_do_tlb_shootdown+308>
 0xfffffc0000736a9c <pmap_do_tlb_shootdown+188>: ldq     t3,48(sp)
 0xfffffc0000736aa0 <pmap_do_tlb_shootdown+192>: beq     t3,0xfffffc0000736b10 <pmap_do_tlb_shootdown+304>
 0xfffffc0000736aa4 <pmap_do_tlb_shootdown+196>: sll     s1,0x4,t2
 0xfffffc0000736aa8 <pmap_do_tlb_shootdown+200>: ldah    t0,4(gp)
 0xfffffc0000736aac <pmap_do_tlb_shootdown+204>: lda     t0,-30440(t0)
 0xfffffc0000736ab0 <pmap_do_tlb_shootdown+208>: addq    t2,t0,t5
 0xfffffc0000736ab4 <pmap_do_tlb_shootdown+212>: br      0xfffffc0000736af0 <pmap_do_tlb_shootdown+272>
 0xfffffc0000736ab8 <pmap_do_tlb_shootdown+216>: nop     
 0xfffffc0000736abc <pmap_do_tlb_shootdown+220>: unop    
 0xfffffc0000736ac0 <pmap_do_tlb_shootdown+224>: ldq     t1,24(t3)
 0xfffffc0000736ac4 <pmap_do_tlb_shootdown+228>: addq    t2,t1,t4
 0xfffffc0000736ac8 <pmap_do_tlb_shootdown+232>: ldq     t0,64(t1)
 0xfffffc0000736acc <pmap_do_tlb_shootdown+236>: and     s2,t0,t0
 0xfffffc0000736ad0 <pmap_do_tlb_shootdown+240>: bne     t0,0xfffffc0000736b00 <pmap_do_tlb_shootdown+288>
 0xfffffc0000736ad4 <pmap_do_tlb_shootdown+244>: ldq     t0,88(t4)
 0xfffffc0000736ad8 <pmap_do_tlb_shootdown+248>: ldq     t1,8(t5)
 0xfffffc0000736adc <pmap_do_tlb_shootdown+252>: cmpeq   t0,t1,t0
 0xfffffc0000736ae0 <pmap_do_tlb_shootdown+256>: bne     t0,0xfffffc0000736b94 <pmap_do_tlb_shootdown+436>
 0xfffffc0000736ae4 <pmap_do_tlb_shootdown+260>: ldq     t3,0(t3)
 0xfffffc0000736ae8 <pmap_do_tlb_shootdown+264>: beq     t3,0xfffffc0000736b10 <pmap_do_tlb_shootdown+304>
 0xfffffc0000736aec <pmap_do_tlb_shootdown+268>: unop    
 0xfffffc0000736af0 <pmap_do_tlb_shootdown+272>: lda     a0,3
 0xfffffc0000736af4 <pmap_do_tlb_shootdown+276>: ldq     t0,32(t3)
 0xfffffc0000736af8 <pmap_do_tlb_shootdown+280>: and     t0,0x10,t0
 0xfffffc0000736afc <pmap_do_tlb_shootdown+284>: beq     t0,0xfffffc0000736ac0 <pmap_do_tlb_shootdown+224>
 0xfffffc0000736b00 <pmap_do_tlb_shootdown+288>: ldq     a1,16(t3)
 0xfffffc0000736b04 <pmap_do_tlb_shootdown+292>: call_pal        0x33
 0xfffffc0000736b08 <pmap_do_tlb_shootdown+296>: ldq     t3,0(t3)
 0xfffffc0000736b0c <pmap_do_tlb_shootdown+300>: bne     t3,0xfffffc0000736af0 <pmap_do_tlb_shootdown+272>
 0xfffffc0000736b10 <pmap_do_tlb_shootdown+304>: stl     zero,32(s0)
 0xfffffc0000736b14 <pmap_do_tlb_shootdown+308>: mov     s3,a0
 0xfffffc0000736b18 <pmap_do_tlb_shootdown+312>: ldq     t12,-29928(gp)
 0xfffffc0000736b1c <pmap_do_tlb_shootdown+316>: stl     zero,36(s0)

 					-jarle

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: gnats-bugs@NetBSD.org
Cc: gnats-admin@netbsd.org, jarle@uninett.no
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Thu, 1 Oct 2009 12:20:43 -0600 (MDT)

 On Thu, 1 Oct 2009, Jarle Greipsland wrote:

 > Annotated console log:
 > [ I pressed the halt switch here ]
 > halted CPU 0
 > CPU 1 is not halted
 >
 > halt code = 1
 > operator initiated halt
 > PC = fffffc0000736b08
 > P00>>>continue^U
 > P00>>>help
 > [ ... some help text here ... ]
 > P00>>>halt 1

    Halting the other cpu is not needed at this point, and might have caused
 the problem when continuing cpu 0.  Also, do you have ddb.onpanic set to 
 0?  If so, you probably want it 1 so that you enter DDB when it panics.

 > WARNING: Unable to halt secondary CPUs (0x3)

    This would be caused by your halting cpu 1 earlier, although I'm pretty
 sure the same thing would have happened even if you hadn't halted it.

 > [ .. end of console log .. ]
 > This seems less helpful than I had imagined; oh well.  I hope you
 > can make some kind of sense out of it.  According to gdb, the PC
 > is somewhere in pmap_do_tlb_shootdown (offset +296 in the listing
 > below):

    It does show that what I thought had happened did indeed happen.

 > 0xfffffc0000736ac0 <pmap_do_tlb_shootdown+224>: ldq     t1,24(t3)
 > 0xfffffc0000736ac4 <pmap_do_tlb_shootdown+228>: addq    t2,t1,t4
 > 0xfffffc0000736ac8 <pmap_do_tlb_shootdown+232>: ldq     t0,64(t1)
 > 0xfffffc0000736acc <pmap_do_tlb_shootdown+236>: and     s2,t0,t0
 > 0xfffffc0000736ad0 <pmap_do_tlb_shootdown+240>: bne     t0,0xfffffc0000736b00 <pmap_do_tlb_shootdown+288>
 > 0xfffffc0000736ad4 <pmap_do_tlb_shootdown+244>: ldq     t0,88(t4)
 > 0xfffffc0000736ad8 <pmap_do_tlb_shootdown+248>: ldq     t1,8(t5)
 > 0xfffffc0000736adc <pmap_do_tlb_shootdown+252>: cmpeq   t0,t1,t0
 > 0xfffffc0000736ae0 <pmap_do_tlb_shootdown+256>: bne     t0,0xfffffc0000736b94 <pmap_do_tlb_shootdown+436>
 > 0xfffffc0000736ae4 <pmap_do_tlb_shootdown+260>: ldq     t3,0(t3)
 > 0xfffffc0000736ae8 <pmap_do_tlb_shootdown+264>: beq     t3,0xfffffc0000736b10 <pmap_do_tlb_shootdown+304>
 > 0xfffffc0000736aec <pmap_do_tlb_shootdown+268>: unop
 > 0xfffffc0000736af0 <pmap_do_tlb_shootdown+272>: lda     a0,3
 > 0xfffffc0000736af4 <pmap_do_tlb_shootdown+276>: ldq     t0,32(t3)
 > 0xfffffc0000736af8 <pmap_do_tlb_shootdown+280>: and     t0,0x10,t0
 > 0xfffffc0000736afc <pmap_do_tlb_shootdown+284>: beq     t0,0xfffffc0000736ac0 <pmap_do_tlb_shootdown+224>
 > 0xfffffc0000736b00 <pmap_do_tlb_shootdown+288>: ldq     a1,16(t3)
 > 0xfffffc0000736b04 <pmap_do_tlb_shootdown+292>: call_pal        0x33
 > 0xfffffc0000736b08 <pmap_do_tlb_shootdown+296>: ldq     t3,0(t3)
 > 0xfffffc0000736b0c <pmap_do_tlb_shootdown+300>: bne     t3,0xfffffc0000736af0 <pmap_do_tlb_shootdown+272>

    This is the loop where pmap_do_tlb_shootdown is processing the job queue 
 for this cpu (cpu 0).  T3 is the current queue entry and almost certainly 
 is linked to itself - meaning it keeps invalidating the same tlb entry 
 over and over and over......  At this point, cpu 0 will have the job queue 
 locked, and I'm certain that cpu 1 wants to invalidate another tlb entry, 
 and is attempting to acquire the lock that cpu 0 holds.

    This is the problem I'm still in the process of trying to figure out 
 what the problem is and how to fix it.  The patch I posted previously is a 
 workaround to detect this particular problem, and will display a message 
 if it occurs.  The other alternative I posted (changing 
 PMAP_TLB_SHOOTDOWN_MAXJOBS to 0) make it never allocate queue entries so 
 it should never loop.

    What I think may be happening is that the IPI interrupt may be occuring 
 at level 5, which is the same level as the clock interrupt.  The 
 mutex for the tlb shootdown queue uses IPL_VM, which I think is at level 
 4.  If I understand the mutex locking mechanism, I think this would allow 
 an IPI request from another cpu interrupt the code that manipulates the 
 shootdown queue entries, and could possibly corrupt the job queue.

 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: Jarle Greipsland <jarle@uninett.no>
To: mhitch@lightning.msu.montana.edu
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Fri, 02 Oct 2009 08:54:35 +0200 (CEST)

 "Michael L. Hitch" <mhitch@lightning.msu.montana.edu> writes:
 >    It does show that what I thought had happened did indeed happen.
 > > 0xfffffc0000736ac0 <pmap_do_tlb_shootdown+224>: ldq     t1,24(t3)
 [ ... ]
 Is there any more info I can gather for you, or can you just as
 easily reproduce this yourself?

 >    This is the problem I'm still in the process of trying to figure out 
 > what the problem is and how to fix it.  The patch I posted previously is a 
 > workaround to detect this particular problem, and will display a message 
 > if it occurs.
 It _does_ occur.  I applied the patch, and a 'build.sh -j4'
 triggered the panic after a while.
 					-jarle

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: Jarle Greipsland <jarle@uninett.no>
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Sat, 3 Oct 2009 10:25:43 -0600 (MDT)

 On Fri, 2 Oct 2009, Jarle Greipsland wrote:

 > "Michael L. Hitch" <mhitch@lightning.msu.montana.edu> writes:
 >>    It does show that what I thought had happened did indeed happen.
 >>> 0xfffffc0000736ac0 <pmap_do_tlb_shootdown+224>: ldq     t1,24(t3)
 > [ ... ]
 > Is there any more info I can gather for you, or can you just as
 > easily reproduce this yourself?

    I'm quite certain in this particular case the job queue entry is linked
 to itself resulting in a hung cpu (which then hangs other cpus because it 
 has the shootdown queue locked for that cpu).

    I haven't been able to easily reproduce this.  I can complete full 
 builds fairly often, although a lot of the time I will get a segment fault 
 in one of the tools (typically grotty or install).

    I also got another deadlock situation yesterday:  cpu 0 had acquired the 
 lock for the shootdown queue (presumably for a different cpu - it should 
 be skipping the current cpu) and got interrupted by a shootdown IPI.  The 
 IPI routine was trying to acquire the lock for the current cpu's queue, 
 which was currently locked (can't tell what held the lock though).

    One thing I haven't tried yet is a LOCKDEBUG kernel, which should do 
 some additional checking on locking, and should be able to provide 
 information on what holds the lock.  This last time I tried LOCKDEBUG, I 
 ran into problems and quickly got lost in the locking morass.

 >>    This is the problem I'm still in the process of trying to figure out
 >> what the problem is and how to fix it.  The patch I posted previously is a
 >> workaround to detect this particular problem, and will display a message
 >> if it occurs.
 > It _does_ occur.  I applied the patch, and a 'build.sh -j4'
 > triggered the panic after a while.

    What was the panic you got?


 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: Jarle Greipsland <jarle@uninett.no>
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Sun, 4 Oct 2009 11:08:29 -0600 (MDT)

    I have just committed the following patch, which seems to help 
 considerably.  I've been doing sucessive builds using 2 cpus on an ES40.
 I haven't gotten any deadlocks yet, but I did just get a segment violation 
 on the grotty program on the previous build this morning.

 Index: sys/arch/alpha/alpha/pmap.c
 ===================================================================
 RCS file: /cvsroot/src/sys/arch/alpha/alpha/pmap.c,v
 retrieving revision 1.242
 diff -u -p -r1.242 pmap.c
 --- sys/arch/alpha/alpha/pmap.c 10 Sep 2009 22:27:11 -0000      1.242
 +++ sys/arch/alpha/alpha/pmap.c 4 Oct 2009 16:58:00 -0000
 @@ -962,7 +962,7 @@ pmap_bootstrap(paddr_t ptaddr, u_int max
          for (i = 0; i < ALPHA_MAXPROCS; i++) {
                  TAILQ_INIT(&pmap_tlb_shootdown_q[i].pq_head);
                  mutex_init(&pmap_tlb_shootdown_q[i].pq_lock, MUTEX_DEFAULT,
 -                   IPL_VM);
 +                   IPL_SCHED);
          }
   #endif



 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: Jarle Greipsland <jarle@uninett.no>
To: mhitch@lightning.msu.montana.edu
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Tue, 06 Oct 2009 11:17:09 +0200 (CEST)

 "Michael L. Hitch" <mhitch@lightning.msu.montana.edu> writes:
 >    One thing I haven't tried yet is a LOCKDEBUG kernel, which should do 
 > some additional checking on locking, and should be able to provide 
 > information on what holds the lock.  This last time I tried LOCKDEBUG, I 
 > ran into problems and quickly got lost in the locking morass.
 Some time ago I tried to boot a LOCKDEBUG kernel, but it paniced
 during autoconfig with an assertion:
 Mutex error: lockdebug_alloc: already initialized
 This is registered as port-alpha/38358

 > >>    This is the problem I'm still in the process of trying to figure out
 > >> what the problem is and how to fix it.  The patch I posted previously is a
 > >> workaround to detect this particular problem, and will display a message
 > >> if it occurs.
 > > It _does_ occur.  I applied the patch, and a 'build.sh -j4'
 > > triggered the panic after a while.
 > 
 >    What was the panic you got?
 The one from your patch:
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ee740
 panic: Oops
 Stopped in pid 9356.1 (as) at   netbsd:cpu_Debugger+0x4:        ret     zero,(ra)
 db{0}> trace
 cpu_Debugger() at netbsd:cpu_Debugger+0x4
 panic() at netbsd:panic+0x268
 pmap_tlb_shootdown() at netbsd:pmap_tlb_shootdown+0x274
 pmap_kenter_pa() at netbsd:pmap_kenter_pa+0xe8
 uvm_pagermapin() at netbsd:uvm_pagermapin+0x1b4
 genfs_gop_write() at netbsd:genfs_gop_write+0x48
 genfs_do_putpages() at netbsd:genfs_do_putpages+0x74c
 VOP_PUTPAGES() at netbsd:VOP_PUTPAGES+0xb0
 ffs_write() at netbsd:ffs_write+0x728
 VOP_WRITE() at netbsd:VOP_WRITE+0xb0
 vn_write() at netbsd:vn_write+0x10c
 dofilewrite() at netbsd:dofilewrite+0x90
 sys_write() at netbsd:sys_write+0xa8
 syscall_plain() at netbsd:syscall_plain+0x160
 XentSys() at netbsd:XentSys+0x60
 --- syscall (4) ---
 --- user mode ---

 					-jarle

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: Jarle Greipsland <jarle@uninett.no>
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Tue, 6 Oct 2009 07:25:11 -0600 (MDT)

 On Tue, 6 Oct 2009, Jarle Greipsland wrote:

 >>    What was the panic you got?
 > The one from your patch:
 > Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ee740
 > panic: Oops

    The patch I posted had the panic call commented out (the panic was from 
 earlier debug testing).  The following line was the workaround that would 
 skip that entry and do a full tlb invalidate.  Things should keep running 
 (for a while longer anyway) after that.

 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: Jarle Greipsland <jarle@uninett.no>
To: mhitch@lightning.msu.montana.edu
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Tue, 06 Oct 2009 15:32:15 +0200 (CEST)

 "Michael L. Hitch" <mhitch@lightning.msu.montana.edu> writes:
 > On Tue, 6 Oct 2009, Jarle Greipsland wrote:
 > 
 > >>    What was the panic you got?
 > > The one from your patch:
 > > Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ee740
 > > panic: Oops
 > 
 >    The patch I posted had the panic call commented out (the panic was from 
 > earlier debug testing).  The following line was the workaround that would 
 > skip that entry and do a full tlb invalidate.  Things should keep running 
 > (for a while longer anyway) after that.

 Ah.  That's what happens when one manually applies a patch :-(
 Oh well.  I have since updated my kernel, and am now running a
 -current GENERIC.MP kernel with the IPL_VM -> IPL_SCHED
 modification.  I have started a "build -j4" job, and I'll
 see how that works out.
 					-jarle
 -- 
 "There's too much blood in my caffeine system."

From: Jarle Greipsland <jarle@uninett.no>
To: mhitch@lightning.msu.montana.edu
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Tue, 06 Oct 2009 18:36:59 +0200 (CEST)

 Jarle Greipsland <jarle@uninett.no> writes:
 > Ah.  That's what happens when one manually applies a patch :-(
 > Oh well.  I have since updated my kernel, and am now running a
 > -current GENERIC.MP kernel with the IPL_VM -> IPL_SCHED
 > modification.  I have started a "build -j4" job, and I'll
 > see how that works out.
 Another data point: It crashed again; still with the same panic
 from your patch, which I forgot to comment out when I updated my
 sources.  So, even with the IPL_VM->IPL_SCHED change in, it still
 reaches the "Whoa!  pool_cache_get returned an in-use entry!"
 printf statement.  I have no idea whether that's significant or
 not.

 I'll comment out the "Oops"-panic now, and see what happens
 then.
 				-jarle

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: Jarle Greipsland <jarle@uninett.no>
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Tue, 6 Oct 2009 11:28:59 -0600 (MDT)

 On Tue, 6 Oct 2009, Jarle Greipsland wrote:

 > Another data point: It crashed again; still with the same panic
 > from your patch, which I forgot to comment out when I updated my
 > sources.  So, even with the IPL_VM->IPL_SCHED change in, it still
 > reaches the "Whoa!  pool_cache_get returned an in-use entry!"
 > printf statement.  I have no idea whether that's significant or
 > not.
 >
 > I'll comment out the "Oops"-panic now, and see what happens
 > then.

    That's interesting - I've been running a number of -j4 builds on an
 ES40 with only 2 cpus enabled (to more closely simulate the CS20), and 
 haven't been able to hit that message, or some checks I've got in the
 pool_cache code.

    What I was trying to do was to see if just changing the mutex 
 initialization to IPL_SCHED was enough, or if it needed to be IPL_HIGH.
 I was also trying IPL_SCHED and IPL_HIGH in the pool_cache_bootstrap()
 just prior to the mutex_init.

 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: Jarle Greipsland <jarle@uninett.no>
To: mhitch@lightning.msu.montana.edu
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Thu, 08 Oct 2009 16:16:03 +0200 (CEST)

 Jarle Greipsland <jarle@uninett.no> writes:
 > Jarle Greipsland <jarle@uninett.no> writes:
 > > Ah.  That's what happens when one manually applies a patch :-(
 > > Oh well.  I have since updated my kernel, and am now running a
 > > -current GENERIC.MP kernel with the IPL_VM -> IPL_SCHED
 > > modification.  I have started a "build -j4" job, and I'll
 > > see how that works out.
 > Another data point: It crashed again; still with the same panic
 > from your patch, which I forgot to comment out when I updated my
 > sources.  So, even with the IPL_VM->IPL_SCHED change in, it still
 > reaches the "Whoa!  pool_cache_get returned an in-use entry!"
 > printf statement.  I have no idea whether that's significant or
 > not.
 > 
 > I'll comment out the "Oops"-panic now, and see what happens
 > then.
 The system then keeps on running.  Though for every "build -j4"
 job I run I get approximately one
   "Whoa!  pool_cache_get returned an in-use entry!"
 message on the console.  I guess this means we have a
 papered-over bug now?
 					-jarle
 -- 
 Q: What's the difference between programming and bug collecting?
 A: None.

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: Jarle Greipsland <jarle@uninett.no>
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Sun, 11 Oct 2009 12:13:57 -0600 (MDT)

 On Thu, 8 Oct 2009, Jarle Greipsland wrote:

 > The system then keeps on running.  Though for every "build -j4"
 > job I run I get approximately one
 >  "Whoa!  pool_cache_get returned an in-use entry!"
 > message on the console.  I guess this means we have a
 > papered-over bug now?

    Yes - that patch just attempts to work around a duplicate pool cache 
 entry.  I have not been able to replicate this on my ES40, and don't have 
 remote power capability on my CS20 which makes it harder to debug when 
 things can hang hard.

    I'm wondering if using IPL_HIGH for the mutex changes anything:

 Index: sys/arch/alpha/alpha/pmap.c
 ===================================================================
 RCS file: /cvsroot/src/sys/arch/alpha/alpha/pmap.c,v
 retrieving revision 1.243
 diff -u -p -r1.243 pmap.c
 --- sys/arch/alpha/alpha/pmap.c 4 Oct 2009 17:00:31 -0000       1.243
 +++ sys/arch/alpha/alpha/pmap.c 11 Oct 2009 18:01:59 -0000
 @@ -962,7 +962,7 @@ pmap_bootstrap(paddr_t ptaddr, u_int max
          for (i = 0; i < ALPHA_MAXPROCS; i++) {
                  TAILQ_INIT(&pmap_tlb_shootdown_q[i].pq_head);
                  mutex_init(&pmap_tlb_shootdown_q[i].pq_lock, MUTEX_DEFAULT,
 -                   IPL_SCHED);
 +                   IPL_HIGH);
          }
   #endif


    If that doesn't change anything, then I'd try increasing the IPL level 
 of the pool_cache entry:

 Index: sys/arch/alpha/alpha/pmap.c
 ===================================================================
 RCS file: /cvsroot/src/sys/arch/alpha/alpha/pmap.c,v
 retrieving revision 1.243
 diff -u -p -r1.243 pmap.c
 --- sys/arch/alpha/alpha/pmap.c 4 Oct 2009 17:00:31 -0000       1.243
 +++ sys/arch/alpha/alpha/pmap.c 11 Oct 2009 17:59:33 -0000
 @@ -958,7 +958,7 @@ pmap_bootstrap(paddr_t ptaddr, u_int max
           */
          pool_cache_bootstrap(&pmap_tlb_shootdown_job_cache,
              sizeof(struct pmap_tlb_shootdown_job), CACHE_LINE_SIZE,
 -            0, PR_LARGECACHE, "pmaptlb", NULL, IPL_VM, NULL, NULL, NULL);
 +            0, PR_LARGECACHE, "pmaptlb", NULL, IPL_SCHED, NULL, NULL, NULL);
          for (i = 0; i < ALPHA_MAXPROCS; i++) {
                  TAILQ_INIT(&pmap_tlb_shootdown_q[i].pq_head);
                  mutex_init(&pmap_tlb_shootdown_q[i].pq_lock, MUTEX_DEFAULT,

    And:

 Index: sys/arch/alpha/alpha/pmap.c
 ===================================================================
 RCS file: /cvsroot/src/sys/arch/alpha/alpha/pmap.c,v
 retrieving revision 1.243
 diff -u -p -r1.243 pmap.c
 --- sys/arch/alpha/alpha/pmap.c 4 Oct 2009 17:00:31 -0000       1.243
 +++ sys/arch/alpha/alpha/pmap.c 11 Oct 2009 17:59:56 -0000
 @@ -958,7 +958,7 @@ pmap_bootstrap(paddr_t ptaddr, u_int max
           */
          pool_cache_bootstrap(&pmap_tlb_shootdown_job_cache,
              sizeof(struct pmap_tlb_shootdown_job), CACHE_LINE_SIZE,
 -            0, PR_LARGECACHE, "pmaptlb", NULL, IPL_VM, NULL, NULL, NULL);
 +            0, PR_LARGECACHE, "pmaptlb", NULL, IPL_HIGH, NULL, NULL, NULL);
          for (i = 0; i < ALPHA_MAXPROCS; i++) {
                  TAILQ_INIT(&pmap_tlb_shootdown_q[i].pq_head);
                  mutex_init(&pmap_tlb_shootdown_q[i].pq_lock, MUTEX_DEFAULT,


 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: Jarle Greipsland <jarle@uninett.no>
To: gnats-bugs@NetBSD.org, mhitch@lightning.msu.montana.edu
Cc: port-alpha-maintainer@netbsd.org, gnats-admin@netbsd.org,
	netbsd-bugs@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Sun, 18 Oct 2009 17:20:33 +0200 (CEST)

 "Michael L. Hitch" <mhitch@lightning.msu.montana.edu> writes:
 >     Yes - that patch just attempts to work around a duplicate pool cache 
 >  entry.  I have not been able to replicate this on my ES40, and don't have 
 >  remote power capability on my CS20 which makes it harder to debug when 
 >  things can hang hard.
 Some more results:

 I ran a few more 'build.sh -j4' jobs without changing anything,
 and the kernel continued to emit spurious "Whoa!  pool_cache_get
 returned an in-use entry!"  messages.

 Then, on Oct 14, I synced my source tree to -current again (this
 might have been a stupid move on my part...), and built and
 booted a new GENERIC.MP kernel.  After about an hour into a
 'build.sh -j4' job, it paniced with a new (to me) message:

 panic: pool_get: pmaptlb: page empty

 Stopped in pid 25249.1 (cc1plus) at     netbsd:cpu_Debugger+0x4:        ret     zero,(ra)

 db{0}> tr
 cpu_Debugger() at netbsd:cpu_Debugger+0x4
 panic() at netbsd:panic+0x268
 pool_get() at netbsd:pool_get+0x408
 pool_cache_get_slow() at netbsd:pool_cache_get_slow+0x1ac
 pool_cache_get_paddr() at netbsd:pool_cache_get_paddr+0x168
 pmap_tlb_shootdown() at netbsd:pmap_tlb_shootdown+0xe8
 pmap_kenter_pa() at netbsd:pmap_kenter_pa+0xe8
 uvm_km_alloc() at netbsd:uvm_km_alloc+0x170
 kmem_backend_alloc() at netbsd:kmem_backend_alloc+0x48
 vmem_xalloc() at netbsd:vmem_xalloc+0x318
 vmem_alloc() at netbsd:vmem_alloc+0x90
 kmem_poolpage_alloc() at netbsd:kmem_poolpage_alloc+0x48
 pool_grow() at netbsd:pool_grow+0x64
 pool_get() at netbsd:pool_get+0x5c
 pool_cache_get_slow() at netbsd:pool_cache_get_slow+0x1ac
 pool_cache_get_paddr() at netbsd:pool_cache_get_paddr+0x168
 kmem_alloc() at netbsd:kmem_alloc+0xc8
 amap_extend() at netbsd:amap_extend+0x1b8
 uvm_mapent_trymerge() at netbsd:uvm_mapent_trymerge+0x3dc
 amap_copy() at netbsd:amap_copy+0x410
 uvm_fault_internal() at netbsd:uvm_fault_internal+0xbb0
 trap() at netbsd:trap+0x548
 XentMM() at netbsd:XentMM+0x20
 --- memory management fault (from ipl 0) ---
 --- user mode ---
 db{0}> show reg
 v0          0x6
 t0          0x1
 t1          0x1
 t2          0xfffffc003ff48000
 t3          0
 t4          0
 t5          0xfffffc0000b46a2d  __func__.21238+0x91c
 t6          0
 t7          0
 s0          0xfffffc0000c378e0  msgbufenabled
 s1          0x104
 s2          0xfffffc0000c350a8  db_onpanic
 s3          0xfffffc0000c6b8e8  pmap_tlb_shootdown_job_cache+0x1a8
 s4          0
 s5          0x2
 s6          0
 a0          0
 a1          0xfffffd01fc0003f8
 a2          0
 a3          0x8
 a4          0x3
 a5          0xfffffc0000000008
 t8          0
 t9          0x8
 t10         0xfffffc0000c941a8  uvmexp
 t11         0
 ra          0xfffffc000080c5a8  panic+0x268
 t12         0xfffffc00003eb590  cpu_Debugger
 at          0x1
 gp          0xfffffc0000c30928  __link_set_prop_linkpools_sym__link__prop_array_pool+0x8008
 sp          0xfffffe0013c7f5e8
 pc          0xfffffc00003eb594  cpu_Debugger+0x4
 ps          0
 ai          0
 pv          0xfffffc00003eb590  cpu_Debugger
 netbsd:cpu_Debugger+0x4:        ret     zero,(ra)
 db{0}> ps
 PID    LID S CPU     FLAGS       STRUCT LWP *               NAME WAIT
 21308>   1 7   1     40004   fffffc0024916c00            cc1plus
 9441     1 3   0        84   fffffc0024916000   alpha--netbsd-c+ wait
 21710    1 3   0        84   fffffc0024813000                 sh wait
 26347    1 2   0     40004   fffffc002de34800            cc1plus
 18814    1 3   0        84   fffffc0024813400   alpha--netbsd-c+ wait
 24418    1 3   0        84   fffffc002daf2800                 sh wait
 25249>   1 7   0         4   fffffc002d29e400            cc1plus
 19917    1 3   0        84   fffffc0024917c00   alpha--netbsd-c+ wait
 2263     1 3   1        84   fffffc002daf3000                 sh wait
 16091    1 2   0     40004   fffffc002caa9800            cc1plus
 19836    1 3   0        84   fffffc003edac400   alpha--netbsd-c+ wait
 7537     1 3   1        84   fffffc00233e9400                 sh wait
 18485    1 3   0        84   fffffc0024d52000             nbmake select
 8826     1 3   0        84   fffffc002daf2000                 sh wait
 28933    1 3   1        84   fffffc002cab8000             nbmake select
 15439    1 3   1        84   fffffc0024812000                 sh wait
 22920    1 3   1        84   fffffc0024917800             nbmake select
 16006    1 3   1        84   fffffc0024d53400                 sh wait
 22712    1 3   1        84   fffffc0024d52800             nbmake select
 28515    1 3   1        84   fffffc002caa9c00                 sh wait
 24901    1 3   1        84   fffffc00233e8800             nbmake select
 22708    1 3   1        84   fffffc0024917000             pickup kqueue
 20418    1 3   0        84   fffffc002d29ec00               bash ttyraw
 17752    1 3   0        84   fffffc002caa9400              xterm select
 29471    1 3   1        84   fffffc003f678000                csh pause
 8486     1 3   0        84   fffffc002cab8c00               sshd select
 23567    1 3   1        84   fffffc002d29f400               sshd netio
 4106     1 3   0        84   fffffc00233e8000                 sh wait
 3271     1 3   1        84   fffffc00233e8c00             nbmake select
 3779     1 3   0        84   fffffc0024916400                 sh wait
 3702     1 3   1        84   fffffc00233e9000             nbmake select
 3935     1 3   1        84   fffffc003ca9e400                 sh wait
 3603     1 3   1        84   fffffc003ca9f000             nbmake select
 750      1 3   0        84   fffffc003ca9e800                 sh wait
 730      1 3   1        84   fffffc003ca9ec00               tail kqueue
 733      1 3   0        84   fffffc003f678400               tcsh pause
 507      1 3   0        84   fffffc003ca9f800               tcsh pause
 40       1 3   1        84   fffffc003ca9fc00               tcsh pause
 41       1 3   1        84   fffffc003edad000              xterm select
 459      1 3   0        84   fffffc003f9fe800                csh pause
 473      1 3   1        84   fffffc003edac800               sshd select
 528      1 3   0        84   fffffc003f960000               sshd netio
 501      1 3   1        84   fffffc003f679800               qmgr kqueue
 350      1 3   1        84   fffffc003f961c00              getty ttyraw
 484      1 3   1        84   fffffc003f679400               cron nanoslp
 498      1 3   1        84   fffffc003edac000              inetd kqueue
 468      1 3   1        84   fffffc003edacc00             master kqueue
 300      1 3   0        84   fffffc003edad400               sshd select
 301      1 3   0        84   fffffc003edad800               ntpd pause
 183      1 3   0        84   fffffc003edadc00          mount_mfs mfsidl
 152      1 3   1        84   fffffc003f679000            syslogd kqueue
 1        1 3   0        84   fffffc003f961000               init wait
 0       39 3   0       204   fffffc003f678800            physiod physiod
 0       38 3   1       204   fffffc003f960400        vmem_rehash vmem_rehash
 0       37 3   0       204   fffffc003f960800           aiodoned aiodoned
 0       36 3   1       204   fffffc003f9fe400            ioflush syncer
 0       35 3   1       204   fffffc003f9fe000           pgdaemon pgdaemon
 0       34 3   0       204   fffffc003f961400          cryptoret crypto_wait
 0       33 3   0       204   fffffc003f961800          atapibus0 sccomp
 0       31 3   0       204   fffffc003f960c00              unpgc unpgc
 0       22 3   1       204   fffffc003f9fec00            atabus1 atath
 0       21 3   0       204   fffffc003f9ff000            atabus0 atath
 0       20 3   1       204   fffffc003f9ff400           scsibus0 sccomp
 0       19 3   1       204   fffffc003f9ff800            xcall/1 xcall
 0       18 1   1       204   fffffc003f9ffc00          softser/1
 0       17 1   1       204   fffffc003fcf8000          softclk/1
 0       16 1   1       204   fffffc003fcf8400          softbio/1
 0       15 1   1       204   fffffc003fcf8800          softnet/1
 0       14 1   1       205   fffffc003fcf8c00             idle/1
 0       13 3   1       204   fffffc003fcf9000         pmfsuspend pmfsuspend
 0       12 3   0       204   fffffc003fcf9400           pmfevent pmfevent
 0       11 3   1       204   fffffc003fcf9800           nfssilly nfssilly
 0       10 3   0       204   fffffc003fcf9c00            cachegc cachegc
 0        9 3   1       204   fffffc003fe28000              vrele vrele
 0        8 3   1       204   fffffc003fe28400          modunload modunload
 0        7 3   0       204   fffffc003fe28800            xcall/0 xcall
 0        6 1   0       204   fffffc003fe28c00          softser/0
 0        5 1   0       204   fffffc003fe29000          softclk/0
 0        4 1   0       204   fffffc003fe29400          softbio/0
 0        3 1   0       204   fffffc003fe29800          softnet/0
 0        2 1   0       205   fffffc003fe29c00             idle/0
 0        1 3   0       204   fffffc0000c16660            swapper schedule
 db{0}> mach cpu 1
 Using CPU 1
 db{0}> tr

 CPU 0: fatal kernel trap:

 CPU 0    trap entry = 0x2 (memory management fault)
 CPU 0    a0         = 0xffffffffffffffd9
 CPU 0    a1         = 0x1
 CPU 0    a2         = 0x0
 CPU 0    pc         = 0xfffffc00003ee944
 CPU 0    ra         = 0xfffffc00003e8104
 CPU 0    pv         = 0xfffffc00003ee890
 CPU 0    curlwp     = 0xfffffc002d29e400
 CPU 0        pid = 25249, comm = cc1plus

 Caught exception in ddb.
 db{0}> show reg
 v0          0x1
 t0          0x5b93a000
 t1          0x2000
 t2          0
 t3          0x2000
 t4          0xf
 t5          0x16055e050
 t6          0x2
 t7          0
 s0          0x2
 s1          0x5b93a000
 s2          0x161214008
 s3          0x161214000
 s4          0x16055e1d0
 s5          0x16055e040
 s6          0x50
 a0          0x5b93a000
 a1          0x48
 a2          0
 a3          0
 a4          0x5
 a5          0x5
 t8          0x160814400
 t9          0x3
 t10         0x120582e58
 t11         0x120581c28
 ra          0x16063d168
 t12         0x16064db44
 at          0x2
 gp          0x1606fb790
 sp          0x1
 pc          0x16064db70
 ps          0x8
 ai          0x120581c28
 pv          0x16064db44
 0x16064db70:    and     t1,#0xff,t4

 I also got a kernel core dump from this one.  Please give some
 instructions if you want me to dig up some data from the dump.

 Later on, after booting the same kernel, I got some more
 "Whoa!  pool_cache_get returned an in-use entry!" messages.  Also
 at some point (I don't think it correlated in time with any of
 the kernel messages) the system hung hard again.  I pressed the
 halt button, and entered DDB:
 halted CPU 0
 CPU 1 is not halted

 halt code = 1
 operator initiated halt
 PC = fffffc00005f6320
 P00>>>cont

 continuing CPU 0
 CP - RESTORE_TERM routine to be called
 panic: user requested console halt
 Stopped in pid 0.35 (system) at netbsd:cpu_Debugger+0x4:        ret     zero,(ra
 )
 db{0}> trace
 cpu_Debugger() at netbsd:cpu_Debugger+0x4
 panic() at netbsd:panic+0x268
 console_restart() at netbsd:console_restart+0x78
 XentRestart() at netbsd:XentRestart+0x90
 --- console restart (from ipl 2) ---
 mutex_spin_enter() at netbsd:mutex_spin_enter+0x200
 pool_cache_put_slow() at netbsd:pool_cache_put_slow+0x138
 pool_cache_put_paddr() at netbsd:pool_cache_put_paddr+0x168
 pmap_do_tlb_shootdown() at netbsd:pmap_do_tlb_shootdown+0x178
 alpha_ipi_process() at netbsd:alpha_ipi_process+0xb8
 interrupt() at netbsd:interrupt+0x88
 XentInt() at netbsd:XentInt+0x1c
 --- interrupt (from ipl 4) ---
 mutex_exit() at netbsd:mutex_exit+0x10
 pool_cache_invalidate() at netbsd:pool_cache_invalidate+0x6c
 pool_reclaim() at netbsd:pool_reclaim+0x68
 pool_drain_end() at netbsd:pool_drain_end+0x44
 uvm_pageout() at netbsd:uvm_pageout+0x740
 exception_return() at netbsd:exception_return
 --- root of call graph ---
 db{0}> show reg
 v0          0xfffffc0000c0de28  cpu_info_primary
 t0          0x1
 t1          0x1
 t2          0xfffffc003ff48000
 t3          0
 t4          0
 t5          0xfffffc0000b46a2d  __func__.21238+0x91c
 t6          0xfffffc002e386888
 t7          0
 s0          0xfffffc0000c378e0  msgbufenabled
 s1          0x104
 s2          0xfffffc0000c350a8  db_onpanic
 s3          0xfffffc0000c8ef18  panicstr
 s4          0
 s5          0xfffffc0000808e48  pool_cache_put_slow+0x138
 s6          0
 a0          0
 a1          0xfffffd01fc0003f8
 a2          0
 a3          0x8
 a4          0x3
 a5          0xfffffc0000000008
 t8          0xb
 t9          0x8
 t10         0x7fff
 t11         0
 ra          0xfffffc000080c5a8  panic+0x268
 t12         0xfffffc00003eb590  cpu_Debugger
 at          0x160328000
 gp          0xfffffc0000c30928  __link_set_prop_linkpools_sym__link__prop_array_pool+0x8008
 sp          0xfffffe00130e5908
 pc          0xfffffc00003eb594  cpu_Debugger+0x4
 ps          0x7
 ai          0
 pv          0xfffffc00003eb590  cpu_Debugger
 netbsd:cpu_Debugger+0x4:        ret     zero,(ra)
 db{0}> mach cpu 1
 Using CPU 1
 db{0}> trace

 CPU 0: fatal kernel trap:

 CPU 0    trap entry = 0x2 (memory management fault)
 CPU 0    a0         = 0xffffffffffffffd9
 CPU 0    a1         = 0x1
 CPU 0    a2         = 0x0
 CPU 0    pc         = 0xfffffc00003ee944
 CPU 0    ra         = 0xfffffc00003e8104
 CPU 0    pv         = 0xfffffc00003ee890
 CPU 0    curlwp     = 0xfffffc003f9fe800
 CPU 0        pid = 0, comm = system

 Caught exception in ddb.
 db{0}> c     
 cpu1: shutting down...

 dumping to dev 8,1 offset 2097597
 dump i/o error


 sd0(esiop0:0:0:0): polling command not done
 panic: scsipi_execute_xs
 Stopped in pid 0.35 (system) at netbsd:cpu_Debugger+0x4:        ret     zero,(ra
 )
 db{0}> reboot 4

 >     I'm wondering if using IPL_HIGH for the mutex changes anything:
 >  
 >  Index: sys/arch/alpha/alpha/pmap.c
 >  ===================================================================
 >  RCS file: /cvsroot/src/sys/arch/alpha/alpha/pmap.c,v
 >  retrieving revision 1.243
 >  diff -u -p -r1.243 pmap.c
 >  --- sys/arch/alpha/alpha/pmap.c 4 Oct 2009 17:00:31 -0000       1.243
 >  +++ sys/arch/alpha/alpha/pmap.c 11 Oct 2009 18:01:59 -0000
 >  @@ -962,7 +962,7 @@ pmap_bootstrap(paddr_t ptaddr, u_int max
 >           for (i = 0; i < ALPHA_MAXPROCS; i++) {
 >                   TAILQ_INIT(&pmap_tlb_shootdown_q[i].pq_head);
 >                   mutex_init(&pmap_tlb_shootdown_q[i].pq_lock, MUTEX_DEFAULT,
 >  -                   IPL_SCHED);
 >  +                   IPL_HIGH);
 >           }
 >    #endif

 I then applied this patch.  I tried several 'build.sh -j4' jobs,
 but all of them seemed to abort with some host tool tripping up:
 /usr/tools/bin/nbgroff: grotty: Illegal instruction (core dumped)
 /usr/tools/bin/nbgroff: troff: Illegal instruction (core dumped)

 Then on one occasion, the kernel started to repeatedly spew 
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ee00
 messages to the console.  The pj value were identical in all the
 messages, but the ci_index value varied (0 or 1).

 Do you still think I should try and increase the IPL level of the
 pool_cache entry as specified in your message?

 					-jarle

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: Jarle Greipsland <jarle@uninett.no>
Cc: gnats-bugs@NetBSD.org, gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Sun, 18 Oct 2009 11:37:20 -0600 (MDT)

 On Sun, 18 Oct 2009, Jarle Greipsland wrote:

 > I ran a few more 'build.sh -j4' jobs without changing anything,
 > and the kernel continued to emit spurious "Whoa!  pool_cache_get
 > returned an in-use entry!"  messages.
 >
 > Then, on Oct 14, I synced my source tree to -current again (this
 > might have been a stupid move on my part...), and built and
 > booted a new GENERIC.MP kernel.  After about an hour into a
 > 'build.sh -j4' job, it paniced with a new (to me) message:
 >
 > panic: pool_get: pmaptlb: page empty

    This would likely indicate pool_cache corruption, which would be in line 
 with the one that my patch worked around.

 > db{0}> mach cpu 1
 > Using CPU 1
 > db{0}> tr
 >
 > CPU 0: fatal kernel trap:

    There's a bug somewhere in handling the registers of the cpus other than 
 the one that's running DDB.  I can't remember if this ever worked 
 properly, although I'm sure I've at least tried it in the past.

 > I also got a kernel core dump from this one.  Please give some
 > instructions if you want me to dig up some data from the dump.

    I don't think there's a way to get much information out of a core dump 
 since 5.0.  The new gdb doesn't yet have the code to access a core dump.
 One more thing to try fixing some day.

 > Later on, after booting the same kernel, I got some more
 > "Whoa!  pool_cache_get returned an in-use entry!" messages.  Also
 > at some point (I don't think it correlated in time with any of
 > the kernel messages) the system hung hard again.  I pressed the
 > halt button, and entered DDB:
 > halted CPU 0
 > CPU 1 is not halted
 >
 > halt code = 1
 > operator initiated halt
 > PC = fffffc00005f6320
 > P00>>>cont
 >
 > continuing CPU 0
 > CP - RESTORE_TERM routine to be called
 > panic: user requested console halt
 > Stopped in pid 0.35 (system) at netbsd:cpu_Debugger+0x4:        ret     zero,(ra
 > )
 > db{0}> trace
 > cpu_Debugger() at netbsd:cpu_Debugger+0x4
 > panic() at netbsd:panic+0x268
 > console_restart() at netbsd:console_restart+0x78
 > XentRestart() at netbsd:XentRestart+0x90
 > --- console restart (from ipl 2) ---
 > mutex_spin_enter() at netbsd:mutex_spin_enter+0x200
 > pool_cache_put_slow() at netbsd:pool_cache_put_slow+0x138
 > pool_cache_put_paddr() at netbsd:pool_cache_put_paddr+0x168
 > pmap_do_tlb_shootdown() at netbsd:pmap_do_tlb_shootdown+0x178
 > alpha_ipi_process() at netbsd:alpha_ipi_process+0xb8
 > interrupt() at netbsd:interrupt+0x88
 > XentInt() at netbsd:XentInt+0x1c
 > --- interrupt (from ipl 4) ---
 > mutex_exit() at netbsd:mutex_exit+0x10
 > pool_cache_invalidate() at netbsd:pool_cache_invalidate+0x6c
 > pool_reclaim() at netbsd:pool_reclaim+0x68
 > pool_drain_end() at netbsd:pool_drain_end+0x44
 > uvm_pageout() at netbsd:uvm_pageout+0x740
 > exception_return() at netbsd:exception_return

    This also appears to be pool cache corruption problems.  In this 
 particular case, CPU0 has received an IPI interrupt to shootdown its tlb 
 entries, and is trying to to release a pool cache entry used for this 
 call, and is hung trying to acquire a mutex related to the pool cache.
 The other cpu presumably holds that lock (and may be trying to acquire a 
 lock held by CPU0, leading to the classic deadlock).

 >>     I'm wondering if using IPL_HIGH for the mutex changes anything:
 >>
 >>  Index: sys/arch/alpha/alpha/pmap.c
 >>  ===================================================================
 >>  RCS file: /cvsroot/src/sys/arch/alpha/alpha/pmap.c,v
 >>  retrieving revision 1.243
 >>  diff -u -p -r1.243 pmap.c
 >>  --- sys/arch/alpha/alpha/pmap.c 4 Oct 2009 17:00:31 -0000       1.243
 >>  +++ sys/arch/alpha/alpha/pmap.c 11 Oct 2009 18:01:59 -0000
 >>  @@ -962,7 +962,7 @@ pmap_bootstrap(paddr_t ptaddr, u_int max
 >>           for (i = 0; i < ALPHA_MAXPROCS; i++) {
 >>                   TAILQ_INIT(&pmap_tlb_shootdown_q[i].pq_head);
 >>                   mutex_init(&pmap_tlb_shootdown_q[i].pq_lock, MUTEX_DEFAULT,
 >>  -                   IPL_SCHED);
 >>  +                   IPL_HIGH);
 >>           }
 >>    #endif
 >
 > I then applied this patch.  I tried several 'build.sh -j4' jobs,
 > but all of them seemed to abort with some host tool tripping up:
 > /usr/tools/bin/nbgroff: grotty: Illegal instruction (core dumped)
 > /usr/tools/bin/nbgroff: troff: Illegal instruction (core dumped)

    This is the problem I get now on my ES45.  I haven't been able to figure 
 out anything from the process core dump, other than memory seems corrupted 
 or incorrect.  I'm not sure if it might be related to the tlb shootdown 
 code not working properly, or perhaps a missing memory barrier call 
 somewhere.

 > Then on one occasion, the kernel started to repeatedly spew
 > Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ee00
 > messages to the console.  The pj value were identical in all the
 > messages, but the ci_index value varied (0 or 1).
 >
 > Do you still think I should try and increase the IPL level of the
 > pool_cache entry as specified in your message?

    Try the higher IPL on the pmap_tlb_shootdown_job_cache.  I'm not real 
 clear on how that IPL is used, but I'm guessing that might be the IPL used 
 by any locking using by the pool cache routines, and may be needed to 
 prevent the IPI interrupt from interrupting a pool cache operation.  [That 
 might have caused the deadlock you observed above.]  Try IPL_CLOCK first, 
 and then IPL_HIGH if that still has problems relating to the pool cache.

 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

State-Changed-From-To: feedback->open
State-Changed-By: dholland@NetBSD.org
State-Changed-When: Mon, 19 Oct 2009 00:58:46 +0000
State-Changed-Why:
This does not need to be in feedback any more. Glad to see you guys working
on it :-)


From: Jarle Greipsland <jarle@uninett.no>
To: gnats-bugs@NetBSD.org, mhitch@lightning.msu.montana.edu
Cc: port-alpha-maintainer@netbsd.org, gnats-admin@netbsd.org,
	netbsd-bugs@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Mon, 26 Oct 2009 15:34:14 +0100 (CET)

 "Michael L. Hitch" <mhitch@lightning.msu.montana.edu> writes:
 >  > Then on one occasion, the kernel started to repeatedly spew
 >  > Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ee00
 >  > messages to the console.  The pj value were identical in all the
 >  > messages, but the ci_index value varied (0 or 1).
 >  >
 >  > Do you still think I should try and increase the IPL level of the
 >  > pool_cache entry as specified in your message?
 >  
 >     Try the higher IPL on the pmap_tlb_shootdown_job_cache.  I'm not real 
 >  clear on how that IPL is used, but I'm guessing that might be the IPL used 
 >  by any locking using by the pool cache routines, and may be needed to 
 >  prevent the IPI interrupt from interrupting a pool cache operation.  [That 
 >  might have caused the deadlock you observed above.]  Try IPL_CLOCK first, 
 >  and then IPL_HIGH if that still has problems relating to the pool cache.
 Results for the IPL_HIGH setting: It still has problems with the
 pool_cache_get stuff.  A number of consecutive 'build.sh -j4'
 resulted in console messages:
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9efa00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee080
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee440

 Also, at during one of the builds, the system hung completely,
 and I had to press the reset button:
 ----------------------------------------------------------------------
 Stopped in pid 0.2 (system) at  netbsd:cpu_Debugger+0x4:	ret     zero,(ra)
 db{0}> tr
 cpu_Debugger() at netbsd:cpu_Debugger+0x4
 comintr() at netbsd:comintr+0x720
 alpha_shared_intr_dispatch() at netbsd:alpha_shared_intr_dispatch+0x5c
 sio_iointr() at netbsd:sio_iointr+0x38
 interrupt() at netbsd:interrupt+0x1c0
 XentInt() at netbsd:XentInt+0x1c
 --- interrupt (from ipl 0) ---
 sched_curcpu_runnable_p() at netbsd:sched_curcpu_runnable_p+0x1c
 idle_loop() at netbsd:idle_loop+0x1b8
 exception_return() at netbsd:exception_return
 --- root of call graph ---
 db{0}> mach cpu 1
 Using CPU 1
 db{0}> tra

 CPU 0: fatal kernel trap:

 CPU 0    trap entry = 0x2 (memory management fault)
 CPU 0    a0         = 0xffffffffffffffd9
 CPU 0    a1         = 0x1
 CPU 0    a2         = 0x0
 CPU 0    pc         = 0xfffffc00003ee944
 CPU 0    ra         = 0xfffffc00003e8104
 CPU 0    pv         = 0xfffffc00003ee890
 CPU 0    curlwp     = 0xfffffc003fe29c00
 CPU 0        pid = 0, comm = system

 Caught exception in ddb.
 db{0}> mach cpu 0
 CPU 0 not paused
 db{0}> show reg
 v0          0x1
 t0          0xfffffc0000b44e9c  uvmadvice
 t1          0xfffffc0000b44e9c  uvmadvice
 t2          0
 t3          0x2000
 t4          0
 t5          0x3
 t6          0x4
 t7          0x1
 s0          0xfffffc0038581698
 s1          0
 s2          0x2
 s3          0xe78
 s4          0xfffffe0013bc16e0
 s5          0x160042000
 s6          0xfffffc0031b69000
 a0          0xfffffc0038581698
 a1          0xfffffc0014c0f760
 a2          0xfffffe0013bc1448
 a3          0x160042000
 a4          0xfffffe0013bc16e0
 a5          0
 t8          0x1
 t9          0
 t10         0xfffffc0000c941e8  uvmexp
 t11         0x80
 ra          0xfffffc00008e0bd4  uvm_fault_internal+0x124
 t12         0xfffffc00008e5f50  uvm_map_lookup_entry
 at          0xfffffe0013bbe000
 gp          0xfffffc0000c30968  __link_set_prop_linkpools_sym__link__prop_array_pool+0x8008
 sp          0x1
 pc          0xfffffc00008e0e50  uvm_fault_internal+0x3a0
 ps          0
 ai          0x80
 pv          0xfffffc00008e5f50  uvm_map_lookup_entry
 netbsd:uvm_fault_internal+0x3a0:        srl     t3,#0xd,t3
 db{0}> tr

 CPU 0: fatal kernel trap:

 CPU 0    trap entry = 0x2 (memory management fault)
 CPU 0    a0         = 0xffffffffffffffd9
 CPU 0    a1         = 0x1
 CPU 0    a2         = 0x0
 CPU 0    pc         = 0xfffffc00003ee944
 CPU 0    ra         = 0xfffffc00003e8104
 CPU 0    pv         = 0xfffffc00003ee890
 CPU 0    curlwp     = 0xfffffc003fe29c00
 CPU 0        pid = 0, comm = system

 Caught exception in ddb.
 db{0}> reboot 4
 ----------------------------------------------------------------------

 Also, for another build, I got a 

 ----------------------------------------------------------------------
 panic: fpsave ipi didn't
 Stopped in pid 22623.1 (sh) at  netbsd:cpu_Debugger+0x4:        ret     zero,(ra)
 db{0}> trace 
 cpu_Debugger() at netbsd:cpu_Debugger+0x4
 panic() at netbsd:panic+0x268
 fpusave_proc() at netbsd:fpusave_proc+0x1b4
 cpu_lwp_free() at netbsd:cpu_lwp_free+0x28
 exit1() at netbsd:exit1+0x568
 sys_exit() at netbsd:sys_exit+0x7c
 syscall_plain() at netbsd:syscall_plain+0x160
 XentSys() at netbsd:XentSys+0x60
 --- syscall (1) ---
 --- user mode ---
 db{0}> mach cpu 1
 CPU 1 not paused
 db{0}> show reg
 v0          0x6
 t0          0x1
 t1          0x1
 t2          0xfffffc003ff48000
 t3          0
 t4          0
 t5          0xfffffc0000b46a65  __func__.21238+0x91c
 t6          0xc5343806
 t7          0xfffffffffffffcbe
 s0          0xfffffc0000c37920  msgbufenabled
 s1          0x104
 s2          0xfffffc0000c350e8  db_onpanic
 s3          0xfffffc003b546800
 s4          0xfffffc0037d7b458
 s5          0xfffffc0000c7bff0  initproc
 s6          0x12003dab0
 a0          0x6
 a1          0xfffffd01fc0003f8
 a2          0
 a3          0x8
 a4          0x3
 a5          0x8
 t8          0x2
 t9          0x8
 t10         0
 t11         0x7
 ra          0xfffffc000080c5a8  panic+0x268
 t12         0xfffffc00003eb590  cpu_Debugger
 at          0xfffffe0013b1a000
 gp          0xfffffc0000c30968  __link_set_prop_linkpools_sym__link__prop_array_pool+0x8008
 sp          0xfffffe00139cbcc8
 pc          0xfffffc00003eb594  cpu_Debugger+0x4
 ps          0x6
 ai          0x7
 pv          0xfffffc00003eb590  cpu_Debugger
 netbsd:cpu_Debugger+0x4:        ret     zero,(ra)
 db{0}> reboot 4
 ----------------------------------------------------------------------

 Hope this helps.
 					-jarle

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: gnats-bugs@NetBSD.org
Cc: jarle@uninett.no
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Tue, 27 Oct 2009 15:33:06 -0600 (MDT)

 On Mon, 26 Oct 2009, Jarle Greipsland wrote:

 > Results for the IPL_HIGH setting: It still has problems with the
 > pool_cache_get stuff.  A number of consecutive 'build.sh -j4'
 > resulted in console messages:
 > Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9efa00
 > Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee080
 > Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee440

    OK, here's something else to try.  I was looking through the alpha 
 hardware reference manual and checking some of the multiprocessor 
 information.  I noted that it showed the use of memory barriers when 
 sending/receiving interrupts between processors.  It looks like the atomic 
 operations that were used in the netbsd-4 branch included the memory 
 barrier, but the ones used in netbsd-5 and later do not.  This patch 
 should add back the memory barriers need for the IPI stuff.

 Index: sys/arch/alpha/alpha/ipifuncs.c
 ===================================================================
 RCS file: /cvsroot/src/sys/arch/alpha/alpha/ipifuncs.c,v
 retrieving revision 1.40
 diff -u -p -r1.40 ipifuncs.c
 --- sys/arch/alpha/alpha/ipifuncs.c	28 Apr 2008 20:23:10 -0000	1.40
 +++ sys/arch/alpha/alpha/ipifuncs.c	27 Oct 2009 21:23:05 -0000
 @@ -131,6 +131,7 @@ alpha_ipi_process(struct cpu_info *ci, s
   	}
   #endif

 +	alpha_mb();
   	pending_ipis = atomic_swap_ulong(&ci->ci_ipis, 0);

   	/*
 @@ -167,6 +168,7 @@ alpha_send_ipi(u_long cpu_id, u_long ipi
   #endif

   	atomic_or_ulong(&cpu_info[cpu_id]->ci_ipis, ipimask);
 +	alpha_mb();
   	alpha_pal_wripir(cpu_id);
   }


 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: Jarle Greipsland <jarle@uninett.no>
To: mhitch@lightning.msu.montana.edu
Cc: gnats-bugs@NetBSD.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Wed, 28 Oct 2009 16:01:33 +0100 (CET)

 "Michael L. Hitch" <mhitch@lightning.msu.montana.edu> writes:
 >    OK, here's something else to try.  I was looking through the alpha 
 > hardware reference manual and checking some of the multiprocessor 
 > information.  I noted that it showed the use of memory barriers when 
 > sending/receiving interrupts between processors.  It looks like the atomic 
 > operations that were used in the netbsd-4 branch included the memory 
 > barrier, but the ones used in netbsd-5 and later do not.  This patch 
 > should add back the memory barriers need for the IPI stuff.
 [ ... ]
 OK, I have applied your patch (and removed the old ones except
 for the one that generates the "Whoa!"-warnings.).  The kernel
 I'm running is GENERIC.MP based on -current from Oct 14th, with
 the following diff:
 ----------------------------------------------------------------------
 Index: arch/alpha/alpha/ipifuncs.c
 ===================================================================
 RCS file: /cvsroot/src/sys/arch/alpha/alpha/ipifuncs.c,v
 retrieving revision 1.40
 diff -u -r1.40 ipifuncs.c
 --- arch/alpha/alpha/ipifuncs.c	28 Apr 2008 20:23:10 -0000	1.40
 +++ arch/alpha/alpha/ipifuncs.c	28 Oct 2009 14:55:46 -0000
 @@ -130,7 +130,7 @@
  		return;
  	}
  #endif
 -
 +	alpha_mb();
  	pending_ipis = atomic_swap_ulong(&ci->ci_ipis, 0);

  	/*
 @@ -167,6 +167,7 @@
  #endif

  	atomic_or_ulong(&cpu_info[cpu_id]->ci_ipis, ipimask);
 +	alpha_mb();
  	alpha_pal_wripir(cpu_id);
  }

 Index: arch/alpha/alpha/pmap.c
 ===================================================================
 RCS file: /cvsroot/src/sys/arch/alpha/alpha/pmap.c,v
 retrieving revision 1.243
 diff -u -r1.243 pmap.c
 --- arch/alpha/alpha/pmap.c	4 Oct 2009 17:00:31 -0000	1.243
 +++ arch/alpha/alpha/pmap.c	28 Oct 2009 14:55:46 -0000
 @@ -3699,6 +3699,12 @@
  		 * don't really have to do anything else.
  		 */
  		mutex_spin_enter(&pq->pq_lock);
 +		if (pj && pj == pq->pq_head.tqh_first) {
 +			printf("Whoa!  pool_cache_get returned an in-use entry! ci_index %d pj %p\n",
 +			    self->ci_index, pj);
 +/**/		/*	panic("Oops"); */
 +			pj = NULL;
 +		}
  		pq->pq_pte |= pte;
  		if (pq->pq_tbia) {
  			mutex_spin_exit(&pq->pq_lock);
 ----------------------------------------------------------------------

 And it both "Whoa!"s and panics:
 ----------------------------------------------------------------------
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ef980
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003d8bfc00
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 1 pj 0xfffffc003f9ee400
 Whoa!  pool_cache_get returned an in-use entry! ci_index 0 pj 0xfffffc003f9ee400

 CPU 1: fatal kernel trap:

 CPU 1    trap entry = 0x2 (memory management fault)
 CPU 1    a0         = 0x40
 CPU 1    a1         = 0x1
 CPU 1    a2         = 0x0
 CPU 1    pc         = 0xfffffc00007371a8
 CPU 1    ra         = 0xfffffc0000737118
 CPU 1    pv         = 0xfffffc00005f6130
 CPU 1    curlwp     = 0xfffffc003f960800
 CPU 1        pid = 0, comm = system

 panic: trap
 Stopped in pid 0.37 (system) at netbsd:cpu_Debugger+0x4:        ret     zero,(ra)
 db{1}> tr
 cpu_Debugger() at netbsd:cpu_Debugger+0x4
 panic() at netbsd:panic+0x268
 trap() at netbsd:trap+0x35c
 XentMM() at netbsd:XentMM+0x20
 --- memory management fault (from ipl 5) ---
 pmap_do_tlb_shootdown() at netbsd:pmap_do_tlb_shootdown+0xe8
 alpha_ipi_process() at netbsd:alpha_ipi_process+0xb8
 interrupt() at netbsd:interrupt+0x88
 XentInt() at netbsd:XentInt+0x1c
 --- interrupt (from ipl 0) ---
 mutex_spin_exit() at netbsd:mutex_spin_exit+0x5c
 pmap_tlb_shootdown() at netbsd:pmap_tlb_shootdown+0x170
 pmap_kremove() at netbsd:pmap_kremove+0xac
 uvm_pagermapout() at netbsd:uvm_pagermapout+0x40
 uvm_aio_aiodone() at netbsd:uvm_aio_aiodone+0xd4
 db{1}> show reg
 v0          0xfffffe0000034800
 t0          0x1
 t1          0x1
 t2          0xfffffc003ff48000
 t3          0
 t4          0
 t5          0xfffffc0000b46a3d  __func__.21238+0x91c
 t6          0
 t7          0
 s0          0xfffffc0000c378e0  msgbufenabled
 s1          0x104
 s2          0xfffffc0000c350a8  db_onpanic
 s3          0xfffffc00009bf5fc  reg_to_frame+0x5c8
 s4          0xfffffe0013923a38
 s5          0x40
 s6          0xfffffc003f960800
 a0          0x5
 a1          0xfffffd01fc0003f8
 a2          0
 a3          0x8
 a4          0x3
 a5          0xfffffe0000000008
 t8          0xfffffe00139237ff
 t9          0x8
 t10         0x3ea0a5
 t11         0x1ff800
 ra          0xfffffc000080c5b8  panic+0x268
 t12         0xfffffc00003eb590  cpu_Debugger
 at          0x12002438c
 gp          0xfffffc0000c30928  __link_set_prop_linkpools_sym__link__prop_array_pool+0x8008
 sp          0xfffffe0013923888
 pc          0xfffffc00003eb594  cpu_Debugger+0x4
 ps          0x6
 ai          0x1ff800
 pv          0xfffffc00003eb590  cpu_Debugger
 netbsd:cpu_Debugger+0x4:        ret     zero,(ra)
 db{1}> mach cpu 0
 Using CPU 0
 db{1}> tr

 CPU 1: fatal kernel trap:

 CPU 1    trap entry = 0x2 (memory management fault)
 CPU 1    a0         = 0xffffffffffffffd9
 CPU 1    a1         = 0x1
 CPU 1    a2         = 0x0
 CPU 1    pc         = 0xfffffc00003ee944
 CPU 1    ra         = 0xfffffc00003e8104
 CPU 1    pv         = 0xfffffc00003ee890
 CPU 1    curlwp     = 0xfffffc003f960800
 CPU 1        pid = 0, comm = system

 Caught exception in ddb.
 db{1}> show reg
 v0          0
 t0          0
 t1          0xfffffc003fe29c00
 t2          0xfffffe0012c8a400
 t3          0
 t4          0
 t5          0xfffffc003fe29c60
 t6          0xfffffc0000c68410  kernel_pmap_store+0x50
 t7          0
 s0          0x1
 s1          0xfffffc003fe29c00
 s2          0xfffffc0000c0de60  cpu_info_primary+0x38
 s3          0xfffffc0000c0de28  cpu_info_primary
 s4          0
 s5          0
 s6          0
 a0          0
 a1          0
 a2          0xfffffe0012c9a000
 a3          0x1
 a4          0xfffffc0000c94308  uvm_fpageqlock
 a5          0
 t8          0x1604db790
 t9          0
 t10         0xffffffff
 t11         0xfffffc003f90a8b8
 ra          0xfffffc00005eac88  idle_loop+0x1b8
 t12         0xfffffc000060e200  kpreempt_enable
 at          0xfffffe0013984000
 gp          0xfffffc0000c30928  __link_set_prop_linkpools_sym__link__prop_array_pool+0x8008
 sp          0x1
 pc          0xfffffc00005eac34  idle_loop+0x164
 ps          0
 ai          0xfffffc003f90a8b8
 pv          0xfffffc000060e200  kpreempt_enable
 netbsd:idle_loop+0x164: ldq     pv,-1d30(gp)
 ----------------------------------------------------------------------

 So, no cigar this time.  Anything else I should try?

 					-jarle
 -- 
 Q: What's the difference between programming and bug collecting?
 A: None.

From: "Michael L. Hitch" <mhitch@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/38335 CVS commit: src/sys/arch/alpha/alpha
Date: Mon, 9 Nov 2009 04:31:04 +0000

 Module Name:	src
 Committed By:	mhitch
 Date:		Mon Nov  9 04:31:03 UTC 2009

 Modified Files:
 	src/sys/arch/alpha/alpha: pmap.c

 Log Message:
 The tlb shootdown IPI can interrupt the pool_cache_get() in places that
 can cause a deadlock or pool cache corruption.  Take the shootdown job
 queue mutex before calling pool_cache_get(), which will block the IPI
 interrupts and seems to fix the remaining tlb shootdown deadlocks and
 pool cache corruption I've been seeing.  Should address both
 PR port-amiga/38335 and PR port-amiga/42174.


 To generate a diff of this commit:
 cvs rdiff -u -r1.249 -r1.250 src/sys/arch/alpha/alpha/pmap.c

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: gnats-bugs@NetBSD.org
Cc: jarle@uninett.no
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Sun, 8 Nov 2009 21:34:34 -0700 (MST)

 On Wed, 28 Oct 2009, Jarle Greipsland wrote:

 > So, no cigar this time.  Anything else I should try?
 >
 > 					-jarle

    I've committed a fix to current that I think will fix this.

 Index: sys/arch/alpha/alpha/pmap.c
 ===================================================================
 RCS file: /cvsroot/src/sys/arch/alpha/alpha/pmap.c,v
 retrieving revision 1.249
 diff -u -p -r1.249 pmap.c
 --- sys/arch/alpha/alpha/pmap.c 7 Nov 2009 07:27:40 -0000       1.249
 +++ sys/arch/alpha/alpha/pmap.c 9 Nov 2009 04:21:12 -0000
 @@ -3581,6 +3581,7 @@ pmap_tlb_shootdown(pmap_t pmap, vaddr_t
                  cpumask |= 1UL << ci->ci_cpuid;

                  pq = &pmap_tlb_shootdown_q[ci->ci_cpuid];
 +               mutex_spin_enter(&pq->pq_lock);

                  /*
                   * Allocate a job.
 @@ -3596,7 +3597,6 @@ pmap_tlb_shootdown(pmap_t pmap, vaddr_t
                   * If a global flush is already pending, we
                   * don't really have to do anything else.
                   */
 -               mutex_spin_enter(&pq->pq_lock);
                  pq->pq_pte |= pte;
                  if (pq->pq_tbia) {
                          mutex_spin_exit(&pq->pq_lock);


 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: Soren Jacobsen <snj@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/38335 CVS commit: [netbsd-5] src/sys/arch/alpha/alpha
Date: Sun, 15 Nov 2009 05:54:38 +0000

 Module Name:	src
 Committed By:	snj
 Date:		Sun Nov 15 05:54:38 UTC 2009

 Modified Files:
 	src/sys/arch/alpha/alpha [netbsd-5]: pmap.c

 Log Message:
 Pull up following revision(s) (requested by mhitch in ticket #1137):
 	sys/arch/alpha/alpha/pmap.c: revision 1.250
 The tlb shootdown IPI can interrupt the pool_cache_get() in places that
 can cause a deadlock or pool cache corruption.  Take the shootdown job
 queue mutex before calling pool_cache_get(), which will block the IPI
 interrupts and seems to fix the remaining tlb shootdown deadlocks and
 pool cache corruption I've been seeing.  Should address both
 PR port-alpha/38335 and PR port-alpha/42174.


 To generate a diff of this commit:
 cvs rdiff -u -r1.236.10.3 -r1.236.10.4 src/sys/arch/alpha/alpha/pmap.c

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

From: Soren Jacobsen <snj@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/38335 CVS commit: [netbsd-5-0] src/sys/arch/alpha/alpha
Date: Sun, 15 Nov 2009 05:55:01 +0000

 Module Name:	src
 Committed By:	snj
 Date:		Sun Nov 15 05:55:00 UTC 2009

 Modified Files:
 	src/sys/arch/alpha/alpha [netbsd-5-0]: pmap.c

 Log Message:
 Pull up following revision(s) (requested by mhitch in ticket #1137):
 	sys/arch/alpha/alpha/pmap.c: revision 1.250
 The tlb shootdown IPI can interrupt the pool_cache_get() in places that
 can cause a deadlock or pool cache corruption.  Take the shootdown job
 queue mutex before calling pool_cache_get(), which will block the IPI
 interrupts and seems to fix the remaining tlb shootdown deadlocks and
 pool cache corruption I've been seeing.  Should address both
 PR port-alpha/38335 and PR port-alpha/42174.


 To generate a diff of this commit:
 cvs rdiff -u -r1.236.14.2 -r1.236.14.3 src/sys/arch/alpha/alpha/pmap.c

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

State-Changed-From-To: open->feedback
State-Changed-By: snj@NetBSD.org
State-Changed-When: Thu, 04 Feb 2010 02:41:25 +0000
State-Changed-Why:
Did the committed fix take care of the issue you're seeing?


From: Jarle Greipsland <jarle@uninett.no>
To: gnats-bugs@NetBSD.org, snj@NetBSD.org
Cc: port-alpha-maintainer@netbsd.org, netbsd-bugs@netbsd.org,
	gnats-admin@netbsd.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Fri, 05 Feb 2010 09:20:03 +0100 (CET)

 snj@NetBSD.org writes:
 > Synopsis: kernel freeze on alpha MP system
 > 
 > State-Changed-From-To: open->feedback
 > State-Changed-By: snj@NetBSD.org
 > State-Changed-When: Thu, 04 Feb 2010 02:41:25 +0000
 > State-Changed-Why:
 > Did the committed fix take care of the issue you're seeing?
 I don't think so.  I have been running with a LOCKDEBUG-kernel,
 and yesterday, while trying to do a 'build.sh release', it
 panicked.

 login: Mutex error: lockdebug_wantlock: locking against myself

 lock address : 0xfffffc0000882f68 type     :               spin
 initialized  : 0xfffffc00006735d8
 shared holds :                  0 exclusive:                  1
 shares wanted:                  0 exclusive:                  1
 current cpu  :                  0 last held:                  0
 current l  : 0xfffffc003fab2400 last held: 0xfffffc003fab2400
 last locked  : 0xfffffc0000674690 unlocked : 0xfffffc0000672478
 owner field  : 0x0000000000000400 wait/sn:                0/1

 panic: LOCKDEBUG
 Stopped in pid 0.35 (system) at netbsd:cpu_Debugger+0x4:        ret     zero,(ra
 )
 db{0}> 
 db{0}> trace
 cpu_Debugger() at netbsd:cpu_Debugger+0x4
 panic() at netbsd:panic+0x278
 lockdebug_abort1() at netbsd:lockdebug_abort1+0x150
 mutex_enter() at netbsd:mutex_enter+0x38c
 pool_get() at netbsd:pool_get+0x58
 pool_cache_put_slow() at netbsd:pool_cache_put_slow+0x2b4
 pool_cache_put_paddr() at netbsd:pool_cache_put_paddr+0x1e0
 pmap_do_tlb_shootdown() at netbsd:pmap_do_tlb_shootdown+0x178
 alpha_ipi_process() at netbsd:alpha_ipi_process+0xb8
 interrupt() at netbsd:interrupt+0x88
 XentInt() at netbsd:XentInt+0x1c
 --- interrupt (from ipl 4) ---
 lockdebug_mem_check() at netbsd:lockdebug_mem_check+0x1b4
 pool_put() at netbsd:pool_put+0x7c
 pool_cache_invalidate_groups() at netbsd:pool_cache_invalidate_groups+0xf4
 pool_cache_invalidate() at netbsd:pool_cache_invalidate+0x8c
 pool_reclaim() at netbsd:pool_reclaim+0x68
 pool_drain_end() at netbsd:pool_drain_end+0x60
 uvm_pageout() at netbsd:uvm_pageout+0x880
 exception_return() at netbsd:exception_return
 --- root of call graph ---
 db{0}> ps
 PID    LID S CPU     FLAGS       STRUCT LWP *               NAME WAIT
 23711    1 3   1         0   fffffc003d13cc00   alpha--netbsd-in biowait
 28502    1 3   1        80   fffffc002abf4800                 sh wait
 26148    1 2   0         0   fffffc003fab2000                 sh
 25393    1 3   1         0   fffffc0013211c00   alpha--netbsd-in nodebug
 13042    1 3   1        80   fffffc002abf5c00                 sh wait
 13735    1 3   1         0   fffffc003d6a9c00   alpha--netbsd-in biowait
 8778     1 3   1        80   fffffc002c220400                 sh wait
 20723    1 3   1        80   fffffc0029f73c00             nbmake select
 3839     1 3   1        80   fffffc003ecbe400                 sh wait
 10654    1 3   1        80   fffffc0028789800             nbmake select
 27117    1 3   0     40080   fffffc002aff8400                 sh wait
 15901    1 3   1        80   fffffc0028788c00             nbmake select
 18873    1 3   1        80   fffffc003d13c800                 sh wait
 21384    1 3   0        80   fffffc003d6a8800             nbmake select
 18742    1 3   1        80   fffffc0029f73000                 sh wait
 4474     1 3   1        80   fffffc0028789400             nbmake select
 20634    1 3   0        80   fffffc001ba59400                 sh wait
 4601     1 3   1        80   fffffc0035c89c00             nbmake select
 18174    1 3   1        80   fffffc002ab44800                 sh wait
 23525    1 3   1        80   fffffc0035c89000             nbmake select
 16471    1 3   1        80   fffffc0029f72000                 sh wait
 18058    1 3   0        80   fffffc002aff9000             nbmake select
 1991     1 3   1        80   fffffc002aff8800                 sh wait
 3250     1 3   0        80   fffffc003fab2800             nbmake select
 1383     1 3   0        80   fffffc003d6a8000                 sh wait
 22718    1 3   0        80   fffffc0035c89800             nbmake select
 18050    1 3   1        80   fffffc003d533400                 sh wait
 22901    1 3   1        80   fffffc002aff9c00             nbmake select
 27793    1 3   0        80   fffffc001ba58c00             nbmake select
 2373     1 3   1        80   fffffc0035c88800                 sh wait
 26438    1 3   1        80   fffffc002aff9800                 sh wait
 11413    1 3   0        80   fffffc002abf4400             nbmake select
 11875    1 3   1        80   fffffc002c220c00             pickup kqueue
 4144     1 3   1        80   fffffc002c221800               bash ttyraw
 12438    1 3   1        80   fffffc003d13d400              xterm select
 5290     1 3   1        80   fffffc003d532800                csh pause
 1592     1 3   0        80   fffffc002c221c00               sshd select
 21396    1 3   1        80   fffffc001ba58400               sshd netio
 26068    1 3   0        80   fffffc0028788800                 sh wait
 18777    1 3   0        80   fffffc003d533c00             nbmake select
 24640    1 3   1        80   fffffc002ab45000                 sh wait
 13734    1 3   0        80   fffffc002c221400             nbmake select
 26943    1 3   0        80   fffffc003ecbe800                 sh wait
 3019     1 3   0        80   fffffc002abf4000             nbmake select
 18256    1 3   0        80   fffffc003d6a9800                 sh wait
 6532     1 3   0        80   fffffc003d532000             nbmake select
 23787    1 3   0        80   fffffc002abf5800                 sh wait
 20208    1 3   1        80   fffffc003d6a8c00               tcsh pause
 527      1 3   1        80   fffffc003fa09800              getty ttyraw
 515      1 3   0        80   fffffc003d533000               cron nanoslp
 508      1 3   1        80   fffffc003ecbec00          python2.5 select
 484      1 3   0        80   fffffc003f6fc000               qmgr kqueue
 443      1 3   1        80   fffffc003d533800              inetd kqueue
 478      1 3   1        80   fffffc003f6fc400             master kqueue
 300      1 3   1        80   fffffc003ecbf400               sshd select
 301      1 3   0        80   fffffc003ecbf800               ntpd pause
 183      1 3   0        80   fffffc003ecbfc00          mount_mfs mfsidl
 152      1 3   1        80   fffffc003f6fd000            syslogd kqueue
 1        1 3   1        80   fffffc003fa09400               init wait
 0       39 3   1       200   fffffc003f6fc800            physiod physiod
 0       38 3   1       200   fffffc003fa08000        vmem_rehash vmem_rehash
 0       37 3   1       200   fffffc003fa08400           aiodoned aiodoned
 0       36 3   0       200   fffffc003fa08800            ioflush syncer
 0    >  35 7   0       200   fffffc003fab2400           pgdaemon
 0       34 3   1       200   fffffc003fa09000          cryptoret crypto_wait
 0       33 3   1       200   fffffc003fa09c00          atapibus0 sccomp
 0       31 3   1       200   fffffc003fa08c00              unpgc unpgc
 0       22 3   0       200   fffffc003fab2c00            atabus1 atath
 0       21 3   1       200   fffffc003fab3000            atabus0 atath
 0       20 3   0       200   fffffc003fab3400           scsibus0 sccomp
 0       19 3   1       200   fffffc003fab3800            xcall/1 xcall
 0       18 1   1       200   fffffc003fab3c00          softser/1
 0       17 1   1       200   fffffc003fcea000          softclk/1
 0       16 1   1       200   fffffc003fcea400          softbio/1
 0       15 1   1       200   fffffc003fcea800          softnet/1
 0    >  14 7   1       201   fffffc003fceac00             idle/1
 0       13 3   1       200   fffffc003fceb000         pmfsuspend pmfsuspend
 0       12 3   0       200   fffffc003fceb400           pmfevent pmfevent
 0       11 3   1       200   fffffc003fceb800           nfssilly nfssilly
 0       10 3   1       200   fffffc003fcebc00            cachegc cachegc
 0        9 3   1       200   fffffc003fe18000              vrele vrele
 0        8 3   0       200   fffffc003fe18400          modunload modunload
 0        7 3   0       200   fffffc003fe18800            xcall/0 xcall
 0        6 1   0       200   fffffc003fe18c00          softser/0
 0        5 1   0       200   fffffc003fe19000          softclk/0
 0        4 1   0       200   fffffc003fe19400          softbio/0
 0        3 1   0       200   fffffc003fe19800          softnet/0
 0        2 1   0       201   fffffc003fe19c00             idle/0
 0        1 3   1       200   fffffc0000841580            swapper uvm
 db{0}> show reg
 v0          0xfffffc000083b980  cpu_info_primary
 t0          0x1
 t1          0x1
 t2          0xfffffc003ff48000
 t3          0xfffffc000084f201  kprintf_inited
 t4          0
 t5          0xfffffc00007e1fd2  sun_noname+0x286
 t6          0
 t7          0
 s0          0xfffffc00008503c4  msgbufenabled
 s1          0x104
 s2          0xfffffc000084e720  db_onpanic
 s3          0xfffffc00007e23e5  __func__.8678+0x2cc
 s4          0x1
 s5          0x5
 s6          0xfffffc003fa936c0
 a0          0
 a1          0xfffffc0000677ca4  kprintf_unlock+0x54
 a2          0
 a3          0x8
 a4          0x3
 a5          0xfffffc0000000008
 t8          0xfffffe0013041787
 t9          0x8
 t10         0x3a46e6e0
 t11         0x9
 ra          0xfffffc0000679328  panic+0x278
 t12         0xfffffc000047b0b0  cpu_Debugger
 at          0x17
 gp          0xfffffc000084e3d0  __link_set_prop_linkpools_sym__link__prop_array_pool+0x8008
 sp          0xfffffe0013041870
 pc          0xfffffc000047b0b4  cpu_Debugger+0x4
 ps          0x6
 ai          0x9
 pv          0xfffffc000047b0b0  cpu_Debugger
 netbsd:cpu_Debugger+0x4:        ret     zero,(ra)
 db{0}> mach cpu 1
 Using CPU 1
 db{0}> trace
 db{0}> show reg
 v0          0xfffffe0000032000
 t0          0
 t1          0xfffffe0012fd2000
 t2          0xfffffe0012fd2000
 t3          0
 t4          0
 t5          0xfffffc003fceac60
 t6          0
 t7          0xfffffc00008aae18  vm_physmem
 s0          0xfffffc003fe20cc0
 s1          0
 s2          0xfffffe0000032000
 s3          0xfffffe0000032038
 s4          0xfffffc000078e3d0  config+0x437e
 s5          0xfffffc00007ae3d0  wildcard.5079+0xd88
 s6          0xfffffc00007ae3d0  wildcard.5079+0xd88
 a0          0xfffffc0000793f8c  config+0x9f3a
 a1          0xfffffc00007aee79  __func__.5392+0xe3
 a2          0x1dd
 a3          0xfffffc00007aee90  __func__.5392+0xfa
 a4          0
 a5          0
 t8          0xfffffc00008aae18  vm_physmem
 t9          0xfffffc00005835b4  calcru+0x204
 t10         0
 t11         0xa
 ra          0xfffffc0000585390  sched_curcpu_runnable_p+0x70
 t12         0xfffffc0000594950  kpreempt_enable
 at          0x1601b306c
 gp          0xfffffc000084e3d0  __link_set_prop_linkpools_sym__link__prop_array_pool+0x8008
 sp          0xfffffc0000593ca0  kpreempt_disable+0x20
 pc          0xfffffc0000594950  kpreempt_enable
 ps          0
 ai          0xa
 pv          0xfffffc0000594950  kpreempt_enable
 netbsd:kpreempt_enable: ldah    gp,2c(pv)
 db{0}> c
 cpu1: shutting down...

 dumping to dev 8,1 offset 2097597
 dump i/o error


 sd0(esiop0:0:0:0): polling command not done
 panic: scsipi_execute_xs
 panic: alpha_send_ipi: CPU 1 not running
 panic: alpha_send_ipi: CPU 1 not running
 [ ... ]

 					-jarle

State-Changed-From-To: feedback->open
State-Changed-By: snj@NetBSD.org
State-Changed-When: Fri, 05 Feb 2010 17:46:44 +0000
State-Changed-Why:
Feedback received.


From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: Jarle Greipsland <jarle@uninett.no>
Cc: gnats-bugs@NetBSD.org
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Thu, 18 Feb 2010 15:04:28 -0700 (MST)

 On Fri, 5 Feb 2010, Jarle Greipsland wrote:

 >> Did the committed fix take care of the issue you're seeing?
 > I don't think so.  I have been running with a LOCKDEBUG-kernel,
 > and yesterday, while trying to do a 'build.sh release', it
 > panicked.
 >
 > login: Mutex error: lockdebug_wantlock: locking against myself
 >
 > lock address : 0xfffffc0000882f68 type     :               spin
 > initialized  : 0xfffffc00006735d8
 > shared holds :                  0 exclusive:                  1
 > shares wanted:                  0 exclusive:                  1
 > current cpu  :                  0 last held:                  0
 > current l  : 0xfffffc003fab2400 last held: 0xfffffc003fab2400
 > last locked  : 0xfffffc0000674690 unlocked : 0xfffffc0000672478
 > owner field  : 0x0000000000000400 wait/sn:                0/1
 >
 > panic: LOCKDEBUG
 > Stopped in pid 0.35 (system) at netbsd:cpu_Debugger+0x4:        ret     zero,(ra
 > )
 > db{0}>
 > db{0}> trace
 > cpu_Debugger() at netbsd:cpu_Debugger+0x4
 > panic() at netbsd:panic+0x278
 > lockdebug_abort1() at netbsd:lockdebug_abort1+0x150
 > mutex_enter() at netbsd:mutex_enter+0x38c
 > pool_get() at netbsd:pool_get+0x58
 > pool_cache_put_slow() at netbsd:pool_cache_put_slow+0x2b4
 > pool_cache_put_paddr() at netbsd:pool_cache_put_paddr+0x1e0
 > pmap_do_tlb_shootdown() at netbsd:pmap_do_tlb_shootdown+0x178
 > alpha_ipi_process() at netbsd:alpha_ipi_process+0xb8
 > interrupt() at netbsd:interrupt+0x88
 > XentInt() at netbsd:XentInt+0x1c
 > --- interrupt (from ipl 4) ---
 > lockdebug_mem_check() at netbsd:lockdebug_mem_check+0x1b4
 > pool_put() at netbsd:pool_put+0x7c
 > pool_cache_invalidate_groups() at netbsd:pool_cache_invalidate_groups+0xf4
 > pool_cache_invalidate() at netbsd:pool_cache_invalidate+0x8c
 > pool_reclaim() at netbsd:pool_reclaim+0x68
 > pool_drain_end() at netbsd:pool_drain_end+0x60
 > uvm_pageout() at netbsd:uvm_pageout+0x880
 > exception_return() at netbsd:exception_return

    This looks like the tlb shootdown IPI interrupted a pool_put() 
 operation, which likley holds a mutex related to some pool.  The
 tlb shootdown is attempting to return an entry to the shootdown
 job pool, and tries to acquire the same lock.

    I hadn't seen this type of deadlock (which it would have without
 LOCKDEBUG) before, but I recently started seeing seeing several
 deadlocks just grepping a number of large files.  Trying to build
 a current LOCKDEBUG kernel resulted in a hard hang when booting the 
 kernel, requiring a power cycle of my CS20 and I had trouble recovering 
 after that.  I switched to a 4 CPU ES40 to debug the LOCKDEBUG problem, 
 and eventually found what that was and using a workaround was finally able 
 to get a working LOCKDEBUG kernel.  My grepping was able to cause 
 deadlocks fairly easily, and I had been trying to to keep the CS20 from 
 hanging in the deadlock by enabling the SPINLOCK_SPINOUT part of 
 LOCKDEBUG.  Some of the deadlocks looked very similar to the above.

    Try the following change, which will use IPL_SCHED for the pool cache 
 used by the tlb shootdown code.  I've done this on my CS20, and have been 
 able to run numereous greps that would previously deadlock.  In the above 
 traceback, I can't quite see how that would work, unless the 
 pool_drain_end() is going to be locking the tlb shootdown job pool.

 Index: sys/arch/alpha/alpha/pmap.c
 ===================================================================
 RCS file: /cvsroot/src/sys/arch/alpha/alpha/pmap.c,v
 retrieving revision 1.252
 diff -u -p -r1.252 pmap.c
 --- sys/arch/alpha/alpha/pmap.c 26 Nov 2009 00:19:11 -0000      1.252
 +++ sys/arch/alpha/alpha/pmap.c 18 Feb 2010 21:52:16 -0000
 @@ -937,7 +937,7 @@ pmap_bootstrap(paddr_t ptaddr, u_int max
           */
          pool_cache_bootstrap(&pmap_tlb_shootdown_job_cache,
              sizeof(struct pmap_tlb_shootdown_job), CACHE_LINE_SIZE,
 -            0, PR_LARGECACHE, "pmaptlb", NULL, IPL_VM, NULL, NULL, NULL);
 +            0, PR_LARGECACHE, "pmaptlb", NULL, IPL_SCHED, NULL, NULL, NULL);
          for (i = 0; i < ALPHA_MAXPROCS; i++) {
                  TAILQ_INIT(&pmap_tlb_shootdown_q[i].pq_head);
                  mutex_init(&pmap_tlb_shootdown_q[i].pq_lock, MUTEX_DEFAULT,


 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

From: "Michael L. Hitch" <mhitch@lightning.msu.montana.edu>
To: gnats-bugs@NetBSD.org
Cc: jarle@uninett.no
Subject: Re: port-alpha/38335 (kernel freeze on alpha MP system)
Date: Fri, 19 Feb 2010 11:10:17 -0700 (MST)

 On Thu, 18 Feb 2010, Michael L. Hitch wrote:

 > > db{0}> trace
 > > cpu_Debugger() at netbsd:cpu_Debugger+0x4
 > > panic() at netbsd:panic+0x278
 > > lockdebug_abort1() at netbsd:lockdebug_abort1+0x150
 > > mutex_enter() at netbsd:mutex_enter+0x38c
 > > pool_get() at netbsd:pool_get+0x58
 > > pool_cache_put_slow() at netbsd:pool_cache_put_slow+0x2b4
 > > pool_cache_put_paddr() at netbsd:pool_cache_put_paddr+0x1e0
 > > pmap_do_tlb_shootdown() at netbsd:pmap_do_tlb_shootdown+0x178
 > > alpha_ipi_process() at netbsd:alpha_ipi_process+0xb8
 > > interrupt() at netbsd:interrupt+0x88
 > > XentInt() at netbsd:XentInt+0x1c
 > > --- interrupt (from ipl 4) ---
 > > lockdebug_mem_check() at netbsd:lockdebug_mem_check+0x1b4
 > > pool_put() at netbsd:pool_put+0x7c
 > > pool_cache_invalidate_groups() at netbsd:pool_cache_invalidate_groups+0xf4
 > > pool_cache_invalidate() at netbsd:pool_cache_invalidate+0x8c
 > > pool_reclaim() at netbsd:pool_reclaim+0x68
 > > pool_drain_end() at netbsd:pool_drain_end+0x60
 > > uvm_pageout() at netbsd:uvm_pageout+0x880
 > > exception_return() at netbsd:exception_return
 ...
 >    Try the following change, which will use IPL_SCHED for the pool cache
 > used by the tlb shootdown code.  I've done this on my CS20, and have been
 > able to run numereous greps that would previously deadlock.  In the above
 > traceback, I can't quite see how that would work, unless the
 > pool_drain_end() is going to be locking the tlb shootdown job pool.

    The patch I suggested is not going to help.  I just ran one more grep 
 today and got a panic just like the above one.

    The problem is that the lock being held is for the pcg_large_pool, which 
 uses IPL_VM, which can be interrupted by the tlb shootdown IPI.  In this 
 case, the lock has been taken by the cpu when doing the pool cache 
 invalidate, and gets interrupted by the IPI on the same cpu.  It needs to 
 do a pool_get() when the tlb shootdown routine is trying to put a pool 
 cache entry back into the cache, and that needs to also lock 
 pcg_large_pool.

    I don't really know all that much about the pool cache or pools, and 
 don't see any easy solution to this.

    A quick and dirty workaround would be to change the maximum number of 
 'jobs' the tlb shutdown does to 0, which effectively forces it to always 
 invalid the entire TLB and never use any pool cache entries.

    An alternative that I looked at quite some time ago (2 years maybe?) was 
 to replace the pool cache usage with statically allocated entries in the 
 pmap_tlb_shootdown_q[].

 --
 Michael L. Hitch			mhitch@montana.edu
 Computer Consultant
 Information Technology Center
 Montana State University	Bozeman, MT	USA

>Unformatted:

NetBSD Home
NetBSD PR Database Search

(Contact us) $NetBSD: query-full-pr,v 1.39 2013/11/01 18:47:49 spz Exp $
$NetBSD: gnats_config.sh,v 1.8 2006/05/07 09:23:38 tsutsui Exp $
Copyright © 1994-2007 The NetBSD Foundation, Inc. ALL RIGHTS RESERVED.