Micrometer: `Collector already registered that provides name: executor_completed_tasks_total` when using `ExecutorServiceMetrics`

[fzyzcjy]

Hi thanks for the lib! I am facing a problem: I have several ExecutorServices, and want to monitor their metrics. I use code like the following:

        scheduledThreadPoolExecutor = new ScheduledThreadPoolExecutor(config.getBackForthScheduledThreadPoolCoreSize());
        scheduledThreadPoolExecutor.setRemoveOnCancelPolicy(true);

        new ExecutorServiceMetrics(scheduledThreadPoolExecutor, "ws.back.forth.executor", null)
                .bindTo(meterRegistry);

// ... have multiple executors, thus have multiple `new ExecutorServiceMetrics`

However, it throws the following error:

...
Caused by: java.lang.IllegalArgumentException: Collector already registered that provides name: executor_completed_tasks_total
    at io.prometheus.client.CollectorRegistry.register(CollectorRegistry.java:54)
    at io.prometheus.client.Collector.register(Collector.java:139)
    at io.micrometer.prometheus.PrometheusMeterRegistry.lambda$applyToCollector$16(PrometheusMeterRegistry.java:410)
    at java.base/java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1955)
    at io.micrometer.prometheus.PrometheusMeterRegistry.applyToCollector(PrometheusMeterRegistry.java:406)
    at io.micrometer.prometheus.PrometheusMeterRegistry.newFunctionCounter(PrometheusMeterRegistry.java:240)
    at io.micrometer.core.instrument.MeterRegistry$More.lambda$counter$1(MeterRegistry.java:920)
    at io.micrometer.core.instrument.MeterRegistry.lambda$registerMeterIfNecessary$5(MeterRegistry.java:561)
    at io.micrometer.core.instrument.MeterRegistry.getOrCreateMeter(MeterRegistry.java:614)
    at io.micrometer.core.instrument.MeterRegistry.registerMeterIfNecessary(MeterRegistry.java:568)
    at io.micrometer.core.instrument.MeterRegistry.registerMeterIfNecessary(MeterRegistry.java:561)
    at io.micrometer.core.instrument.MeterRegistry.access$700(MeterRegistry.java:77)
    at io.micrometer.core.instrument.MeterRegistry$More.counter(MeterRegistry.java:920)
    at io.micrometer.core.instrument.FunctionCounter$Builder.register(FunctionCounter.java:122)
    at io.micrometer.core.instrument.binder.jvm.ExecutorServiceMetrics.monitor(ExecutorServiceMetrics.java:312)
    at io.micrometer.core.instrument.binder.jvm.ExecutorServiceMetrics.bindTo(ExecutorServiceMetrics.java:275)
    at com.rzzsdxx.proj.support_modules.web_socket.back_forth.impl.WsBackForthService.<init>(WsBackForthService.java:60)
    at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500)
    at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:481)
    at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:212)

What should I do? Thanks!

[izeye]

@fzyzcjy Thanks for the issue.

I tried to reproduce this with a sample project, but I couldn't reproduce it. Could you provide a sample project to reproduce it?

[fzyzcjy]

