Re: Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

On Sep 2, 2023, at 7:35 AM, Martin Pieuchot  wrote:
> 
> On 28/06/23(Wed) 20:07, Kurt Miller wrote:
>> On Jun 28, 2023, at 7:16 AM, Martin Pieuchot  wrote:
>>> 
>>> On 28/06/23(Wed) 08:58, Claudio Jeker wrote:
 
 I doubt this is a missing wakeup. It is more the system is thrashing and
 not making progress. The SIGSTOP causes all threads to park which means
 that the thread not busy in its sched_yield() loop will finish its 
 operation
 and then on SIGCONT progress is possible.
 
 I need to recheck your ps output from ddb but I guess one of the threads
 is stuck in a different place. That is where we need to look.
 It may well be a bad interaction between SCHED_LOCK() and whatever else is
 going on.
>>> 
>>> Or simply a poor userland scheduling based on sched_yield()...
>>> 
>>> To me it seems there are two bugs in your report:
>>> 
>>> 1/ a deadlock due to a single rwlock in sysctl(2)
>>> 
>>> 2/ something unknown in java not making progress and calling
>>> sched_yield() and triggering 1/ 
>>> 
>>> While 1/ is well understood 2/ isn't.  Why is java not making progress
>>> is what should be understood.  Knowing where is the sched_yield() coming
>>> from can help.
>> 
>> Okay. I dug into 2/ and believe I understand what’s happening there.
>> The short version is that many threads are calling sched_yield(2) and
>> that’s somehow preventing either an mmap or munmap call from completing.
> 
> I don't understand how that could happen.  sched_yield() shouldn't
> prevent anything from happening.  This syscall doesn't require the
> KERNEL_LOCK() nor mmap/munmap(2).
> 
>> Java spawns a number of GCTaskThread threads for doing tasks like garbage
>> collection. The number of threads depends on the number of physical cpus
>> in the machine. My machine as 64, java spawns 43 GCTaskThreads. When there’s
>> nothing to do these threads are waiting on a condition variable. When there’s
>> work to do it all 43 threads are clamoring to get the work done in a design
>> that I find a bit unusual.
>> 
>> Until all 43 threads have no work to do they all continue to check for more
>> work. If there’s none but at least one thread is not done yet it does
>> the following; a certain number of hard spins or a sched_yield(2) call
>> or a 1ms sleep (via pthread_cond_timedwait(3) configured w/CLOCK_MONOTONIC).
>> After either a hard spin, sched_yield or the 1ms sleep it rechecks for more
>> work to do. If there still no work it repeats the above until all 43 threads
>> have no work to do. 
>> 
>> The relavant code is here with the defaults for some vars:
>> 
>> https://github.com/battleblow/jdk8u/blob/jdk8u372-ga/hotspot/src/share/vm/utilities/taskqueue.cpp#L153
>> 
>>uintx WorkStealingHardSpins = 4096
>> {experimental}
>>uintx WorkStealingSleepMillis   = 1   
>> {experimental}
>>uintx WorkStealingSpinToYieldRatio  = 10  
>> {experimental}
>>uintx WorkStealingYieldsBeforeSleep = 5000
>> {experimental}
>> 
>> What I see when java is stuck in what I was calling run-away state, is
>> that one thread (not necessarily a GCTaskThread) is stuck in mmap or
>> munmap called via malloc/free and the set of 43 GCTaskThreads are trying
>> to finish up a task.  Based on the feedback from you, Claudio
>> and Vitaliy, I’m assuming that the frequent calls to sched_yield are 
>> preventing the mmap/munmap call from completing. Since malloc made
>> the call, the malloc mutex is held and about 20 other threads block
>> waiting on the one thread to complete mmap/munmap. In unmodified
>> -current the sched_yield calls are sufficient to prevent the mmap/unmap
>> call from ever completing leading to 1/.
> 
> We're making progress here.  The question is now why/where is the thread
> stuck in mmap/munmap...
> 
>> I’ve attached two debug sessions of a run-away java process. In each I
>> have sorted the thread back traces into the following categories:
>> 
>> Stuck thread
>> Run away threads
>> Malloc mutex contention threads
>> Appear to be normal condition var or sem wait threads
>> 
>> I’m currently testing reducing the number of sched_yield calls before
>> sleeping 1ms from 5000 down to 10. In some limited testing this appears
>> to be a work-around for the mmap/munmap starvation problem. I will
>> do a long test to confirm this is a sufficent work-around for the problem.
>> 
> 
>> Stuck thread (on proc or run state not making progress):
>> 
>> Thread 35 (thread 559567 of process 32495):
>> #0  map (d=0xdc4e3717e0, sz=8192, zero_fill=0) at malloc.c:865
> 
> This corresponds to a call to mprotect().  However the thread is still
> in userland at this point, so it isn't clear to me if it is stuck or
> not.
> 
> If it is in kernel, it would be useful to get the kernel trace.  You
> could enter ddb(4) and print it from 

Re: Sparc64 livelock/system freeze w/cpu traces

[Martin Pieuchot]

On 28/06/23(Wed) 20:07, Kurt Miller wrote:
> On Jun 28, 2023, at 7:16 AM, Martin Pieuchot  wrote:
> > 
> > On 28/06/23(Wed) 08:58, Claudio Jeker wrote:
> >> 
> >> I doubt this is a missing wakeup. It is more the system is thrashing and
> >> not making progress. The SIGSTOP causes all threads to park which means
> >> that the thread not busy in its sched_yield() loop will finish its 
> >> operation
> >> and then on SIGCONT progress is possible.
> >> 
> >> I need to recheck your ps output from ddb but I guess one of the threads
> >> is stuck in a different place. That is where we need to look.
> >> It may well be a bad interaction between SCHED_LOCK() and whatever else is
> >> going on.
> > 
> > Or simply a poor userland scheduling based on sched_yield()...
> > 
> > To me it seems there are two bugs in your report:
> > 
> > 1/ a deadlock due to a single rwlock in sysctl(2)
> > 
> > 2/ something unknown in java not making progress and calling
> >  sched_yield() and triggering 1/ 
> > 
> > While 1/ is well understood 2/ isn't.  Why is java not making progress
> > is what should be understood.  Knowing where is the sched_yield() coming
> > from can help.
> 
> Okay. I dug into 2/ and believe I understand what’s happening there.
> The short version is that many threads are calling sched_yield(2) and
> that’s somehow preventing either an mmap or munmap call from completing.

I don't understand how that could happen.  sched_yield() shouldn't
prevent anything from happening.  This syscall doesn't require the
KERNEL_LOCK() nor mmap/munmap(2).

> Java spawns a number of GCTaskThread threads for doing tasks like garbage
> collection. The number of threads depends on the number of physical cpus
> in the machine. My machine as 64, java spawns 43 GCTaskThreads. When there’s
> nothing to do these threads are waiting on a condition variable. When there’s
> work to do it all 43 threads are clamoring to get the work done in a design
> that I find a bit unusual.
> 
> Until all 43 threads have no work to do they all continue to check for more
> work. If there’s none but at least one thread is not done yet it does
> the following; a certain number of hard spins or a sched_yield(2) call
> or a 1ms sleep (via pthread_cond_timedwait(3) configured w/CLOCK_MONOTONIC).
> After either a hard spin, sched_yield or the 1ms sleep it rechecks for more
> work to do. If there still no work it repeats the above until all 43 threads
> have no work to do. 
> 
> The relavant code is here with the defaults for some vars:
> 
> https://github.com/battleblow/jdk8u/blob/jdk8u372-ga/hotspot/src/share/vm/utilities/taskqueue.cpp#L153
> 
> uintx WorkStealingHardSpins = 4096
> {experimental}
> uintx WorkStealingSleepMillis   = 1   
> {experimental}
> uintx WorkStealingSpinToYieldRatio  = 10  
> {experimental}
> uintx WorkStealingYieldsBeforeSleep = 5000
> {experimental}
> 
> What I see when java is stuck in what I was calling run-away state, is
> that one thread (not necessarily a GCTaskThread) is stuck in mmap or
> munmap called via malloc/free and the set of 43 GCTaskThreads are trying
> to finish up a task.  Based on the feedback from you, Claudio
> and Vitaliy, I’m assuming that the frequent calls to sched_yield are 
> preventing the mmap/munmap call from completing. Since malloc made
> the call, the malloc mutex is held and about 20 other threads block
> waiting on the one thread to complete mmap/munmap. In unmodified
> -current the sched_yield calls are sufficient to prevent the mmap/unmap
> call from ever completing leading to 1/.

We're making progress here.  The question is now why/where is the thread
stuck in mmap/munmap...

> I’ve attached two debug sessions of a run-away java process. In each I
> have sorted the thread back traces into the following categories:
> 
> Stuck thread
> Run away threads
> Malloc mutex contention threads
> Appear to be normal condition var or sem wait threads
> 
> I’m currently testing reducing the number of sched_yield calls before
> sleeping 1ms from 5000 down to 10. In some limited testing this appears
> to be a work-around for the mmap/munmap starvation problem. I will
> do a long test to confirm this is a sufficent work-around for the problem.
> 

> Stuck thread (on proc or run state not making progress):
> 
> Thread 35 (thread 559567 of process 32495):
> #0  map (d=0xdc4e3717e0, sz=8192, zero_fill=0) at malloc.c:865

This corresponds to a call to mprotect().  However the thread is still
in userland at this point, so it isn't clear to me if it is stuck or
not.

If it is in kernel, it would be useful to get the kernel trace.  You
could enter ddb(4) and print it from there.   Or, if that works on
sparc64, use btrace(8) replacing XXX below with the corresponding TID:

# btrace -e "profile:hz:100 /tid == XXX/ { 

Re: Sparc64 livelock/system freeze w/cpu traces

[Claudio Jeker]

