java—如何找到在应用程序中花费的gc时间(从应用程序内部)

hzbexzde  于 2021-06-30  发布在  Java
关注(0)|答案(1)|浏览(345)

我们想知道在应用程序中花费的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似乎在一段时间后停留在某个数字上。
即使应用程序运行了几个小时,它也不会消失。
有人能指出这里的错误吗?

iyfamqjs

iyfamqjs1#

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

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

因此返回的时间不能是启动后的总gc时间。
它只是最后发生的gcs持续时间的总和。
正确的代码是:

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

相关问题