Java garbage collection behavior for many short-lived objects

Question

I have a Java process that allocates a lot of very short objects (measured using YourKit to have an average age between 10-20 ms) and very few long objects, and its function is to receive a TCP message, somehow convert it and take to Kafka.

Most objects are created by Kafka, written in Scala, and therefore use many immutable objects. Using YourKit again, I measured that the size of immutable objects from Kafka is about 75% of the total, and the number of objects from Kafka is about 53% of the total. The vast majority of these objects do not miss 20 ms.

In an attempt to optimize my application for this use case, I tried to set up the garbage collector so that it recognized short-lived objects as a common precedent and dropped most before it reached the old generation. Here are the pens I have used so far:

-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps \ -XX:+PrintHeapAtGC -XX:+DisableExplicitGC -XX:+PrintTenuringDistribution \ -XX:+UseParallelOldGC -XX:NewRatio=1 \ 

The most important flags are -XX:NewRatio and -XX:UseParallelOldGC , but I notice some strange behavior in the GC templates.

Here is an illustration of using heap before the first full GC:

Here's an example of using a steady state heap:

As you can see, the life span is very slow (I also confirmed this using the heap information printed after each gc), until the first full GC, but after the first full GC, ownership starts very quickly.

I do not understand the reason for this, and I believe that full GCs are completely unnecessary - a full GC causes almost the entire heap that needs to be returned, because the vast majority of objects have already lost their strong link.

If this helps to include heap information after each GC, I will do it, but for now this should be enough information.

If anyone knows why this might happen, let me know. Full GC per hour seems too frequent for such an application.

EDIT:

As requested, here are some additional details:

• I am using Java 7, version 1.7.0_51.
• I allocated 1 GB of memory for this process, and the heap was fixed with this size.
• Some heaps from lower GCs to the first full GC:

 {Heap before GC invocations=395 (full 0): PSYoungGen total 521728K, used 519744K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 518656K, 100% used [0x00000000e0000000,0x00000000ffa80000,0x00000000ffa80000) from space 3072K, 35% used [0x00000000ffd00000,0x00000000ffe10000,0x0000000100000000) to space 2560K, 0% used [0x00000000ffa80000,0x00000000ffa80000,0x00000000ffd00000) ParOldGen total 524288K, used 177521K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 33% used [0x00000000c0000000,0x00000000cad5c560,0x00000000e0000000) PSPermGen total 33280K, used 33132K [0x00000000bae00000, 0x00000000bce80000, 0x00000000c0000000) object space 33280K, 99% used [0x00000000bae00000,0x00000000bce5b3d0,0x00000000bce80000) 35744.334: [GC Desired survivor size 2621440 bytes, new threshold 1 (max 15) [PSYoungGen: 519744K->1184K(521216K)] 697265K->179113K(1045504K), 0.0039310 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] Heap after GC invocations=395 (full 0): PSYoungGen total 521216K, used 1184K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 518656K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000ffa80000) from space 2560K, 46% used [0x00000000ffa80000,0x00000000ffba8000,0x00000000ffd00000) to space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000) ParOldGen total 524288K, used 177929K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 33% used [0x00000000c0000000,0x00000000cadc2560,0x00000000e0000000) PSPermGen total 33280K, used 33132K [0x00000000bae00000, 0x00000000bce80000, 0x00000000c0000000) object space 33280K, 99% used [0x00000000bae00000,0x00000000bce5b3d0,0x00000000bce80000) } 

