Fasterj

|home |articles |cartoons |site map |contact us |
Tools: | GC log analysers| Multi-tenancy tools| Books| SizeOf| Thread analysers|

Our valued sponsors who help make this site possible
AppDynamics: Get complete browser to backend visibility. Monitor Now! 

New Relic: Try free w/ production profiling and get a free shirt! 

ManageEngine's Site24x7: End-to-End analysis on Java EE web transactions. Sign up for FREE! 

Garbage Collection JMX Notifications

JProfiler
Get rid of your performance problems and memory leaks!

Chart Java Jitter with jHiccup
Monitor and identify pauses in your Java apps. Download now

Use jKool analytics as a service
Spot patterns in time-series data - real-time and free


See Your Message Here
You could have your tool advertised here, to be seen by thousands of potential customers

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:


AppDynamics
AppDynamics: Get complete browser to backend visibility. Monitor Now!

New Relic
New Relic: Try free w/ production profiling and get a free shirt!

ManageEngine
ManageEngine's Site24x7: End-to-End analysis on Java EE web transactions. Sign up for FREE!


JProfiler
Get rid of your performance problems and memory leaks!

Chart Java Jitter with jHiccup
Monitor and identify pauses in your Java apps. Download now

Use jKool analytics as a service
Spot patterns in time-series data - real-time and free


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

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 + " microseconds; 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 microseconds; 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 microseconds; 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


Last Updated: 2014-12-01
Copyright © 2007-2014 Fasterj.com. All Rights Reserved.
All trademarks and registered trademarks appearing on Fasterj.com are the property of their respective owners.
URL: http://www.fasterj.com/articles/gcnotifs.shtml
RSS Feed: http://www.JavaPerformanceTuning.com/newsletters.rss
Trouble with this page? Please contact us