On Wed, Jun 28, 2023 at 01:16:42PM +0200, Martin Pieuchot wrote:
> On 28/06/23(Wed) 08:58, Claudio Jeker wrote:
> > On Tue, Jun 27, 2023 at 08:18:15PM -0400, Kurt Miller wrote:
> > > On Jun 27, 2023, at 1:52 PM, Kurt Miller  
> > > wrote:
> > > > 
> > > > On Jun 14, 2023, at 12:51 PM, Vitaliy Makkoveev  
> > > > wrote:
> > > >> 
> > > >> On Tue, May 30, 2023 at 01:31:08PM +0200, Martin Pieuchot wrote:
> > > >>> So it seems the java process is holding the `sysctl_lock' for too long
> > > >>> and block all other sysctl(2).  This seems wrong to me.  We should 
> > > >>> come
> > > >>> up with a clever way to prevent vslocking too much memory.  A single
> > > >>> lock obviously doesn't fly with that many CPUs. 
> > > >>> 
> > > >> 
> > > >> We vslock memory to prevent context switch while doing copyin() and
> > > >> copyout(), right? This is required for avoid context switch within 
> > > >> foreach
> > > >> loops of kernel lock protected lists. But this seems not be required 
> > > >> for
> > > >> simple sysctl_int() calls or rwlock protected data. So sysctl_lock
> > > >> acquisition and the uvm_vslock() calls could be avoided for significant
> > > >> count of mibs and pushed deep down for the rest.
> > > > 
> > > > I’m back on -current testing and have some additional findings that
> > > > may help a bit. The memory leak fix had no effect on this issue. 
> > > > -current
> > > > behavior is as I previously described. When java trips the issue, it 
> > > > goes into a state where many threads are all running at 100% cpu but 
> > > > does not make forward progress. I’m going to call this state run-away 
> > > > java
> > > > process. Java is calling sched_yield(2) when in this state.
> > > > 
> > > > When java is in run-away state, a different process can trip
> > > > the next stage were processes block waiting on sysctllk indefinitely.
> > > > Top with process arguments is one, pgrep and ps -axl also trip this.
> > > > My last test on -current java was stuck in run-away state for 7 hours
> > > > 45 minutes before cron daily ran and cause the lockups.
> > > > 
> > > > I did a test with -current + locking sched_yield() back up with the
> > > > kernel lock. The behavior changed slightly. Java still enters run-away
> > > > state occasionally but eventually does make forward progress and 
> > > > complete. When java is in run-away state the sysctllk issue can still
> > > > be tripped, but if it is not tripped java eventually completes. For 
> > > > about 200 invocations of a java command that usually takes 50 seconds
> > > > to complete, 4 times java entered run-away state but eventually 
> > > > completed:
> > > > 
> > > > Typically it runs like this:
> > > >0m51.16s real 5m09.37s user 0m49.96s system
> > > > 
> > > > The exceptions look like this:
> > > >1m11.15s real 5m35.88s user13m20.47s system 
> > > >   27m18.93s real31m13.19s user   754m48.41s system
> > > >   13m44.44s real19m56.11s user   501m39.73s system 
> > > >   19m23.72s real24m40.97s user   629m08.16s system
> > > > 
> > > > Testing -current with dumbsched.3 behaves the same as -current described
> > > > above.
> > > > 
> > > > One other thing I observed so far is what happens when egdb is 
> > > > Attached to the run-away java process. egdb stops the process
> > > > using ptrace(2) PT_ATTACH. Now if I issue a command that would
> > > > typically lock up the system like top displaying command line
> > > > arguments, the system does not lock up. I think this rules out
> > > > the kernel memory is fragmented theory.
> > > > 
> > > > Switching cpu’s in ddb tends to lock up ddb so I have limited
> > > > info but here what I have from -current lockup and -current
> > > > with dumbsched.3 lockup. 
> > > 
> > > Another data point to support the idea of a missing wakeup; when
> > > java is in run-away state, if I send SIGSTOP followed by SIGCONT
> > > it dislodges it from run-away state and returns to normal operation.
> > 
> > I doubt this is a missing wakeup. It is more the system is thrashing and
> > not making progress. The SIGSTOP causes all threads to park which means
> > that the thread not busy in its sched_yield() loop will finish its operation
> > and then on SIGCONT progress is possible.
> > 
> > I need to recheck your ps output from ddb but I guess one of the threads
> > is stuck in a different place. That is where we need to look.
> > It may well be a bad interaction between SCHED_LOCK() and whatever else is
> > going on.
> 
> Or simply a poor userland scheduling based on sched_yield()...
> 
> To me it seems there are two bugs in your report:
> 
> 1/ a deadlock due to a single rwlock in sysctl(2)
> 
> 2/ something unknown in java not making progress and calling
>   sched_yield() and triggering 1/ 
> 
> While 1/ is well understood 2/ isn't.  Why is java not making progress
> is what should be understood.  Knowing where is the sched_yield() coming
> from can help.

For 1/ the main issue is that 

Re: Sparc64 livelock/system freeze w/cpu traces

[Martin Pieuchot]

On 28/06/23(Wed) 08:58, Claudio Jeker wrote:
> On Tue, Jun 27, 2023 at 08:18:15PM -0400, Kurt Miller wrote:
> > On Jun 27, 2023, at 1:52 PM, Kurt Miller  wrote:
> > > 
> > > On Jun 14, 2023, at 12:51 PM, Vitaliy Makkoveev  wrote:
> > >> 
> > >> On Tue, May 30, 2023 at 01:31:08PM +0200, Martin Pieuchot wrote:
> > >>> So it seems the java process is holding the `sysctl_lock' for too long
> > >>> and block all other sysctl(2).  This seems wrong to me.  We should come
> > >>> up with a clever way to prevent vslocking too much memory.  A single
> > >>> lock obviously doesn't fly with that many CPUs. 
> > >>> 
> > >> 
> > >> We vslock memory to prevent context switch while doing copyin() and
> > >> copyout(), right? This is required for avoid context switch within 
> > >> foreach
> > >> loops of kernel lock protected lists. But this seems not be required for
> > >> simple sysctl_int() calls or rwlock protected data. So sysctl_lock
> > >> acquisition and the uvm_vslock() calls could be avoided for significant
> > >> count of mibs and pushed deep down for the rest.
> > > 
> > > I’m back on -current testing and have some additional findings that
> > > may help a bit. The memory leak fix had no effect on this issue. -current
> > > behavior is as I previously described. When java trips the issue, it 
> > > goes into a state where many threads are all running at 100% cpu but 
> > > does not make forward progress. I’m going to call this state run-away java
> > > process. Java is calling sched_yield(2) when in this state.
> > > 
> > > When java is in run-away state, a different process can trip
> > > the next stage were processes block waiting on sysctllk indefinitely.
> > > Top with process arguments is one, pgrep and ps -axl also trip this.
> > > My last test on -current java was stuck in run-away state for 7 hours
> > > 45 minutes before cron daily ran and cause the lockups.
> > > 
> > > I did a test with -current + locking sched_yield() back up with the
> > > kernel lock. The behavior changed slightly. Java still enters run-away
> > > state occasionally but eventually does make forward progress and 
> > > complete. When java is in run-away state the sysctllk issue can still
> > > be tripped, but if it is not tripped java eventually completes. For 
> > > about 200 invocations of a java command that usually takes 50 seconds
> > > to complete, 4 times java entered run-away state but eventually completed:
> > > 
> > > Typically it runs like this:
> > >0m51.16s real 5m09.37s user 0m49.96s system
> > > 
> > > The exceptions look like this:
> > >1m11.15s real 5m35.88s user13m20.47s system 
> > >   27m18.93s real31m13.19s user   754m48.41s system
> > >   13m44.44s real19m56.11s user   501m39.73s system 
> > >   19m23.72s real24m40.97s user   629m08.16s system
> > > 
> > > Testing -current with dumbsched.3 behaves the same as -current described
> > > above.
> > > 
> > > One other thing I observed so far is what happens when egdb is 
> > > Attached to the run-away java process. egdb stops the process
> > > using ptrace(2) PT_ATTACH. Now if I issue a command that would
> > > typically lock up the system like top displaying command line
> > > arguments, the system does not lock up. I think this rules out
> > > the kernel memory is fragmented theory.
> > > 
> > > Switching cpu’s in ddb tends to lock up ddb so I have limited
> > > info but here what I have from -current lockup and -current
> > > with dumbsched.3 lockup. 
> > 
> > Another data point to support the idea of a missing wakeup; when
> > java is in run-away state, if I send SIGSTOP followed by SIGCONT
> > it dislodges it from run-away state and returns to normal operation.
> 
> I doubt this is a missing wakeup. It is more the system is thrashing and
> not making progress. The SIGSTOP causes all threads to park which means
> that the thread not busy in its sched_yield() loop will finish its operation
> and then on SIGCONT progress is possible.
> 
> I need to recheck your ps output from ddb but I guess one of the threads
> is stuck in a different place. That is where we need to look.
> It may well be a bad interaction between SCHED_LOCK() and whatever else is
> going on.

Or simply a poor userland scheduling based on sched_yield()...

To me it seems there are two bugs in your report:

1/ a deadlock due to a single rwlock in sysctl(2)

2/ something unknown in java not making progress and calling
  sched_yield() and triggering 1/ 

While 1/ is well understood 2/ isn't.  Why is java not making progress
is what should be understood.  Knowing where is the sched_yield() coming
from can help.

Re: Sparc64 livelock/system freeze w/cpu traces

[Claudio Jeker]

