Bug 446397 - java testcase hangs on 2.6.24.7-52ibmrt2.3 kernel
java testcase hangs on 2.6.24.7-52ibmrt2.3 kernel
Status: CLOSED ERRATA
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: realtime-kernel (Show other bugs)
beta
x86_64 All
urgent Severity urgent
: 1.0.1
: ---
Assigned To: Steven Rostedt
: Reopened
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-05-14 09:48 EDT by IBM Bug Proxy
Modified: 2008-11-07 04:05 EST (History)
7 users (show)

See Also:
Fixed In Version: 2.6.24.7-62.el5rt
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-08-26 15:57:02 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
ps command output showing java threads and their priorities (2.24 KB, text/plain)
2008-05-27 08:49 EDT, IBM Bug Proxy
no flags Details
backtraces from gdb (18.28 KB, text/plain)
2008-05-27 08:49 EDT, IBM Bug Proxy
no flags Details
sysrq-t output (120.39 KB, text/plain)
2008-05-27 08:49 EDT, IBM Bug Proxy
no flags Details
sysrq-w output (12.53 KB, text/plain)
2008-05-27 08:49 EDT, IBM Bug Proxy
no flags Details
request for javacore (392 bytes, text/plain)
2008-05-29 11:18 EDT, IBM Bug Proxy
no flags Details
rwlock-prio-fix patch from Steven (1.21 KB, text/plain)
2008-05-29 20:33 EDT, IBM Bug Proxy
no flags Details
program which starts one realtime thread that starts others and waits for the others to run (7.71 KB, application/octet-stream)
2008-06-03 13:25 EDT, IBM Bug Proxy
no flags Details
same test as previous attachment, modified output (7.73 KB, application/octet-stream)
2008-06-03 13:49 EDT, IBM Bug Proxy
no flags Details
javacore from the hang (365.26 KB, text/plain)
2008-11-07 04:05 EST, IBM Bug Proxy
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
IBM Linux Technology Center 44781 None None None Never

  None (edit)
Description IBM Bug Proxy 2008-05-14 09:48:29 EDT
=Comment: #0=================================================
Sudhanshu Singh <sudhanshusingh@in.ibm.com> - 2008-05-14 08:40 EDT
Problem description:

java testcase hangs with 2.6.24.7-52ibmrt2.3 kernel.

   Provide output from "uname -a", if possible:

Linux rt-aspen.austin.ibm.com 2.6.24.7-52ibmrt2.3 #1 SMP PREEMPT RT Mon May 12
20:23:45 EDT 2008 x86_64 x86_64 x86_64 GNU/Linux

Hardware Environment
    Machine type (p650, x235, SF2, etc.): LS21
    Cpu type (Power4, Power5, IA-64, etc.): x86_64
    Describe any special hardware you think might be relevant to this problem:


Additional information:
=Comment: #1=================================================
Sripathi Kodi <sripathi@in.ibm.com> - 2008-05-14 09:15 EDT
We had seen a problem with the futex-gup and futex-fast_gup patches in
2.6.24.4-46.el5rt kernel. Please see bug 44312 (RH bug 443963). Hence we removed
these patches for our use.

With the latest kernel  (2.6.24.7-52.el5rt), we are seeing application hangs
even without the gup patches. I removed the rwlocks-multi patches from the
kernel, but it did not seem to fix the problem. I am looking at this further to
isolate the problem.
Comment 1 IBM Bug Proxy 2008-05-15 01:56:43 EDT
------- Comment From ankigarg@in.ibm.com 2008-05-15 01:55 EDT-------
As discussed with Sripathi, will spend sometime on this bug today.
Comment 2 IBM Bug Proxy 2008-05-15 07:17:05 EDT
------- Comment From ankigarg@in.ibm.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@in.ibm.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 3 IBM Bug Proxy 2008-05-15 08:32:31 EDT
------- Comment From sripathi@in.ibm.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@in.ibm.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 4 IBM Bug Proxy 2008-05-15 12:40:32 EDT
------- Comment From sripathi@in.ibm.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@in.ibm.com 2008-05-15 12:39 EDT-------
Running the test overnight to confirm.
Comment 5 IBM Bug Proxy 2008-05-15 18:00:30 EDT
------- Comment From jstultz@us.ibm.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 6 IBM Bug Proxy 2008-05-15 20:40:45 EDT
------- Comment From jstultz@us.ibm.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 7 IBM Bug Proxy 2008-05-16 02:48:55 EDT
------- Comment From sripathi@in.ibm.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 8 IBM Bug Proxy 2008-05-16 15:32:31 EDT
------- Comment From jstultz@us.ibm.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 9 IBM Bug Proxy 2008-05-16 18:56:30 EDT
------- Comment From jstultz@us.ibm.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 10 IBM Bug Proxy 2008-05-16 20:00:29 EDT
------- Comment From jstultz@us.ibm.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 11 IBM Bug Proxy 2008-05-16 20:08:31 EDT
------- Comment From jstultz@us.ibm.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 12 IBM Bug Proxy 2008-05-21 18:08:33 EDT
------- Comment From jstultz@us.ibm.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@us.ibm.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 13 IBM Bug Proxy 2008-05-22 05:40:38 EDT
------- Comment From sripathi@in.ibm.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.
Comment 14 Clark Williams 2008-05-22 16:39:33 EDT
elevating to blocker status and assigning srostedt
Comment 15 IBM Bug Proxy 2008-05-26 02:32:29 EDT
------- Comment From sripathi@in.ibm.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 16 IBM Bug Proxy 2008-05-26 13:08:28 EDT
------- Comment From sripathi@in.ibm.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 17 IBM Bug Proxy 2008-05-26 13:32:23 EDT
------- Comment From sripathi@in.ibm.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.
Comment 18 Luis Claudio R. Goncalves 2008-05-26 13:53:54 EDT
Try using sysrq-w, as it will show you other tasks:

