7 Replies Latest reply on Aug 28, 2014 1:50 PM by shawkins

    BufferManager Cleaner thread consuming 90% of total CPU

    deveshmishra

      We are experiencing BufferManager Cleaner thread consuming 90% of total CPU. This issue is intermittent and happens 1 out of 10 times, but it is so annoying that we have to restart the system for things to settle down. Below is our configuration.

       

      1) JBOSS EAP 6.1.0 Alpha

      2) TEIID 8.7.0

       

      Below is the statement from thread dump. This particular thread consumes 90% of the total CPU.

       

      3XMTHREADINFO      "BufferManager Cleaner" J9VMThread:0x0000004C6BADC400, j9thread_t:0x0000004C62C72CF0, java/lang/Thread:0x000000481C0F0B18, state:CW, prio=5

      3XMJAVALTHREAD            (java/lang/Thread getId:0x75, isDaemon:true)

      3XMTHREADINFO1            (native thread ID:0x5454CA00, native priority:0x5, native policy:UNKNOWN)

      3XMHEAPALLOC             Heap bytes allocated since last GC cycle=102989856 (0x6238020)

      3XMTHREADINFO3           Java callstack:

      4XESTACKTRACE                at java/util/concurrent/ConcurrentSkipListMap.firstEntry(ConcurrentSkipListMap.java:2147(Compiled Code))

      4XESTACKTRACE                at org/teiid/common/buffer/impl/LrfuEvictionQueue.firstEntry(LrfuEvictionQueue.java:97(Compiled Code))

      4XESTACKTRACE                at org/teiid/common/buffer/impl/BufferManagerImpl.doEvictions(BufferManagerImpl.java:847(Compiled Code))

      4XESTACKTRACE                at org/teiid/common/buffer/impl/BufferManagerImpl$Cleaner.run(BufferManagerImpl.java:108(Compiled Code))

      4XESTACKTRACE                at java/util/TimerThread.mainLoop(Timer.java:555)

      4XESTACKTRACE                at java/util/TimerThread.run(Timer.java:505)

      3XMTHREADINFO3           No native callstack available on this platform

        • 1. Re: BufferManager Cleaner thread consuming 90% of total CPU
          shawkins

          Is this during a period of sustained load?  Unless a substantial amount new batches are being added the cleaning process should just degrade to status checks until enough new batches have built-up.

          • 2. Re: BufferManager Cleaner thread consuming 90% of total CPU
            markaddleman

            I've been looking over the BufferManagerImpl$Cleaner code.  It appears that it is designed to loop in a semi-busy way:  It sleeps for 100 ms, cleans up whatever is needed and then goes back to sleep for 100 ms.  Is that right?  If so, that would explain why we see it active in our thread dumps.  Perhaps it is a red herring to our performance problem.  The COMMAND_LOG doesn't indicate that there are any high frequency queries.

             

            The high CPU condition occurs shortly after our VDB deploys and we issue a lot of queries against the system tables.  We also begin a number of continuous queries but each of these have built-in delays of at least 30 seconds.  Again, the COMMAND_LOG does not indicate that the continuous queries are executing at an unexpectedly high rate.

            • 3. Re: Re: BufferManager Cleaner thread consuming 90% of total CPU
              deveshmishra

              Hi Steven,

               

              We are not putting any load on the system and this issue is intermittent so the load should not be a cause of concern. This happens 2 out of 10 times. Today we put some log statements in BufferManagerImpl.doEvictions() and saw a looping situation occurring around queue.remove(ce); Modified code is attached. I put the logs like below.

               

              1. long doEvictions(long maxToFree, boolean checkActiveBatch, LrfuEvictionQueue<CacheEntry> queue) {
              2.   if (queue == evictionQueue) {
              3.   maxToFree = Math.min(maxToFree, this.maxProcessingBytes);
              4.   }
              5.   long freed = 0;
              6.   while (freed <= maxToFree && (
              7.   !checkActiveBatch //age out
              8.   || (queue == evictionQueue && activeBatchBytes.get() + overheadBytes.get() + this.maxReserveBytes/2 > reserveBatchBytes.get()) //nominal cleaning criterion
              9.   || (queue != evictionQueue && activeBatchBytes.get() + overheadBytes.get() + 3*this.maxReserveBytes/4 > reserveBatchBytes.get()))) { //assume that basically all initial batches will need to be written out at some point
              10.   //Added this comment
              11.   LogManager.logInfo(LogConstants.CTX_BUFFER_MGR, "preparing to evict first entry, maxtofree " + maxToFree + " ,freed " + freed);
              12.   CacheEntry ce = queue.firstEntry(checkActiveBatch);
              13.   if (ce == null) {
              14.   //Added this comment
              15.   LogManager.logInfo(LogConstants.CTX_BUFFER_MGR, "breaking doEvictions maxtofree " + maxToFree + " ,freed " + freed);
              16.   break;
              17.   }
              18.   synchronized (ce) {
              19.   if (!memoryEntries.containsKey(ce.getId())) {
              20.   if (!checkActiveBatch) {
              21. //Added this comment
              22.   LogManager.logInfo(LogConstants.CTX_BUFFER_MGR, "removing from queue ce_id=" + ce.getId() + " + maxToFree= + " + maxToFree + ",freed=" + freed);
              23.   queue.remove(ce);
              24.   }
              25.   continue; //not currently a valid eviction
              26.   }
              27.   }
              28. ....
              29. .....

               

              The looping occurs while removing from the queue. This looping generated 1.3 gig of logs in just 30 mins of run. I can provide that entirely if that helps. Sample log below, pls not that ce_id is for all the executions.


              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  removing from queue ce_id=75288 + maxToFree= + 8388608,freed=141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  preparing to evict first entry, maxtofree 8388608 ,freed 141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  removing from queue ce_id=75288 + maxToFree= + 8388608,freed=141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  preparing to evict first entry, maxtofree 8388608 ,freed 141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  removing from queue ce_id=75288 + maxToFree= + 8388608,freed=141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  preparing to evict first entry, maxtofree 8388608 ,freed 141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  removing from queue ce_id=75288 + maxToFree= + 8388608,freed=141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  preparing to evict first entry, maxtofree 8388608 ,freed 141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  removing from queue ce_id=75288 + maxToFree= + 8388608,freed=141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  preparing to evict first entry, maxtofree 8388608 ,freed 141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  removing from queue ce_id=75288 + maxToFree= + 8388608,freed=141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  preparing to evict first entry, maxtofree 8388608 ,freed 141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  removing from queue ce_id=75288 + maxToFree= + 8388608,freed=141213

              27 Aug 2014 10:58:06,436 INFO  [org.teiid.BUFFER_MGR] (BufferManager Cleaner)  preparing to evict first entry, maxtofree 8388608 ,freed 141213

               

              Thanks in advance.

              • 4. Re: BufferManager Cleaner thread consuming 90% of total CPU
                shawkins

                I believe this sequence of events is when we are checking for aging out initial cache entries and the first entry reports that another thread is evicting it, then the loop is tight in retrying that eviction.  If the head of the queue is relatively new or not currently being evicted by another thread, then this won't occur which would explain why it's not always reproducible.  Can you log an issue for this?

                • 5. Re: BufferManager Cleaner thread consuming 90% of total CPU
                  deveshmishra

                  Thanks Steven, I will log an issue, If you have any solution which comes directly to your mind or any settings or any hack, please let me know. This is critical to our project. Thanks

                  • 6. Re: BufferManager Cleaner thread consuming 90% of total CPU
                    deveshmishra
                    • 7. Re: BufferManager Cleaner thread consuming 90% of total CPU
                      shawkins

                      I don't think there is a good workaround as there aren't a set of configuration options to control this behavior.  If possible can you test against the commit on TEIID-3106