On Tue, Jun 27, 2023 at 08:18:15PM -0400, Kurt Miller wrote:
> On Jun 27, 2023, at 1:52 PM, Kurt Miller  wrote:
> > 
> > On Jun 14, 2023, at 12:51 PM, Vitaliy Makkoveev  wrote:
> >> 
> >> On Tue, May 30, 2023 at 01:31:08PM +0200, Martin Pieuchot wrote:
> >>> So it seems the java process is holding the `sysctl_lock' for too long
> >>> and block all other sysctl(2).  This seems wrong to me.  We should come
> >>> up with a clever way to prevent vslocking too much memory.  A single
> >>> lock obviously doesn't fly with that many CPUs. 
> >>> 
> >> 
> >> We vslock memory to prevent context switch while doing copyin() and
> >> copyout(), right? This is required for avoid context switch within foreach
> >> loops of kernel lock protected lists. But this seems not be required for
> >> simple sysctl_int() calls or rwlock protected data. So sysctl_lock
> >> acquisition and the uvm_vslock() calls could be avoided for significant
> >> count of mibs and pushed deep down for the rest.
> > 
> > I’m back on -current testing and have some additional findings that
> > may help a bit. The memory leak fix had no effect on this issue. -current
> > behavior is as I previously described. When java trips the issue, it 
> > goes into a state where many threads are all running at 100% cpu but 
> > does not make forward progress. I’m going to call this state run-away java
> > process. Java is calling sched_yield(2) when in this state.
> > 
> > When java is in run-away state, a different process can trip
> > the next stage were processes block waiting on sysctllk indefinitely.
> > Top with process arguments is one, pgrep and ps -axl also trip this.
> > My last test on -current java was stuck in run-away state for 7 hours
> > 45 minutes before cron daily ran and cause the lockups.
> > 
> > I did a test with -current + locking sched_yield() back up with the
> > kernel lock. The behavior changed slightly. Java still enters run-away
> > state occasionally but eventually does make forward progress and 
> > complete. When java is in run-away state the sysctllk issue can still
> > be tripped, but if it is not tripped java eventually completes. For 
> > about 200 invocations of a java command that usually takes 50 seconds
> > to complete, 4 times java entered run-away state but eventually completed:
> > 
> > Typically it runs like this:
> >0m51.16s real 5m09.37s user 0m49.96s system
> > 
> > The exceptions look like this:
> >1m11.15s real 5m35.88s user13m20.47s system 
> >   27m18.93s real31m13.19s user   754m48.41s system
> >   13m44.44s real19m56.11s user   501m39.73s system 
> >   19m23.72s real24m40.97s user   629m08.16s system
> > 
> > Testing -current with dumbsched.3 behaves the same as -current described
> > above.
> > 
> > One other thing I observed so far is what happens when egdb is 
> > Attached to the run-away java process. egdb stops the process
> > using ptrace(2) PT_ATTACH. Now if I issue a command that would
> > typically lock up the system like top displaying command line
> > arguments, the system does not lock up. I think this rules out
> > the kernel memory is fragmented theory.
> > 
> > Switching cpu’s in ddb tends to lock up ddb so I have limited
> > info but here what I have from -current lockup and -current
> > with dumbsched.3 lockup. 
> 
> Another data point to support the idea of a missing wakeup; when
> java is in run-away state, if I send SIGSTOP followed by SIGCONT
> it dislodges it from run-away state and returns to normal operation.

I doubt this is a missing wakeup. It is more the system is thrashing and
not making progress. The SIGSTOP causes all threads to park which means
that the thread not busy in its sched_yield() loop will finish its operation
and then on SIGCONT progress is possible.

I need to recheck your ps output from ddb but I guess one of the threads
is stuck in a different place. That is where we need to look.
It may well be a bad interaction between SCHED_LOCK() and whatever else is
going on.

-- 
:wq Claudio

Re: Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

On Jun 27, 2023, at 1:52 PM, Kurt Miller  wrote:
> 
> On Jun 14, 2023, at 12:51 PM, Vitaliy Makkoveev  wrote:
>> 
>> On Tue, May 30, 2023 at 01:31:08PM +0200, Martin Pieuchot wrote:
>>> So it seems the java process is holding the `sysctl_lock' for too long
>>> and block all other sysctl(2).  This seems wrong to me.  We should come
>>> up with a clever way to prevent vslocking too much memory.  A single
>>> lock obviously doesn't fly with that many CPUs. 
>>> 
>> 
>> We vslock memory to prevent context switch while doing copyin() and
>> copyout(), right? This is required for avoid context switch within foreach
>> loops of kernel lock protected lists. But this seems not be required for
>> simple sysctl_int() calls or rwlock protected data. So sysctl_lock
>> acquisition and the uvm_vslock() calls could be avoided for significant
>> count of mibs and pushed deep down for the rest.
> 
> I’m back on -current testing and have some additional findings that
> may help a bit. The memory leak fix had no effect on this issue. -current
> behavior is as I previously described. When java trips the issue, it 
> goes into a state where many threads are all running at 100% cpu but 
> does not make forward progress. I’m going to call this state run-away java
> process. Java is calling sched_yield(2) when in this state.
> 
> When java is in run-away state, a different process can trip
> the next stage were processes block waiting on sysctllk indefinitely.
> Top with process arguments is one, pgrep and ps -axl also trip this.
> My last test on -current java was stuck in run-away state for 7 hours
> 45 minutes before cron daily ran and cause the lockups.
> 
> I did a test with -current + locking sched_yield() back up with the
> kernel lock. The behavior changed slightly. Java still enters run-away
> state occasionally but eventually does make forward progress and 
> complete. When java is in run-away state the sysctllk issue can still
> be tripped, but if it is not tripped java eventually completes. For 
> about 200 invocations of a java command that usually takes 50 seconds
> to complete, 4 times java entered run-away state but eventually completed:
> 
> Typically it runs like this:
>0m51.16s real 5m09.37s user 0m49.96s system
> 
> The exceptions look like this:
>1m11.15s real 5m35.88s user13m20.47s system 
>   27m18.93s real31m13.19s user   754m48.41s system
>   13m44.44s real19m56.11s user   501m39.73s system 
>   19m23.72s real24m40.97s user   629m08.16s system
> 
> Testing -current with dumbsched.3 behaves the same as -current described
> above.
> 
> One other thing I observed so far is what happens when egdb is 
> Attached to the run-away java process. egdb stops the process
> using ptrace(2) PT_ATTACH. Now if I issue a command that would
> typically lock up the system like top displaying command line
> arguments, the system does not lock up. I think this rules out
> the kernel memory is fragmented theory.
> 
> Switching cpu’s in ddb tends to lock up ddb so I have limited
> info but here what I have from -current lockup and -current
> with dumbsched.3 lockup. 

Another data point to support the idea of a missing wakeup; when
java is in run-away state, if I send SIGSTOP followed by SIGCONT
it dislodges it from run-away state and returns to normal operation.

Re: Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

On Jun 14, 2023, at 12:51 PM, Vitaliy Makkoveev  wrote:
> 
> On Tue, May 30, 2023 at 01:31:08PM +0200, Martin Pieuchot wrote:
>> So it seems the java process is holding the `sysctl_lock' for too long
>> and block all other sysctl(2).  This seems wrong to me.  We should come
>> up with a clever way to prevent vslocking too much memory.  A single
>> lock obviously doesn't fly with that many CPUs. 
>> 
> 
> We vslock memory to prevent context switch while doing copyin() and
> copyout(), right? This is required for avoid context switch within foreach
> loops of kernel lock protected lists. But this seems not be required for
> simple sysctl_int() calls or rwlock protected data. So sysctl_lock
> acquisition and the uvm_vslock() calls could be avoided for significant
> count of mibs and pushed deep down for the rest.

I’m back on -current testing and have some additional findings that
may help a bit. The memory leak fix had no effect on this issue. -current
behavior is as I previously described. When java trips the issue, it 
goes into a state where many threads are all running at 100% cpu but 
does not make forward progress. I’m going to call this state run-away java
process. Java is calling sched_yield(2) when in this state.

When java is in run-away state, a different process can trip
the next stage were processes block waiting on sysctllk indefinitely.
Top with process arguments is one, pgrep and ps -axl also trip this.
My last test on -current java was stuck in run-away state for 7 hours
45 minutes before cron daily ran and cause the lockups.

I did a test with -current + locking sched_yield() back up with the
kernel lock. The behavior changed slightly. Java still enters run-away
state occasionally but eventually does make forward progress and 
complete. When java is in run-away state the sysctllk issue can still
be tripped, but if it is not tripped java eventually completes. For 
about 200 invocations of a java command that usually takes 50 seconds
to complete, 4 times java entered run-away state but eventually completed:

Typically it runs like this:
0m51.16s real 5m09.37s user 0m49.96s system

The exceptions look like this:
1m11.15s real 5m35.88s user13m20.47s system 
   27m18.93s real31m13.19s user   754m48.41s system
   13m44.44s real19m56.11s user   501m39.73s system 
   19m23.72s real24m40.97s user   629m08.16s system

Testing -current with dumbsched.3 behaves the same as -current described
above.

One other thing I observed so far is what happens when egdb is 
Attached to the run-away java process. egdb stops the process
using ptrace(2) PT_ATTACH. Now if I issue a command that would
typically lock up the system like top displaying command line
arguments, the system does not lock up. I think this rules out
the kernel memory is fragmented theory.

Switching cpu’s in ddb tends to lock up ddb so I have limited
info but here what I have from -current lockup and -current
with dumbsched.3 lockup. 

-current lockup 7 hours 45 min of run-away java then cron tripped it:

login: Stopped at  db_enter+0x8:   nop
ddb{0}> show all locks
CPU 6:
exclusive sched_lock _lock r = 0 (0x1ca4aa0)
CPU 12:
exclusive mutex >pm_mtx r = 0 (0x4001995e7f0)
Process 94379 (pgrep) thread 0x40018de79e0 (98675)
exclusive rwlock sysctllk r = 0 (0x1c240f8)
Process 70417 (java) thread 0x40018fdf140 (294923)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x40018fdf980 (389444)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x40018fdfc40 (20515)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x400190c5c50 (325344)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x400190c4650 (450774)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x400190c4390 (441666)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x400190c5990 (398914)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x4001910b420 (176161)
exclusive rwlock uobjlk r = 0 (0x40018f72190)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x4001910b160 (12453)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x4001910a0e0 (299519)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x4001910a920 (95241)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x40019604bf0 (281549)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 70417 (java) thread 0x40019605430 (219368)
shared rwlock vmmaplk r = 0 (0x400183a58b8)
Process 20430 (idle0) thread 0x40019965600 (355187)
exclusive kernel_lock _lock r = 0 (0x1cdfa38)
ddb{0}> ps
   PID TID   PPIDUID  S   FLAGS  WAIT  COMMAND
 51289  418052  86061  0  30x100090  sysctllk  cron
 68696   17984  86061  0  30x100090  sysctllk  cron
 57906   47164  86061  0  30x100090  sysctllk  cron
 57329   81627  86061  

Re: Sparc64 livelock/system freeze w/cpu traces

[Vitaliy Makkoveev]

On Tue, May 30, 2023 at 01:31:08PM +0200, Martin Pieuchot wrote:
> On 25/05/23(Thu) 16:33, Kurt Miller wrote:
> > On May 22, 2023, at 2:27 AM, Claudio Jeker  wrote:
> > > I have seen these WITNESS warnings on other systems as well. I doubt this
> > > is the problem. IIRC this warning is because sys_mount() is doing it wrong
> > > but it is not really an issue since sys_mount is not called often.
> > 
> > Yup. I see that now that I have tested witness on several arches. They all
> > show this lock order reversal right after booting the system. I guess this
> > means what I am seeing isn’t something that witness detects.
> > 
> > On -current with my T4-1, I can reliably reproduce the issues I am seeing.
> > While the problem is intermittent I can’t get very far into the jdk build 
> > without
> > tripping it. Instructions for reproducing the issue are:
> > 
> > Add wxallowed to /usr/local/ and /usr/ports (or wherever WRKOBJDIR has
> > been changed to)
> > 
> > doas pkg_add jdk zip unzip cups-libs bash gmake libiconv giflib
> > 
> > cd /usr/ports/devel/jdk/1.8
> > FLAVOR=native_bootstrap make
> > 
> > There are two stages to the problem. A java command (or javac or javah)
> > gets stuck making forward progress and nearly all of its cpu time is in
> > sys time category. You can see this in top as 1500-3000% CPU time on
> > the java process. ktrace of the process in this state shows endless
> > sched_yield() calls. Debugging shows many threads in
> > pthread_cond_wait(3). The condition vars are configured to use
> > CLOCK_MONOTONIC.
> > 
> > The second stage of the problem is when things lock up. While java is
> > spinning in this sched_yield() state, if you display the process arguments 
> > in
> > top (pressing the right arrow) you trip the lockups. top stops responding.
> > getty will reprompt if enter is pressed, but locks up if a username is 
> > entered.
> > Most processes lock up when doing anything after this point. ddb ps at this
> > stage shows top waiting on vmmaplk and the rest of the stuck processes
> > waiting on sysctllk (sshd, systat, login).
> 
> So it seems the java process is holding the `sysctl_lock' for too long
> and block all other sysctl(2).  This seems wrong to me.  We should come
> up with a clever way to prevent vslocking too much memory.  A single
> lock obviously doesn't fly with that many CPUs. 
> 

