metrics-guice Registers instrumented MBeans multiple times

[jhalterman]

I noticed that metrics-guice 2.1.1 attempts to register instrumented MBeans multiple times, resulting in an internal InstanceAlreadyExistsException (logged as WARN). I'm not sure if this has any side-effects other than the WARN message:

static class T {
  @Timed
  public void dosomething(){}
}

public void testIt() {
  Guice.createInjector(new InstrumentationModule(), new AbstractModule() {
    protected void configure() {
      bind(T.class);
    }
  });
}

Corresponding WARN:

 WARN [main] (JmxReporter.java:388) - Error processing com.test.package=T,name=dosomething
javax.management.InstanceAlreadyExistsException: com.test.package:type=T,name=dosomething
    at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:453)
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.internal_addObject(DefaultMBeanServerInterceptor.java:1484)
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:963)
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:917)
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:312)
    at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:482)
    at com.yammer.metrics.reporting.JmxReporter.registerBean(JmxReporter.java:451)
    at com.yammer.metrics.reporting.JmxReporter.processTimer(JmxReporter.java:423)
    at com.yammer.metrics.reporting.JmxReporter.processTimer(JmxReporter.java:16)
    at com.yammer.metrics.core.Timer.processWith(Timer.java:214)
    at com.yammer.metrics.reporting.JmxReporter.onMetricAdded(JmxReporter.java:386)
    at com.yammer.metrics.core.MetricsRegistry.addListener(MetricsRegistry.java:442)
    at com.yammer.metrics.reporting.JmxReporter.start(JmxReporter.java:446)
    at com.yammer.metrics.guice.JmxReporterProvider.get(JmxReporterProvider.java:19)
    at com.yammer.metrics.guice.JmxReporterProvider.get(JmxReporterProvider.java:8)
    at com.google.inject.internal.BoundProviderFactory.get(BoundProviderFactory.java:55)
    at com.google.inject.internal.ProviderToInternalFactoryAdapter$1.call(ProviderToInternalFactoryAdapter.java:46)
    at com.google.inject.internal.InjectorImpl.callInContext(InjectorImpl.java:1031)
    at com.google.inject.internal.ProviderToInternalFactoryAdapter.get(ProviderToInternalFactoryAdapter.java:40)
    at com.google.inject.Scopes$1$1.get(Scopes.java:65)
    at com.google.inject.internal.InternalFactoryToProviderAdapter.get(InternalFactoryToProviderAdapter.java:40)
    at com.google.inject.internal.InternalInjectorCreator$1.call(InternalInjectorCreator.java:204)
    at com.google.inject.internal.InternalInjectorCreator$1.call(InternalInjectorCreator.java:198)
    at com.google.inject.internal.InjectorImpl.callInContext(InjectorImpl.java:1024)
    at com.google.inject.internal.InternalInjectorCreator.loadEagerSingletons(InternalInjectorCreator.java:198)
    at com.google.inject.internal.InternalInjectorCreator.injectDynamically(InternalInjectorCreator.java:179)
    at com.google.inject.internal.InternalInjectorCreator.build(InternalInjectorCreator.java:109)
    at com.google.inject.Guice.createInjector(Guice.java:95)
    at com.google.inject.Guice.createInjector(Guice.java:72)
    at com.google.inject.Guice.createInjector(Guice.java:62)
    at com.test.package.InstrumentationTest.testIt(InstrumentationTest.java:18)

[tomdz]

You seem to bind the same mbean multiple times in the same VM, from what it looks like unit tests ? The mbean server is a VM-level singleton, so any mbeans registered as part of your test will stay around even after the test is done unless they are explicitly de-registered.
I'm not sure what metrics can do in this case except replace the existing mbean, i.e. catch the {{InstanceAlreadyExistsException}} and de-register the mbean under that name before registering the (new) mbean.

[jhalterman]

It actually occurs the first time I run that test for some type (such as if I rename T to something else).

It looks like JMXReporter.registerBean is called twice for the same objectName. Here are the two call stacks:

Thread [main] (Suspended (breakpoint at line 451 in JmxReporter))   
    JmxReporter.registerBean(MetricName, JmxReporter$MetricMBean, ObjectName) line: 451 
    JmxReporter.processTimer(MetricName, Timer, JmxReporter$Context) line: 423  
    JmxReporter.processTimer(MetricName, Timer, Object) line: 1 
    Timer.processWith(MetricProcessor<T>, MetricName, T) line: 214  
    JmxReporter.onMetricAdded(MetricName, Metric) line: 386 
    MetricsRegistry.notifyMetricAdded(MetricName, Metric) line: 516 <----
    MetricsRegistry.getOrAdd(MetricName, T) line: 491   
    MetricsRegistry.newTimer(MetricName, TimeUnit, TimeUnit) line: 320  
    TimedInterceptor.forMethod(MetricsRegistry, Class<?>, Method) line: 26  
    TimedListener.hear(TypeLiteral<T>, TypeEncounter<T>) line: 27   

Thread [main] (Suspended (breakpoint at line 451 in JmxReporter))   
    JmxReporter.registerBean(MetricName, JmxReporter$MetricMBean, ObjectName) line: 451 
    JmxReporter.processTimer(MetricName, Timer, JmxReporter$Context) line: 423  
    JmxReporter.processTimer(MetricName, Timer, Object) line: 1 
    Timer.processWith(MetricProcessor<T>, MetricName, T) line: 214  
    JmxReporter.onMetricAdded(MetricName, Metric) line: 386 
    MetricsRegistry.addListener(MetricsRegistryListener) line: 442  <----
    JmxReporter.start() line: 446   
    JmxReporterProvider.get() line: 19  
    JmxReporterProvider.get() line: 1   

It also occurs during runtime, such as when a db health check is run:

WARN  [2012-03-24 22:46:55,278] com.yammer.metrics.reporting.JmxReporter: Error processing sql:type=raw,name=___Health_Check____SELECT_1
! javax.management.InstanceAlreadyExistsException: sql:type=raw,name=___Health_Check____SELECT_1
!   at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:453)
!   at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.internal_addObject(DefaultMBeanServerInterceptor.java:1484)
!   at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:963)
!   at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:917)
!   at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:312)
!   at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:482)
!   at com.yammer.metrics.reporting.JmxReporter.registerBean(JmxReporter.java:451)
!   at com.yammer.metrics.reporting.JmxReporter.processTimer(JmxReporter.java:423)
!   at com.yammer.metrics.reporting.JmxReporter.processTimer(JmxReporter.java:16)
!   at com.yammer.metrics.core.Timer.processWith(Timer.java:214)
!   at com.yammer.metrics.reporting.JmxReporter.onMetricAdded(JmxReporter.java:386)
!   at com.yammer.metrics.core.MetricsRegistry.notifyMetricAdded(MetricsRegistry.java:516)
!   at com.yammer.metrics.core.MetricsRegistry.getOrAdd(MetricsRegistry.java:491)
!   at com.yammer.metrics.core.MetricsRegistry.newTimer(MetricsRegistry.java:320)
!   at com.yammer.metrics.jdbi.InstrumentedTimingCollector.getTimer(InstrumentedTimingCollector.java:53)
!   at com.yammer.metrics.jdbi.InstrumentedTimingCollector.collect(InstrumentedTimingCollector.java:48)
!   at org.skife.jdbi.v2.SQLStatement.internalExecute(SQLStatement.java:1303)

[diwakergupta]

Any chance of getting a 2.1.x release with this fix? The 3.0.0 ETA is unknown and @timed annotations are pretty much unusable without this fix.

[codahale]

Fixed by #202, unless I'm missing something. 2.1.2 has this fix.