CODEWITHSUNDEEP
javagarbage-collectionjvm
btz
btz

Reputation: 75

Programmatically capture Full GC count

I'm trying to capture the full GCs which occur in our Java application. So far I have two approaches, both with flaws:

  1. Poll the GarbageCollectorMXBean objects every x seconds, then try to pull the GC time and the GC count since the last poll and try to detect how long a GC occurred. Unfortunately with this, we don't know if it's a Full GC.
  2. Use javax.management.NotificationListener, the subscribe to the GarbageCollectorMXBean notifications. In theory, the application will then be notified when a GC occurs, with the text "end of major GC" and "end of minor GC" as well as a cause. The flaw of this approach is that the duration seems to be wildly incorrect (sometimes showing 898 seconds when the GC log will show .2 seconds) and there is the mysterious case "No GC" which seems to indicate no GC was actually performed (as there was no entry in the gc log).

A hybrid approach is possible where the GC MXBeans can be queried when I get a GC notification, then check if a GC has been performed. The downside of this is that the No GC cause might still trigger at the end of "major GC" and cause the logic to be more complex.

What I'm really after is the total amount of time the application has been paused due to GC operations. I figure that capturing a full GC will be adequate to indicate that the application has halted for a period of time, so that if we detect frequent GCs we know there is heavy usage or the application will run out of memory shortly. Is there a better solution to detecting GC time and whether there was a full GC?

Edit: To be clear, I would like to capture this information inside the given JVM. This JVM is controlled by a separate team, and we don't necessary have control over the JVM arguments they will set, we can only make recommendations. The idea is similar to flight recorder, but instead providing information in real time to administrators.

Upvotes: 5

Views: 3237

Answers (4)

Michael Tang
Michael Tang

Reputation: 11

Through the name of GarbageCollectorMXBean, we can deduce which one is responsible the execution of full gc. 

GarbageCollectorMXBean fullGcMXBean = null;
        List<GarbageCollectorMXBean> gcMxBeanList = ManagementFactory.getGarbageCollectorMXBeans();
        for(GarbageCollectorMXBean gcMxBean: gcMxBeanList){
            if(gcMxBean.getName().endsWith("MarkSweep")){
                fullGcMXBean = gcMxBean;
                break;
            }
        }

Upvotes: 1

Peter Lamberg
Peter Lamberg

Reputation: 8641

You can listen for GC notifications. See code below.

I'm crossposting this answer here since it seems relevant. Based on pointers given by @the8472 in this question I crafted a more complete sample for logging GC from inside JVM (and thus detecting/counting it). I hope this will save somebody some time :)

package fi.pelam.gclogutil;
import java.lang.management.*;
import java.util.Map;
import javax.management.openmbean.CompositeData;
import javax.management.*;

import com.sun.management.GarbageCollectionNotificationInfo;
import com.sun.management.GcInfo;

public class GcLogUtil {
    static public void startLoggingGc() {
        // http://www.programcreek.com/java-api-examples/index.php?class=javax.management.MBeanServerConnection&method=addNotificationListener
        // https://docs.oracle.com/javase/8/docs/jre/api/management/extension/com/sun/management/GarbageCollectionNotificationInfo.html#GARBAGE_COLLECTION_NOTIFICATION
        for (GarbageCollectorMXBean gcMbean : ManagementFactory.getGarbageCollectorMXBeans()) {
            try {
                ManagementFactory.getPlatformMBeanServer().
                        addNotificationListener(gcMbean.getObjectName(), listener, null,null);
            } catch (Exception e) {
                e.printStackTrace();
            }
        }
    }

    static private NotificationListener listener = new NotificationListener() {
        @Override
        public void handleNotification(Notification notification, Object handback) {
            if (notification.getType().equals(GarbageCollectionNotificationInfo.GARBAGE_COLLECTION_NOTIFICATION)) {
                // https://docs.oracle.com/javase/8/docs/jre/api/management/extension/com/sun/management/GarbageCollectionNotificationInfo.html
                CompositeData cd = (CompositeData) notification.getUserData();
                GarbageCollectionNotificationInfo gcNotificationInfo = GarbageCollectionNotificationInfo.from(cd);
                GcInfo gcInfo = gcNotificationInfo.getGcInfo();
                System.out.println("GarbageCollection: "+
                        gcNotificationInfo.getGcAction() + " " +
                        gcNotificationInfo.getGcName() +
                        " duration: " + gcInfo.getDuration() + "ms" +
                        " used: " + sumUsedMb(gcInfo.getMemoryUsageBeforeGc()) + "MB" +
                        " -> " + sumUsedMb(gcInfo.getMemoryUsageAfterGc()) + "MB");
            }
        }
    };

    static private long sumUsedMb(Map<String, MemoryUsage> memUsages) {
        long sum = 0;
        for (MemoryUsage memoryUsage : memUsages.values()) {
            sum += memoryUsage.getUsed();
        }
        return sum / (1024 * 1024);
    }
}

Upvotes: 3

Thorbj&#248;rn Ravn Andersen
Thorbj&#248;rn Ravn Andersen

Reputation: 75356

If you can access the file system of the JVM in question, you can tell the JVM to log information about garbage collections.

For Oracle Java 8 several flags exist (from http://docs.oracle.com/javase/8/docs/technotes/tools/unix/java.html#BABFAFAE)

-XX:+PrintGC

Enables printing of messages at every GC. By default, this option is disabled.

-XX:+PrintGCApplicationConcurrentTime

Enables printing of how much time elapsed since the last pause (for example, a GC pause). By default, this option is disabled.

-XX:+PrintGCApplicationStoppedTime

Enables printing of how much time the pause (for example, a GC pause) lasted. By default, this option is disabled.

-XX:+PrintGCDateStamps

Enables printing of a date stamp at every GC. By default, this option is disabled.

-XX:+PrintGCDetails

Enables printing of detailed messages at every GC. By default, this option is disabled.

-XX:+PrintGCTaskTimeStamps

Enables printing of time stamps for every individual GC worker thread task. By default, this option is disabled.

-XX:+PrintGCTimeStamps

Enables printing of time stamps at every GC. By default, this option is disabled.

Upvotes: 1

eckes
eckes

Reputation: 10423

If you use the hotspot specific GC beans, then you can new/old distinction, not concurrent/full. But that is in most cases enough.

In that case I would poll, and use the before/after informations in #LastGCInfo from the relevant generation:

For example java.lang:type=GarbageCollector,name=PS Scavenge is the young generation and java.lang:type=GarbageCollector,name=PS MarkSweep the old generation when ParallelOld is enabled.

With CMS you see concurrent collections and the full collections in java.lang:type=GarbageCollector,name=ConcurrentMarkSweep (but hopefully there is never a full collection :)

This is GC and VM specific, so it needs some heuristics to support all platforms you care about.

I think more fine-grained monitoring is only possible with the Flight Recorder events, but I havent have experience with that.

Upvotes: 2

Related Questions