Bug 446397

------- Comment From ankigarg.com 2008-05-15 01:55 EDT-------
As discussed with Sripathi, will spend sometime on this bug today.

------- Comment From ankigarg.com 2008-05-15 07:11 EDT-------
I see the issue even with the latest -54 based MRG kernel (this does not have
the fastgup patches).

------- Comment From ankigarg.com 2008-05-15 07:13 EDT-------
#strace -p<process id>
.....
clone(child_stack=0xe33c84b4,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
parent_tidptr=0xe33c8bd8, tls=0xe33c8bd8, child_tidptr=0xfff76a78) = 6399
sched_setscheduler(6399, SCHED_FIFO, { 43 }) = 0
futex(0xe33c8d80, FUTEX_WAKE, 1)        = 1
futex(0x872a04c, FUTEX_WAKE, 2147483647) = 1
futex(0x872a078, FUTEX_UNLOCK_PI, 1162915828) = 0
futex(0x870b890, FUTEX_UNLOCK_PI, 1162915828) = 0
gettimeofday({1210849492, 560610}, {0, 0}) = 0
gettimeofday({1210849492, 560873}, {0, 0}) = 0
gettimeofday({1210849492, 561037}, {0, 0}) = 0
gettimeofday({1210849492, 561177}, NULL) = 0
gettimeofday({1210849492, 561324}, {0, 0}) = 0
gettimeofday({1210849492, 561463}, {0, 0}) = 0
gettimeofday({1210849492, 561607}, {0, 0}) = 0
gettimeofday({1210849492, 561853}, {0, 0}) = 0
gettimeofday({1210849492, 562013}, {0, 0}) = 0
gettimeofday({1210849492, 562162}, {0, 0}) = 0
futex(0x805e3b8, FUTEX_WAIT, 1, NULL)   = 0
futex(0x805e39c, FUTEX_UNLOCK_PI, 1162915828) = 0
futex(0x805e3b8, FUTEX_WAIT, 3, NULL

------- Comment From sripathi.com 2008-05-15 08:25 EDT-------
I attached gdb to the java process when it is hung, but I could not get much
information from it. strace output makes most sense only when it is captured
right from the beginning. I am running the test with strace, but the problem
hasn't recreated with strace so far.

------- Comment From sripathi.com 2008-05-15 08:32 EDT-------
When run with strace, I often hit OutOfMemoryError from Java before I can
confirm that the problem has occurred. This test is sensitive to timings and
strace may be making some GC calculations go awry.

------- Comment From sripathi.com 2008-05-15 12:36 EDT-------
I used a brute force method to find out which patches were causing the problem.
I started off the 2.6.24.7-54.el5rt kernel and started removing bunches of
patches from the end. With this approach, the hang seems to go away when I
remove the rwlockmulti patches:

ApplyPatch rwlockmulti-001-rwsems-framework.patch
ApplyPatch rwlockmulti-002-rwlocks-management.patch
ApplyPatch rwlockmulti-003-map-tasks-to-reader-locks.patch
ApplyPatch rwlockmulti-004-reader-limit-on-rwlocks.patch
ApplyPatch rwlockmulti-005-map-rwlocks-back-to-readers.patch
ApplyPatch rwlockmulti-006-rwlock_pi_implementation.patch

The test gives OutOfMemoryErrors in some of the runs, but at least the hang I
see with the default kernel is gone.

------- Comment From sripathi.com 2008-05-15 12:39 EDT-------
Running the test overnight to confirm.

------- Comment From jstultz.com 2008-05-15 17:59 EDT-------
I spoke with Steven and he suspects the rwlock changes are just making a
pre-existing issue more visible, not actually the cause of the issue itself.

I added some debug checks in the futex_wake and futex_unlock_pi paths, and I'm
seeing futex_unlock_pi return -EPERM right as the hang happens, from the line:

if ((uval & FUTEX_TID_MASK) != task_pid_vnr(current))

Need to dig a bit more.

------- Comment From jstultz.com 2008-05-15 20:39 EDT-------
It seems uval is null in the line from comment #19. I verified it was not being
set to null later in the code and then hitting this again via the retry loop, so
it seems that the previous get_user() call is claiming the value at the uaddr
address (I can trigger this easily, and the uaddr address changes between tries)
is zero.

I've added a fair amount of debug code trying to catch any early exits from
futex_lock_pi as well as wake/wait, but this is the only error message I get.

------- Comment From sripathi.com 2008-05-16 02:43 EDT-------
(In reply to comment #19)
> I spoke with Steven and he suspects the rwlock changes are just making a
> pre-existing issue more visible, not actually the cause of the issue itself.

The test ran to completion overnight. It again started running fine today.
However, I will believe Steven and not poke at rwlock changes much.

------- Comment From jstultz.com 2008-05-16 15:29 EDT-------
Today I ran just a 2.6.24.4-rt4 kernel and I also saw the -EPERM on
futex_unlock_pi, however the test case did not hang. So I'm guessing the null
uval issue isn't what we're chasing here.

------- Comment From jstultz.com 2008-05-16 18:52 EDT-------
I've isolated the hang I'm seeing down to just the
rwlockmulti-006-rwlock_pi_implementation.patch patch. Still trying to see how
that connects, but hopefully it gives some extra insight.

------- Comment From jstultz.com 2008-05-16 19:56 EDT-------
So setting the /proc/sys/kernel/rwlock_reader_limit value to 1 seems to avoid
the hang I'm seeing.

------- Comment From jstultz.com 2008-05-16 20:05 EDT-------
One interesting fact of the test I'm using that triggers this hang, it is about
13 threads that are all affined to one cpu.

------- Comment From jstultz.com 2008-05-21 18:05 EDT-------
Another intersting point. If I run a different non-sharable test with taskset -c
0, the test hangs as well.

This links the rwlock pi functionality with rt threads bound to one cpu, as a
core part of the issue.

------- Comment From jstultz.com 2008-05-21 18:07 EDT-------
We've talked w/ the JTC and will be sharing a link to the JVM with Clark (on the
RH-IBM realtime list). We cannot share the test cases that so far trigger this
issue, but I'm working to see if other public java tests might trigger this issue.

------- Comment From sripathi.com 2008-05-22 05:37 EDT-------
I tried RH's latest kernel (2.6.24.7-57.el5rt). The hang is still present.
Workaround is to set /proc/sys/kernel/rwlock_reader_limit to 1.

elevating to blocker status and assigning srostedt

------- Comment From sripathi.com 2008-05-26 02:27 EDT-------
I have run our Java latency benchmark with /proc/sys/kernel/rwlock_reader_limit
set to 1. I saw that the number of failures in this test increase, compared to
rwlock_reader_limit being set to 64. I will look for a C testcase that can
demonstrate similar results. Hence, it looks like setting rwlock_reader_limit to
1 is not a viable long term solution for us. We will have to fix the hang
problem that we have seen.

------- Comment From sripathi.com 2008-05-26 13:07 EDT-------
I have been trying to understand the cause of the hang. I have looked at the
threads of the java process when it is hung and tried to understand what is
going on. However, I have been quite confused about it so far.

When the hang occurs, I see a bunch of java threads running. Attaching gdb to it
and obtaining the backtraces, I see 2 threads in sem_wait(), a number of them in
pthread_cond_wait() and a couple of them doing sleep() or yield, which I presume
means they are waiting for other threads to complete. It is a bit more difficult
to obtain the futex addresses, because I can't see function variables in
libpthread in spite of installing glibc-debuginfo.

From the kernel side, I see some threds stuck at

[<ffffffff8105e21d>] ? rt_mutex_adjust_prio+0x35/0x3e

and some at

[<ffffffff8105a827>] ? get_futex_key+0x8a/0x15c

I will investigate this a bit more and attach the backtraces to this bug.

------- Comment From sripathi.com 2008-05-26 13:29 EDT-------
I see a few Java threads with the kernel backtrace (using sysrq-t) like the
following:

java          S [ffff8102230c2140] ffff8102230d5c90     0  6952   6744
ffff8102230d5c48 0000000000000082 ffffe2000c93e0a0 ffff81022f1861c0
0000000000001b23 0000000000000000 ffff8102230c2140 ffff810217d294c0
ffff8102230c2480 0000000108114000 ffff8102230d5cf0 ffff81022e681540
Call Trace:
[<ffffffff8105a827>] ? get_futex_key+0x8a/0x15c
[<ffffffff812876cd>] schedule+0xdf/0xff
[<ffffffff8105ac0b>] futex_wait+0x207/0x34d
[<ffffffff81033088>] ? try_to_wake_up+0x1d7/0x1e8
[<ffffffff8105d9a6>] ? __rt_mutex_adjust_prio+0x11/0x25
[<ffffffff81033099>] ? default_wake_function+0x0/0x14
[<ffffffff8105be8e>] do_futex+0x85/0xb42
[<ffffffff810a853d>] ? __cache_free+0x3b/0x1f3
[<ffffffff810a888a>] ? kmem_cache_free+0x63/0x70
[<ffffffff8105cedd>] compat_sys_futex+0xed/0x10b
[<ffffffff8100f855>] ? syscall_trace_enter+0xb7/0xbb
[<ffffffff81027a94>] cstar_do_call+0x1b/0x65

get_futex_key+0x8a is the place we return to from find_extend_vma.

ffffffff8105a81c:       48 89 de                mov    %rbx,%rsi
ffffffff8105a81f:       4c 89 ef                mov    %r13,%rdi
ffffffff8105a822:       e8 4e cf 03 00          callq  ffffffff81097775
<find_extend_vma>
ffffffff8105a827:       48 85 c0                test   %rax,%rax
ffffffff8105a82a:       48 89 c1                mov    %rax,%rcx

If I can trust the backtrace, this would mean we never return from
find_extend_vma(). However, I don't see find_extend_vma() in the backtrace. I
will run this with CONFIG_DEBUG_VM tomorrow to see if it pops up anything.

Another interesting thread shows this backtrace:
java          S [ffff810217d4eaa0] ffff810217d4dc90     0  6799   6744
ffff810217d4dc48 0000000000000082 ffff810217d4dbe8 ffffffff8105e21d
0000000000000000 ffff810217d4f2b0 ffff810217d4eaa0 ffff810217d294c0
ffff810217d4ede0 0000000181288517 0000000000000202 ffff81022e6815a0
Call Trace:
[<ffffffff8105e21d>] ? rt_mutex_adjust_prio+0x35/0x3e
[<ffffffff812876cd>] schedule+0xdf/0xff
[<ffffffff8105ac0b>] futex_wait+0x207/0x34d
[<ffffffff81288517>] ? rt_read_slowunlock+0x32f/0x33c
[<ffffffff8105ee19>] ? rt_mutex_up_read+0x1fc/0x201
[<ffffffff8105f730>] ? rt_up_read+0x9/0xb
[<ffffffff8105b159>] ? futex_wake+0xe4/0xf6
[<ffffffff81033099>] ? default_wake_function+0x0/0x14
[<ffffffff8105be8e>] do_futex+0x85/0xb42
[<ffffffff8102fdb5>] ? pick_next_task_fair+0x2d/0x35
[<ffffffff8105cedd>] compat_sys_futex+0xed/0x10b
[<ffffffff8100f855>] ? syscall_trace_enter+0xb7/0xbb
[<ffffffff81027a94>] cstar_do_call+0x1b/0x65

rt_mutex_adjust_prio+0x35 is the place where we return from
__spin_unlock_irqrestore.

ffffffff8105e20d:       e8 83 f7 ff ff          callq  ffffffff8105d995
<__rt_mutex_adjust_prio>
ffffffff8105e212:       4c 89 e6                mov    %r12,%rsi
ffffffff8105e215:       4c 89 ef                mov    %r13,%rdi
ffffffff8105e218:       e8 18 b7 22 00          callq  ffffffff81289935
<__spin_unlock_irqrestore>
ffffffff8105e21d:       41 5b                   pop    %r11
ffffffff8105e21f:       5b                      pop    %rbx

I am unable to see the backtraces for a few threads through sysrq-t. I don't
know the reason for it.

Try using sysrq-w, as it will show you other tasks:

'w'     - Dumps tasks that are in uninterruptable (blocked) state.

From comment #16:

> pthread_cond_wait() and a couple of them doing sleep() or yield, which I presume

That "yield" scares me. That itself can cause a system hang on an RT system.
What is doing yield. Yield on RT is almost never correct.

------- Comment From sripathi.com 2008-05-27 06:14 EDT-------
(In reply to comment #40)
> ------- Comment From lgoncalv 2008-05-26 13:53 EST-------
> Try using sysrq-w, as it will show you other tasks:
>
> 'w'     - Dumps tasks that are in uninterruptable (blocked) state.

Using sysrq-w, I see that all java threads are in runnable states. Using
sysrq-t, I see that a few java threads are in 'R' state and a few others in 'S'
state. I can see the backtrace of threads in 'S' state, but I don't see the
backtrace of any of the threads in 'R' state.

------- Comment From sripathi.com 2008-05-27 06:17 EDT-------
(In reply to comment #41)
> ------- Comment From srostedt 2008-05-26 15:51 EST-------
>
> That "yield" scares me. That itself can cause a system hang on an RT system.
> What is doing yield. Yield on RT is almost never correct.

I should have made this more clear. The thread that is calling sched_yield seems
to be the main thread in Java and it is NOT an RT thread. It is just a
SCHED_OTHER thread.

Created attachment 306765 [details]
ps command output showing java threads and their priorities

Created attachment 306766 [details]
backtraces from gdb

Created attachment 306767 [details]
sysrq-t output

Created attachment 306768 [details]
sysrq-w output

------- Comment From jstultz.com 2008-05-28 20:07 EDT-------
(In reply to comment #43)
> (In reply to comment #41)
> > ------- Comment From srostedt 2008-05-26 15:51 EST-------
> >
> > That "yield" scares me. That itself can cause a system hang on an RT system.
> > What is doing yield. Yield on RT is almost never correct.
>
> I should have made this more clear. The thread that is calling sched_yield seems
> to be the main thread in Java and it is NOT an RT thread. It is just a
> SCHED_OTHER thread.

Without reading Sripathi's comments (wasn't subscribed to the bug) I've been
duplicating much of his work. I too have found from the sysrq-t, ps output and
strace, that the behavior seems to follow this pattern:

1) The java test case is run bound to one cpu
2) Very quickly after the jvm starts up, the test hangs
3) From top you can see the java process is 100% busy
4) From sysrq-t you can see which thread is running, hogging the cpu
5) From ps -eLo tid,rtprio,priority,comm we can see the task is priority boosted
and is at equal or greater priority then all other java threads
6) From strace -p <tid> we see a number of sched_yeilds() which sometimes never
end, and sometimes suddenly move on to other calls (possibly due interruptions
from the tracing attachment?)