We vslock memory to prevent context switch while doing copyin() and
copyout(), right? This is required for avoid context switch within foreach
loops of kernel lock protected lists. But this seems not be required for
simple sysctl_int() calls or rwlock protected data. So sysctl_lock
acquisition and the uvm_vslock() calls could be avoided for significant
count of mibs and pushed deep down for the rest.

Re: Sparc64 livelock/system freeze w/cpu traces

[Martin Pieuchot]

On 25/05/23(Thu) 16:33, Kurt Miller wrote:
> On May 22, 2023, at 2:27 AM, Claudio Jeker  wrote:
> > I have seen these WITNESS warnings on other systems as well. I doubt this
> > is the problem. IIRC this warning is because sys_mount() is doing it wrong
> > but it is not really an issue since sys_mount is not called often.
> 
> Yup. I see that now that I have tested witness on several arches. They all
> show this lock order reversal right after booting the system. I guess this
> means what I am seeing isn’t something that witness detects.
> 
> On -current with my T4-1, I can reliably reproduce the issues I am seeing.
> While the problem is intermittent I can’t get very far into the jdk build 
> without
> tripping it. Instructions for reproducing the issue are:
> 
> Add wxallowed to /usr/local/ and /usr/ports (or wherever WRKOBJDIR has
> been changed to)
> 
> doas pkg_add jdk zip unzip cups-libs bash gmake libiconv giflib
> 
> cd /usr/ports/devel/jdk/1.8
> FLAVOR=native_bootstrap make
> 
> There are two stages to the problem. A java command (or javac or javah)
> gets stuck making forward progress and nearly all of its cpu time is in
> sys time category. You can see this in top as 1500-3000% CPU time on
> the java process. ktrace of the process in this state shows endless
> sched_yield() calls. Debugging shows many threads in
> pthread_cond_wait(3). The condition vars are configured to use
> CLOCK_MONOTONIC.
> 
> The second stage of the problem is when things lock up. While java is
> spinning in this sched_yield() state, if you display the process arguments in
> top (pressing the right arrow) you trip the lockups. top stops responding.
> getty will reprompt if enter is pressed, but locks up if a username is 
> entered.
> Most processes lock up when doing anything after this point. ddb ps at this
> stage shows top waiting on vmmaplk and the rest of the stuck processes
> waiting on sysctllk (sshd, systat, login).

