问题描述

在使用 micrometer 收集实例的 jvm 指标中，发现 gc 最长耗时不准确，数据如图

按照指标的逻辑，这里的最长时间也应该是 0.786ms 。

问题排查

自查代码

首先怀疑是否自己的收集数据代码写错了，导致数据未收取到。

由于 spring-boot 2.0 以上版本的 metrics 指标收集使用的 micrometer ，因此直接通过 actuator 接口查看数据，发现确实不准确，接口返回数据就是 0 。
检查代码逻辑，debug 确认代码无误，可以收集到数据，并且没有经过二次处理，可以返回到前端该数据。

查看源码

自己的收集逻辑没有问题，那么排查是否是数据本身的问题，查看 micrometer 源码。

使用 JvmGcMetrics 类收集 GC 相关指标，部分代码：

for (GarbageCollectorMXBean mbean : ManagementFactory.getGarbageCollectorMXBeans()) {
    if (mbean instanceof NotificationEmitter) {
        ((NotificationEmitter) mbean).addNotificationListener((notification, ref) -> {
            final String type = notification.getType();
            if (type.equals(GarbageCollectionNotificationInfo.GARBAGE_COLLECTION_NOTIFICATION)) {
                CompositeData cd = (CompositeData) notification.getUserData();
                GarbageCollectionNotificationInfo notificationInfo = GarbageCollectionNotificationInfo.from(cd);

                if (isConcurrentPhase(notificationInfo.getGcCause())) {
                   ...
                } else {
                    Timer.builder("jvm.gc.pause")
                            .tags(tags)
                            .tags("action", notificationInfo.getGcAction(),
                                    "cause", notificationInfo.getGcCause())
                            .description("Time spent in GC pause")
                            .register(registry)
                            .record(notificationInfo.getGcInfo().getDuration(), TimeUnit.MILLISECONDS);
                }
                ...
            }
        }, null, null);
    }

GarbageCollectorImpl 类实现了 NotificationBroadcaster 接口，因此当 GC 发生时，会执行监听中的函数，计算 Timer 指标。

Timer 的 record 方法会执行具体的数据记录

@Override
protected void recordNonNegative(long amount, TimeUnit unit) {
    long nanoAmount = (long) TimeUtils.convert(amount, unit, TimeUnit.NANOSECONDS);
    count.getAndAdd(1);//计次加1
    total.getAndAdd(nanoAmount);//增加总值
    max.record(nanoAmount, TimeUnit.NANOSECONDS);//记录最大值
}

那么查看 max.record 方法

private void updateMax(AtomicLong max, long sample) {
    for (; ; ) {
        long curMax = max.get();
        if (curMax >= sample || max.compareAndSet(curMax, sample))
            break;
    }
}

首先获取到当前的最大值，如果最大值大于新传入的值，则返回，否则替换最大值，并确认执行成功后返回。

这里使用了 AtomicLong 进行原子操作，这里刚好用到了之前看过的 CAS 相关知识（初识CAS虽然也不是太懂）。AtomicLong 的 compareAndSet 会去调用 native 方法，进行比较并替换，保证并发情况下，数据的一致性，该方法返回 boolean ，如果替换成功则为 true，否则为false。

1
2
3

public final boolean compareAndSet(long expect, long update) {
    return unsafe.compareAndSwapLong(this, valueOffset, expect, update);
}

整个代码逻辑看下来并没有问题，那么数据怎么会有问题呢，只能进行 debug 了。

运行应用，debug 源码

首先：打断点，直接运行；未进入 debug

接着：限制内存到 64M ，直接运行，未进入 debug

再接着：添加定时任务，每 1s 执行一次代码，代码中创建多个对象；未进入 debug

。。。

难道是从未发生过 GC 吗

于是在启动应用时，同时使用 VisualVM 进行监控，查看到底有没有 GC 。

事实证明，不光执行过，而且有点频繁。

看来，是无法直接 debug 了。那么就打 log 吧。这里采用了一个偷懒的方法，因为自己的应用中有很多代码是帮助测试的，不想去下载源码，所以为了能在源码中打印日志，直接新建类覆盖源码中的类，同包同名覆盖。

覆盖了执行时的代码，打印出当前最大值与传入值。再次运行应用

private void updateMax(AtomicLong max, long sample) {
    for (; ; ) {
        long curMax = max.get();
        log.info("curmax:{}", curMax);
        log.info("sample:{}", sample);
        if (curMax >= sample || max.compareAndSet(curMax, sample))
            break;
    }
}

查看运行一段时间后的日志，发现问题

curMax 会变成 0 …

由于经验太少，到这里，又想不通了。幸好有同事指点，TimeWindowMax 类是时间窗口，数据是在一段时间内有效。(事实证明，一定要多看源码，多学习）

时间有效期

于是继续在源码里绕，加上谷歌，发现了一个 DistributionStatisticConfig 类

并且在 Timer.Builder() 时，同时 build 了这个对象

private Builder(String name) {
    this.name = name;
    this.distributionConfigBuilder = new DistributionStatisticConfig.Builder();
    minimumExpectedValue(Duration.ofMillis(1));
    maximumExpectedValue(Duration.ofSeconds(30));
}

在记录 max 之前，调用了 rotate（）方法

public void record(double sample, TimeUnit timeUnit) {
    rotate();
    final long sampleNanos = (long) TimeUtils.convert(sample, timeUnit, TimeUnit.NANOSECONDS);
    for (AtomicLong max : ringBuffer) {
        updateMax(max, sampleNanos);
    }
}

private void rotate() {
    long timeSinceLastRotateMillis = clock.wallTime() - lastRotateTimestampMillis;
    if (timeSinceLastRotateMillis < durationBetweenRotatesMillis) {
        // Need to wait more for next rotation.
        return;
    }

    if (!rotatingUpdater.compareAndSet(this, 0, 1)) {
        // Being rotated by other thread already.
        return;
    }

    try {
        int iterations = 0;
        synchronized (this) {
            do {
                ringBuffer[currentBucket].set(0);
                if (++currentBucket >= ringBuffer.length) {
                    currentBucket = 0;
                }
                timeSinceLastRotateMillis -= durationBetweenRotatesMillis;
                lastRotateTimestampMillis += durationBetweenRotatesMillis;
            } while (timeSinceLastRotateMillis >= durationBetweenRotatesMillis && ++iterations < ringBuffer.length);
        }
    } finally {
        rotating = 0;
    }
}

而 durationBetweenRotatesMillis 这个值，是在构建 TimeWindowMax 时传入的

public TimeWindowMax(Clock clock, DistributionStatisticConfig config) {
    this(clock, config.getExpiry().toMillis(), config.getBufferLength());
}

public TimeWindowMax(Clock clock, long rotateFrequencyMillis, int bufferLength) {
    this.clock = clock;
    this.durationBetweenRotatesMillis = rotateFrequencyMillis;
    ...
}

大致可以确定，内存中的值，会被定期重置，打印日志验证

间隔时间是一分钟，而不是猜想的两分钟。。那么继续看代码。发现 Timer.register() 中，有 distributionConfigBuilder.build()

public Timer register(MeterRegistry registry) {
    // the base unit for a timer will be determined by the monitoring system implementation
    return registry.timer(new Meter.Id(name, tags, null, description, Type.TIMER), distributionConfigBuilder.build(),
            pauseDetector == null ? registry.config().pauseDetector() : pauseDetector);
}

再层层递进，查看源码

@Override
protected Timer newTimer(Meter.Id id, DistributionStatisticConfig distributionStatisticConfig, PauseDetector pauseDetector) {
    DistributionStatisticConfig merged = distributionStatisticConfig.merge(DistributionStatisticConfig.builder()
            .expiry(config.step())
            .build());

进入 step() 方法

default Duration step() {
    String v = get(prefix() + ".step");
    return v == null ? Duration.ofMinutes(1) : Duration.parse(v);
}

至此，终于弄明白了这个问题 /(ㄒoㄒ)/~~

总结

由于经验不足，以及看过的源码太少，导致整个问题的排查过程中，绕在源码里，找不到想找的地方。
排查问题的技能太少，多次没有思路，比如 debug 无法进入源码，最大值被重置等。

总之知识积累不够，凡是解决问题，必然需要全面的知识体系，才能迅速定位，快速排查。

好好学习，多看源码才是硬道理 ^_^