Re: [guava] recencyQueue, memory use, expireAfterWrite

[Benjamin Manes]

maxWeight will be -1 if neither the maximum size methods on the builder were configured nor are the expiration times zero (immediate expiration).

The recency queue is used for maximum size to buffer the LRU history, "catching up" the LRU state in batches. This avoids having to lock on every access to update the policy and batches can be applied without blocking other threads.

The draining should be triggered often enough and be fast enough with other application behavior that it is always within a threshold size. This should be capped for as a safety measure just in case. I think I forgot to copy that over from CLHM which caps the recencyQueue (arbitrarily at 1 << 20). Even in a stress test the cache would never reach an unsavory size. While performing the policy operations should be frequent and cheap enough to be handled automatically, you can be more proactive by having a background thread call cleanUp() on the cache.

For extremely hot caches where you know of very specific keys that WILL be used, e.g. your example, then you might also find that the hit penalty is too expensive (hash table, lru, etc). In those scenarios a special purpose cache might be more appropriate, like a direct mapped policy to an AtomicReferenceArray.

On Fri, Mar 1, 2013 at 2:01 AM, <dominic...@gmail.com> wrote:

Hi there,

I've been looking at using the guava LoadingCache, to cache calls to class.getAnnotations().  The reasoning behind this is to potentially minimise the effects of http://bugs.sun.com/view_bug.do?bug_id=7122142.

What I'm finding is that when concurrency is high, the memory use by the CacheBuilder is very large.  100s of MB.  The cache builder looks like the follows:

