java - 如何查找应用程序中花费的 GC 时间(从应用程序内部)

Question

我们想知道应用程序中花费的 GC 时间。

从应用程序外部很容易做到这一点，但我们想从应用程序内部了解它。

如果每分钟 GC 时间太高，请采取一些纠正措施。

这是到目前为止编写的代码。

private Long prevGcObservingTime = null; // field in the class
private Long prevGcDuration = null; // field in the class

boolean isGcTimeHigh(boolean printStats)
{
    List<GarbageCollectorMXBean> mxBeans = ManagementFactory.getGarbageCollectorMXBeans();
    long totalGcSinceStartup = 0;
    for (GarbageCollectorMXBean mxBean: mxBeans)
    {
      if (mxBean instanceof com.sun.management.GarbageCollectorMXBean)
      {
        com.sun.management.GarbageCollectorMXBean internal = (com.sun.management.GarbageCollectorMXBean) mxBean;
        GcInfo gcInfo = internal.getLastGcInfo();
        totalGcSinceStartup += gcInfo.getDuration();
      }
    }
    long currentTime = System.currentTimeMillis();
    if (prevGcObservingTime == null)
    {
      // collecting GC for the first time
      prevGcObservingTime = currentTime;
      prevGcDuration = totalGcSinceStartup;
      return false;
    }
    double deltaDuration = (currentTime - prevGcObservingTime)/1000.0;
    if (deltaDuration <= 1)
    {
      // time between two measurements should be reasonable 
      return false;
    }
    if (deltaDuration > 60)
    {
      // too much time gap can have skewed measurement from a brief GC eruption
      prevGcObservingTime = currentTime;
      prevGcDuration = totalGcSinceStartup;
      return false;
    }
    double gcTimePerSecond = (totalGcSinceStartup - prevGcDuration)/deltaDuration;
    prevGcObservingTime = currentTime;
    prevGcDuration = totalGcSinceStartup;

    if (printStats)
      log.info("prevGcDuration={}, totalGcSinceStartup={}, deltaDuration={}, gcTimePerSecond={}",
        prevGcDuration, totalGcSinceStartup, deltaDuration, gcTimePerSecond);

    return false;
}

这是输出:

2015-01-14 22:27:55.227; prevGcDuration=691, totalGcSinceStartup=691, deltaDuration=1.001, gcTimePerSecond=0.0
2015-01-14 22:28:07.576; prevGcDuration=691, totalGcSinceStartup=691, deltaDuration=12.349, gcTimePerSecond=0.0
2015-01-14 22:28:08.690; prevGcDuration=676, totalGcSinceStartup=676, deltaDuration=19.56, gcTimePerSecond=-0.7668711656441718
2015-01-14 22:28:08.854; prevGcDuration=675, totalGcSinceStartup=675, deltaDuration=13.245, gcTimePerSecond=-1.20800302000755
2015-01-14 22:28:22.210; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=14.634, gcTimePerSecond=-1.4350143501435013
2015-01-14 22:28:23.891; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=1.001, gcTimePerSecond=0.0
2015-01-14 22:28:30.117; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=1.895, gcTimePerSecond=0.0
2015-01-14 22:28:37.228; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=2.001, gcTimePerSecond=0.0
2015-01-14 22:28:38.728; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=1.002, gcTimePerSecond=0.0
2015-01-14 22:28:38.901; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=1.001, gcTimePerSecond=0.0
2015-01-14 22:28:52.242; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=1.001, gcTimePerSecond=0.0
2015-01-14 22:28:53.740; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=2.001, gcTimePerSecond=0.0
2015-01-14 22:28:53.911; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=2.002, gcTimePerSecond=0.0
2015-01-14 22:29:08.753; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=1.001, gcTimePerSecond=0.0
2015-01-14 22:29:08.925; prevGcDuration=670, totalGcSinceStartup=670, deltaDuration=2.001, gcTimePerSecond=0.0
2015-01-14 22:29:14.672; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=2.416, gcTimePerSecond=-15.728476821192054
2015-01-14 22:29:14.678; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=2.75, gcTimePerSecond=-13.818181818181818
2015-01-14 22:29:16.056; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=1.384, gcTimePerSecond=0.0
2015-01-14 22:29:37.657; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=15.594, gcTimePerSecond=0.0
2015-01-14 22:29:37.673; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=16.988, gcTimePerSecond=0.0
2015-01-14 22:29:37.678; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=25.922, gcTimePerSecond=-1.46593627034951
2015-01-14 22:29:52.693; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=1.001, gcTimePerSecond=0.0
2015-01-14 22:29:52.693; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=1.001, gcTimePerSecond=0.0
2015-01-14 22:29:52.701; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=1.001, gcTimePerSecond=0.0
2015-01-14 22:29:59.707; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=1.001, gcTimePerSecond=0.0
2015-01-14 22:30:08.562; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=8.862, gcTimePerSecond=0.0
2015-01-14 22:30:10.218; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=1.656, gcTimePerSecond=0.0
2015-01-14 22:30:10.221; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=10.514, gcTimePerSecond=0.0
2015-01-14 22:30:11.303; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=1.085, gcTimePerSecond=0.0
2015-01-14 22:30:12.364; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=1.061, gcTimePerSecond=0.0
2015-01-14 22:30:29.293; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=16.929, gcTimePerSecond=0.0
2015-01-14 22:30:29.297; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=19.076, gcTimePerSecond=0.0
2015-01-14 22:30:30.838; prevGcDuration=632, totalGcSinceStartup=632, deltaDuration=1.545, gcTimePerSecond=0.0

问题是totalGcSinceStartup在一段时间后似乎卡在某个数字上。

即使应用程序运行几个小时，它也不会消失。

有人可以指出这里的错误吗？

Answer 1

我发现了一个愚蠢的错误:

    GcInfo gcInfo = internal.getLastGcInfo();
    totalGcSinceStartup += gcInfo.getDuration();

所以返回的时间不可能是自启动以来GC的总时间。

它只是最后发生的 GC 的持续时间总和。

正确的代码是:

long totalGcSinceStartup = 0;
for (GarbageCollectorMXBean mxBean: mxBeans)
    totalGcSinceStartup += mxBean.getCollectionTime();