如何通过ObservationHandler获取ServerHttpObservationFilter的Timer请求耗时？

问题场景 #

尝试通过ObservationHandler从ServerHttpObservationFilter的Observation中获取请求总耗时，实现代码如下：

public class LogDurationObservationHandler implements ObservationHandler<ServerRequestObservationContext>, Ordered {

    private static final Logger logger = LoggerFactory.getLogger(LogDurationObservationHandler.class);

    private final MeterRegistry meterRegistry;

    public LogDurationObservationHandler(MeterRegistry meterRegistry) {
        this.meterRegistry = meterRegistry;
    }

    @Override
    public boolean supportsContext(Observation.Context context) {
        return context instanceof ServerRequestObservationContext;
    }

    @Override
    public void onStop(ServerRequestObservationContext context) {
        double duration = this.meterRegistry.get(context.getName()).timer().totalTime(TimeUnit.MILLISECONDS);
        logger.error("Duration from onStop: {}", duration);
    }

    @Override
    public int getOrder() {
        return Ordered.LOWEST_PRECEDENCE;
    }

}

运行时错误 #

执行代码后抛出如下异常：

io.micrometer.core.instrument.search.MeterNotFoundException: Unable to find a meter that matches all the requirements at once. Here's what was found:
   FAIL: No meter with name 'http.server.requests' was found.
   OK: A meter with type timer was found.
    at io.micrometer.core.instrument.search.MeterNotFoundException$FromRequiredSearch.build(MeterNotFoundException.java:245) ~[micrometer-core-1.12.0-RC1.jar:1.12.0-RC1]
    at io.micrometer.core.instrument.search.MeterNotFoundException$FromRequiredSearch.access$100(MeterNotFoundException.java:49) ~[micrometer-core-1.12.0-RC1.jar:1.12.0-RC1]
    at io.micrometer.core.instrument.search.MeterNotFoundException.forSearch(MeterNotFoundException.java:46) ~[micrometer-core-1.12.0-RC1.jar:1.12.0-RC1]
    at io.micrometer.core.instrument.search.RequiredSearch.lambda$getOne$1(RequiredSearch.java:199) ~[micrometer-core-1.12.0-RC1.jar:1.12.0-RC1]
    at java.base/java.util.Optional.orElseThrow(Optional.java:403) ~[na:na]
    at io.micrometer.core.instrument.search.RequiredSearch.getOne(RequiredSearch.java:199) ~[micrometer-core-1.12.0-RC1.jar:1.12.0-RC1]
    at io.micrometer.core.instrument.search.RequiredSearch.timer(RequiredSearch.java:120) ~[micrometer-core-1.12.0-RC1.jar:1.12.0-RC1]
    at com.example.demo.LogDurationObservationHandler.onStop(LogDurationObservationHandler.java:30) ~[main/:na]

核心需求与环境 #

• 核心需求：获取Spring Framework中请求对应的Observation启动/停止耗时，替换原有基于OncePerRequestFilter的统计实现
• 使用环境：
  • Spring Boot 3.2.0-RC2
  • 依赖：
    • org.springframework.boot:spring-boot-starter-web
    • org.springframework.boot:spring-boot-starter-actuator

解决方案 #

不需要自行创建Timer，通过ObservationHandler完全可以实现需求。你的问题根源在于错误地尝试从MeterRegistry中查询Timer：

1. 在onStop阶段，当前请求的Timer数据尚未同步到MeterRegistry，无法直接查询到；
2. context.getName()仅对应Observation的名称，Micrometer的Timer是多维度标签化的，仅通过名称无法精准匹配到对应请求的Timer。

正确的做法是直接从ServerRequestObservationContext关联的Observation中获取时间戳计算耗时：

方式一：直接计算时间差 #

@Override
public void onStop(ServerRequestObservationContext context) {
    long durationMs = context.getObservation().getEndTimestamp() - context.getObservation().getStartTimestamp();
    logger.error("Duration from onStop: {} ms", durationMs);
}

方式二：使用Observation内置的Duration方法 #

@Override
public void onStop(ServerRequestObservationContext context) {
    Duration duration = context.getObservation().getDuration();
    logger.error("Duration from onStop: {} ms", duration.toMillis());
}

补充说明 #

如果需要将该耗时添加到自定义的Micrometer Metrics中（比如增加业务维度标签），可以在onStop中手动创建Timer并记录，但如果仅需获取当前请求的耗时，直接从Observation上下文获取时间戳是最直接高效的方案，无需依赖MeterRegistry的查询逻辑。

内容的提问来源于stack exchange，提问作者Cisco