So it seems the java process is holding the `sysctl_lock' for too long
and block all other sysctl(2).  This seems wrong to me.  We should come
up with a clever way to prevent vslocking too much memory.  A single
lock obviously doesn't fly with that many CPUs. 

Once that's improved it should be easier to debug the java issue.
sched_yield() is called from _spinlock() in librthread.  sparc64 should
use the futex version of pthread_cond_wait(3) which doesn't rely on
_spinlock() and sched_yield(2).  So I'm puzzled.  This seems like a poor
man scheduling issue hoping that another thread/process will make
progress.  Can you figure out where this sched_yield() is coming from?

> I tried bisecting when this was introduced but as I go back in time with
> kernels it becomes more intermittent and I didn’t notice that so I would need
> to redo the bisecting. I can say I have seen the problem reproduce as far
> back as Feb 16th kernel. When I updated the jdk in late January I didn’t 
> notice
> it but it could have been a lucky build as I tend to only do one 
> native_bootstrap
> build of the jdk when updating as a way to test the resulting package.
> 
> Here is some sample output of top, systat and ddb ps output on -current in
> my last reproduction of the problem.
> 
> load averages: 15.27,  4.25,  1.68
>   
> oracle.intricatesoftware.com 16:13:10
> 64 processes: 62 idle, 2 on processor 
>  up 0 
> days 00:04:58
> 64  CPUs:  0.0% user,  1.8% nice, 55.5% sys,  0.4% spin,  0.1% intr, 42.2% 
> idle
> Memory: Real: 143M/2676M act/tot Free: 13G Cache: 2334M Swap: 0K/16G
>   PID USERNAME PRI NICE  SIZE   RES STATE WAIT  TIMECPU COMMAND
> 38582 _pbuild   105  290M   64M onproc/19 fsleep   17:16 2892.14% javac
> 
>3 users Load 15.27 4.25 1.68oracle.intricatesof 
> 16:13:09
> 
> memory totals (in KB)PAGING   SWAPPING Interrupts
>real   virtual free   in  out   in  out12777 total
> Active   146752146752 13198032   opsvcons0
> All 2740160   2740160 29713104   pages5 
> vpci0:0
>   2 mpii0
> Proc:r  d  s  wCsw   Trp   Sys   Int   Sof  Flt   forks mpii1
> 18   148 78089 18666  8090 94097  18891   fkppw   2 em0
>   fksvm  31 ehci0
>0.1%Int   0.3%Spn  55.1%Sys   1.8%Usr  42.7%Idle   pwait   12737 clock
> |||||||||||   relck
> > rlkok
>   noram
> Namei Sys-cacheProc-cacheNo-cache ndcpy
> Calls hits%

Re: Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

On May 22, 2023, at 2:27 AM, Claudio Jeker  wrote:
> I have seen these WITNESS warnings on other systems as well. I doubt this
> is the problem. IIRC this warning is because sys_mount() is doing it wrong
> but it is not really an issue since sys_mount is not called often.

Yup. I see that now that I have tested witness on several arches. They all
show this lock order reversal right after booting the system. I guess this
means what I am seeing isn’t something that witness detects.

On -current with my T4-1, I can reliably reproduce the issues I am seeing.
While the problem is intermittent I can’t get very far into the jdk build 
without
tripping it. Instructions for reproducing the issue are:

Add wxallowed to /usr/local/ and /usr/ports (or wherever WRKOBJDIR has
been changed to)

doas pkg_add jdk zip unzip cups-libs bash gmake libiconv giflib

cd /usr/ports/devel/jdk/1.8
FLAVOR=native_bootstrap make

There are two stages to the problem. A java command (or javac or javah)
gets stuck making forward progress and nearly all of its cpu time is in
sys time category. You can see this in top as 1500-3000% CPU time on
the java process. ktrace of the process in this state shows endless
sched_yield() calls. Debugging shows many threads in
pthread_cond_wait(3). The condition vars are configured to use
CLOCK_MONOTONIC.

The second stage of the problem is when things lock up. While java is
spinning in this sched_yield() state, if you display the process arguments in
top (pressing the right arrow) you trip the lockups. top stops responding.
getty will reprompt if enter is pressed, but locks up if a username is entered.
Most processes lock up when doing anything after this point. ddb ps at this
stage shows top waiting on vmmaplk and the rest of the stuck processes
waiting on sysctllk (sshd, systat, login).

I tried bisecting when this was introduced but as I go back in time with
kernels it becomes more intermittent and I didn’t notice that so I would need
to redo the bisecting. I can say I have seen the problem reproduce as far
back as Feb 16th kernel. When I updated the jdk in late January I didn’t notice
it but it could have been a lucky build as I tend to only do one 
native_bootstrap
build of the jdk when updating as a way to test the resulting package.

Here is some sample output of top, systat and ddb ps output on -current in
my last reproduction of the problem.

load averages: 15.27,  4.25,  1.68  

oracle.intricatesoftware.com 16:13:10
64 processes: 62 idle, 2 on processor   
   up 0 
days 00:04:58
64  CPUs:  0.0% user,  1.8% nice, 55.5% sys,  0.4% spin,  0.1% intr, 42.2% idle
Memory: Real: 143M/2676M act/tot Free: 13G Cache: 2334M Swap: 0K/16G
  PID USERNAME PRI NICE  SIZE   RES STATE WAIT  TIMECPU COMMAND
38582 _pbuild   105  290M   64M onproc/19 fsleep   17:16 2892.14% javac

   3 users Load 15.27 4.25 1.68oracle.intricatesof 16:13:09

memory totals (in KB)PAGING   SWAPPING Interrupts
   real   virtual free   in  out   in  out12777 total
Active   146752146752 13198032   opsvcons0
All 2740160   2740160 29713104   pages5 vpci0:0
  2 mpii0
Proc:r  d  s  wCsw   Trp   Sys   Int   Sof  Flt   forks mpii1
18   148 78089 18666  8090 94097  18891   fkppw   2 em0
  fksvm  31 ehci0
   0.1%Int   0.3%Spn  55.1%Sys   1.8%Usr  42.7%Idle   pwait   12737 clock
|||||||||||   relck
> rlkok
  noram
Namei Sys-cacheProc-cacheNo-cache ndcpy
Calls hits%hits %miss   % fltcp
  zfod
  cow
Disks   cd0   sd0   sd1   sd2   cd1   sd3   66409 fmin
seeks   88545 ftarg
xfers   3 itarg
speed 18K   2 wired
  sec 0.0 pdfre
  pdscn
  pzidl   1 IPKTS
   13 kmape   1 OPKTS

ddb{0}> ps
   PID TID   PPIDUID  S   FLAGS  WAIT  COMMAND
 94135  299634   9252  0  30x82  sysctllk  sshd
 38582  227559  44647 55  30x200083  

Re: Sparc64 livelock/system freeze w/cpu traces

[Claudio Jeker]

On Sun, May 21, 2023 at 06:11:42PM -0400, Kurt Miller wrote:
> 
> 
> > On May 17, 2023, at 2:39 PM, Kurt Miller  wrote:
> > 
> > On May 13, 2023, at 3:07 PM, Kurt Miller  > > wrote:
> >> 
> >> On May 13, 2023, at 9:16 AM, Kurt Miller  
> >> wrote:
> >>> 
> >>> On May 12, 2023, at 10:26 AM, Martin Pieuchot  wrote:
>  
>  On 09/05/23(Tue) 20:02, Kurt Miller wrote:
> > While building devel/jdk/1.8 on May 3rd snapshot I noticed the build 
> > freezing
> > and processes getting stuck like ps. After enabling ddb.console I was 
> > able to
> > reproduce the livelock and capture cpu traces. Dmesg at the end.
> > Let me know if more information is needed as this appears to be rather
> > reproducible on my T4-1.
>  
>  It seems that all CPUs are waiting for the KERNEL_LOCK().  Doing ps /o
>  in ddb(4) should show us which CPU is currently holding it.  I can't
>  figure it out just by looking at the traces below.
>  
> 
> I managed to get WITNESS working on sparc64. Here’s what it found:
> 
> ddb{0}> show witness /b
> Number of known direct relationships is 255
> 
> Lock order reversal between ">mnt_lock"(rwlock) and 
> ">i_lock"(rrwlock)!
> Lock order ">mnt_lock"(rwlock) -> ">i_lock"(rrwlock) first seen at:
> #0  rrw_enter+0x58
> #1  VOP_LOCK+0x5c
> #2  vn_lock+0x9c
> #3  vget+0x12c
> #4  cache_lookup+0x308
> #5  ufs_lookup+0x11c
> #6  VOP_LOOKUP+0x40
> #7  vfs_lookup+0x2fc
> #8  namei+0x37c
> #9  ffs_mount+0x340
> #10 sys_mount+0x2fc
> #11 syscall+0x3c4
> #12 syscall_setup+0x134
> 
> Lock order ">i_lock"(rrwlock) -> ">mnt_lock"(rwlock) first seen at:
> #0  vfs_busy+0x34
> #1  vfs_lookup+0x39c
> #2  namei+0x37c
> #3  sys___realpath+0x1bc
> #4  syscall+0x3c4
> #5  syscall_setup+0x134
> 

I have seen these WITNESS warnings on other systems as well. I doubt this
is the problem. IIRC this warning is because sys_mount() is doing it wrong
but it is not really an issue since sys_mount is not called often.

-- 
:wq Claudio

Re: Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

> On May 17, 2023, at 2:39 PM, Kurt Miller  wrote:
> 
> On May 13, 2023, at 3:07 PM, Kurt Miller  > wrote:
>> 
>> On May 13, 2023, at 9:16 AM, Kurt Miller  wrote:
>>> 
>>> On May 12, 2023, at 10:26 AM, Martin Pieuchot  wrote:
 
 On 09/05/23(Tue) 20:02, Kurt Miller wrote:
> While building devel/jdk/1.8 on May 3rd snapshot I noticed the build 
> freezing
> and processes getting stuck like ps. After enabling ddb.console I was 
> able to
> reproduce the livelock and capture cpu traces. Dmesg at the end.
> Let me know if more information is needed as this appears to be rather
> reproducible on my T4-1.
 
 It seems that all CPUs are waiting for the KERNEL_LOCK().  Doing ps /o
 in ddb(4) should show us which CPU is currently holding it.  I can't
 figure it out just by looking at the traces below.
 

I managed to get WITNESS working on sparc64. Here’s what it found:

ddb{0}> show witness /b
Number of known direct relationships is 255

Lock order reversal between ">mnt_lock"(rwlock) and ">i_lock"(rrwlock)!
Lock order ">mnt_lock"(rwlock) -> ">i_lock"(rrwlock) first seen at:
#0  rrw_enter+0x58
#1  VOP_LOCK+0x5c
#2  vn_lock+0x9c
#3  vget+0x12c
#4  cache_lookup+0x308
#5  ufs_lookup+0x11c
#6  VOP_LOOKUP+0x40
#7  vfs_lookup+0x2fc
#8  namei+0x37c
#9  ffs_mount+0x340
#10 sys_mount+0x2fc
#11 syscall+0x3c4
#12 syscall_setup+0x134

Lock order ">i_lock"(rrwlock) -> ">mnt_lock"(rwlock) first seen at:
#0  vfs_busy+0x34
#1  vfs_lookup+0x39c
#2  namei+0x37c
#3  sys___realpath+0x1bc
#4  syscall+0x3c4
#5  syscall_setup+0x134

Re: Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

On May 13, 2023, at 3:07 PM, Kurt Miller  wrote:
> 
> On May 13, 2023, at 9:16 AM, Kurt Miller  wrote:
>> 
>> On May 12, 2023, at 10:26 AM, Martin Pieuchot  wrote:
>>> 
>>> On 09/05/23(Tue) 20:02, Kurt Miller wrote:
 While building devel/jdk/1.8 on May 3rd snapshot I noticed the build 
 freezing
 and processes getting stuck like ps. After enabling ddb.console I was able 
 to
 reproduce the livelock and capture cpu traces. Dmesg at the end.
 Let me know if more information is needed as this appears to be rather
 reproducible on my T4-1.
>>> 
>>> It seems that all CPUs are waiting for the KERNEL_LOCK().  Doing ps /o
>>> in ddb(4) should show us which CPU is currently holding it.  I can't
>>> figure it out just by looking at the traces below.
>>> 

I finally got the deadlock to reproduce and not have ddbcpu panic while printing
traces. It took many tries as most result in ether ddbcpu panic or freezing. The
deadlock is easy to reproduce but getting ddb info cleanly is not. I’m leaving
it in ddb in case you want additional information.

This is with the May 16th snapshot. ps output and dmesg at the end.

login: Stopped at  db_enter+0x8:   nop
ddb{0}> tr
vcons_softintr(400151b8a00, 1ccb300, 20, 400e268c690, 1395360, 6) at 
vcons_softintr+0x3c
intr_handler(2017ec8, 400151afa00, 5a3f33f, 1c9bc20, 0, ac) at intr_handler+0x50
sparc_intr_retry(0, 0, 197bfc8, 2ad7bb92cc, 1c00, 12) at sparc_intr_retry+0x5c
cpu_idle_cycle(1ccb2e0, 2018000, 198d270, 1c9bc20, 0, 19a7d40) at 
cpu_idle_cycle+0x2c
sched_idle(2018360, 4001516adc0, 197bfc8, 0, 0, 3b9ac800) at sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{0}> machine ddbcpu 0x1
Stopped at  __mp_lock+0x68: ld  [%o0 + 0x800], %g1
ddb{1}> bt
rw_enter(400e2688a50, 19a7d40, 1cb1000, 0, 1c0b000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e273bcd0, 400e273bd08, 400e273bbd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(400e268c690, 400e273bd08, 400e273bbd0, 0, 1c0c000, 1c9d1f0) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e273bcd0, 0, 400e268c690, 1395360, 2) at uvm_fault+0x1bc
text_access_fault(400e273bed0, 9, 2b53146f7d, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(2b6d1309e0, 52a, 2ad7bb92c8, 2ad7bb92cc, 0, 2b) at 
sun4v_texttrap+0x1fc
ddb{1}> machine ddbcpu 0x2
Stopped at  __mp_lock+0x64: nop
ddb{2}> bt
rw_enter(400e2688a50, 19a7d40, 1cb1000, 0, 1c0b000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e3373cd0, 400e3373d08, 400e3373bd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(400e268c690, 400e3373d08, 400e3373bd0, 0, 1c0c000, 1c9d1f0) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e3373cd0, 0, 400e268c690, 1395360, 2) at uvm_fault+0x1bc
text_access_fault(400e3373ed0, 9, 2b53146f7d, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(2b6d1309e0, 52a, 2ad7bb92c8, 2ad7bb92cc, 0, 2b) at 
sun4v_texttrap+0x1fc
ddb{2}> machine ddbcpu 0x3
Stopped at  __mp_lock+0x64: nop
ddb{3}> bt
uvm_fault_lower(0, 400e273fd08, 40010e77cd0, 40010e77d18, 1c0c000, 1c9d1f0) at 
uvm_fault_lower+0x880
uvm_fault(0, 400e273fcd0, 0, 400e268c690, 1395360, 2) at uvm_fault+0x1bc
text_access_fault(400e273fed0, 9, 2b53146f7d, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(2b6d1309e0, 52a, 2ad7bb92c8, 2ad7bb92cc, 0, 2b) at 
sun4v_texttrap+0x1fc
ddb{3}> machine ddbcpu 0x4
Stopped at  __mp_lock+0x68: ld  [%o0 + 0x800], %g1
ddb{4}> bt
rw_enter(400e2688a50, 19a7d40, 1cb1000, 0, 1c0b000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e3343cd0, 400e3343d08, 400e3343bd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(400e268c690, 400e3343d08, 400e3343bd0, 0, 1c0c000, 1c9d1f0) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e3343cd0, 0, 400e268c690, 1395360, 2) at uvm_fault+0x1bc
text_access_fault(400e3343ed0, 9, 2b53146f7d, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(2b6d1309e0, 52a, 2ad7bb92c8, 2ad7bb92cc, 0, 2b) at 
sun4v_texttrap+0x1fc
ddb{4}> machine ddbcpu 0x5
Stopped at  __mp_lock+0x64: nop
ddb{5}> bt
mi_switch(1, 400e09c8000, 1998ee0, 0, 0, 19a7d40) at mi_switch+0x2ac
sleep_finish(0, 1, 20, 194f978, 0, 0) at sleep_finish+0x16c
rw_enter(400e2688a50, 19a7d40, 1cb1000, 0, 1c0b000, 0) at rw_enter+0x21c
uvm_fault_lower_lookup(400e3357cd0, 400e3357d08, 400e3357bd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(400e268c690, 400e3357d08, 400e3357bd0, 0, 1c0c000, 1c9d1f0) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e3357cd0, 0, 400e268c690, 1395360, 2) at uvm_fault+0x1bc
text_access_fault(400e3357ed0, 9, 2b53146f7d, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(2b6d1309e0, 52a, 2ad7bb92c8, 2ad7bb92cc, 0, 2b) at 
sun4v_texttrap+0x1fc
ddb{5}> machine ddbcpu 0x6
Stopped at  __mp_lock+0x70: bne,pt  __mp_lock+0x5c
ddb{6}> bt
rw_enter(400e2688a50, 19a7d40, 1cb1000, 0, 1c0b000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e3313cd0, 400e3313d08, 400e3313bd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(400e268c690, 400e3313d08, 400e3313bd0, 0, 

Re: Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

On May 13, 2023, at 9:16 AM, Kurt Miller  wrote:
> 
> On May 12, 2023, at 10:26 AM, Martin Pieuchot  wrote:
>> 
>> On 09/05/23(Tue) 20:02, Kurt Miller wrote:
>>> While building devel/jdk/1.8 on May 3rd snapshot I noticed the build 
>>> freezing
>>> and processes getting stuck like ps. After enabling ddb.console I was able 
>>> to
>>> reproduce the livelock and capture cpu traces. Dmesg at the end.
>>> Let me know if more information is needed as this appears to be rather
>>> reproducible on my T4-1.
>> 
>> It seems that all CPUs are waiting for the KERNEL_LOCK().  Doing ps /o
>> in ddb(4) should show us which CPU is currently holding it.  I can't
>> figure it out just by looking at the traces below.
>> 

Here’s another one. Unfortunately, I got a ddb panic while switching cpus again.
This time I did the ps /o first. I can keep trying for a clean set of traces 
without
ddb panic’s if that is helpful.

login: Stopped at  db_enter+0x8:   nop
ddb{0}> ps /o
   TIDPIDUID PRFLAGS PFLAGS  CPU  COMMAND
284507  78236 550x23  0x400   26  java
278836  78236 550x23  0x400   32  java
481738  78236 550x23  0x400   30  java
448486  78236 550x23  0x400   25  java
 31673  78236 550x23  0x400   15  java
354968  78236 550x23  0x4009  java
244070  78236 550x23  0x400   52  java
 27520  78236 550x23  0x4005  java
160016  78236 550x23  0x400   31  java
176767  78236 550x23  0x400   16  java
107452  78236 550x23  0x400   24  java
   223  78236 550x23  0x4006  java
 57612  78236 550x23  0x4008  java
450768  78236 550x23  0x400   35  java
283448  78236 550x23  0x400   40  java
286351  78236 550x23  0x400   39  java
  1388  78236 550x23  0x4001  java
112191  78236 550x23  0x400   13  java
ddb{0}> tr
vcons_softintr(400151b8a00, 1c91a58, 20, 400e2324ff0, 1146040, 6) at 
vcons_softintr+0x3c
intr_handler(2017ec8, 400151afa00, 1edca0da, 1c8ddf0, 0, ac) at 
intr_handler+0x50
sparc_intr_retry(0, 0, 1edc7f69, 893a1a216c, 1c00, 12) at sparc_intr_retry+0x5c
cpu_idle_cycle(1c91a38, 2018000, 17fe630, 1c8ddf0, 0, 19a1530) at 
cpu_idle_cycle+0x2c
sched_idle(2018360, 4001516ab00, 17e7bd8, 0, 1c76566, 3b9ac800) at 
sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{0}> machine ddbcpu 0x1
Stopped at  __mp_lock+0x68: ld  [%o0 + 0x800], %g1
ddb{1}> bt
rw_enter(400e239b8e0, 19a1530, 1cd1000, 0, 1c0c000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e247dcd0, 400e247dd08, 400e247dbd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(400e2324ff0, 400e247dd08, 400e247dbd0, 0, 1c02000, 1c80230) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e247dcd0, 0, 400e2324ff0, 1146040, 1) at uvm_fault+0x1bc
text_access_fault(400e247ded0, 9, 88ce3e62ac, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(898179b060, 52a, 893a1a2168, 893a1a216c, 0, 2b) at 
sun4v_texttrap+0x1fc
ddb{1}> machine ddbcpu 0x2
Sptanoippced:att ra p  t yp e  0x 14 7  ( *t  r a  p  )  :p  c  =  1  6 
 6 8  a  e  c__ m p_ lo ck +0 x 68 : l d  [ %o 0  + 
 0 x8 00 ],   %g 1
  TI D  P IDn p  c  =  1  6U6ID8  a  f  0p  sPRtFLaAGtSe  =  8  2  
0 0  0PF6LAOM
ND  
MA
284507  78236 550x23  0x400   26  java
278836  78236 550x23  0x400   32  java
481738  78236 550x23  0x400   30  java
448486  78236 550x23  0x400   25  java
 31673  78236 550x23  0x400   15  java
354968  78236 550x23  0x4009  java
244070  78236 550x23  0x400   52  java
 27520  78236 550x23  0x4005  java
160016  78236 550x23  0x400   31  java
176767  78236 550x23  0x400   16  java
107452  78236 550x23  0x400   24  java
   223  78236 550x23  0x4006  java
 57612  78236 550x23  0x4008  java
450768  78236 550x23  0x400   35  java
283448  78236 550x23  0x400   40  java
286351  78236 550x23  0x400   39  java
  1388  78236 550x23  0x4001  java
112191  78236 550x23  0x400   13  java
mi_switch(1c88c98, 400e0728000, 17fe630, 1c8ddf0, 400e0db5204, 19a1530) at 
mi_switch+0x2ac
sched_idle(400e0728360, 4001515db90, 17e7bd8, 400151269f0, 0, 3b9ac800) at 
sched_idle+0x250
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
https://www.openbsd.org/ddb.html describes the minimum info required in bug
reports.  Insufficient info makes it difficult to find and fix bugs.
ddb{2}> bt
mi_switch(1c88c98, 400e0728000, 17fe630, 

Re: Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

On May 13, 2023, at 9:16 AM, Kurt Miller  wrote:
> 
> On May 12, 2023, at 10:26 AM, Martin Pieuchot  wrote:
>> 
>> On 09/05/23(Tue) 20:02, Kurt Miller wrote:
>>> While building devel/jdk/1.8 on May 3rd snapshot I noticed the build 
>>> freezing
>>> and processes getting stuck like ps. After enabling ddb.console I was able 
>>> to
>>> reproduce the livelock and capture cpu traces. Dmesg at the end.
>>> Let me know if more information is needed as this appears to be rather
>>> reproducible on my T4-1.
>> 
>> It seems that all CPUs are waiting for the KERNEL_LOCK().  Doing ps /o
>> in ddb(4) should show us which CPU is currently holding it.  I can't
>> figure it out just by looking at the traces below.
>> 

Here’s another one. Unfortunately, I got a ddb panic while switching cpus again.
This time I did the ps /o first. I can keep trying for a clean set of traces 
without
ddb panic’s if that is helpful.

login: Stopped at  db_enter+0x8:   nop
ddb{0}> ps /o
TIDPIDUID PRFLAGS PFLAGS  CPU  COMMAND
 284507  78236 550x23  0x400   26  java
 278836  78236 550x23  0x400   32  java
 481738  78236 550x23  0x400   30  java
 448486  78236 550x23  0x400   25  java
  31673  78236 550x23  0x400   15  java
 354968  78236 550x23  0x4009  java
 244070  78236 550x23  0x400   52  java
  27520  78236 550x23  0x4005  java
 160016  78236 550x23  0x400   31  java
 176767  78236 550x23  0x400   16  java
 107452  78236 550x23  0x400   24  java
223  78236 550x23  0x4006  java
  57612  78236 550x23  0x4008  java
 450768  78236 550x23  0x400   35  java
 283448  78236 550x23  0x400   40  java
 286351  78236 550x23  0x400   39  java
   1388  78236 550x23  0x4001  java
 112191  78236 550x23  0x400   13  java
ddb{0}> tr
vcons_softintr(400151b8a00, 1c91a58, 20, 400e2324ff0, 1146040, 6) at 
vcons_softintr+0x3c
intr_handler(2017ec8, 400151afa00, 1edca0da, 1c8ddf0, 0, ac) at 
intr_handler+0x50
sparc_intr_retry(0, 0, 1edc7f69, 893a1a216c, 1c00, 12) at sparc_intr_retry+0x5c
cpu_idle_cycle(1c91a38, 2018000, 17fe630, 1c8ddf0, 0, 19a1530) at 
cpu_idle_cycle+0x2c
sched_idle(2018360, 4001516ab00, 17e7bd8, 0, 1c76566, 3b9ac800) at 
sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{0}> machine ddbcpu 0x1
Stopped at  __mp_lock+0x68: ld  [%o0 + 0x800], %g1
ddb{1}> bt
rw_enter(400e239b8e0, 19a1530, 1cd1000, 0, 1c0c000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e247dcd0, 400e247dd08, 400e247dbd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(400e2324ff0, 400e247dd08, 400e247dbd0, 0, 1c02000, 1c80230) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e247dcd0, 0, 400e2324ff0, 1146040, 1) at uvm_fault+0x1bc
text_access_fault(400e247ded0, 9, 88ce3e62ac, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(898179b060, 52a, 893a1a2168, 893a1a216c, 0, 2b) at 
sun4v_texttrap+0x1fc
ddb{1}> machine ddbcpu 0x2
Sptanoippced:att ra p  t yp e  0x 14 7  ( *t  r a  p  )  :p  c  =  1  6 
 6 8  a  e  c__ m p_ lo ck +0 x 68 : l d  [ %o 0  + 
 0 x8 00 ],   %g 1
   TI D  P IDn p  c  =  1  6U6ID8  a  f  0p  sPRtFLaAGtSe  =  8  2  
0 0  0PF6LAOM
ND  
MA
 284507  78236 550x23  0x400   26  java
 278836  78236 550x23  0x400   32  java
 481738  78236 550x23  0x400   30  java
 448486  78236 550x23  0x400   25  java
  31673  78236 550x23  0x400   15  java
 354968  78236 550x23  0x4009  java
 244070  78236 550x23  0x400   52  java
  27520  78236 550x23  0x4005  java
 160016  78236 550x23  0x400   31  java
 176767  78236 550x23  0x400   16  java
 107452  78236 550x23  0x400   24  java
223  78236 550x23  0x4006  java
  57612  78236 550x23  0x4008  java
 450768  78236 550x23  0x400   35  java
 283448  78236 550x23  0x400   40  java
 286351  78236 550x23  0x400   39  java
   1388  78236 550x23  0x4001  java
 112191  78236 550x23  0x400   13  java
mi_switch(1c88c98, 400e0728000, 17fe630, 1c8ddf0, 400e0db5204, 19a1530) at 
mi_switch+0x2ac
sched_idle(400e0728360, 4001515db90, 17e7bd8, 400151269f0, 0, 3b9ac800) at 
sched_idle+0x250
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
https://www.openbsd.org/ddb.html describes the minimum info required in bug
reports.  Insufficient info makes it difficult to find and fix bugs.
ddb{2}> bt

Re: Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

On May 12, 2023, at 10:26 AM, Martin Pieuchot  wrote:
> 
> On 09/05/23(Tue) 20:02, Kurt Miller wrote:
>> While building devel/jdk/1.8 on May 3rd snapshot I noticed the build freezing
>> and processes getting stuck like ps. After enabling ddb.console I was able to
>> reproduce the livelock and capture cpu traces. Dmesg at the end.
>> Let me know if more information is needed as this appears to be rather
>> reproducible on my T4-1.
> 
> It seems that all CPUs are waiting for the KERNEL_LOCK().  Doing ps /o
> in ddb(4) should show us which CPU is currently holding it.  I can't
> figure it out just by looking at the traces below.
> 

I don’t think this will be helpful. I reproduced the deadlock with the May 10
snapshot, broke into ddb and while doing the cpu traces hit a ddb panic while
Switching to cpu 18. ps /o output at end.  I’ll try again to get a clean set of 
traces.

login: Stopped at  db_enter+0x8:   nop
ddb{0}> bt
vcons_softintr(400151b8a00, 1c940b8, 20, 400e230c870, 11b5d40, 6) at 
vcons_softintr+0x3c
intr_handler(2017ec8, 400151afa00, 2422a40a, 1c82298, 0, 6) at intr_handler+0x50
sparc_intr_retry(0, 0, 17cc340, 9e6475cc0c, 1c00, 12) at sparc_intr_retry+0x5c
cpu_idle_cycle(1c94098, 2018000, 184bdd0, 1c82298, 0, 19a6a30) at 
cpu_idle_cycle+0x2c
sched_idle(2018360, 4001516a000, 17cc340, 0, 1c56e2e, 3b9ac800) at 
sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{0}> machine ddbcpu 0x01
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{1}> bt
sched_idle(400e0718360, 4001516bb80, 17cc340, 0, 0, 3b9ac800) at 
sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{1}> machine ddbcpu 0x2
Stopped at  sun4v_send_ipi+0x88:bne,pn  sun4v_send_ipi+0x98
ddb{2}> bt
setrunnable(40014c2b6b0, 1c57ad0, 18f1a58, 3, 1f63b9, 6) at setrunnable+0xe4
wakeup_proc(1, 400e2310350, 0, 2e4, 3, 6) at wakeup_proc+0xa0
wakeup_n(400e2310350, , 0, 3ec772000, , 
1d1bf50) at wakeup_n+0x94
uvmfault_unlockall(400e5ff3cd0, 0, 400e230c870, 400e5ff3a00, 24, 4) at 
uvmfault_unlockall+0xc
uvm_fault_lower(0, 400e5ff3d08, 40010cb0510, 40010cb0558, 1c04000, 1c7b2f8) at 
uvm_fault_lower+0x880
uvm_fault(0, 400e5ff3cd0, 0, 400e230c870, 11b5d40, 1) at uvm_fault+0x1bc
text_access_fault(400e5ff3ed0, 9, 9ea37ea2e4, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(9ef623ffc0, 52a, 9e6475cc08, 9e6475cc0c, 0, 2b) at 
sun4v_texttrap+0x1fc
ddb{2}> machine ddbcpu 0x3
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{3}> bt
sched_idle(400e0738360, 4001515d350, 17cc340, 1c00, 1825df8, 3b9ac800) at 
sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{3}> machine ddbcpu 0x4
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{4}> bt
sched_idle(400e0748360, 4001515c590, 17cc340, 1c00, 1825df8, 3b9ac800) at 
sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{4}> machine ddbcpu 0x5
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{5}> bt
sched_idle(400e0758360, 4001515c010, 17cc340, 400e0f11b78, 1825df8, 3b9ac800) 
at sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{5}> machine ddbcpu 0x6
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{6}> bt
sched_idle(400e0768360, 4001515c2d0, 0, 0, 0, 0) at sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{6}> machine ddbcpu 0x7
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{7}> bt
sched_idle(400e0778360, 4001515c850, 0, 0, 0, 0) at sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{7}> machine ddbcpu 0x8
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{8}> bt
sched_idle(400e0788360, 4001515cb10, 0, 0, 0, 0) at sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{8}> machine ddbcpu 0x9
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{9}> bt
sched_idle(400e0798360, 4001515cdd0, 0, 0, 0, 0) at sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{9}> machine ddbcpu 0xa
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{10}> b
synccrash   dumphaltreboot  poweroff
ddb{10}> bt
sched_idle(400e07a8360, 4001515d090, 0, 0, 0, 0) at sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{10}> machine ddbcpu 0xb
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{11}> bt
sched_idle(400e07b8360, 4001515d610, 0, 0, 0, 0) at sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{11}> machine ddbcpu 0xc
Stopped at  cpu_idle_cycle+0x44:and %g1, -0x3, %g1
ddb{12}> bt
sched_idle(400e07c8360, 4001515db90, 0, 0, 0, 0) at sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{12}> 

Re: Sparc64 livelock/system freeze w/cpu traces

[Martin Pieuchot]

On 09/05/23(Tue) 20:02, Kurt Miller wrote:
> While building devel/jdk/1.8 on May 3rd snapshot I noticed the build freezing
> and processes getting stuck like ps. After enabling ddb.console I was able to
> reproduce the livelock and capture cpu traces. Dmesg at the end.
> Let me know if more information is needed as this appears to be rather
> reproducible on my T4-1.

It seems that all CPUs are waiting for the KERNEL_LOCK().  Doing ps /o
in ddb(4) should show us which CPU is currently holding it.  I can't
figure it out just by looking at the traces below.

> Cpu traces for cpus 0-63 done in order, however I moved the less interesting
> ones down below the traces with more meaningful traces.
> 
> Stopped at  __mp_lock+0x70: bne,pt  __mp_lock+0x5c
> ddb{0}> bt
> task_add(1, 4001528d490, 1, 0, 1c00, 1ccdbf8) at task_add+0x6c
> ifiq_input(4001528d450, 20172b0, 400151c3380, 0, 1000, 1) at ifiq_input+0x1d0
> em_rxeof(40015292200, 59, 4001528d66c, 20172b0, 19a07c0, ff00) at 
> em_rxeof+0x2b4
> em_intr(0, 2, 40015297c00, 4, 40015297c20, 0) at em_intr+0xc4
> intr_handler(2017530, 400151c1100, 4d63d37, 0, 14ec228, ac) at 
> intr_handler+0x50
> sparc_intr_retry(1c1c158, 2017d2c, 400151afa00, 10, 400151afa20, 0) at 
> sparc_intr_retry+0x5c
> db_enter_ddb(1ca6000, 1ca6798, 130, 0, 0, 19a07c0) at db_enter_ddb+0xbc
> db_ktrap(101, 20179a8, 18a1420, 0, 1c75b66, 3b9ac800) at db_ktrap+0x104
> trap(20179a8, 101, 14ec224, 820006, 1c00, 1ccdbf8) at trap+0x2cc
> Lslowtrap_reenter(0, , 2017c58, 4, 0, 60) at 
> Lslowtrap_reenter+0xf8
> vcons_cnlookc(0, 2017d2c, 400151afa00, 10, 400151afa20, 0) at 
> vcons_cnlookc+0x84
> vcons_softintr(400151b8a00, 1c7e548, 20, 1, 40015297c20, 6) at 
> vcons_softintr+0x3c
> intr_handler(2017ec8, 400151afa00, 4c2210e, 1c7b3e8, 0, 6) at 
> intr_handler+0x50
> sparc_intr_retry(0, 0, 18a1420, a855edc1cc, 1c00, 12) at sparc_intr_retry+0x5c
> cpu_idle_cycle(1c7e528, 2018000, 1793b58, 1c7b3e8, 0, 19a07c0) at 
> cpu_idle_cycle+0x2c
> sched_idle(2018360, 4001516b600, 18a1420, 0, 1c75b66, 3b9ac800) at 
> sched_idle+0x158
> proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
> ddb{0}> machine ddbcpu 1
> Stopped at  __mp_lock+0x6c: subcc   %g3, %g1, %g0
> ddb{1}> bt
> rw_enter(40013cdaf00, 19a07c0, 1c7f000, 0, 1c04000, 0) at rw_enter+0x1fc
> uvm_fault_lower_lookup(400e2c09cd0, 400e2c09d08, 400e2c09bd0, 0, 0, 4) at 
> uvm_fault_lower_lookup+0x2c
> uvm_fault_lower(40013ccd180, 400e2c09d08, 400e2c09bd0, 0, 1c1d000, 1ca88d0) 
> at uvm_fault_lower+0x3c
> uvm_fault(0, 400e2c09cd0, 0, 40013ccd180, 11f9be0, 1) at uvm_fault+0x1bc
> text_access_fault(400e2c09ed0, 9, a860ee37d0, 0, 0, 0) at 
> text_access_fault+0x114
> sun4v_texttrap(a8a09a5120, 52a, a855edc1c8, a855edc1cc, 0, 2b) at 
> sun4v_texttrap+0x1fc
> ddb{1}> machine ddbcpu 2
> Stopped at  __mp_lock+0x68: ld  [%o0 + 0x800], %g1
> ddb{2}> bt
> rw_enter(40013cdaf00, 19a07c0, 1c7f000, 0, 1c04000, 0) at rw_enter+0x1fc
> uvm_fault_lower_lookup(400e2c2dcd0, 400e2c2dd08, 400e2c2dbd0, 0, 0, 4) at 
> uvm_fault_lower_lookup+0x2c
> uvm_fault_lower(40013ccd180, 400e2c2dd08, 400e2c2dbd0, 0, 1c1d000, 1ca88d0) 
> at uvm_fault_lower+0x3c
> uvm_fault(0, 400e2c2dcd0, 0, 40013ccd180, 11f9be0, 1) at uvm_fault+0x1bc
> text_access_fault(400e2c2ded0, 9, a860ee37d0, 0, 0, 0) at 
> text_access_fault+0x114
> sun4v_texttrap(a8a09a5120, 52a, a855edc1c8, a855edc1cc, 0, 19a07c0) at 
> sun4v_texttrap+0x1fc
> ddb{2}> machine ddbcpu 0x3
> Stopped at  __mp_lock+0x68: ld  [%o0 + 0x800], %g1
> ddb{3}> bt
> mi_switch(1, 400e0968000, 18dc7e0, 0, 0, 19a07c0) at mi_switch+0x2ac
> sleep_finish(0, 1, 20, 1917b80, 0, 0) at sleep_finish+0x16c
> rw_enter(40013cdaf00, 19a07c0, 1c7f000, 0, 1c04000, 0) at rw_enter+0x21c
> uvm_fault_lower_lookup(400e2b75cd0, 400e2b75d08, 400e2b75bd0, 0, 0, 4) at 
> uvm_fault_lower_lookup+0x2c
> uvm_fault_lower(40013ccd180, 400e2b75d08, 400e2b75bd0, 0, 1c1d000, 1ca88d0) 
> at uvm_fault_lower+0x3c
> uvm_fault(0, 400e2b75cd0, 0, 40013ccd180, 11f9be0, 1) at uvm_fault+0x1bc
> text_access_fault(400e2b75ed0, 9, a860ee37d0, 0, 0, 0) at 
> text_access_fault+0x114
> sun4v_texttrap(a8a09a5120, 52a, a855edc1c8, a855edc1cc, 0, 19a07c0) at 
> sun4v_texttrap+0x1fc
> ddb{3}> machine ddbcpu 0x4
> Stopped at  __mp_lock+0x6c: subcc   %g3, %g1, %g0
> ddb{4}> bt
> rw_enter(40013cdaf00, 19a07c0, 1c7f000, 0, 1c04000, 0) at rw_enter+0x1fc
> uvm_fault_lower_lookup(400e2a09cd0, 400e2a09d08, 400e2a09bd0, 0, 0, 4) at 
> uvm_fault_lower_lookup+0x2c
> uvm_fault_lower(40013ccd180, 400e2a09d08, 400e2a09bd0, 0, 1c1d000, 1ca88d0) 
> at uvm_fault_lower+0x3c
> uvm_fault(0, 400e2a09cd0, 0, 40013ccd180, 11f9be0, 1) at uvm_fault+0x1bc
> text_access_fault(400e2a09ed0, 9, a860ee37d0, 0, 0, 0) at 
> text_access_fault+0x114
> sun4v_texttrap(a8a09a5120, 52a, a855edc1c8, a855edc1cc, 0, 19a07c0) at 
> sun4v_texttrap+0x1fc
> ddb{6}> machine ddbcpu 0x7
> Stopped at  __mp_lock+0x64: nop
> ddb{7}> bt
> rw_enter(40013cdaf00, 19a07c0, 

Sparc64 livelock/system freeze w/cpu traces

[Kurt Miller]

While building devel/jdk/1.8 on May 3rd snapshot I noticed the build freezing
and processes getting stuck like ps. After enabling ddb.console I was able to
reproduce the livelock and capture cpu traces. Dmesg at the end.
Let me know if more information is needed as this appears to be rather
reproducible on my T4-1.

Cpu traces for cpus 0-63 done in order, however I moved the less interesting
ones down below the traces with more meaningful traces.

Stopped at  __mp_lock+0x70: bne,pt  __mp_lock+0x5c
ddb{0}> bt
task_add(1, 4001528d490, 1, 0, 1c00, 1ccdbf8) at task_add+0x6c
ifiq_input(4001528d450, 20172b0, 400151c3380, 0, 1000, 1) at ifiq_input+0x1d0
em_rxeof(40015292200, 59, 4001528d66c, 20172b0, 19a07c0, ff00) at em_rxeof+0x2b4
em_intr(0, 2, 40015297c00, 4, 40015297c20, 0) at em_intr+0xc4
intr_handler(2017530, 400151c1100, 4d63d37, 0, 14ec228, ac) at intr_handler+0x50
sparc_intr_retry(1c1c158, 2017d2c, 400151afa00, 10, 400151afa20, 0) at 
sparc_intr_retry+0x5c
db_enter_ddb(1ca6000, 1ca6798, 130, 0, 0, 19a07c0) at db_enter_ddb+0xbc
db_ktrap(101, 20179a8, 18a1420, 0, 1c75b66, 3b9ac800) at db_ktrap+0x104
trap(20179a8, 101, 14ec224, 820006, 1c00, 1ccdbf8) at trap+0x2cc
Lslowtrap_reenter(0, , 2017c58, 4, 0, 60) at 
Lslowtrap_reenter+0xf8
vcons_cnlookc(0, 2017d2c, 400151afa00, 10, 400151afa20, 0) at vcons_cnlookc+0x84
vcons_softintr(400151b8a00, 1c7e548, 20, 1, 40015297c20, 6) at 
vcons_softintr+0x3c
intr_handler(2017ec8, 400151afa00, 4c2210e, 1c7b3e8, 0, 6) at intr_handler+0x50
sparc_intr_retry(0, 0, 18a1420, a855edc1cc, 1c00, 12) at sparc_intr_retry+0x5c
cpu_idle_cycle(1c7e528, 2018000, 1793b58, 1c7b3e8, 0, 19a07c0) at 
cpu_idle_cycle+0x2c
sched_idle(2018360, 4001516b600, 18a1420, 0, 1c75b66, 3b9ac800) at 
sched_idle+0x158
proc_trampoline(0, 0, 0, 0, 0, 0) at proc_trampoline+0x14
ddb{0}> machine ddbcpu 1
Stopped at  __mp_lock+0x6c: subcc   %g3, %g1, %g0
ddb{1}> bt
rw_enter(40013cdaf00, 19a07c0, 1c7f000, 0, 1c04000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e2c09cd0, 400e2c09d08, 400e2c09bd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(40013ccd180, 400e2c09d08, 400e2c09bd0, 0, 1c1d000, 1ca88d0) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e2c09cd0, 0, 40013ccd180, 11f9be0, 1) at uvm_fault+0x1bc
text_access_fault(400e2c09ed0, 9, a860ee37d0, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(a8a09a5120, 52a, a855edc1c8, a855edc1cc, 0, 2b) at 
sun4v_texttrap+0x1fc
ddb{1}> machine ddbcpu 2
Stopped at  __mp_lock+0x68: ld  [%o0 + 0x800], %g1
ddb{2}> bt
rw_enter(40013cdaf00, 19a07c0, 1c7f000, 0, 1c04000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e2c2dcd0, 400e2c2dd08, 400e2c2dbd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(40013ccd180, 400e2c2dd08, 400e2c2dbd0, 0, 1c1d000, 1ca88d0) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e2c2dcd0, 0, 40013ccd180, 11f9be0, 1) at uvm_fault+0x1bc
text_access_fault(400e2c2ded0, 9, a860ee37d0, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(a8a09a5120, 52a, a855edc1c8, a855edc1cc, 0, 19a07c0) at 
sun4v_texttrap+0x1fc
ddb{2}> machine ddbcpu 0x3
Stopped at  __mp_lock+0x68: ld  [%o0 + 0x800], %g1
ddb{3}> bt
mi_switch(1, 400e0968000, 18dc7e0, 0, 0, 19a07c0) at mi_switch+0x2ac
sleep_finish(0, 1, 20, 1917b80, 0, 0) at sleep_finish+0x16c
rw_enter(40013cdaf00, 19a07c0, 1c7f000, 0, 1c04000, 0) at rw_enter+0x21c
uvm_fault_lower_lookup(400e2b75cd0, 400e2b75d08, 400e2b75bd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(40013ccd180, 400e2b75d08, 400e2b75bd0, 0, 1c1d000, 1ca88d0) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e2b75cd0, 0, 40013ccd180, 11f9be0, 1) at uvm_fault+0x1bc
text_access_fault(400e2b75ed0, 9, a860ee37d0, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(a8a09a5120, 52a, a855edc1c8, a855edc1cc, 0, 19a07c0) at 
sun4v_texttrap+0x1fc
ddb{3}> machine ddbcpu 0x4
Stopped at  __mp_lock+0x6c: subcc   %g3, %g1, %g0
ddb{4}> bt
rw_enter(40013cdaf00, 19a07c0, 1c7f000, 0, 1c04000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e2a09cd0, 400e2a09d08, 400e2a09bd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(40013ccd180, 400e2a09d08, 400e2a09bd0, 0, 1c1d000, 1ca88d0) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e2a09cd0, 0, 40013ccd180, 11f9be0, 1) at uvm_fault+0x1bc
text_access_fault(400e2a09ed0, 9, a860ee37d0, 0, 0, 0) at 
text_access_fault+0x114
sun4v_texttrap(a8a09a5120, 52a, a855edc1c8, a855edc1cc, 0, 19a07c0) at 
sun4v_texttrap+0x1fc
ddb{6}> machine ddbcpu 0x7
Stopped at  __mp_lock+0x64: nop
ddb{7}> bt
rw_enter(40013cdaf00, 19a07c0, 1c7f000, 0, 1c04000, 0) at rw_enter+0x1fc
uvm_fault_lower_lookup(400e2bfdcd0, 400e2bfdd08, 400e2bfdbd0, 0, 0, 4) at 
uvm_fault_lower_lookup+0x2c
uvm_fault_lower(40013ccd180, 400e2bfdd08, 400e2bfdbd0, 0, 1c1d000, 1ca88d0) at 
uvm_fault_lower+0x3c
uvm_fault(0, 400e2bfdcd0, 0, 40013ccd180, 11f9be0, 1) at uvm_fault+0x1bc
text_access_fault(400e2bfded0, 9, a860ee37d0, 0, 0, 0) at 
text_access_fault+0x114