• Heap output of the first full GC:

 {Heap before GC invocations=1457 (full 0): PSYoungGen total 521728K, used 520064K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 519168K, 100% used [0x00000000e0000000,0x00000000ffb00000,0x00000000ffb00000) from space 2560K, 35% used [0x00000000ffd80000,0x00000000ffe60000,0x0000000100000000) to space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000) ParOldGen total 524288K, used 523194K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 99% used [0x00000000c0000000,0x00000000dfeeea68,0x00000000e0000000) PSPermGen total 34304K, used 34213K [0x00000000bae00000, 0x00000000bcf80000, 0x00000000c0000000) object space 34304K, 99% used [0x00000000bae00000,0x00000000bcf695e8,0x00000000bcf80000) 99997.829: [GC Desired survivor size 2621440 bytes, new threshold 1 (max 15) [PSYoungGen: 520064K->1600K(521728K)] 1043258K->525386K(1046016K), 0.0072540 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] Heap after GC invocations=1457 (full 0): PSYoungGen total 521728K, used 1600K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 519168K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000ffb00000) from space 2560K, 62% used [0x00000000ffb00000,0x00000000ffc90000,0x00000000ffd80000) to space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000) ParOldGen total 524288K, used 523786K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 99% used [0x00000000c0000000,0x00000000dff82a68,0x00000000e0000000) PSPermGen total 34304K, used 34213K [0x00000000bae00000, 0x00000000bcf80000, 0x00000000c0000000) object space 34304K, 99% used [0x00000000bae00000,0x00000000bcf695e8,0x00000000bcf80000) } {Heap before GC invocations=1458 (full 1): PSYoungGen total 521728K, used 1600K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 519168K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000ffb00000) from space 2560K, 62% used [0x00000000ffb00000,0x00000000ffc90000,0x00000000ffd80000) to space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000) ParOldGen total 524288K, used 523786K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 99% used [0x00000000c0000000,0x00000000dff82a68,0x00000000e0000000) PSPermGen total 34304K, used 34213K [0x00000000bae00000, 0x00000000bcf80000, 0x00000000c0000000) object space 34304K, 99% used [0x00000000bae00000,0x00000000bcf695e8,0x00000000bcf80000) 99997.837: [Full GC [PSYoungGen: 1600K->0K(521728K)] [ParOldGen: 523786K->17123K(524288K)] 525386K->17123K(1046016K) [PSPermGen: 34213K->33877K(68096K)], 0.1576350 secs] [Times: user=0.53 sys=0.03, real=0.16 secs] Heap after GC invocations=1458 (full 1): PSYoungGen total 521728K, used 0K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 519168K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000ffb00000) from space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000) to space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000) ParOldGen total 524288K, used 17123K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 3% used [0x00000000c0000000,0x00000000c10b8fc8,0x00000000e0000000) PSPermGen total 68096K, used 33877K [0x00000000bae00000, 0x00000000bf080000, 0x00000000c0000000) object space 68096K, 49% used [0x00000000bae00000,0x00000000bcf156f0,0x00000000bf080000) } 

• The output of a small collection heap after the first full GC:

  {Heap before GC invocations=1837 (full 9): PSYoungGen total 509440K, used 507104K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 494592K, 100% used [0x00000000e0000000,0x00000000fe300000,0x00000000fe300000) from space 14848K, 84% used [0x00000000fe300000,0x00000000fef38000,0x00000000ff180000) to space 14848K, 0% used [0x00000000ff180000,0x00000000ff180000,0x0000000100000000) ParOldGen total 524288K, used 342941K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 65% used [0x00000000c0000000,0x00000000d4ee7520,0x00000000e0000000) PSPermGen total 54272K, used 33876K [0x00000000bae00000, 0x00000000be300000, 0x00000000c0000000) object space 54272K, 62% used [0x00000000bae00000,0x00000000bcf15378,0x00000000be300000) 133247.303: [GC Desired survivor size 15204352 bytes, new threshold 1 (max 15) [PSYoungGen: 507104K->13696K(509440K)] 850045K->369421K(1033728K), 0.0318090 secs] [Times: user=0.37 sys=0.01, real=0.03 secs] Heap after GC invocations=1837 (full 9): PSYoungGen total 509440K, used 13696K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 494592K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000fe300000) from space 14848K, 92% used [0x00000000ff180000,0x00000000ffee0000,0x0000000100000000) to space 14848K, 0% used [0x00000000fe300000,0x00000000fe300000,0x00000000ff180000) ParOldGen total 524288K, used 355725K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 67% used [0x00000000c0000000,0x00000000d5b63520,0x00000000e0000000) PSPermGen total 54272K, used 33876K [0x00000000bae00000, 0x00000000be300000, 0x00000000c0000000) object space 54272K, 62% used [0x00000000bae00000,0x00000000bcf15378,0x00000000be300000) } 

