-
1. Re: BufferManager Cleaner thread consuming 90% of total CPU
shawkins Aug 25, 2014 9:26 AM (in response to deveshmishra)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 Aug 25, 2014 4:39 PM (in response to shawkins)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 Aug 27, 2014 11:41 AM (in response to shawkins)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.
- long doEvictions(long maxToFree, boolean checkActiveBatch, LrfuEvictionQueue<CacheEntry> queue) {
- if (queue == evictionQueue) {
- maxToFree = Math.min(maxToFree, this.maxProcessingBytes);
- }
- long freed = 0;
- while (freed <= maxToFree && (
- !checkActiveBatch //age out
- || (queue == evictionQueue && activeBatchBytes.get() + overheadBytes.get() + this.maxReserveBytes/2 > reserveBatchBytes.get()) //nominal cleaning criterion
- || (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
- //Added this comment
- LogManager.logInfo(LogConstants.CTX_BUFFER_MGR, "preparing to evict first entry, maxtofree " + maxToFree + " ,freed " + freed);
- CacheEntry ce = queue.firstEntry(checkActiveBatch);
- if (ce == null) {
- //Added this comment
- LogManager.logInfo(LogConstants.CTX_BUFFER_MGR, "breaking doEvictions maxtofree " + maxToFree + " ,freed " + freed);
- break;
- }
- synchronized (ce) {
- if (!memoryEntries.containsKey(ce.getId())) {
- if (!checkActiveBatch) {
- //Added this comment
- LogManager.logInfo(LogConstants.CTX_BUFFER_MGR, "removing from queue ce_id=" + ce.getId() + " + maxToFree= + " + maxToFree + ",freed=" + freed);
- queue.remove(ce);
- }
- continue; //not currently a valid eviction
- }
- }
- ....
- .....
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.
-
BufferManagerImpl.java 43.0 KB
-
loop.txt.zip 1.1 KB
-
4. Re: BufferManager Cleaner thread consuming 90% of total CPU
shawkins Aug 27, 2014 12:38 PM (in response to deveshmishra)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 Aug 27, 2014 10:40 PM (in response to shawkins)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 Aug 28, 2014 4:41 AM (in response to shawkins)Logged https://issues.jboss.org/browse/TEIID-3106. Thanks
-
7. Re: BufferManager Cleaner thread consuming 90% of total CPU
shawkins Aug 28, 2014 1:50 PM (in response to deveshmishra)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