Hi,

Spring boot: 2.4.3

when using Metrics.counter(...) instead of using meterRegistry.counter(...) behaves differently when using a custom MeterFilter.

I have this MeterFilter:

@Component
class CustomMeterFilter implements MeterFilter {
    private int tag;

    @Override
    public Meter.Id map(Meter.Id id) {
        return id.withTags(Tags.of("tag", Integer.toString(tag)));
    }

    public void setTag(int tag) {
        this.tag = tag;
    }
}

And this runner which generates some metrics:

@Component
class Runner implements ApplicationRunner {
    private final MeterRegistry meterRegistry;
    private final CustomMeterFilter customMeterFilter;

    Runner(MeterRegistry meterRegistry, CustomMeterFilter customMeterFilter) {
        this.meterRegistry = meterRegistry;
        this.customMeterFilter = customMeterFilter;
    }

    @Override
    public void run(ApplicationArguments args) throws Exception {
        for (int i = 0; i < 10; i++) {
            customMeterFilter.setTag(i);

            meterRegistry.counter("bug.instance").increment();
            Metrics.counter("bug.static").increment();
        }
    }
}

when scraping the metrics, I get:

curl -s localhost:8080/actuator/prometheus | grep ^bug

bug_instance_total{tag="1",} 1.0
bug_instance_total{tag="2",} 1.0
bug_instance_total{tag="3",} 1.0
bug_instance_total{tag="4",} 1.0
bug_instance_total{tag="5",} 1.0
bug_instance_total{tag="6",} 1.0
bug_instance_total{tag="7",} 1.0
bug_instance_total{tag="8",} 1.0
bug_instance_total{tag="9",} 1.0
bug_instance_total{tag="0",} 1.0
bug_static_total{tag="0",} 10.0

I expected all the tag tags on bug_static_total, too, not only on bug_instance_total.

Reproducer project: https://github.com/phxql/global-registry-vs-instance

Comment From: drgnchan

@phxql Hi! The autowired MeterRegistry own your customMeterFilter because the bean is processed by MeterRegistryPostProcessor.postProcessAfterInitialization() which will addFilters.

MeterRegistryPostProcessor.java:

public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
        if (bean instanceof MeterRegistry) {
            this.getConfigurer().configure((MeterRegistry)bean);
        }

        return bean;
    }

MeterRegistryConfigurer.java:

void configure(MeterRegistry registry) {
        this.customize(registry);
        if (!(registry instanceof AutoConfiguredCompositeMeterRegistry)) {
            this.addFilters(registry);
        }

        if (!this.hasCompositeMeterRegistry || registry instanceof CompositeMeterRegistry) {
            this.addBinders(registry);
        }

        if (this.addToGlobalRegistry && registry != Metrics.globalRegistry) {
            Metrics.addRegistry(registry);
        }

    }

maybe you can add one line which manual config the filter in your code to get all the tag tags on bug_static_total

@Component
class Runner implements ApplicationRunner {
    private final MeterRegistry meterRegistry;
    private final CustomMeterFilter customMeterFilter;

    Runner(MeterRegistry meterRegistry, CustomMeterFilter customMeterFilter) {
        this.meterRegistry = meterRegistry;
        this.customMeterFilter = customMeterFilter;
       //added
        Metrics.globalRegistry.config().meterFilter(customMeterFilter);
    }

    @Override
    public void run(ApplicationArguments args) throws Exception {
        for (int i = 0; i < 10; i++) {
            customMeterFilter.setTag(i);
            meterRegistry.counter("bug.instance").increment();
            **Metrics.counter("bug.static").increment();**
            System.out.println("hi");
        }
    }
}

Comment From: wilkinsona

The behaviour that you are seeing is expected as Spring Boot’s auto-configuration does not apply meter filters to Micrometer’s static global registry. We should update the documentation to clarify this.

Comment From: wilkinsona

We say this about meter binders:

By default, metrics from all MeterBinder beans will be automatically bound to the Spring-managed MeterRegistry

We should say something similar for meter filters, and perhaps state explicitly that the global registry isn’t Spring-managed.

Comment From: phxql

