GarbageCollect Notification in JDK7

GCMonitoring.java

/**
 * gc monitoring only on jdk7 or later
 *
 * @author lichengwu
 * @version 1.0
 * @created 2013-09-14 10:44 PM
 */
public class GCMonitoring {

    private static final long JVM_START_TIME = ManagementFactory.getRuntimeMXBean().getStartTime();


    private static DateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");

    private static final long ONE_BYTE = 1024;


    public static void init() {
        //get all GarbageCollectorMXBeans
        List<GarbageCollectorMXBean> gcBeans = ManagementFactory.getGarbageCollectorMXBeans();
        //register every GarbageCollectorMXBean
        for (GarbageCollectorMXBean gcBean : gcBeans) {
            System.out.println(
                    "register " + gcBean.getName() + " for " + Arrays.deepToString(gcBean.getMemoryPoolNames()));

            NotificationEmitter emitter = (NotificationEmitter) gcBean;
            //new listener
            NotificationListener listener = new NotificationListener() {
                //record total gc time spend
                long totalGcTimeSpend = 0;

                @Override
                public void handleNotification(Notification notification, Object handback) {
                    HandBack handBack = (HandBack) handback;

                    //get gc info
                    GarbageCollectionNotificationInfo info =
                            GarbageCollectionNotificationInfo.from((CompositeData) notification.getUserData());
                    //output
                    String gcType = info.getGcAction();
                    if (gcType.length() > 7) {
                        gcType = gcType.substring(7);
                    }
                    //get a glance of gc
                    StringBuilder gcGlance = new StringBuilder();
                    gcGlance.append(gcType).append(": - ").append(info.getGcInfo().getId());
                    gcGlance.append(" (").append(info.getGcCause()).append(") ");
                    gcGlance.append("start: ")
                            .append(dateFormat.format(new Date(JVM_START_TIME + info.getGcInfo().getStartTime())));
                    gcGlance.append(", end: ")
                            .append(dateFormat.format(new Date(JVM_START_TIME + info.getGcInfo().getEndTime())));

                    System.out.println(gcGlance.toString());

                    //memory info
                    Map<String, MemoryUsage> beforeUsageMap = info.getGcInfo().getMemoryUsageBeforeGc();
                    Map<String, MemoryUsage> afterUsageMap = info.getGcInfo().getMemoryUsageAfterGc();
                    for (Map.Entry<String, MemoryUsage> entry : afterUsageMap.entrySet()) {
                        String name = entry.getKey();
                        MemoryUsage afterUsage = entry.getValue();
                        MemoryUsage beforeUsage = beforeUsageMap.get(name);

                        StringBuilder usage = new StringBuilder();
                        usage.append("\t[").append(name).append("] ");
                        usage.append("init:").append(afterUsage.getInit() / ONE_BYTE).append("K; ");
                        usage.append("used:").append(handBack
                                .handUsage(beforeUsage.getUsed(), afterUsage.getUsed(), beforeUsage.getMax()))
                                .append("; ");
                        usage.append("committed: ").append(handBack
                                .handUsage(beforeUsage.getCommitted(), afterUsage.getCommitted(),
                                        beforeUsage.getMax()));

                        System.out.println(usage.toString());
                    }
                    totalGcTimeSpend += info.getGcInfo().getDuration();
                    //summary
                    long percent =
                            (info.getGcInfo().getEndTime() - totalGcTimeSpend) * 1000L / info.getGcInfo().getEndTime();
                    StringBuilder summary = new StringBuilder();
                    summary.append("duration:").append(info.getGcInfo().getDuration()).append("ms");
                    summary.append(", throughput:").append((percent / 10)).append(".").append(percent % 10).append('%');
                    System.out.println(summary.toString());
                    System.out.println();
                }
            };

            //add the listener
            emitter.addNotificationListener(listener, new NotificationFilter() {
                private static final long serialVersionUID = 3763793138186359389L;

                @Override
                public boolean isNotificationEnabled(Notification notification) {
                    //filter GC notification
                    return notification.getType()
                            .equals(GarbageCollectionNotificationInfo.GARBAGE_COLLECTION_NOTIFICATION);
                }
            }, HandBack.getInstance());
        }
    }


    private static class HandBack {

        private HandBack() {
        }

        private static HandBack instance = new HandBack();

        public static HandBack getInstance() {
            return instance;
        }