I'm talking w/ the JVM folks to see where we are when we get caught in this
yield loop, and why we might be doing it.

------- Comment From jstultz.com 2008-05-28 20:46 EDT-------
Another JVM backtrace from a different test case then the one sripathi was using
that shows the running java thread which is looping on sched_yield():

(gdb) bt
#0  0xffffe425 in __kernel_vsyscall ()
#1  0x4fc24d4c in sched_yield () from /lib/libc.so.6
#2  0xf7effe64 in j9thread_yield ()
from
/home/jstultz/linux-rt-tests/internal/java/jvm/ibm-ws-rt-i386-1.0-3.0/jre/bin/realtime/libj9thr23.so
#3  0xf7abf1ec in java_lang_Thread_yield ()
from
/home/jstultz/linux-rt-tests/internal/java/jvm/ibm-ws-rt-i386-1.0-3.0/jre/bin/realtime/libjclscar_23.so
#4  0x082337a8 in ?? ()
#5  0xb93d2168 in ?? ()
#6  0xf7e465e0 in completed.1 ()
from
/home/jstultz/linux-rt-tests/internal/java/jvm/ibm-ws-rt-i386-1.0-3.0/jre/bin/realtime/libj9prt23.so
#7  0x0822ea70 in ?? ()
#8  0xb93d20c8 in ?? ()
#9  0xf7e2e2dc in j9mem_free_memory ()
from
/home/jstultz/linux-rt-tests/internal/java/jvm/ibm-ws-rt-i386-1.0-3.0/jre/bin/realtime/libj9prt23.so
#10 0xf7e8945f in javaProtectedThreadProc ()
from
/home/jstultz/linux-rt-tests/internal/java/jvm/ibm-ws-rt-i386-1.0-3.0/jre/bin/realtime/libj9vm23.so
#11 0xf7e36f99 in j9sig_protect ()
from
/home/jstultz/linux-rt-tests/internal/java/jvm/ibm-ws-rt-i386-1.0-3.0/jre/bin/realtime/libj9prt23.so
#12 0xf7e87a0d in javaThreadProc ()
from
/home/jstultz/linux-rt-tests/internal/java/jvm/ibm-ws-rt-i386-1.0-3.0/jre/bin/realtime/libj9vm23.so
#13 0xf7ada4e3 in RTjavaThreadProc ()
from
/home/jstultz/linux-rt-tests/internal/java/jvm/ibm-ws-rt-i386-1.0-3.0/jre/bin/realtime/libjclscar_23.so
#14 0xf7f004e5 in thread_wrapper ()
from
/home/jstultz/linux-rt-tests/internal/java/jvm/ibm-ws-rt-i386-1.0-3.0/jre/bin/realtime/libj9thr23.so
#15 0x4fcbf43b in start_thread () from /lib/libpthread.so.0
#16 0x4fc3ffde in clone () from /lib/libc.so.6