Well, what's strange is, is that the tag tag is applied by the MeterFilter to the Metrics, too:

bug_static_total{tag="0",} 10.0

I didn't add the tag in the code above, that's the work from MeterFilter. The difference is that all 10 events are attached to the tag="0" when using Metrics, which is not the case when using MeterRegistry.

I guess this is due the fact that Metrics dispatches internally to the MeterRegistry, but this behaviour is strange. It would be okay if the metrics reported through Metrics contain NO tag from MeterFilters or contain ALL tags from MeterFilters, but the actual behaviour is totally unexpected (and has actually lead to wrong data reporting in our dashboards).

Our "workaround" is now ditching the Metrics and using the MeterRegistry directly.

Comment From: drgnchan

I guess this is due the fact that Metrics dispatches internally to the MeterRegistry, but this behaviour is strange.

after i debug the source code,i found that Metrics's globalRegistry (CompositeMeterRegistry) will listen meter added event.The listener do the job that add meter each registry in nonCompositeDescendants which contains the spring-managed registry MeterRegistry.

public CompositeMeterRegistry(Clock clock, Iterable<MeterRegistry> registries) {
        super(clock);
        config()
                .namingConvention(NamingConvention.identity)
                .onMeterAdded(m -> {
                    if (m instanceof CompositeMeter) { // should always be
                        lock(registriesLock, () -> nonCompositeDescendants.forEach(((CompositeMeter) m)::add));
                    }
                })
                .onMeterRemoved(m -> {
                    if (m instanceof CompositeMeter) { // should always be
                        lock(registriesLock, () -> nonCompositeDescendants.forEach(r -> r.removeByPreFilterId(m.getId())));
                    }
                });

        registries.forEach(this::add);
    }

when the spring-managed registry add the meter,the registerMeterIfNecessary() method will invoke getMappedId() method which will apply every filter.

private <M extends Meter> M registerMeterIfNecessary(Class<M> meterClass, Meter.Id id,
                                                         @Nullable DistributionStatisticConfig config, BiFunction<Meter.Id, DistributionStatisticConfig, M> builder,
                                                         Function<Meter.Id, M> noopBuilder) {
        Id mappedId = getMappedId(id);
        Meter m = getOrCreateMeter(config, builder, id, mappedId, noopBuilder);

        if (!meterClass.isInstance(m)) {
            throw new IllegalArgumentException("There is already a registered meter of a different type with the same name");
        }
        return meterClass.cast(m);
    }

Comment From: wilkinsona

@phxql I see what you mean. I agree that the behaviour is strange as Micrometer is applying filters differently depending on whether things are done directly or via a composite registry (in this case the global registry) passing things down to a descendent.

Both will behave the same way if you register the meter filter with the global registry:

@Override
public void run(ApplicationArguments args) throws Exception {
    Metrics.globalRegistry.config().meterFilter(this.customMeterFilter);
    for (int i = 0; i < 10; i++) {
        customMeterFilter.setTag(i);
        meterRegistry.counter("bug.instance").increment();
        Metrics.counter("bug.static").increment();
    }
}

This results in 10 entries for each:

bug_static_total{tag="1",} 1.0
bug_static_total{tag="2",} 1.0
bug_static_total{tag="3",} 1.0
bug_static_total{tag="4",} 1.0
bug_static_total{tag="5",} 1.0
bug_static_total{tag="6",} 1.0
bug_static_total{tag="7",} 1.0
bug_static_total{tag="8",} 1.0
bug_static_total{tag="9",} 1.0
bug_static_total{tag="0",} 1.0
…
bug_instance_total{tag="1",} 1.0
bug_instance_total{tag="2",} 1.0
bug_instance_total{tag="3",} 1.0
bug_instance_total{tag="4",} 1.0
bug_instance_total{tag="5",} 1.0
bug_instance_total{tag="6",} 1.0
bug_instance_total{tag="7",} 1.0
bug_instance_total{tag="8",} 1.0
bug_instance_total{tag="9",} 1.0
bug_instance_total{tag="0",} 1.0

Alternatively, you can create the counter once and then increment it:

@Override
public void run(ApplicationArguments args) throws Exception {
    Counter instanceCounter = meterRegistry.counter("bug.instance");
    Counter staticCounter = Metrics.counter("bug.static");
    for (int i = 0; i < 10; i++) {
        customMeterFilter.setTag(i);
        instanceCounter.increment();
        staticCounter.increment();
    }
}

This results in behaviour that's different to the above, but it's still consistent across the two metrics:

bug_instance_total{tag="0",} 10.0
…
bug_static_total{tag="0",} 10.0

@shakuzen Could you take a look at this please? I'm wondering if Micrometer's behaviour is intentional here or if there's a bug in how filters are applied when passing meters down to a descendant.

Comment From: snicoll

I've pinged Tommy on that comment above and will follow-up in a separate issue if needed.

Comment From: shakuzen

It's not clear to me what the goal is with the custom meter filter. In the example mentioned, it's described the expected output for the metrics created by the runner, but the filter will affect all metrics created, not just those in the runner. And some metrics may be created on other threads at the same time the runner is running, so the state of the filter during those metrics creation is not deterministic - probably not what you want. If you want to create counters with a tag of different values, that could be done directly rather than through a filter affecting other metrics in the application.

for (int i = 0; i < 10; i++) {
    meterRegistry.counter("bug.instance", "tag", "" + i).increment();
}

Tagging metrics based on a filter with dynamic state is likely to be problematic, but I'd be interested to hear about the use case if that's actually the intention rather than the straightforward usage in the above code.

As for the behavior, it is expected, though I can see how it is a bit surprising here.

Well, what's strange is, is that the tag tag is applied by the MeterFilter to the Metrics, too:

bug_static_total{tag="0",} 10.0

I didn't add the tag in the code above, that's the work from MeterFilter. The difference is that all 10 events are attached to the tag="0" when using Metrics, which is not the case when using MeterRegistry.

Metrics uses the global registry, which is not managed by Spring and therefore will not have the custom meter filter bean applied to it by Spring Boot. So, Metrics.counter("bug.static") will return the same CompositeCounter every time. That CompositeCounter is associated with the same counter in the PrometheusMeterRegistry which does have the filter applied, hence the tag=0 from the state of the filter the first time Metrics.counter("bug.static") is called. It won't create a different counter in response to the change in state of the filter because the global registry does not have the filter applied to it. It would return a counter based on the state of the filter if you used a registry with the filter - such as the Spring-managed composite or the PrometheusMeterRegistry itself.

Essentially the strangeness arises because the filter is applied to the PrometheusMeterRegistry (because it is Spring-managed) but not the global registry (because it isn't Spring managed). In a DI-capable environment, DI should be used (in this case, inject the Spring-managed registry) instead of the global static registry. The global static is provided as a fallback option in scenarios where DI is not available.

To elaborate with the two snippets @wilkinsona provided, calling the counter method will create a new meter or retrieve an existing meter from the registry. Therefore, calling it each time in the loop means it will create or retrieve based on the ID with any configured filters applied. Calling the counter method once outside the loop means it will create/retrieve a meter one time and then subsequent increment calls will all happen on that same meter - there is no chance of that increment happening on a meter with different tag values.

Hopefully all that makes things more clear. Let me know if not.

Comment From: phxql

Tagging metrics based on a filter with dynamic state is likely to be problematic, but I'd be interested to hear about the use case if that's actually the intention rather than the straightforward usage in the above code.

We have a system which stores a tenant in a request scoped bean. This tenant should be applied as a tag to all metrics produced in this request. We didn't want to change all Metrics.counter(...) invocations, but decided to solve that with a MeterFilter, which reads the tenant from the request scoped bean.

Comment From: shakuzen

Thanks for the context. That helps me understand the goal better. It still sounds like you wouldn't want the tenant tag applied to metrics not tenant related. Extracting the metrics calls to a method you should be able to apply the request-scope tags to them without duplicating that logic at every call site. You could take inspiration from the Boot WebMvcMetricsFilter and WebMvcTagsProvider classes, for example. You could even customize the DefaultWebMvcTagsProvider to add the tenant tag to Spring Boot's request-based metrics.