'w'     - Dumps tasks that are in uninterruptable (blocked) state.
Comment 19 Steven Rostedt 2008-05-26 15:51:21 EDT
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 20 IBM Bug Proxy 2008-05-27 06:16:26 EDT
------- Comment From sripathi@in.ibm.com 2008-05-27 06:14 EDT-------
(In reply to comment #40)
> ------- Comment From lgoncalv@redhat.com 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 21 IBM Bug Proxy 2008-05-27 06:24:29 EDT
------- Comment From sripathi@in.ibm.com 2008-05-27 06:17 EDT-------
(In reply to comment #41)
> ------- Comment From srostedt@redhat.com 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.
Comment 22 IBM Bug Proxy 2008-05-27 08:49:01 EDT
Created attachment 306765 [details]
ps command output showing java threads and their priorities
Comment 23 IBM Bug Proxy 2008-05-27 08:49:03 EDT
Created attachment 306766 [details]
backtraces from gdb
Comment 24 IBM Bug Proxy 2008-05-27 08:49:05 EDT
Created attachment 306767 [details]
sysrq-t output
Comment 25 IBM Bug Proxy 2008-05-27 08:49:06 EDT
Created attachment 306768 [details]
sysrq-w output
Comment 26 IBM Bug Proxy 2008-05-28 20:08:50 EDT
------- Comment From jstultz@us.ibm.com 2008-05-28 20:07 EDT-------
(In reply to comment #43)
> (In reply to comment #41)
> > ------- Comment From srostedt@redhat.com 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 27 IBM Bug Proxy 2008-05-28 20:48:50 EDT
------- Comment From jstultz@us.ibm.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?
Comment 28 Luis Claudio R. Goncalves 2008-05-29 11:05:09 EDT
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.
Comment 29 IBM Bug Proxy 2008-05-29 11:18:37 EDT
Created attachment 307087 [details]
request for javacore
Comment 30 IBM Bug Proxy 2008-05-29 13:17:56 EDT
------- Comment From Sean_Foley@ca.ibm.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 31 IBM Bug Proxy 2008-05-29 14:18:08 EDT
------- Comment From dvhltc@us.ibm.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.
Comment 32 IBM Bug Proxy 2008-05-29 20:33:00 EDT
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 33 IBM Bug Proxy 2008-05-30 15:41:08 EDT
------- Comment From Sean_Foley@ca.ibm.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 34 IBM Bug Proxy 2008-05-30 15:57:25 EDT
------- Comment From jstultz@us.ibm.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 35 IBM Bug Proxy 2008-06-02 08:41:04 EDT
------- Comment From sripathi@in.ibm.com 2008-06-02 08:35 EDT-------
I have tested this on the -62 kernel and found it to solve the reported problem.
Comment 36 Clark Williams 2008-06-02 14:26:05 EDT
closing on our side
Comment 37 IBM Bug Proxy 2008-06-03 13:25:16 EDT
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.
Comment 38 IBM Bug Proxy 2008-06-03 13:49:11 EDT
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.
Comment 39 Beth Uptagrafft 2008-07-28 12:33:23 EDT
Need to reopen and set status to Modified.
Comment 46 errata-xmlrpc 2008-08-26 15:57:02 EDT
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
Comment 47 IBM Bug Proxy 2008-11-07 04:05:46 EST
Created attachment 322830 [details]
javacore from the hang

Note You need to log in before you can comment on or make changes to this bug.