1 2 Previous Next 29 Replies Latest reply on Dec 13, 2010 11:06 PM by jaikiran Go to original post
      • 15. Re: JBoss 6 100% CPU usage after scanning
        nick.x.newman

        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

          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

            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

              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

                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:

                 

                JBAS-8580.png

                • 20. Re: JBoss 6 100% CPU usage after scanning
                  mreasy

                  Seems the wait consumes the CPU:

                  JBAS-8580_2.png

                  • 21. Re: JBoss 6 100% CPU usage after scanning
                    nick.x.newman

                    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

                      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

                        @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

                          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

                            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

                              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?

                              • 27. Re: JBoss 6 100% CPU usage after scanning
                                genman

                                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

                                  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

                                    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.

                                    1 2 Previous Next