Skip to main content

orbd from jdk6u5 consumes 100% cpu

8 replies [Last post]
mgoe
Offline
Joined: 2007-10-02

Hi,

a bug (http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6595055) which I reported against jdk7 is now also present in jdk6u5. This is a showstopper for us, since our application relies on CORBA and the orbd naming service.

Best regards,
Martin Goettlicher

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
mgoe
Offline
Joined: 2007-10-02

I did some further experiments. Calling orbd with -J-Dcom.sun.CORBA.transport.ORBUseNIOSelectToWait=false seems to work around the bug.

Best regards,
Martin Goettlicher

alanb
Offline
Joined: 2005-08-08

It's possible this is actually bug 6403933. Can you try a recent build of jdk7 to see if you can duplicate the problem? 6403933 is fixed in 6.0u4 but I need to check if that 6.0uN build you are using has the fixes from 6.0u3/6.0u4.

mgoe
Offline
Joined: 2007-10-02

I just checked with orbd from:

java version "1.7.0-ea"
Java(TM) SE Runtime Environment (build 1.7.0-ea-b22)
Java HotSpot(TM) Server VM (build 11.0-b08, mixed mode)

and I can still reproduce the bug using my c++ test program from http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6595055.

alanb
Offline
Joined: 2005-08-08

Are you sure you are seeing the same problem with jdk7-b22? Can you post the output of "jstack
" for when this happen?

mgoe
Offline
Joined: 2007-10-02

OK, here is the call stack of orbd from jdk7-b22:

Full thread dump Java HotSpot(TM) Server VM (11.0-b08 mixed mode):

"p: default-threadpool; w: Idle" daemon prio=10 tid=0x08199400 nid=0x784f in Object.wait() [0x805ba000..0x805bafb0]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x85244b18> (a com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl)
at com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl.requestWork(WorkQueueImpl.java:142)
- locked <0x85244b18> (a com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl)
at com.sun.corba.se.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:389)

"p: default-threadpool; w: Idle" daemon prio=10 tid=0x08191c00 nid=0x784e in Object.wait() [0x8060b000..0x8060c030]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x85244b18> (a com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl)
at com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl.requestWork(WorkQueueImpl.java:142)
- locked <0x85244b18> (a com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl)
at com.sun.corba.se.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:389)

"Attach Listener" daemon prio=10 tid=0x081d7c00 nid=0x7803 waiting on condition [0x00000000..0x00000000]
java.lang.Thread.State: RUNNABLE

"Thread-2" daemon prio=10 tid=0x08178000 nid=0x77e9 waiting on condition [0x806ad000..0x806addb0]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.sun.corba.se.impl.activation.ProcessMonitorThread.run(ProcessMonitorThread.java:55)

"SelectorThread" daemon prio=10 tid=0x080ddc00 nid=0x77e8 runnable [0x806fe000..0x806fee30]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:233)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:83)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
- locked <0x85262b80> (a sun.nio.ch.Util$1)
- locked <0x85262b70> (a java.util.Collections$UnmodifiableSet)
- locked <0x852626e8> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
at com.sun.corba.se.impl.transport.SelectorImpl.run(SelectorImpl.java:267)

"Low Memory Detector" daemon prio=10 tid=0x080ec400 nid=0x77e6 runnable [0x00000000..0x00000000]
java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x080ea400 nid=0x77e5 waiting on condition [0x00000000..0x80a552a8]
java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x080e7800 nid=0x77e4 waiting on condition [0x00000000..0x80ad6428]
java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x080e6000 nid=0x77e3 runnable [0x00000000..0x80b27d90]
java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x080d4800 nid=0x77e2 in Object.wait() [0x80b78000..0x80b79130]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x8528e430> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
- locked <0x8528e430> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:150)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)

"Reference Handler" daemon prio=10 tid=0x080d3400 nid=0x77e1 in Object.wait() [0x80bc9000..0x80bc9db0]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x8528e1b0> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:134)
- locked <0x8528e1b0> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x0804ec00 nid=0x77dd in Object.wait() [0xb7db7000..0xb7db8208]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x8527bf70> (a java.lang.Object)
at java.lang.Object.wait(Object.java:503)
at com.sun.corba.se.impl.orb.ORBImpl.run(ORBImpl.java:1241)
- locked <0x8527bf70> (a java.lang.Object)
at com.sun.corba.se.impl.activation.ORBD.run(ORBD.java:172)
at com.sun.corba.se.impl.activation.ORBD.main(ORBD.java:348)

"VM Thread" prio=10 tid=0x080cfc00 nid=0x77e0 runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x08055c00 nid=0x77de runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x08057400 nid=0x77df runnable

"VM Periodic Task Thread" prio=10 tid=0x080ee000 nid=0x77e7 waiting on condition

JNI global references: 652

jconsole with the JTop plugin shows that the "SelectorThread" consumes the cpu cycles.

raih
Offline
Joined: 2006-01-17

This is indeed a bug in JDK/orbd. We will be fixing it soon.

The problem is around a channel that was originally registered with Selector for i/o gets closed on the server side (due to early client side exit). But the server side can know about such channel only when it does i/o (read/write) and thereby getting into an IO exception. In this case, (bug 6595055)
there are times (erroneous) when server side (selector) did not know the channel is already closed, but continue to do the selection cycle on a key set whose associated channel is alreay closed or invalid. Hence, selector's select(..) keep spinning with zero return.

One fix is to have a provision in the application, to check if any of the Selector's key-set is having a closed channel/or invalid registration due to channel closure.