        public String handUsage(long before, long after, long max) {
            StringBuilder usage = new StringBuilder();

            if (max == -1) {
                usage.append("").append(before / ONE_BYTE).append("K -> ").append(after / ONE_BYTE).append("K)");
                return usage.toString();
            }

            long beforePercent = ((before * 1000L) / max);
            long afterPercent = ((after * 1000L) / max);

            usage.append(beforePercent / 10).append('.').append(beforePercent % 10).append("%(")
                    .append(before / ONE_BYTE).append("K) -> ").append(afterPercent / 10).append('.')
                    .append(afterPercent % 10).append("%(").append(after / ONE_BYTE).append("K)");
            return usage.toString();

        }

    }

}

output

register G1 Young Generation for [G1 Eden Space, G1 Survivor Space]
register G1 Old Generation for [G1 Eden Space, G1 Survivor Space, G1 Old Gen, G1 Perm Gen]
major GC: - 1 (System.gc()) start: 2013-09-15 09:38:35.193, end: 2013-09-15 09:38:59.283
	[G1 Eden Space] init:26624K; used:3072K -> 4096K); committed: 26624K -> 26624K)
	[G1 Old Gen] init:97280K; used:0.0%(0K) -> 0.0%(0K); committed: 4.9%(97280K) -> 4.9%(97280K)
	[Code Cache] init:2496K; used:0.8%(433K) -> 0.8%(433K); committed: 5.0%(2496K) -> 5.0%(2496K)
	[G1 Perm Gen] init:20480K; used:5.9%(5012K) -> 5.9%(5012K); committed: 24.3%(20480K) -> 24.3%(20480K)
	[G1 Survivor Space] init:0K; used:0K -> 0K); committed: 0K -> 0K)
duration:24090ms, throughput:87.3%

minor GC: - 1 (G1 Humongous Allocation) start: 2013-09-15 09:38:59.618, end: 2013-09-15 09:39:00.870
	[G1 Eden Space] init:26624K; used:0K -> 1024K); committed: 4096K -> 4096K)
	[G1 Old Gen] init:97280K; used:0.1%(1990K) -> 0.1%(1990K); committed: 0.1%(3072K) -> 0.1%(3072K)
	[Code Cache] init:2496K; used:0.8%(433K) -> 0.8%(433K); committed: 5.0%(2496K) -> 5.0%(2496K)
	[G1 Perm Gen] init:20480K; used:5.9%(5017K) -> 5.9%(5017K); committed: 24.3%(20480K) -> 24.3%(20480K)
	[G1 Survivor Space] init:0K; used:0K -> 0K); committed: 0K -> 0K)
duration:1252ms, throughput:99.3%

minor GC: - 2 (G1 Humongous Allocation) start: 2013-09-15 09:39:21.662, end: 2013-09-15 09:39:23.649
	[G1 Eden Space] init:26624K; used:1024K -> 1024K); committed: 2048K -> 2048K)
	[G1 Old Gen] init:97280K; used:1.8%(35814K) -> 1.8%(35814K); committed: 3.7%(73728K) -> 3.7%(73728K)
	[Code Cache] init:2496K; used:0.8%(437K) -> 0.8%(437K); committed: 5.0%(2496K) -> 5.0%(2496K)
	[G1 Perm Gen] init:20480K; used:6.5%(5487K) -> 6.5%(5487K); committed: 24.3%(20480K) -> 24.3%(20480K)
	[G1 Survivor Space] init:0K; used:1024K -> 1024K); committed: 1024K -> 1024K)
duration:1987ms, throughput:98.4%

minor GC: - 3 (G1 Humongous Allocation) start: 2013-09-15 09:39:42.826, end: 2013-09-15 09:39:46.322
	[G1 Eden Space] init:26624K; used:1024K -> 1024K); committed: 45056K -> 45056K)
	[G1 Old Gen] init:97280K; used:1.8%(35910K) -> 1.8%(35910K); committed: 5.5%(109568K) -> 5.5%(109568K)
	[Code Cache] init:2496K; used:0.8%(440K) -> 0.8%(440K); committed: 5.0%(2496K) -> 5.0%(2496K)
	[G1 Perm Gen] init:20480K; used:6.5%(5533K) -> 6.5%(5533K); committed: 24.3%(20480K) -> 24.3%(20480K)
	[G1 Survivor Space] init:0K; used:1024K -> 1024K); committed: 1024K -> 1024K)
duration:3496ms, throughput:97.1%


Process finished with exit code 0