why GC is running every hour?

Question

We have observed that full garbage collections (GCs) are often performed on an hourly basis.

Checked the time intreval of JreMemoryLeakPreventionListener. it is set to Long.MAX_VALUE. though gc is running every hour.

Also observed that GC called hourly basis is an explicit GC

GC logs:

2016-10-15T23:23:09.341-0400: 165558.099: [GC (System.gc()) [PSYoungGen: 264601K->5865K(1357312K)] 389672K->130937K(4153856K), 0.0075210 secs] [Times: user=0.07 sys=0.00, real=0.00 secs] 
2016-10-15T23:23:09.349-0400: 165558.107: [Full GC (System.gc()) [PSYoungGen: 5865K->0K(1357312K)] [ParOldGen: 125071K->125178K(2796544K)] 130937K->125178K(4153856K) [PSPermGen: 72263K->72263K(131072K)], 0.3417940 secs] [Times: user=5.16 sys=0.04, real=0.35 secs] 
2016-10-16T00:23:09.692-0400: 169158.450: [GC (System.gc()) [PSYoungGen: 198858K->2600K(1354752K)] 324037K->127779K(4151296K), 0.0077680 secs] [Times: user=0.08 sys=0.01, real=0.01 secs] 
2016-10-16T00:23:09.700-0400: 169158.458: [Full GC (System.gc()) [PSYoungGen: 2600K->0K(1354752K)] [ParOldGen: 125178K->124436K(2796544K)] 127779K->124436K(4151296K) [PSPermGen: 72282K->72282K(131072K)], 0.3481690 secs] [Times: user=5.13 sys=0.03, real=0.35 secs] 
2016-10-16T01:23:10.050-0400: 172758.808: [GC (System.gc()) [PSYoungGen: 279139K->7990K(1361408K)] 403576K->132426K(4157952K), 0.0075860 secs] [Times: user=0.07 sys=0.00, real=0.01 secs] 
2016-10-16T01:23:10.058-0400: 172758.815: [Full GC (System.gc()) [PSYoungGen: 7990K->0K(1361408K)] [ParOldGen: 124436K->124383K(2796544K)] 132426K->124383K(4157952K) [PSPermGen: 72284K->72284K(131072K)], 0.3713300 secs] [Times: user=5.73 sys=0.04, real=0.37 secs] 
2016-10-16T02:23:10.430-0400: 176359.188: [GC (System.gc()) [PSYoungGen: 112842K->544K(1358848K)] 237225K->124927K(4155392K), 0.0167260 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
2016-10-16T02:23:10.447-0400: 176359.205: [Full GC (System.gc()) [PSYoungGen: 544K->0K(1358848K)] [ParOldGen: 124383K->124265K(2796544K)] 124927K->124265K(4155392K) [PSPermGen: 72292K->72292K(131072K)], 0.2931430 secs] [Times: user=3.21 sys=0.03, real=0.29 secs] 
2016-10-16T03:23:10.742-0400: 179959.500: [GC (System.gc()) [PSYoungGen: 117926K->768K(1363968K)] 242192K->125033K(4160512K), 0.0070720 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
2016-10-16T03:23:10.749-0400: 179959.507: [Full GC (System.gc()) [PSYoungGen: 768K->0K(1363968K)] [ParOldGen: 124265K->124263K(2796544K)] 125033K->124263K(4160512K) [PSPermGen: 72306K->72306K(131072K)], 0.2602180 secs] [Times: user=3.33 sys=0.02, real=0.26 secs] 
2016-10-16T04:23:11.011-0400: 183559.768: [GC (System.gc()) [PSYoungGen: 198248K->2356K(1362432K)] 322511K->126619K(4158976K), 0.0076610 secs] [Times: user=0.07 sys=0.00, real=0.01 secs] 
2016-10-16T04:23:11.018-0400: 183559.776: [Full GC (System.gc()) [PSYoungGen: 2356K->0K(1362432K)] [ParOldGen: 124263K->124978K(2796544K)] 126619K->124978K(4158976K) [PSPermGen: 72308K->72308K(131072K)], 0.3353340 secs] [Times: user=5.78 sys=0.04, real=0.33 secs] 
2016-10-16T05:23:11.355-0400: 187160.113: [GC (System.gc()) [PSYoungGen: 228778K->10333K(1367040K)] 353757K->135311K(4163584K), 0.0069470 secs] [Times: user=0.08 sys=0.00, real=0.00 secs] 
2016-10-16T05:23:11.362-0400: 187160.120: [Full GC (System.gc()) [PSYoungGen: 10333K->0K(1367040K)] [ParOldGen: 124978K->130352K(2796544K)] 135311K->130352K(4163584K) [PSPermGen: 72308K->72308K(131072K)], 0.2240270 secs] [Times: user=2.96 sys=0.02, real=0.23 secs] 

Tomcat Version : Apache Tomcat/8.0.24

# /opt/tomcat/bin/version.sh 
Using CATALINA_BASE:   /opt/tomcat
Using CATALINA_HOME:   /opt/tomcat
Using CATALINA_TMPDIR: /opt/tomcat/temp
Using JRE_HOME:        /usr
Using CLASSPATH:       /opt/hbase/conf:/opt/tomcat/bin/bootstrap.jar:/opt/tomcat/bin/tomcat-juli.jar
Server version: Apache Tomcat/8.0.24
Server built:   Jul 1 2015 20:19:55 UTC
Server number:  8.0.24.0
OS Name:        Linux
OS Version:     2.6.32-573.3.1.el6.x86_64
Architecture:   amd64
JVM Version:    1.7.0_79-b15
JVM Vendor:     Oracle Corporation

Why GC is running on hourly basis even though the heap is not full?

Coppersmith

your GC log is not really readable. – Rationalize

Is your application code explicitly invoking System.gc()? Looks like it, because Full GC is triggered 23rd minute of every hour. – Herr

No. System.gc() is not invoked in the application code – Coppersmith

It is most likely 23 mins past the hour because it was started at 23 mins past the hour. See my answer, – Darrin

consider setting a method entry breakpoint on System.gc – Forebear

Answer 1

I suspect this is a duplicate but can't find it.

The default period for the DGC (Distributed GC) is 1 hour. This runs regularly to clean up distributed RMI resources such as JMX.

You can lengthen the cycle to a week.

https://docs.oracle.com/javase/8/docs/technotes/guides/rmi/sunrmiproperties.html

see

sun.rmi.dgc.server.gcInterval

When it is necessary to ensure that unreachable remote objects are unexported and garbage collected in a timely fashion, the value of this property represents the maximum interval (in milliseconds) that the Java RMI runtime will allow between garbage collections of the local heap. The default value is 3600000 milliseconds (one hour).

and

sun.rmi.dgc.client.gcInterval

When it is necessary to ensure that DGC clean calls for unreachable remote references are delivered in a timely fashion, the value of this property represents the maximum interval (in milliseconds) that the Java RMI runtime will allow between garbage collections of the local heap. The default value is 3600000 milliseconds (one hour).

Both of these have to be set to a high number (I set it to a week)

Darrin

This every one hour GC is not happening regularly. – Coppersmith

sometimes it is not happening on hourly basis – Coppersmith

@Coppersmith In that case, it is running because it actually needed it or System.gc() was called, possibly by a library. – Darrin

Is there any way to identify which library is calling the GC explicitly . i can see 2 types of collection type in GC log. – Coppersmith

[Full GC (Ergonomics) and [Full GC (System.gc()) – Coppersmith

For hourly basis GC, collection type is "GC (System.gc())". – Coppersmith

@Coppersmith Ergonomics is due to a formula blogs.oracle.com/jonthecollector/entry/the_unspoken_the_why_of Most likely your GC isn't tuned properly. – Darrin

For irregular GC, collection type is "[Full GC (Ergonomics) " – Coppersmith

@Coppersmith sometimes you get two log lines for a single Full GC. The format of logs changes so much, you can determine the update of any version of Java just from the difference between log output formats. – Darrin

@ Peter Lawrey i am not getting two log lines for single GC.the problem is, full GC was running on hourly basis yesterday. but it is not running on hourly basis today.i just want to understand when GC will be called on regular(hourly) and irregular interval – Coppersmith

@Coppersmith it checks every hour whether a GC has run or not. If no GC has happened for an hour it triggers a Full GC. When your application is triggering a GC otherwise, there is no extra Full GC. – Darrin

but it is not happening every time. today gc has run only once. it supposed to be 9 times as the current time is 09:30. that is why i am suspecting that GC is not happening properly. – Coppersmith

@Coppersmith good point, it should be triggering a GC even if there is nothing to clean up. Perhaps it can detect whether there have been any remote objects left. – Darrin

This answer is almost correct. RMI DGC runs local GC every hour, to pick up what DGC has released. DGC itself works on a timed lease principle. So the simple answer is that RMI calls System.gc() every hour. – Quell