By jonthecollector on Jun 22, 2007
Before I get to that let's talk a little bit about the JVM's behavior with regard to allocating large objects. Large, of course, is a relative term and what I mean here is large relative to the size of the young generation. My comments here apply to JDK 5 update 10 and later and JDK 1.4.2 update 13 and later. Earlier versions of those JVM's had a bug in them (6369448) that made their behavior different. All versions of JDK 6 are also free from this bug. By the way the customer was on JDK 5 update 6 so was subject to 6369448. That made it a little more interesting for me but may not be of interest to you if you are running on the later releases. And also the policy I describe below does not apply to the throughput collector (UseParallelGC) which has its own variation on this policy.
Objects are normally allocated out of the young generation and get moved to the tenured generation as they age. But what happens when a object is larger than the young generation (actually larger than the eden space in the young generation)? If the application tries to allocate object AAA and there is not enough free space in eden for the allocation, a garbage collection usually occurs. The exception to this is if AAA is larger than eden. An outline of the policy for allocation and collections follow.
- Allocate out of the young generation
- Possibly allocate out of the tenured generation
- Collect the young generation
- Possibly collect the tenured generation
If the allocation in 1. fails, before starting a GC the JVM considers allocating AAA out of the tenured generation at 2. The JVM compares the size of AAA to the current capacity of eden. By capacity I mean the total size available in an empty eden. If the capacity of eden is too small to hold AAA, then collecting the young generation will not help with the allocation of AAA. So the JVM tries to allocate AAA directly out of the tenured generation. If the allocation out of the tenured generation succeeds, no young generation GC is done and the JVM just continues. If AAA is smaller than eden, then the JVM proceeds to the collection of the young generation at 3. After the the young generation collection, a check is done at 4. to see if enough space has been freed to allocate AAA in eden. If AAA still cannot be allocated out of the young generation, then the tenured generation is collected at 5. and an allocation attempt is made out of the tenured generation. If AAA cannot be allocated in the tenured generation, some additional heroics are attempted (e.g., clearing all SoftReferences). Failing those heroics an out-of-memory is thrown.
A few things to note. The initial allocation at 1. is what we refer to as fast-path allocation. Fast-path allocation does not call into the JVM to allocate an object. The JIT compilers know how to allocate out of the young generation and code for an allocation is generated in-line for object allocation. The interpreter also knows how to do the allocation without making a call to the VM. And yes, both know about thread local allocation buffers (TLAB's) and use them. The allocation out of the tenured generation at 2. could be attempted unconditionally for any sized object. That could avoid a collection of the young generation, but would also defeat the purpose of having the young generation. We want new objects allocated in the young generation because that's where they will probably die. We only want the longed-lived objects to make it into the tenured generation. Also an allocation at 2. is not a fast-path allocation so the execution of the application could be significantly affected by too much allocation at 2. At 4. a check is made to see if enough space has been freed in the young generation for AAA and if not the tenured generation is collected. Why not attempt the allocation of AAA out of the tenured generation before doing the collection? Attempting the allocation first would probably work lots of the time, but there are pathological cases where allocations would repeatedly be done at 4. If we called allocation at 2. slow-path allocation, we'd have to call allocation at 4. slow-slow-path allocation. At 4. we've already stopped the world and done a young generation collection. The pathological case would execute very slowly. We know. We've tried variations that did the slow-slow-path allocation first and the reports that we usually got was the the JVM was hung! The JVM was not hung. Going slow-slow-path just made it seem so. Doing the collection of the tenured generation actually also collects the young generation and doing that avoids the pathological case in practice.
The final thing to note is that you don't want to be stuck using slow-path allocation (allocation at 2.) It's really slow compared to fast-path allocation. So if you have large objects (and only you would know), try to make your young generation large enough to hold plenty of them (10's would be good, 100's would be better). Or that you have very few of them.
The policy for the throughput collector differs from the above at 2. and 5. At 2. the throughput collector will allocate an object out of the tenured generation if it is larger than half of eden. That variation tries to not fill up the young generation with large objects. Is this better? I just don't know. The heroics at 5. are also different.
The interesting exchange with the customer that got me thinking about this blog started with this snippet of a GC log. Again this was with JDK 5 update 6 so the bug 6369448 was in play.
963236.282: [GC 963236.282: [ParNew: 15343K->0K(21184K), 0.1025429 secs] 8289743K->8274557K(12287936K), 0.1029416 secs] 963236.479: [GC 963236.479: [ParNew: 10666K->0K(21184K), 0.1072986 secs] 963236.587: [CMS (concurrent mode failure): 8285141K->7092744K(12266752K), 91.3603721 secs] 8285224K->7092744K(12287936K), 91.4763098 secs] 963328.194: [GC 963328.194: [ParNew: 21120K->0K(21184K), 0.1455909 secs] 7135030K->7114033K(12287936K), 0.1459930 secs] 963328.434: [GC 963328.435: [ParNew: 7442K->0K(21184K), 0.0745429 secs] 963328.509: [CMS (concurrent mode failure): 7114084K->7073781K(12266752K), 78.1535121 secs] 7121475K->7073781K(12287936K), 78.2286852 secs] 963408.503: [GC 963408.503: [ParNew : 21120K->0K(21184K), 0.0651745 secs] 7116067K->7097487K(12287936K), 0.0656080 secs]
When I first looked at this log I jumped right to the first concurrent mode failure. The first thing to notice was that the available free space in the tenured generation was large (about 4g). The total space in the tenured generation was 12266752K and the occupancy (amount of space currently being used) of the tenured generation was only 8285141K (see the part of the log immediately following the first "concurrent mode failure" message). That's about 4g of space. With that much free space the only thing I could think of was a really bad case of fragmentation. Now a concurrent mode failure is bad for the low-pause collector. If it is due to fragmentation at least the resulting collection is a compacting collection and you should not have to worry about fragmentation for a while. So why is there another concurrent mode failure after just one minor collection? And there is even more free space in the tenured generation when this second one occurred (about 5g). So now I'm sweating. I fortunately started noticing some other peculiarities in the log. For example the first minor collection starts when the young generation had only allocated 15343K out of a total of 21184K. That's not that unusual because the survivor space can be sizable and mostly empty. But the third collection is also a minor collection and the young generation has allocated 21120K by the time the minor collection starts (as does the fifth collection). Hmmm. Looking at the occupancies of the young generation at the point of the two concurrent mode failures shows the pattern: the young generation has a good chunk of free space but is still being collected. So I asked the customer if very large objects are being allocated, objects that are approaching the size of the young generation. To my relief the answer was yes. What follows now is my interpretation of the logs. I didn't have the application to run and really debug the behavior, but I think the pieces fit together.
The first collection (a minor collection) starts seemingly early because a large object is being allocated. The object is larger than the avalable space in eden but is not larger than all of eden so the minor collection does free up enough space to allocate that large object. The next collection is started when an even larger object allocation is attempted. This is where bug 6369448 comes into play. If not for 6369448 the larger object would have been allocated out of the tenured generation at 2. (the corrected case that I discussed above). There was an inconsistency in the test at 2. and the check at 4. before the collection of the tenured generation. A young generation is divided into an eden and two survivor spaces. The test at 2. compared the object size to the total size of the young generation. The check at 4. only checked the size (as is correct) against eden. So the short circuit at 2. was not taken, the collection at 3. doesn't free up enough space, and a tenured generation collection (concurrent mode failure) is the result. The third collection is an uninteresting minor collection. The fourth collection again is a collection prompted by the allocation of an object too big to fit into eden so another concurrent mode failure happens. The fifth collection is also uninteresting as are the many minor collections that follow.
My story for the two concurrent mode failures does depend on the large objects fitting in that gap in size between eden and the total young generation, but I'm willing to assume that there was a mix of object sizes and occasionally there was something in the gap. The two concurrent mode failure pattern above didn't happen often in the entire log and it was a long log. And the customer increased the size of the young generation and these types of concurrent mode failures did not reoccur.
I've always expected the occurrence of slow-path allocation to be a rare event. I think it is rare, but that's not the same as never so I'm thinking about adding a counter to be printed into the GC log to indicate how many slow-path allocations have occurred since the last GC.