利用JMX的Notifications监听GC

来源：互联网发布：8848 m3手机备份数据编辑：程序博客网时间：2024/06/09 18:36

在Java 7 update 4之前，用java代码监听GC运行情况是不可能的，Java 7 update 4之后，每个垃圾收集器都提供了通知机制，通过监听GarbageCollectorMXBean，可以得到GC完成之后的详细信息。

用法：

  Notification notif;  // receive the notification emitted by a GarbageCollectorMXBean and set to notif  ...  String notifType = notif.getType();  if (notifType.equals(GarbageCollectionNotificationInfo.GARBAGE_COLLECTION_NOTIFICATION)) {      // retrieve the garbage collection notification information      CompositeData cd = (CompositeData) notif.getUserData();      GarbageCollectionNotificationInfo info = GarbageCollectionNotificationInfo.from(cd);      ....  }

在GarbageCollectionNotificationInfo中，能获得大多数GC日志里面的内存：

属性名类型注释gcNamejava.lang.String如:G1 Old Generation,G1 Young Generation等gcActionjava.lang.String标识是哪个gc动作，一般为：end of major GC，Young Gen GC等，分别表示老年代和新生代的gc结束。gcCausejava.lang.String引起gc的原因,如：System.gc()，Allocation Failure，G1 Humongous Allocation等gcInfojavax.management.openmbean.CompositeDatagc的详细信息，见下表

GC详细信息：

属性名类型注释indexjava.lang.Long标识这个收集器进行了几次gcstartTimejava.lang.Longgc的开始时间endTimejava.lang.Longgc的结束时间memoryUsageBeforeGcjavax.management.openmbean.TabularDatagc前内存情况memoryUsageAfterGcjavax.management.openmbean.TabularDatagc后内存情况

内存使用情况：

initrepresents the initial amount of memory (in bytes) that the Java virtual machine requests from the operating system for memory management during startup. The Java virtual machine may request additional memory from the operating system and may also release memory to the system over time. The value of init may be undefined.usedrepresents the amount of memory currently used (in bytes).committedrepresents the amount of memory (in bytes) that is guaranteed to be available for use by the Java virtual machine. The amount of committed memory may change over time (increase or decrease). The Java virtual machine may release memory to the system and committed could be less than init. committed will always be greater than or equal to used.maxrepresents the maximum amount of memory (in bytes) that can be used for memory management. Its value may be undefined. The maximum amount of memory may change over time if defined. The amount of used and committed memory will always be less than or equal to max if max is defined. A memory allocation may fail if it attempts to increase the used memory such that used > committed even if used less equal max would still be true (for example, when the system is low on virtual memory).

Below is a picture showing an example of a memory pool:

    +----------------------------------------------+    +////////////////           |                  +    +////////////////           |                  +    +----------------------------------------------+    |--------|       init    |---------------|           used    |---------------------------|              committed    |----------------------------------------------|

目前的监听机制只能得到GC完成之后的数据，其它环节的GC情况无法观察到。

并且gc的详细信息中的耗时也没有细分停顿时间和并发时间，相信这个数据更为重要。

实例：

 
/**
 * 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();
 
        }
 
    }
 
}
view rawGCMonitoring.java hosted with ❤ by GitHub

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