@izeye I also find it VERY strange to reproduce :( If I do things like what you have done then no problem. But in my case it is mixed inside a big codebase...

(examples of where I use it:)

1.

@Component
class A {
public A() {
        scheduledThreadPoolExecutor = new ScheduledThreadPoolExecutor(...);
        new ExecutorServiceMetrics(scheduledThreadPoolExecutor, "...", null)
                .bindTo(meterRegistry);
}

2.

@Configuration
class Config {
@Bean
B b() {
        ScheduledThreadPoolExecutor scheduledThreadPoolExecutor = new ScheduledThreadPoolExecutor(...);
        new ExecutorServiceMetrics(scheduledThreadPoolExecutor, "...", null)
                .bindTo(meterRegistry);
        return new B(scheduledThreadPoolExecutor);
}

[izeye]

As far as I know, the only way to reproduce it is to create meters that have the same name but different sets of tags like https://github.com/izeye/sample-micrometer-spring-boot/commit/7ca127aa5c7f62ccbe592479a1a97838658defcb.

@fzyzcjy Could you check if that's your case?

[fzyzcjy]

@izeye Sorry that is not the case. I have also checked that but different from mine. Actually I can show you the full-text search result:

You see, I never put any tags there!

[fzyzcjy]

I have tried to print out logs, but no success.

application.yml

logging:
  config: classpath:logback-spring.xml
  level:
    io.micrometer: trace

However, looking at my log, I only see:

21:36:31.592 [main] DEBUG i.m.c.u.i.l.InternalLoggerFactory - Using SLF4J as the default logging framework

and no more logs...

---

And here is the prometheus endpoint:

So it can be seen that, only spring.app.schedule.executor is there. Actually if I remove that new ExecutorServiceMetrics zero things related to executor will be shown. But if I remove even more new ExecutorServiceMetrics and only remain one or two, then things get ok.

On the other hand, you can see some lines of code are commented out. If I uncomment them, I see errors.

---

EDIT: Even stranger things happen. Just now when I uncomment them, it goes well; but still, only one of the executors show metrics.

---

EDIT: Wait - I see the problem of that spring.app.worker.id.registerer.executor - it does not container common tags. Ok so ignore this one, I will delete this line of metrics code. But what about the others...

[izeye]

@fzyzcjy The limitation is specific to Prometheus, so you can log relevant meters by doing something similar to what I did in https://github.com/izeye/sample-micrometer-spring-boot/commit/78228c6331be27029d74922c655ef578830f141a.

[fzyzcjy]

@izeye Sounds great! I will have a try and reply to you. Thanks!

[fzyzcjy]

Hmm I do only see the meter that appear in the endpoint. But no more...

07:59:44.836 [main] INFO  c.r.p.s.s.l.SimpleMonitorListener - meter id=MeterId{name='executor.active', tags=[tag(application=proj),tag(name=spring.app.schedule.executor),tag(worker.id=2)]}
07:59:44.836 [main] INFO  c.r.p.s.s.l.SimpleMonitorListener - meter id=MeterId{name='executor.queue.remaining', tags=[tag(application=proj),tag(name=spring.app.schedule.executor),tag(worker.id=2)]}
07:59:44.837 [main] INFO  c.r.p.s.s.l.SimpleMonitorListener - meter id=MeterId{name='executor.completed', tags=[tag(application=proj),tag(name=spring.app.schedule.executor),tag(worker.id=2)]}
07:59:44.837 [main] INFO  c.r.p.s.s.l.SimpleMonitorListener - meter id=MeterId{name='executor.pool.max', tags=[tag(application=proj),tag(name=spring.app.schedule.executor),tag(worker.id=2)]}
07:59:44.837 [main] INFO  c.r.p.s.s.l.SimpleMonitorListener - meter id=MeterId{name='executor.queued', tags=[tag(application=proj),tag(name=spring.app.schedule.executor),tag(worker.id=2)]}
07:59:44.837 [main] INFO  c.r.p.s.s.l.SimpleMonitorListener - meter id=MeterId{name='executor.pool.core', tags=[tag(application=proj),tag(name=spring.app.schedule.executor),tag(worker.id=2)]}
07:59:44.837 [main] INFO  c.r.p.s.s.l.SimpleMonitorListener - meter id=MeterId{name='executor.pool.size', tags=[tag(application=proj),tag(name=spring.app.schedule.executor),tag(worker.id=2)]}

code:

   @EventListener(ApplicationReadyEvent.class)
    public void handleApplicationReadyEvent(ApplicationReadyEvent event) {
        log.info("See ApplicationReadyEvent args={}", (Object) event.getArgs());

        for (Meter meter : this.meterRegistry.getMeters()) {
            Meter.Id id = meter.getId();
            if (id.getName().startsWith("executor.")) {
                log.info("meter id={}", id);
            }
        }
    }

[fzyzcjy]

Even stranger. Just immediately after my call to new ExecutorServiceMetrics(), there is nothing related Meter.

code

@Component
@Slf4j
public class MyServiceA {
public MyServiceA(MeterRegistry meterRegistry, ...) {
        scheduledThreadPoolExecutor = new TraceableScheduledExecutorService(beanFactory,
                MyExecutors.newScheduledThreadPoolExecutor(config.getBackForthScheduledThreadPoolCoreSize(), true));

        System.out.println("hello ws.back.forth.executor");
        new ExecutorServiceMetrics(scheduledThreadPoolExecutor, Meters.name("ws.back.forth.executor"), null)
                .bindTo(meterRegistry);
        for (Meter meter : meterRegistry.getMeters()) {
            log.info("meter id={}", meter.getId());
        }
}

result:

hello ws.back.forth.executor
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.memory.used', tags=[tag(id=direct)]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.single.attempt', tags=[tag(state=failed)]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=blocked)]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.uptime', tags=[]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.enqueue', tags=[tag(action=publish.kafka)]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=nonheap),tag(id=Compressed Class Space)]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=runnable)]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.section', tags=[tag(section=call.ws.success)]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='system.load.average.1m', tags=[]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.overall.start', tags=[tag(state=start)]}
08:02:46.559 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.framework.wrapper.send', tags=[tag(state=success)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.authenticated.local.connection', tags=[]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=2),tag(success=0)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=1),tag(success=1)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=nonheap),tag(id=Metaspace)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=1),tag(success=0)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.count', tags=[tag(id=mapped - 'non-volatile memory')]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=trace)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=heap),tag(id=G1 Old Gen)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-profiled nmethods')]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.total.capacity', tags=[tag(id=direct)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=heap),tag(id=G1 Eden Space)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.pause', tags=[tag(action=end of minor GC),tag(cause=Metadata GC Threshold)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=heap),tag(id=G1 Eden Space)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='system.cpu.usage', tags=[]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.live', tags=[]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.classes.unloaded', tags=[]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=nonheap),tag(id=Compressed Class Space)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.classes.loaded', tags=[]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.peak', tags=[]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=3),tag(success=1)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=3),tag(success=0)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.overall', tags=[tag(state=failed)]}
08:02:46.560 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.section', tags=[tag(section=call.ws.failed)]}
08:02:46.561 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=2),tag(success=1)]}
08:02:46.561 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.enqueue', tags=[tag(action=no.ws.no.ext.throw)]}
08:02:46.561 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=warn)]}
08:02:46.561 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=error)]}
08:02:46.561 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.enqueue', tags=[tag(action=external.push)]}
08:02:46.561 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.memory.promoted', tags=[]}
08:02:46.561 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=nonheap),tag(id=Compressed Class Space)]}
08:02:46.561 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=waiting)]}
08:02:46.561 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=heap),tag(id=G1 Eden Space)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.count', tags=[tag(id=mapped)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.memory.allocated', tags=[]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=info)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-profiled nmethods')]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=heap),tag(id=G1 Survivor Space)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-nmethods')]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.pause', tags=[tag(action=end of minor GC),tag(cause=G1 Evacuation Pause)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.c2s.heartbeat.recv', tags=[]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.total.capacity', tags=[tag(id=mapped)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.max.data.size', tags=[]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.memory.used', tags=[tag(id=mapped - 'non-volatile memory')]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=heap),tag(id=G1 Old Gen)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='system.cpu.count', tags=[]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.single.attempt', tags=[tag(state=success)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-nmethods')]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.overall', tags=[tag(state=success)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.enqueue', tags=[tag(action=no.ws.disable.ext.throw)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.start.time', tags=[]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.memory.used', tags=[tag(id=mapped)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.count', tags=[tag(id=direct)]}
08:02:46.562 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.single.attempt.start', tags=[tag(state=start)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.framework.wrapper.send.start', tags=[tag(state=start)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.framework.wrapper.send', tags=[tag(state=failed)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.daemon', tags=[]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.files.max', tags=[]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.section', tags=[tag(section=before.kafka)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=new)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.total.capacity', tags=[tag(id=mapped - 'non-volatile memory')]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-nmethods')]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=heap),tag(id=G1 Survivor Space)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=timed-waiting)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=heap),tag(id=G1 Old Gen)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=nonheap),tag(id=Metaspace)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=nonheap),tag(id=Metaspace)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=heap),tag(id=G1 Survivor Space)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=terminated)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.section', tags=[tag(section=inside.kafka)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.user.machine.map.overall.connection', tags=[]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-profiled nmethods')]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.files.open', tags=[]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.live.data.size', tags=[]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=debug)]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.cpu.usage', tags=[]}
08:02:46.563 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.c2s.heartbeat.issue.close', tags=[]}

