JProfiler Get rid of your performance problems and memory leaks! Modern Garbage Collection Tuning Java Performance Tuning, 2nd ed The classic and most comprehensive book on tuning Java Java Performance Tuning Newsletter Your source of Java performance news. Subscribe now! Enter email: JProfiler Get rid of your performance problems and memory leaks!

Jack Shirazi gives you the details on accessing garbage collection notifications that are available from the Oracle Java 7 update 4 JVM.

From Java 7 update 4 (jdk1.7.0_04) notifications are generated after each garbage collection (GC). Prior to this there was no way to get notifications from the garbage collector: previous JMX GC monitoring was done on a polling basis, requesting the details of the last GC (this has been available since the platform mbeans were first provided), and by requesting overall heap usage from the Runtime object. Although this is acceptable in many cases, it did mean you were prone to missing individual GCs, which can lead to inaccurate analysis. The way most tuners obtained the data they needed for GC analysis was via a GC log, using -verbose:gc (to stdout) or -Xloggc:FILEPATH (to file FILEPATH) with various other GC options to specify the level of GC logging detail you wanted, e.g. -XX:+PrintGCTimeStamps

The data available now in 7u4 from GC notifications is basic, so it is likely that many GC tuning exercises will still require use of the gc file logging output. However the JMX notifications can be useful - they provide the quickest available information to the JVM itself of what its GC is doing, and they are a valid option for processes outside the JVM for basic GC monitoring as an alternative to tailing the GC logs.

How do you get the notifications? Here's a basic example of monitoring your own JVMs GCs - just call the installGCMonitoring() method, and this outputs various statistics obtainable from the GC notifications. The code is quite short and provides full details on accessing all the information available in the 7u4 release (it's possible more details will become available in future releases). The same details are available remotely using normal JMX access. Note the required code is really just getting the beans and adding a listener, quite straightforward. The example here is a lot longer than the few lines that takes in order to provide an example of displaying the resulting data usefully, so that it's easier for you to adapt to your needs.

  public static void installGCMonitoring(){
    //get all the GarbageCollectorMXBeans - there's one for each heap generation
    //so probably two - the old generation and young generation
    List<GarbageCollectorMXBean> gcbeans = java.lang.management.ManagementFactory.getGarbageCollectorMXBeans();
    //Install a notifcation handler for each bean
    for (GarbageCollectorMXBean gcbean : gcbeans) {
      System.out.println(gcbean);
      NotificationEmitter emitter = (NotificationEmitter) gcbean;
      //use an anonymously generated listener for this example
      // - proper code should really use a named class
      NotificationListener listener = new NotificationListener() {
        //keep a count of the total time spent in GCs
        long totalGcDuration = 0;

        //implement the notifier callback handler
        @Override
        public void handleNotification(Notification notification, Object handback) {
          //we only handle GARBAGE_COLLECTION_NOTIFICATION notifications here
          if (notification.getType().equals(GarbageCollectionNotificationInfo.GARBAGE_COLLECTION_NOTIFICATION)) {
            //get the information associated with this notification
            GarbageCollectionNotificationInfo info = GarbageCollectionNotificationInfo.from((CompositeData) notification.getUserData());
            //get all the info and pretty print it
            long duration = info.getGcInfo().getDuration();
            String gctype = info.getGcAction();
            if ("end of minor GC".equals(gctype)) {
              gctype = "Young Gen GC";
            } else if ("end of major GC".equals(gctype)) {
              gctype = "Old Gen GC";
            }
            System.out.println();
            System.out.println(gctype + ": - " + info.getGcInfo().getId()+ " " + info.getGcName() + " (from " + info.getGcCause()+") "+duration + " milliseconds; start-end times " + info.getGcInfo().getStartTime()+ "-" + info.getGcInfo().getEndTime());
            //System.out.println("GcInfo CompositeType: " + info.getGcInfo().getCompositeType());
            //System.out.println("GcInfo MemoryUsageAfterGc: " + info.getGcInfo().getMemoryUsageAfterGc());
            //System.out.println("GcInfo MemoryUsageBeforeGc: " + info.getGcInfo().getMemoryUsageBeforeGc());

            //Get the information about each memory space, and pretty print it
            Map<String, MemoryUsage> membefore = info.getGcInfo().getMemoryUsageBeforeGc();
            Map<String, MemoryUsage> mem = info.getGcInfo().getMemoryUsageAfterGc();
            for (Entry<String, MemoryUsage> entry : mem.entrySet()) {
              String name = entry.getKey();
              MemoryUsage memdetail = entry.getValue();
              long memInit = memdetail.getInit();
              long memCommitted = memdetail.getCommitted();
              long memMax = memdetail.getMax();
              long memUsed = memdetail.getUsed();
              MemoryUsage before = membefore.get(name);
              long beforepercent = ((before.getUsed()*1000L)/before.getCommitted());
              long percent = ((memUsed*1000L)/before.getCommitted()); //>100% when it gets expanded

              System.out.print(name + (memCommitted==memMax?"(fully expanded)":"(still expandable)") +"used: "+(beforepercent/10)+"."+(beforepercent%10)+"%->"+(percent/10)+"."+(percent%10)+"%("+((memUsed/1048576)+1)+"MB) / ");
            }
            System.out.println();
            totalGcDuration += info.getGcInfo().getDuration();
            long percent = totalGcDuration*1000L/info.getGcInfo().getEndTime();
            System.out.println("GC cumulated overhead "+(percent/10)+"."+(percent%10)+"%");
          }
        }
      };

      //Add the listener
      emitter.addNotificationListener(listener, null, null);
    }
  }

And here's an example of the output generated by the first couple of GCs from the above installGCMonitoring() method, running in a GC intensive application:

Young Gen GC: - 1 Copy (from Allocation Failure) 122440 milliseconds; start-end times 980649-1103089
Perm Gen [shared-ro](fully expanded)used: 45.1%->45.1%(5MB) / Tenured Gen(still expandable)used: 0.0%->33.6%(4MB) / Eden Space(still expandable)used: 99.9%->0.0%(1MB) / Code Cache(still expandable)used: 95.8%->95.8%(1MB) / Perm Gen [shared-rw](fully expanded)used: 54.4%->54.4%(7MB) / Perm Gen(still expandable)used: 1.5%->1.5%(1MB) / Survivor Space(still expandable)used: 0.0%->100.0%(1MB) / 
GC cumulated overhead 11.0%

Young Gen GC: - 2 Copy (from Allocation Failure) 258976 milliseconds; start-end times 3459569-3718545
Perm Gen [shared-ro](fully expanded)used: 45.1%->45.1%(5MB) / Tenured Gen(still expandable)used: 33.6%->71.2%(8MB) / Eden Space(still expandable)used: 99.9%->0.0%(1MB) / Code Cache(still expandable)used: 95.6%->95.6%(1MB) / Perm Gen [shared-rw](fully expanded)used: 54.4%->54.4%(7MB) / Perm Gen(still expandable)used: 4.0%->4.0%(1MB) / Survivor Space(still expandable)used: 100.0%->100.0%(1MB) / 
GC cumulated overhead 10.2%

Contact Me