Can someone on the JTC side check and see if there is a j9mem_free_memory() ->
java_lang_Thread_yield() code path that could be causing this?

Would you be able to explain us the general idea of the test: a) are all the
threads running in the same priority? b) what the thread is doing when it calls
sched_yield()? Is it CPU load, I/O load? c) any other relevant details?

From what I have been reading it seems like you would be able to create a small
reproducer in Java - as you seem to have found the loop where the hangs happen.
maybe even a C reproducer.

Created attachment 307087 [details]
request for javacore

------- Comment From Sean_Foley.com 2008-05-29 13:11 EDT-------
That is a code path that is taken at initialization of the RTSJ libraries.

The yielding thread is in a loop, yielding each time it sees that certain
number of high priority threads have not been placed in a thread pool.  These
newly created threads are being created with a priority that is higher than any
user-available priority.  So the yielding thread should be prempted by these
new threads.  Either the new threads are not being created at all, or they are
not getting the CPU time they should be getting.

------- Comment From dvhltc.com 2008-05-29 14:13 EDT-------
(In reply to comment #56)
> That is a code path that is taken at initialization of the RTSJ libraries.
>
> The yielding thread is in a loop, yielding each time it sees that certain
> number of high priority threads have not been placed in a thread pool.  These
> newly created threads are being created with a priority that is higher than any
> user-available priority.  So the yielding thread should be prempted by these
> new threads.  Either the new threads are not being created at all, or they are
> not getting the CPU time they should be getting.

Are these newly created threads responsible for updating the pool that the
yielding thread is watching?  If so, is there some lock on the pool that may be
effectively boosting the yielding thread even higher?  If not, what is the
priority of the threads responsible for updating the pool.  Are there locks
involved?

I believe it was stated earlier that the yielding thread was as high or higher
than any other java thread.  If so, it will not give up the CPU as the
sched_yield is a no-op for the highest priority rt tasks on a runqueue.

Created attachment 307154 [details]
rwlock-prio-fix patch from Steven

Yay!  Here is the fix from Steven I just successfully tested w/ both our
failing test cases, and neither of them hung!

I'm going to try to merge this into our internal tree so we can get some test
cycles on it over night while we wait for it to be included into the RH tree.

------- Comment From Sean_Foley.com 2008-05-30 15:33 EDT-------
That's good news!

Regarding the use of sched_yield, I will open up a JTC defect to change the
Thread.yield/counter check to a monitor-wait/counter/notify combination, since
it is safer and also consumes less CPU time.  The defect will be assigned to
the RTSJ JCL team.

------- Comment From jstultz.com 2008-05-30 15:53 EDT-------
Tests from last night passed. Need to verify its right in -62 and I'll move this
to accepted.

------- Comment From sripathi.com 2008-06-02 08:35 EDT-------
I have tested this on the -62 kernel and found it to solve the reported problem.

closing on our side

Created attachment 308270 [details]
program which starts one realtime thread that starts others and waits for the others to run

others to run

I've created a simple test program that may be of benefit for the future.  I
have not been able to reproduce the MRG failure with this test program, because
there was something else going on in the MRG failure that cause the main thread
to run java code with its priority elevated abnormally, which I have been
unable to reproduce with this program.

However, this simple test case can reproduce the threading behaviour which
caused the deadlock in the original failure.


usage: 
ThreadDeadlock realtimeJavaPriority1 realtimeJavaPriority2 num [incrementPrio2]
[spin]

The test starts a RealtimeThread thread1 at priority realtimeJavaPriority1.
It creates num Realtime threads at priority realtimeJavaPriority2, each of
which puts itself to sleep.
The thread thread1 will run a yielding loop until it sees that all threads have
been started.
If incrementPrio2 is true, then only the first spawned thread will have
realtimeJavaPriority2, and each subsequent spawned thread will have a priority
one higher than the previous.
If spin is true, then all threads spawned by thread1 will not sleep, but will
spin in a yielding loop.

If thread1 waits too long (indicating deadlock), then the test fails, otherwise
it passes.


The usage statement will also print out a listing of mappings from java
priorities to O/S priorities.


The test case for the MRG defect is:

<i>
taskset 0x1 java -jar ThreadDeadlock.jar 20 21 1
</i>
This passes, because the spawned thread will sleep, giving CPU time to the
spawning thread.  If the spawning thread is boosted to a very high priority
however, the test will deadlock, since the spawned thread will never get CPU
time.  With the defect this would not pass.



Other examples to consider:

taskset 0x1 java -jar ThreadDeadlock.jar 21 20 1
This mimics the failing MRG test case, and so the test fails.  This causes a
thread spinning at prio 21 to wait for a single spawned thread at prio 20. 
With only a single CPU available, the spawned thread is not granted CPU time,
so deadlock occurs.

taskset 0x1 java -jar ThreadDeadlock.jar 20 21 1 false true
This also fails, because the spawned thread is spinning, and so the spawning
thread will not get CPU time.



One a 4-core machine:

java -jar ThreadDeadlock.jar 20 21 3 false true
Passes, all threads are spinning but there are 4 realtime threads and 4 CPUs

java -jar ThreadDeadlock.jar 20 21 10 false true
Fails, there are 11 spinning threads total and 4 CPUs, so the spawning thread
gets no CPU time since it has lowest priority.

java -jar ThreadDeadlock.jar 30 20 10 true true
Fails.	There are 11 spinning threads and only 4 CPUs.	Additionally, the
lowest priority threads get no CPU time.

java -jar ThreadDeadlock.jar 30 20 4 true true
Usually passes but sometimes fails.  This is is similar to the previous
example, except the limited amount of synchronization taking place between
threads frees up the CPU enough for the lowest priority thread to get CPU time.
 The synchronization is likely caused by the calls to get the system time to
make the test time-out when deadlock occurs.

java -jar ThreadDeadlock.jar 20 21 4 false true
Usually passes but sometimes fails, there are 5 spinning threads total and 4
CPUs.  Once again, the limited amount of synchronization alllows the test to
pass most times.

java -jar ThreadDeadlock.jar 21 20 10 false true
Passes.  There are many spinning threads and 4 CPUs.  But the spawned threads
are yielding as they spin, and they are all the same priority, which causes a
round-robin amongst themselves that gives them all CPU time.  The spawning
thread has high priority and so it gets CPU time.

java -jar ThreadDeadlock.jar 30 20 10 true false
Passes.  The spawned threads will sleep, so all threads get CPU time.

Created attachment 308271 [details]
same test as previous attachment, modified output

I changed the output of the test to say either "no deadlock" or "deadlock
occurred", instead of passed/failed, to avoid confusion.  With some command
lines deadlock is expected, and with some others it is not.

Need to reopen and set status to Modified.

An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2008-0585.html

Created attachment 322830 [details]
javacore from the hang