mgoe
Offline
Joined: 2007-10-02

Using the JTop plugin for jconsole I found out that once orbd consumes 100% cpu all cpu cycles are consumed by a thread called "SelectorThread". This thread has the following call stack:

Name: SelectorThread
State: RUNNABLE
Total blocked: 30 Total waited: 0

Stack trace:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(Unknown Source)
sun.nio.ch.EPollSelectorImpl.doSelect(Unknown Source)
sun.nio.ch.SelectorImpl.lockAndDoSelect(Unknown Source)
- locked sun.nio.ch.Util$1@81bb3b
- locked java.util.Collections$UnmodifiableSet@12b520a
- locked sun.nio.ch.EPollSelectorImpl@1170f1f
sun.nio.ch.SelectorImpl.select(Unknown Source)
com.sun.corba.se.impl.transport.SelectorImpl.run(Unknown Source)

"jstack -l" gives the following output:

2007-10-15 19:27:38
Full thread dump Java HotSpot(TM) Tiered VM (1.6.0_05-ea-b04 mixed mode):

"Attach Listener" daemon prio=10 tid=0x0807cc00 nid=0x2994 waiting on condition [0x00000000..0x00000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"p: default-threadpool; w: Idle" daemon prio=10 tid=0x081a3800 nid=0x2923 in Object.wait() [0x80203000..0x80203f30]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x852da8f0> (a com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl)
at com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl.requestWork(Unknown Source)
- locked <0x852da8f0> (a com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl)
at com.sun.corba.se.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(Unknown Source)

Locked ownable synchronizers:
- None

"p: default-threadpool; w: Idle" daemon prio=10 tid=0x0814e000 nid=0x2922 in Object.wait() [0x80254000..0x80254db0]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x852da8f0> (a com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl)
at com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl.requestWork(Unknown Source)
- locked <0x852da8f0> (a com.sun.corba.se.impl.orbutil.threadpool.WorkQueueImpl)
at com.sun.corba.se.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(Unknown Source)

Locked ownable synchronizers:
- None

"Thread-2" daemon prio=10 tid=0x081c7400 nid=0x2917 waiting on condition [0x802a5000..0x802a60b0]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.sun.corba.se.impl.activation.ProcessMonitorThread.run(Unknown Source)

Locked ownable synchronizers:
- None

"SelectorThread" daemon prio=10 tid=0x081c6800 nid=0x2916 runnable [0x802f6000..0x802f7130]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(Unknown Source)
at sun.nio.ch.EPollSelectorImpl.doSelect(Unknown Source)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(Unknown Source)
- locked <0x852db498> (a sun.nio.ch.Util$1)
- locked <0x852db488> (a java.util.Collections$UnmodifiableSet)
- locked <0x852dafb0> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(Unknown Source)
at com.sun.corba.se.impl.transport.SelectorImpl.run(Unknown Source)

Locked ownable synchronizers:
- None

"Low Memory Detector" daemon prio=10 tid=0x80d9e800 nid=0x2914 runnable [0x00000000..0x00000000]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"CompilerThread1" daemon prio=10 tid=0x80d9d000 nid=0x2913 waiting on condition [0x00000000..0x808312b8]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"CompilerThread0" daemon prio=10 tid=0x80d9bc00 nid=0x2912 waiting on condition [0x00000000..0x808b23f8]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"Signal Dispatcher" daemon prio=10 tid=0x80d9a800 nid=0x2911 runnable [0x00000000..0x80903a90]
java.lang.Thread.State: RUNNABLE

Locked ownable synchronizers:
- None

"Finalizer" daemon prio=10 tid=0x80d83400 nid=0x2910 in Object.wait() [0x80954000..0x80954e30]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x8530cbf0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(Unknown Source)
- locked <0x8530cbf0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(Unknown Source)
at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)

Locked ownable synchronizers:
- None

"Reference Handler" daemon prio=10 tid=0x80d82400 nid=0x290f in Object.wait() [0x809a5000..0x809a60b0]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x8530d6b0> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
- locked <0x8530d6b0> (a java.lang.ref.Reference$Lock)

Locked ownable synchronizers:
- None

"main" prio=10 tid=0x08058c00 nid=0x290b in Object.wait() [0xb7e15000..0xb7e16208]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x852dbb28> (a java.lang.Object)
at java.lang.Object.wait(Object.java:485)
at com.sun.corba.se.impl.orb.ORBImpl.run(Unknown Source)
- locked <0x852dbb28> (a java.lang.Object)
at com.sun.corba.se.impl.activation.ORBD.run(Unknown Source)
at com.sun.corba.se.impl.activation.ORBD.main(Unknown Source)

Locked ownable synchronizers:
- None

"VM Thread" prio=10 tid=0x80d7d800 nid=0x290e runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x08060c00 nid=0x290c runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x08061c00 nid=0x290d runnable

"VM Periodic Task Thread" prio=10 tid=0x80da0400 nid=0x2915 waiting on condition

JNI global references: 652

I don't have an idea why I could not see any differences in the call stack while being idle and while consuming 100% cpu.

I hope this helps to debug the problem. Using the test program written in c++ attached to the bug report I mentioned above it is very easy to reproduce this problem.

For the time until a fix is available I would be very happy if someone could suggest a workaround.

Best regards,
Martin Goettlicher

linuxhippy
Offline
Joined: 2004-01-07

Hi Martin,

Could you do some profiling, so see where the cycles are consumed?

Good luck, lg Clemens