LoadingCache<Class,Annotation[]> cache = CacheBuilder.newBuilder()
.maximumSize(1000)
.expireAfterWrite(100,TimeUnit.SECONDS)
.concurrencyLevel(16)
.build(new CacheLoader<Class,Annotation[]>() {
  public Annotation[] load(Class key) throws Exception {
      return key.getAnnotations();
  }
}


The access is a simple get:

cache.getUnchecked(SomeClassJAXBAnnotations.class)


Upon looking at a heap dump to see what is causing the large number of GC cycles, and memory usage.  I'm seeing the there is a "recencyQueue" that is holding onto the majority of the space.  The code suggests that the recencyQueue (LocalCache.java) is used to record which entries were accessed for updating the access list's ordering, until the queue is drained or a write occurs.   My confusion is, If I'm not using .expireAfterAccess, why is there a recencyQueue used? 

If the cache is being accessed for 1 hot key, or has low writes, and high reads (100 concurrent threads); then the amount entries on the queue seems to be large, and consumes a large portion of ram.

It seems that the map Segment's recencyQueue, uses the method "map.usesAccessQueue()" to determine if the recencyQueue is either a ConcurrentLinkedQueue, or just a /dev/null type queue.  However, map.usesAccessQueue is returning true; as it is using the map's evictBySize() which in turn uses maxWeight >=0.  It seems maxWeight can never be less than 0, as the builder doesn't allow this.


Does anyone know if the above scenario is expected?

- Large amount of memory used by the recencyQueue storing accesses, when there is high number of concurrent reads and no writes
- the recencyQueue in operation when .expireAfterAccess is not used.


 
Apologies if the above is hard to follow, or makes no sense.  If it helps I can try to put an example on github.

thanks in advance
/dom

--
--
guava-...@googlegroups.com
Project site: http://guava-libraries.googlecode.com
This group: http://groups.google.com/group/guava-discuss
 
This list is for general discussion.
To report an issue: http://code.google.com/p/guava-libraries/issues/entry
To get help: http://stackoverflow.com/questions/ask (use the tag "guava")
 
---
You received this message because you are subscribed to the Google Groups "guava-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to guava-discus...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Louis Wasserman]

> My confusion is, If I'm not using .expireAfterAccess, why is there a recencyQueue used?  

If you're using maximumSize, then each segment will maintain LRU ordering -- using the recency queue -- and evict the least recently used elements if the maximum size gets hit.  See the maximumSize Javadoc:

> As the cache size grows close to the maximum, the cache evicts entries that are less likely to be used again. For example, the cache may evict an entry because it hasn't been used recently or very often.

--
Louis Wasserman

[Kevin Bourrillion]

On Fri, Mar 1, 2013 at 2:01 AM, <dominic...@gmail.com> wrote:

What I'm finding is that when concurrency is high, the memory use by the CacheBuilder is very large.  100s of MB.

Please tell me you mean 100s of KB!

(We've measured this cache configuration in the past as using on the order of 80 bytes per entry.)

--

Kevin Bourrillion | Java Librarian | Google, Inc. | kev...@google.com

[dominic...@gmail.com]

Thank you both for the info, and clarification. Very much appreciated.

/dom

[dominic...@gmail.com]

HI Kevin,

Apologies for the delay in the responding. 
It was definitely MB.  However, the type of load I was hitting it with was large, and very unrealistic. 
If you are interested in the numbers, I put the code at: https://github.com/tootedom/google-cache-builder-inv

Thanks all for the explanations of recency queue.

/dom

[Benjamin Manes]

Your analysis states that the recency queue is only drained on a write. If that can be proven then it is definitely a bug. The queue is intended to be drained on either a write OR when a threshold size is reached (64 entries). This means that the cache should be trying to maintain a high water mark of 64 segments x 64 entries = 4,096. As Kevin mentioned, this is 80 bytes per entry so ~330kb. That per-entry size doesn't account for ConcurrentLinkedQueue's node class and that the queue is not strictly bounded, so 400kb under an artificial load would be the maximum I'd expect.

Can you run your test with ConcurrentLinkedHashMap? This was the reference implementation and, having left Google, I am more familiar with its code at this point. If it does not suffer the same degradation scenario then, for me, it would confirm that there is a bug in Guava's cache. If it also shows the same negative behavior then I'd want to dig into the test and confirm that there is an algorithmic flaw in both implementations.

The memory leak test mentioned earlier was how I validate CLHM. Note that I added a Thread.yield() after every read to simulate different requests and make it more realistic. Otherwise a thread would acquire a cpu time slice and perform many more reads, causing the queue to grow much faster than typical. Removing the yield might cause the safety limit to be reached, but it would still never cause unbounded growth. I usually confirm both scenarios before a major release as a regression test.

--

[dominic...@gmail.com]

Hi Ben,

>> Your analysis states that the recency queue is only drained on a write. If that can be proven then it is definitely a bug.

It's not the only time it's drained no.  From the limited number of scenarios I've looked into, a cache.stats call, and a random (modulus put).  These, both result in it being drained.  From the source, there's also quite another set of scenarios in which drainRecencyQueue is called.

>> Can you run your test with ConcurrentLinkedHashMap? This was the reference implementation and, having left Google, I am more familiar with its code at this
>> point. If it does not suffer the same degradation scenario then, for me, it would confirm that there is a bug in Guava's cache. If it also shows the same negative
>> behavior then I'd want to dig into the test and confirm that there is an algorithmic flaw in both implementations.

The ConcurrentLinkedHashMap exhibited the same type of memory use.  Eclipse MAT shows that the use of the memory is from the a number of ConcurrentQueue's that are referenced by a/several buffer fields (I put the links to some screenshots on the github page).

I took a look at the memory leak test you referenced.  Removing the thread.yield makes that test exhibit the same type of scenario that my tests cases are exhibiting:

For example, if you run the memory leak test with -Xmx512m the cache gets will consume a large proportion of the heap.  Run with 1024mb, and same occurs.  A large portion of the heap is consume.  Putting the thread.yield back in results in low memory overhead.

cheers
/dom

[Martin Buchholz]

An historical note that probably doesn't matter here, but:

The ConcurrentLinkedQueue implementation was changed a number of years ago to make it easier for the GC to collect all of its Nodes.  Excessive memory retention under load seems consistent with the behavior of the older implementation.

[Benjamin Manes]

Thanks Dominic,

Running the memory leak test without yield, it stays consistently at 8M tasks pending. This is at the current threshold of 1M entries.

If I reduce the threshold to 32k (1 << 15), it stays consistently at 260k pending.

If I reduce the threshold to 1024 (1 << 10), it stays consistently at 8k pending.

This is on a 4-way Xeon with SMT enabled; javac 1.6.0_30. It appears that the rule of thumb is (num_logical_cpus x max_buffer_size).

I do try to be GC hygienic, as Martin alluded to. In the past I've run the load test over a weekend to try to confirm that an out-of-memory didn't occur due to bad retention.

Your results are interesting as I haven't driven into it using EMAT to investigate the heap. I'll play with that, but I'm guessing that we may be hitting the Application Memory Wall in these synthetic benchmarks.

I've experimented with ideas for a lighter-weight alternative to CLQ, but never had something satisfactory. We only need single-consumer, multiple-consumer queues in this cache design.

One point of clarification, is this purely a problem in synthetic workloads or were you investigating an issue found in a production environment?

On Mon, Mar 4, 2013 at 4:05 PM, <dominic...@gmail.com> wrote:

[Benjamin Manes]

OK, I'm sorry for being obtuse. Everything makes sense.

The tuning the threshold size of the ConcurrentLinkedQueues will help reduce the number of GC collections and worse case retention, but not change the outcome significantly. The GC thrashing will be the major culprit of performance problems in a synthetic benchmark.

In simple terms, a garbage collection is triggered when the heap is full. You are most likely seeing hundreds of megabytes of to be garbage collected tasks. Worst case, the queue retains too many objects that are still alive. At 8M x 32b, that's 256mb of pending tasks. If we reduce the threshold size to 32k per queue, then its a mere 8mb.

Regardless, though, the objects are being retained only long enough for the drain to occur, but are still be created. It then becomes a performance concern of triggering too many garbage collections by creating so much garbage. At best we could avoid the object creation until after verifying that it is below the threshold limit. This would make the code more confusing to follow and probably not provide much real-world value. As you said, using a Thread.yield() to simulate real-world usage causes it to behave nicely. An application is usually doing a lot more interesting work than hitting a cache.

For your use-case the answer is to use a caching strategy that doesn't create garbage on every read. We do this for the LRU policy as a trade-off of creating garbage for better concurrency. At best we could evolve to an array-based single-writer/multiple-producer queue with entry references, so that memory usage is fixed. That would might be nice, but also unrealistic.

I see no reason why any eviction policy is needed for caching annotations. Most applications do not use class unloading and the number of classes being processed by this cache is probably fairly small. An unbounded ConcurrentHashMap or a custom classloader that eagerly loads annotations should be suitable.

hope that helps,

Ben

[dominic...@gmail.com]

Hi Ben,

>> One point of clarification, is this purely a problem in synthetic workloads or were you investigating an issue found in a production environment?

Indeed, it's not an issue in production that I'm investigating.  I was just looking into potential caching mechanism(s) for a several items (annotation caching, configuration options pulled from a db, method lookup and parameter invocation on a class, to name a few..).  It was just when I started looking at the caching for annotations, I was at first surprised that the cache was slower than the not cached version.  The reason being the large number of GC cycles; and as a result the investigation into why, how, what, etc could be the reasoning behind it.

>>
>> The tuning the threshold size of the ConcurrentLinkedQueues will help reduce the number of GC collections and worse case retention,
>> but not change the outcome significantly. The GC thrashing will be the major culprit of performance problems in a synthetic benchmark.

>>

>> In simple terms, a garbage collection is triggered when the heap is full. You are most likely seeing hundreds of megabytes of to be
>> garbage collected tasks. Worst case, the queue retains too many objects that are still alive. At 8M x 32b, that's 256mb of pending tasks.
>> If we reduce the threshold size to 32k per queue, then its a mere 8mb.

>>

Indeed that major factor of the performance is GC thrashing, and the reason behind why I was pondering what was causing the large amount of short lived objects.

Based on your information regarding the threshold value in the CLHM, I took a copy locally and adapted it.
Changing threshold (MAXIMUM_BUFFER_SIZE) in the ConcurrentLinkedHashMap code locally to 1 << 10 and running the synthetic test.  The results shows that now the Cached version using ConcurrentLinkedHashMap, is much more performant than, that of the non cached version.  I do not see a similar threshold value to run in the guava CacheBuilder to check if the same is true for it.  Equally with 1<<12 (32k constant pending items) the synthetic benchmark is much more performant.  The size allocated to the eden space (and the type of gc collector in operation) is of importance in judging the trade off between throughput and the buffer size.

Maybe the MAXIMUM_BUFFER_SIZE could be configurable for the user dependent upon his/her concerns in the CLHM, and limitations on available JVM heap head room?

>>
>>Regardless, though, the objects are being retained only long enough for the drain to occur, but are still be created.
>> It then becomes a performance concern of triggering too many garbage collections by creating so much garbage.
>> At best we could avoid the object creation until after verifying that it is below the threshold limit. This would make
>> the code more confusing to follow and probably not provide much real-world value.
>>

If it makes the code too confusing, then totally agree that it's not worth if it doesn't provide much real-world value.

>>
>> As you said, using a Thread.yield() to simulate real-world usage causes it to behave nicely.
>> An application is usually doing a lot more interesting work than hitting a cache.
>>

a Thread.yield() and then a LockSupport.parkNanos(1L) to stop any unfair OS scheduling, and contend with os/jvm differences,
would be more real-world type usage.  Kind of makes mirco benchmarking of this a very tricky thing to do. 
But yes, you would definitely hope the application is doing something more interesting than just caching.

>>
>> For your use-case the answer is to use a caching strategy that doesn't create garbage on every read.
>> We do this for the LRU policy as a trade-off of creating garbage for better concurrency.
>> At best we could evolve to an array-based single-writer/multiple-

>> producer queue with entry references, so that memory usage is fixed.
>> That would might be nice, but also unrealistic.
>>

Yeah an alternate caching strategy for the use case would probably be more appropriate.  But I suppose, there's
only so much garbage that can be created before it starts to effect concurrency, especially if there's
far greater proportion of stop the world GC pauses occurring (either due to lots of eden space init mark and remark
phases occurring, and/or the amount of objects surviving a young sweep; amongst other things - dependent on the GC type). 
How likely this scenario is to occur is highly dependent on the application, the use of the cache and the likely hood for the queue to grow between
 it being drained compared to the amount of gc stop the world it may cause.

>>

>> I see no reason why any eviction policy is needed for caching annotations.
>> Most applications do not use class unloading and the number of classes being processed by
>> this cache is probably fairly small.

>>

For sure in 99% of the cases there isn't any need for an eviction policy for caching annotations.  It would only be
applicable to those cases where jvm class redefinition and/or reflection is used at runtime to modify the class; which would
be a slim proportion of use cases.

Although, It is not strictly the eviction policy that's the cause of the garbage here though.  It's the bounding of the queue
to a maximum size, and the need to determining based on LRU the item that should be thrown away.

>>
>> An unbounded ConcurrentHashMap or a custom classloader
>> that eagerly loads annotations should be suitable.
>>

Absolutely, a ConcurrentReferenceHashMap with soft references works well for this case.
JK8 will hopefully solve the getAnnotations() issue.  It was just a use case for which caching may have been helpful.


>> hope that helps,

Unquestionably, you've been a great help and it is very much appreciated.

thanks again,
/dom

[Benjamin Manes]

Thanks again for the analysis. I've reduced the threshold to 1024 (1 << 10) per buffer. I think this is a reasonable maximum that shouldn't be reached in a real-world environment.

Please feel free to create an issue on Guava to add the maximum threshold constraint to the recency queue.

[dominic...@gmail.com]

Hi Ben,

Apologies again for the delay in responding.  Thank you very much for the response, for the help, and for looking into this.

I've added the results, and differences, to the github page of what changing the max buffer size to 1<<10 has on the heap usage, and throughput.  I've also added to the page the differences you see when running with the CMS or throughput GC collector; for the synthetic benchmark. 

I'll look at creating an issue on the Guava project to see if adding a threshold constraint to the recency queue is possible.

Thanks again
/dom

[Shengyuan Lu]

Hi Guava-ers,

I answered a Guava question on StackOverflow here: SimpleTimeLimiter shutdown.

But I am not sure that my answer is correct or not, because no one commented on, no vote up/down, even no other answers so far.

I guess that a subtle reason that why SimpleTimeLimiter doesn't shutdown ExecutorService.  If any one could answer the question? Thank you!

Regards,

Shengyuan

[Benjamin Manes]

Hi Dominic,

I ran your analysis against the latest snapshot of CLHM. This version replaces the queue-based buffer with a lossy ring buffer. This appears to remove the GC pressure that you experienced previously. It would be great if you could do another analysis round on this version before I release it. These changes are being tracked for CacheBuilder in issue 1487.

Warmup

 --------------

 'GetAnnotations' Finished with 1 thread(s). Average time: 126 ms

 'GetAnnotations' Finished with 10 thread(s). Average time: 862 ms

 'GetAnnotations' Finished with 20 thread(s). Average time: 1662 ms

number of young gc collections: 11, number of old gc collections: 0

 Jit compilation: 63

 'CacheBuilder' Finished with 1 thread(s). Average time: 271 ms

 'CacheBuilder' Finished with 10 thread(s). Average time: 1258 ms

 'CacheBuilder' Finished with 20 thread(s). Average time: 5138 ms

number of young gc collections: 2, number of old gc collections: 1

 Jit compilation: 571

 'LinkedCacheBuilder' Finished with 1 thread(s). Average time: 78 ms

 'LinkedCacheBuilder' Finished with 10 thread(s). Average time: 122 ms

 'LinkedCacheBuilder' Finished with 20 thread(s). Average time: 137 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 99

 --------------

 

 Run

 --------------

 CACHE BUILDER

 --------------

 'CacheBuilder' Finished with 1 thread(s). Average time: 94 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 1

 'CacheBuilder' Finished with 2 thread(s). Average time: 294 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 0

 'CacheBuilder' Finished with 4 thread(s). Average time: 487 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 0

 'CacheBuilder' Finished with 8 thread(s). Average time: 964 ms

number of young gc collections: 1, number of old gc collections: 0

 Jit compilation: 0

 'CacheBuilder' Finished with 16 thread(s). Average time: 1504 ms

number of young gc collections: 1, number of old gc collections: 0

 Jit compilation: 15

 'CacheBuilder' Finished with 32 thread(s). Average time: 9817 ms

number of young gc collections: 3, number of old gc collections: 1

 Jit compilation: 74

 'CacheBuilder' Finished with 64 thread(s). Average time: 15467 ms

number of young gc collections: 11, number of old gc collections: 2

 Jit compilation: 0

Young Space in mb:

(min:0/max:275)

                 :   |                                                             

                 :   |  |  |    |                                                  

                 :  || || ||   ||            | |            | |           | |  ||  

                 :|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||

                 :   2   1   3   0   0   0   9   0   0   0   0   0   0   2   8   5 

                 :   7   4                   9                           1   3   5 

                 :   5                                                             

Survivor Space in mb:

(min:0/max:137)

                    :                               |||         ||                    

                    :                               |||         ||                    

                    :          |||||                |||         ||                    

                    :|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||

                    :   0   0   5   3   3   3   3   1   0   0   1   1   1   1   0   0 

                    :           2   4   4   4   4   3           3   6   6   6         

                    :                               7           7                     

Old Space in mb:

(min:0/max:504)

               :                                             ||||||||||||||||||||

               :               |||||||||||||||||||           ||||||||||||||||||||

               :               ||||||||||||||||||||||||||||||||||||||||||||||||||

               :|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||

               :   0   0   9   3   3   3   3   3   2   2   2   5   5   5   5   5 

               :           5   5   5   5   5   6   7   7   7   0   0   0   0   0 

               :               3   3   3   3   7   4   4   4   4   4   4   4   4 

Perm Space in mb:

(min:6/max:6)

                :|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||

                :   6   6   6   6   6   6   6   6   6   6   6   6   6   6   6   6 

 --------------

 GET ANNOTATIONS

 --------------

 'GetAnnotations' Finished with 1 thread(s). Average time: 102 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 17

 'GetAnnotations' Finished with 2 thread(s). Average time: 154 ms

number of young gc collections: 1, number of old gc collections: 0

 Jit compilation: 0

 'GetAnnotations' Finished with 4 thread(s). Average time: 428 ms

number of young gc collections: 2, number of old gc collections: 0

 Jit compilation: 0

 'GetAnnotations' Finished with 8 thread(s). Average time: 868 ms

number of young gc collections: 3, number of old gc collections: 0

 Jit compilation: 0

 'GetAnnotations' Finished with 16 thread(s). Average time: 1744 ms

number of young gc collections: 7, number of old gc collections: 0

 Jit compilation: 0

 'GetAnnotations' Finished with 32 thread(s). Average time: 3487 ms

number of young gc collections: 14, number of old gc collections: 0

 Jit compilation: 0

 'GetAnnotations' Finished with 64 thread(s). Average time: 7121 ms

number of young gc collections: 27, number of old gc collections: 0

 Jit compilation: 0

Young Space in mb:

(min:0/max:138)

                 :                 |           

                 :                 ||||||    ||

                 :   |             ||||||||  ||

                 :|||||||||||||||||||||||||||||

                 :   4   4   3   4   1   8   1 

                 :   9   0   3       2   7   3 

                 :                   9       0 

Survivor Space in mb:

(min:0/max:0)

                    :|||||||||||||||||||||||||||||

                    :   0   0   0   0   0   0   0 

Old Space in mb:

(min:0/max:1)

               :  |||||||||||||||||||||||||||

               :  |||||||||||||||||||||||||||

               :  |||||||||||||||||||||||||||

               :|||||||||||||||||||||||||||||

               :   1   1   1   1   1   1   1 

Perm Space in mb:

(min:6/max:6)

                :|||||||||||||||||||||||||||||

                :   6   6   6   6   6   6   6 

 

 --------------

 LINKED CACHE BUILDER

 --------------

 'LinkedCacheBuilder' Finished with 1 thread(s). Average time: 35 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 0

 'LinkedCacheBuilder' Finished with 2 thread(s). Average time: 49 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 0

 'LinkedCacheBuilder' Finished with 4 thread(s). Average time: 62 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 0

 'LinkedCacheBuilder' Finished with 8 thread(s). Average time: 101 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 0

 'LinkedCacheBuilder' Finished with 16 thread(s). Average time: 161 ms

number of young gc collections: 0, number of old gc collections: 0

 Jit compilation: 0

'LinkedCacheBuilder' Finished with 32 thread(s). Average time: 247 ms

number of young gc collections: 0, number of old gc collections: 0

Jit compilation: 0

'LinkedCacheBuilder' Finished with 64 thread(s). Average time: 434 ms

number of young gc collections: 0, number of old gc collections: 0

Jit compilation: 0

Young Space in mb:

(min:0/max:3)

                 :  |

                 : ||

                 : ||

                 :|||

                 :   

Survivor Space in mb:

(min:0/max:0)

                    :|||

                    :   

Old Space in mb:

(min:0/max:0)

               :|||

               :   

Perm Space in mb:

(min:6/max:6)

                :|||

[Dominic Tootell]

Hi Ben,

Thank you for the email.  I took the 1.4-SNAPSHOT and did a comparison against the 1.3 modified version (which had the reduced recency queue size [1<<10]), and all I can say is WOW.  A huge difference.  The 1.4 CLHM is a vast improvement in terms of performance and GC.  Performing the test, the CLHM version hardly registers long enough to be graphed in VisualVM.

I include a picture of a couple of screen shots.  Top graphs are a previous test with the latest guava 14.0-SNAPSHOT, and the modified 1.3 of the CLHM.   The bottom set of graphs is from an identical run, but using a 1.4-SNAPSHOT of the CLHM. 

Great work indeed.  Hope you are well.

Let me know if you need any more information.

thanks
/dom

[Benjamin Manes]

Thanks! I'll cut a release then. Hopefully we'll see these changes appear in Guava soon, too.