-
15. Re: JBoss 6 100% CPU usage after scanning
nick.x.newman Oct 13, 2010 1:14 PM (in response to jaikiran)Hi,
The version of JBoss that is affected by this problem is 6.0.0.M2. The version that does not appear to be affected is 5.1.0.GA (I should have thought of this earlier - sorry). So perhaps the problem is something that has been changed in recent versions?
Nick
-
16. Re: JBoss 6 100% CPU usage after scanning
nick.x.newman Oct 13, 2010 4:24 PM (in response to jaikiran)Hi,
Even better information.
I started an instance of JBoss 6.0.0.M2 on the same box (virtual machine, that is) as the JBoss 5.1.0.GA instance. The JBoss 6 instance was affected by the scanning but the 5.1 instance was not. So that points pretty strongly to a recent change.
Nick
-
17. Re: JBoss 6 100% CPU usage after scanning
genman Oct 20, 2010 11:51 AM (in response to nick.x.newman)Here's what I observed...
I don't see anything interesting in the stack trace, but if you look at the per-thread CPU usage, you see something like this:
pool-1-thread-18 52031 pool-1-thread-3 51265 pool-1-thread-2 50015 pool-1-thread-15 48687 pool-1-thread-4 48062 pool-1-thread-17 47750 pool-1-thread-16 46906 pool-1-thread-20 44687 pool-1-thread-19 44390 pool-1-thread-5 44000 pool-1-thread-14 43968 pool-1-thread-6 43468 HDScanner 37546 pool-8-thread-1 35328 pool-1-thread-8 25000 pool-1-thread-10 23593 pool-1-thread-11 22937 pool-1-thread-9 22468 pool-1-thread-13 21812 pool-1-thread-7 16531 pool-1-thread-12 14703
The CPU usage of each pool goes up and up and up.
Each thread is doing something like this:
Thread: pool-1-thread-1 : priority:5, demon:false, threadId:63, threadState:WAITING
- waiting on <0x1025dc7> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)
java.util.concurrent.PriorityBlockingQueue.take(PriorityBlockingQueue.java:220)
org.jboss.resource.adapter.mail.inflow.NewMsgsWorker.run(NewMsgsWorker.java:78)
org.jboss.resource.work.WorkWrapper.run(WorkWrapper.java:172)
org.jboss.threads.SimpleDirectExecutor.execute(SimpleDirectExecutor.java:33)
org.jboss.threads.QueueExecutor.runTask(QueueExecutor.java:780)
org.jboss.threads.QueueExecutor.access$100(QueueExecutor.java:45)
org.jboss.threads.QueueExecutor$Worker.run(QueueExecutor.java:800)
java.lang.Thread.run(Thread.java:619)
org.jboss.threads.JBossThread.run(JBossThread.java:122) -
18. Re: JBoss 6 100% CPU usage after scanning
nick.x.newman Oct 28, 2010 12:38 PM (in response to genman)Elias,
Thank you for confirmation of the problem. I believe that my thread dumps (attached to an earlier entry) tell essentially the same story as yours do.
I think that this is going to become a significant problem for me. I really don't want to have to restart JBoss after every scan! So I have submitted this as a bug: https://jira.jboss.org/browse/JBAS-8580
Nick
-
19. Re: JBoss 6 100% CPU usage after scanning
mreasy Nov 4, 2010 12:28 PM (in response to nick.x.newman)I am experiencing the same problem with today's (2010-11-04) snapshot of JBoss6. This is seen on different Windows, RedHat-Linux and Solaris machines.
I do NOT do any port scanning and also disabled AJP and HTTPS (just in case).
Threads affected are as well the ones named pool1-*, they execute sth. for about one second each, as can be seen here:
-
-
21. Re: JBoss 6 100% CPU usage after scanning
nick.x.newman Nov 4, 2010 12:41 PM (in response to mreasy)Hi Rico,
That's very interesting. So do you do anything (if not port scanning) to put JBoss into this state? For me it seems to behave well until the scan.
Nick
-
22. Re: JBoss 6 100% CPU usage after scanning
genman Nov 4, 2010 1:59 PM (in response to nick.x.newman)I'm suspecting there is a bug in org.jboss.threads.QueueExecutor... Suspect is this "for" loop:
private Runnable takeTask() { ... for (;;) { // these parameters may change on each iteration final int threadCount = this.threadCount; final int coreThreadLimit = coreThreads; final boolean allowCoreThreadTimeout = this.allowCoreThreadTimeout; if (stop || threadCount > maxThreads) { // too many threads. Handle a task if there is one, otherwise exit return pollTask(); } else if (!allowCoreThreadTimeout && threadCount < coreThreadLimit) { // ignore timeout until we are not a core thread or until core threads are allowed to time out try { enqueueCondition.await(); } catch (InterruptedException e) { intr = true; } } else { final TimeUnit timeUnit = keepAliveTimeUnit; final long time = keepAliveTime; final long remaining = time - timeUnit.convert(elapsed, TimeUnit.MILLISECONDS); if (remaining <= 0L && (allowCoreThreadTimeout || threadCount > coreThreadLimit)) { // the timeout has expired return pollTask(); } try { enqueueCondition.await(remaining, timeUnit); } catch (InterruptedException e) { intr = true; } } task = queue.poll(); if (task != null) { removeCondition.signal(); return task; } elapsed = System.currentTimeMillis() - start; }
I'm guessing the following is happening...
I believe that the condition variable enqueueCondition is "true" while the "poll" is returning null. What ends up happening is the "await" is returning immediately, then the queue.poll() is triggered, but returns null, then the loop cycles again. So, there's some sort of false signaling going on. Why it cycles every 1 second is because the "elapsed" eventually kicks the thread out.
Also, it would be better if the thread is interrupted to immediately return "null" rather than loop again.
-
23. Re: JBoss 6 100% CPU usage after scanning
mreasy Nov 4, 2010 4:23 PM (in response to genman)@Nick: I do only a start-up of JBoss and around 10 seconds after full start the behavior can be seen. There are some internal HTTP and JNDI requests going on, since I do have applications deployed - I did not run a test with an out-of-the-box JBoss yet.
@Elias: Yes, this looks promising. I'm going to debug into that code tomorrow and let you know.
-
24. Re: JBoss 6 100% CPU usage after scanning
dmlloyd Nov 4, 2010 4:33 PM (in response to genman)Elias Ross wrote:
I'm suspecting there is a bug in org.jboss.threads.QueueExecutor... Suspect is this "for" loop:
I believe that the condition variable enqueueCondition is "true" while the "poll" is returning null. What ends up happening is the "await" is returning immediately, then the queue.poll() is triggered, but returns null, then the loop cycles again. So, there's some sort of false signaling going on.
There may be, however Conditions do allow for spurious wakeups which is why we re-test the condition on every iteration of the loop. So await() should return spuriously at most one time. The only possible exception would be another thread hammering on the condition variable which seems unlikely unless the queue is being flooded with tasks (in which case poll() would eventually return a task). How sure are you that you are seeing a busy wait? The profiler snapshot you give looks like it might be wallclock time (during which await() will be blocking).
If you look at the original thread stack dump, the thread statuses are WAITING, not RUNNING.
Elias Ross wrote:
Also, it would be better if the thread is interrupted to immediately return "null" rather than loop again.
Not in this case; these are thread pool worker threads which would be within their rights to simply ignore interruption, unlike application or framework threads which should take interruption as a hint to cancel the current task. The only time a thread pool would typically respect interruption is when it is being shut down. As you can see, the shutdown flag is tested in the condition loop. Interruption would awaken the waiter and the stop flag would then be read, causing the loop to terminate. If interruption were caused by an application-level interruption request, then the interrupt will be consumed and ignored by the Worker class.
-
25. Re: JBoss 6 100% CPU usage after scanning
mreasy Nov 5, 2010 9:26 AM (in response to dmlloyd)The thread states are mostly waiting, but also running each for about 1 seconds per call, resulting in an overall enduring load. If you look at an individual thread you see it entering the RUNNING state for about 0.8 - 1.5 seconds then WAITING again for 30-60 seconds. With 10-20 pool-threads you get the overall load on the system.
Backlink to jira you created: https://jira.jboss.org/browse/JBTHR-17
-
26. Re: JBoss 6 100% CPU usage after scanning
mreasy Nov 5, 2010 12:28 PM (in response to mreasy)Did a little debugging and checked the code and resolved the issue by adding the following after the if-block, which checks "if (remaining <= 0L && (allowCoreThreadTimeout || threadCount > coreThreadLimit))":
if (remaining <= 0L) { // JBTHR-17 if remaining is 0 or less and we did not meet the condition above, // we do NOT want to wait a negative amount of time. Instead waiting for keepAliveTime makes most sense. remaining = keepAliveTime; }
Attached a patch, which I will also attach to https://jira.jboss.org/browse/JBTHR-17, including this and some visibility increasements to prevent synthetic accessor methods. (Not completely sure whether the volatiles are needed also, but this made sense to me, since they are used from different thread contextes).
Btw: Can you point me to the jboss-threads svn repository location - I did only find the sources from nexus?
-
JBTHR-17.diff.zip 1.5 KB
-
-
27. Re: JBoss 6 100% CPU usage after scanning
genman Nov 5, 2010 4:55 PM (in response to mreasy)I got had the feeling that if remaining was <= 0, then it would get stuck in a loop for a bit...and then I didn't notice the && in there.
I wrote a handy test program which I'll attach to the bug which reproduces the problem. You'll see CPU usage go up and stay up for quite a bit.
-
28. Re: JBoss 6 100% CPU usage after scanning
nick.x.newman Dec 13, 2010 12:23 PM (in response to genman)I upgraded to JBoss 6.0.0 CR1and since then I have had no further problems. On another box I left the original JBoss and it continued to have problems.
I think that is a solid indication that the problem has been fixed.
My sincere thanks to all involved.
Nick
-
29. Re: JBoss 6 100% CPU usage after scanning
jaikiran Dec 13, 2010 11:06 PM (in response to nick.x.newman)Nick Newman wrote:
I upgraded to JBoss 6.0.0 CR1and since then I have had no further problems. On another box I left the original JBoss and it continued to have problems.
That's good news. Thanks for reporting back.