• The output of the full GC heap after the first:

 {Heap before GC invocations=1457 (full 0): PSYoungGen total 521728K, used 520064K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 519168K, 100% used [0x00000000e0000000,0x00000000ffb00000,0x00000000ffb00000) from space 2560K, 35% used [0x00000000ffd80000,0x00000000ffe60000,0x0000000100000000) to space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000) ParOldGen total 524288K, used 523194K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 99% used [0x00000000c0000000,0x00000000dfeeea68,0x00000000e0000000) PSPermGen total 34304K, used 34213K [0x00000000bae00000, 0x00000000bcf80000, 0x00000000c0000000) object space 34304K, 99% used [0x00000000bae00000,0x00000000bcf695e8,0x00000000bcf80000) 99997.829: [GC Desired survivor size 2621440 bytes, new threshold 1 (max 15) [PSYoungGen: 520064K->1600K(521728K)] 1043258K->525386K(1046016K), 0.0072540 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] Heap after GC invocations=1457 (full 0): PSYoungGen total 521728K, used 1600K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 519168K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000ffb00000) from space 2560K, 62% used [0x00000000ffb00000,0x00000000ffc90000,0x00000000ffd80000) to space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000) ParOldGen total 524288K, used 523786K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 99% used [0x00000000c0000000,0x00000000dff82a68,0x00000000e0000000) PSPermGen total 34304K, used 34213K [0x00000000bae00000, 0x00000000bcf80000, 0x00000000c0000000) object space 34304K, 99% used [0x00000000bae00000,0x00000000bcf695e8,0x00000000bcf80000) } {Heap before GC invocations=1458 (full 1): PSYoungGen total 521728K, used 1600K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 519168K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000ffb00000) from space 2560K, 62% used [0x00000000ffb00000,0x00000000ffc90000,0x00000000ffd80000) to space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000) ParOldGen total 524288K, used 523786K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 99% used [0x00000000c0000000,0x00000000dff82a68,0x00000000e0000000) PSPermGen total 34304K, used 34213K [0x00000000bae00000, 0x00000000bcf80000, 0x00000000c0000000) object space 34304K, 99% used [0x00000000bae00000,0x00000000bcf695e8,0x00000000bcf80000) 99997.837: [Full GC [PSYoungGen: 1600K->0K(521728K)] [ParOldGen: 523786K->17123K(524288K)] 525386K->17123K(1046016K) [PSPermGen: 34213K->33877K(68096K)], 0.1576350 secs] [Times: user=0.53 sys=0.03, real=0.16 secs] Heap after GC invocations=1458 (full 1): PSYoungGen total 521728K, used 0K [0x00000000e0000000, 0x0000000100000000, 0x0000000100000000) eden space 519168K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000ffb00000) from space 2560K, 0% used [0x00000000ffb00000,0x00000000ffb00000,0x00000000ffd80000) to space 2560K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x0000000100000000) ParOldGen total 524288K, used 17123K [0x00000000c0000000, 0x00000000e0000000, 0x00000000e0000000) object space 524288K, 3% used [0x00000000c0000000,0x00000000c10b8fc8,0x00000000e0000000) PSPermGen total 68096K, used 33877K [0x00000000bae00000, 0x00000000bf080000, 0x00000000c0000000) object space 68096K, 49% used [0x00000000bae00000,0x00000000bcf156f0,0x00000000bf080000) } 

Answer 1

The only full GC in your journal ^{[seriously, is it too hard to publish somwhere without destroying it?]} Takes about 160 ms, younger GCs take 30 ms or less.

You do not set any pause time goals.

One or more hours pass between full GCs.

If you get the impression that full GCs are somehow “evil” and should be avoided at all costs, then you are mistaken.

They can be frustrating with CMS because with CMS Full GCs are a single-threaded failover strategy that can take a lot of time on large heaps.

But you use the Parallel Old Gen collector, as well as the bandwidth collector on a small heap, where the full GC is very fast, especially if most of the old gen content is garbage that does not need to be visited by an icon-programmable algorithm.

And given that you did not even indicate the purpose of the pause time or tried the CMS, it seems to me that you do not even have a clearly defined goal for them.

So there is no problem here.