[izeye]

@fzyzcjy Thanks for the further investigation. I'm not sure what's happening there at the moment. It would be helpful to allow me to understand it if you could share a sample project to reproduce it. Or you can debug it with the exception.

[fzyzcjy]

@izeye Thanks for the reply! Unfortunately I cannot create a minimum reproducible sample... It seems to only have error in such mixed and complicated environment :(

Or you can debug it with the exception.

I am willing to debug. But I have not seen any Exceptions. And no logs either (e.g. log.trace would be quite helpful) :(

[izeye]

@fzyzcjy The opening comment includes a stack trace, so I think you can debug with it to see what's going on.

[fzyzcjy]

@izeye That's another problem... And actually that stack contains almost nothing - just tell us that the name already exists...

Is there any way I can see more insights (more logs) of micrometer?

[izeye]

@fzyzcjy Sorry, there's nothing I can advise without a sample project at the moment.

[fzyzcjy]

@izeye I mean more logs. I have tried to set level to TRACE without any more logs... As we know more logging means more possibility to debug successfully

[checketts]

Is it possible that there is code triggering an initial meter being registered, then the subsequent meter is registered (that errors), there are common tags or a filters adding the extra tag?

[fzyzcjy]

@checketts Sorry I do not quite understand the situation you described. I do not add common tags, except using this code:

@Configuration
public class MicrometerConfig {

    @Value("${project-name}")
    private String projectName;
    @Autowired
    private MachineInfo machineInfo;

    @Bean
    MeterRegistryCustomizer<MeterRegistry> metricsCommonTags() {
        return registry -> {
            registry.config()
                    .commonTags("application", projectName)
                    .commonTags("worker.id", String.valueOf(machineInfo.getSelfWorkerId()));
        };
    }
}

[checketts]

Can you remove those common tags and see if the error goes away? (Just as a test, we can add them back later)

My theory is that something is registering an executor's meters very early in the application's lifecycle before the common tags are taking effect. Then once they take effect, you are registering the other executor and the tags aren't aligning at that point (which causes the error)

[fzyzcjy]

@checketts No the error does not go away... I comment out that @Bean MeterRegistryCustomizer<MeterRegistry> metricsCommonTags(), and now it looks like:

hello ws.back.forth.executor
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.memory.used', tags=[tag(id=direct)]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.single.attempt', tags=[tag(state=failed)]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=blocked)]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.uptime', tags=[]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.enqueue', tags=[tag(action=publish.kafka)]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=nonheap),tag(id=Compressed Class Space)]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=runnable)]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.section', tags=[tag(section=call.ws.success)]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='system.load.average.1m', tags=[]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.overall.start', tags=[tag(state=start)]}
11:36:45.671 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.framework.wrapper.send', tags=[tag(state=success)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.authenticated.local.connection', tags=[]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=2),tag(success=0)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=1),tag(success=1)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=nonheap),tag(id=Metaspace)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=1),tag(success=0)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.count', tags=[tag(id=mapped - 'non-volatile memory')]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=trace)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=heap),tag(id=G1 Old Gen)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-profiled nmethods')]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.total.capacity', tags=[tag(id=direct)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=heap),tag(id=G1 Eden Space)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.pause', tags=[tag(action=end of minor GC),tag(cause=Metadata GC Threshold)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=heap),tag(id=G1 Eden Space)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='system.cpu.usage', tags=[]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.live', tags=[]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.classes.unloaded', tags=[]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=nonheap),tag(id=Compressed Class Space)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.classes.loaded', tags=[]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.peak', tags=[]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=3),tag(success=1)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=3),tag(success=0)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.overall', tags=[tag(state=failed)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.section', tags=[tag(section=call.ws.failed)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.ws.overall', tags=[tag(num.tries=2),tag(success=1)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.enqueue', tags=[tag(action=no.ws.no.ext.throw)]}
11:36:45.672 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=warn)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=error)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.enqueue', tags=[tag(action=external.push)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.memory.promoted', tags=[]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=nonheap),tag(id=Compressed Class Space)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=waiting)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=heap),tag(id=G1 Eden Space)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.count', tags=[tag(id=mapped)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.memory.allocated', tags=[]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=info)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-profiled nmethods')]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=heap),tag(id=G1 Survivor Space)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-nmethods')]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.pause', tags=[tag(action=end of minor GC),tag(cause=G1 Evacuation Pause)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.c2s.heartbeat.recv', tags=[]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.total.capacity', tags=[tag(id=mapped)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.max.data.size', tags=[]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.memory.used', tags=[tag(id=mapped - 'non-volatile memory')]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=heap),tag(id=G1 Old Gen)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='system.cpu.count', tags=[]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.single.attempt', tags=[tag(state=success)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-nmethods')]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.overall', tags=[tag(state=success)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.enqueue', tags=[tag(action=no.ws.disable.ext.throw)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.start.time', tags=[]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.memory.used', tags=[tag(id=mapped)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.count', tags=[tag(id=direct)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.external.push.send.single.attempt.start', tags=[tag(state=start)]}
11:36:45.673 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.framework.wrapper.send.start', tags=[tag(state=start)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.framework.wrapper.send', tags=[tag(state=failed)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.daemon', tags=[]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.files.max', tags=[]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.section', tags=[tag(section=before.kafka)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=new)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.buffer.total.capacity', tags=[tag(id=mapped - 'non-volatile memory')]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-nmethods')]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=heap),tag(id=G1 Survivor Space)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=timed-waiting)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.used', tags=[tag(area=heap),tag(id=G1 Old Gen)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=nonheap),tag(id=Metaspace)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=nonheap),tag(id=Metaspace)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.max', tags=[tag(area=heap),tag(id=G1 Survivor Space)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.threads.states', tags=[tag(state=terminated)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.mixed.push.section', tags=[tag(section=inside.kafka)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.user.machine.map.overall.connection', tags=[]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.memory.committed', tags=[tag(area=nonheap),tag(id=CodeHeap 'non-profiled nmethods')]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.files.open', tags=[]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='jvm.gc.live.data.size', tags=[]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='logback.events', tags=[tag(level=debug)]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='process.cpu.usage', tags=[]}
11:36:45.674 [main] INFO  c.r.p.s.w.b.impl.WsBackForthService - meter id=MeterId{name='spring.app.ws.c2s.heartbeat.issue.close', tags=[]}

[fzyzcjy]

I do see the problem!! @izeye @checketts

Suggestion for improvements (only need several lines of code)

1. Add a log.warn when bindTo actually binds to nowhere.
2. Maybe add support for Spring Sleuth executors such as TraceableScheduledExecutorService.

What is the problem

Look at my code above.

scheduledThreadPoolExecutor = new TraceableScheduledExecutorService(...);

Then that class TraceableScheduledExecutorService will NOT be recognized in bindTo, so bind to nowhere!

Thank you all the same for your help.

[checketts]

Now you understand the problem would you be interested in creating a simple project that replicates it so we can understand your recommendation better?

[fzyzcjy]

@checketts Sure. Just two lines of code:

ExecutorService executor = new TraceableScheduledExecutorService(beanFactory, Executors.newSingleThreadScheduledExecutor());
new ExecutorServiceMetrics(executor, "my.name", null).bindTo(meterRegistry);

You can put it to whereever you like, for example, it seems that @izeye has some good unit test repos.

P.S. You may need dependency for Spring Cloud Sleuth. Just follow their install tips, very simple to install and understand. Or have a brief look at this tutorial

[izeye]

@fzyzcjy Thanks for the suggestion!

I don't fully understand where the Prometheus exception came from, but the logging suggestion seems to be reasonable. I created https://github.com/micrometer-metrics/micrometer/pull/2443 to try to resolve it.

[shakuzen]

Thanks everyone for all the investigation and suggestion and change from this. I'm a little confused about the latest state of this, though. Is the original exception no longer an issue? The added logging won't change whether such an exception happens or not. Do we need to do anything still for this issue?

[shakuzen]

If the original exception isn't an issue anymore, perhaps we can focus resolving this issue on making sure it is possible and clear how to get traces with Sleuth and metrics with Micrometer from the same ExecutorService?

[fzyzcjy]

@shakuzen For me, the original issue disappears after changing configurations. Thanks for everyone!

[shakuzen]

Just to follow-up, if you wanted to trace and get metrics from an executor service and its submitted tasks using Sleuth and Micrometer, you can make your ExecutorService a Spring bean like:

@Bean
ExecutorService myExecutorService(MeterRegistry meterRegistry) {
    return ExecutorServiceMetrics.monitor(meterRegistry, Executors.newSingleThreadScheduledExecutor(), "myExecutorService");
}

And Sleuth will take care of tracing it in auto-configuration.