Thread safety of Metrics library

[Priyanka Mitra]

Hi,

We would like to use Metrics to instrument our Java application and just beginning to explore Metrics framework.  I have a few questions regarding the thread-safety of Meters, Histograms, Timers, Gauges and Counters. Can they be used in multi-threaded context?

Second question is on annotation usage. As long as we define the dependency metrics-annotation in pom.xml, we could use annotation to instrument Java applications, right? If anyone can point me to annotation usage/examples especially for Meters, Histogram and Gauges that would be very helpful.

Much thanks,

-Priyanka

[Ryan Tenney]

Hi Priyanka,

Metrics is entirely thread safe.  As far as annotations, metrics defines the annotations, but it does not do anything with them.  Other projects such as metrics-aspectj, metrics-cdi, metrics-guice and metrics-spring interact with the annotations.  (See a list of third party modules here: https://dropwizard.github.io/metrics/3.1.0/manual/third-party/)

Cheers,

Ryan

[Priyanka Mitra]

Thanks Ryan! This is a very useful information. Appreciate your help.

-Priyanka

[Florian]

Hi Ryan,

I encountered some problems using Metrics 3.1.0 in a multi-threaded environment that's why I wrote a simple test:

package com.testProject.metrics;

import java.util.HashMap;
import java.util.Map;
import java.util.Random;

import com.codahale.metrics.MetricRegistry;
import com.codahale.metrics.Timer;

import org.apache.log4j.Logger;
import org.databene.contiperf.PerfTest;
import org.databene.contiperf.junit.ContiPerfRule;
import org.databene.contiperf.timer.RandomTimer;
import org.junit.After;
import org.junit.Rule;
import org.junit.Test;
import org.springframework.beans.factory.annotation.Autowired;

import static org.junit.Assert.assertNotNull;

public class MetricsThreadSafetyTest {

  private static final Logger LOGGER = Logger.getLogger(MetricsThreadSafetyTest.class);

  private Map<String, Timer.Context> timerContextMap = new HashMap<String, Timer.Context>();

  @Rule
  public ContiPerfRule i = new ContiPerfRule();

  @Autowired
  final MetricRegistry metrics = new MetricRegistry();

  @Test
  @PerfTest(duration = 200, threads = 2, timer = RandomTimer.class, timerParams = { 30, 80 }, rampUp = 50, warmUp = 50)
  public void shouldCreateIdenticalTimers() {
    String timerName = startTimer(MetricsThreadSafetyTest.class, "timer");
    try {
      Thread.sleep(100);
      LOGGER.info("[MetricsThreadSafetyTest] running " + timerName);
    } catch (InterruptedException e) {
      e.printStackTrace();
    } finally {
      stopTimer(timerName);
      LOGGER.debug("[MetricsThreadSafetyTest] timer stopped");
    }
    assertNotNull(metrics.getTimers());
  }

  public String startTimer(Class<?> clazz, String... names) {

    String timerName = MetricRegistry.name(clazz, names);

    Timer timer = metrics.timer(timerName);
    Timer.Context timerContext = timer.time();
    LOGGER.info("[MetricsThreadSafetyTest] starting " + timerName + " at: " + System.nanoTime());
    timerContextMap.put(timerName, timerContext);

    return timerName;
  }

  public void stopTimer(final String name) {
    Timer.Context timerContext = timerContextMap.get(name);
    if (timerContext != null) {
      LOGGER.info("[MetricsThreadSafetyTest] stopping " + name + " at: " + System.nanoTime());
      long time = timerContext.stop();
      LOGGER.info("[MetricsThreadSafetyTest] time: " + time);
    }
  }

}

Which gave me the following results:

com.testProject.metrics.MetricsThreadSafetyTest.shouldCreateIdenticalTimers
2015-03-09 16:48:22,131 [Thread-0] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] starting com.testProject.metrics.MetricsThreadSafetyTest.timer at: 27564875089318
2015-03-09 16:48:22,158 [Thread-1] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] starting com.testProject.metrics.MetricsThreadSafetyTest.timer at: 27564902541610
2015-03-09 16:48:22,231 [Thread-0] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] running com.testProject.metrics.MetricsThreadSafetyTest.timer
2015-03-09 16:48:22,233 [Thread-0] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] stopping com.testProject.metrics.MetricsThreadSafetyTest.timer at: 27564977332227
2015-03-09 16:48:22,234 [Thread-0] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] time: 75131035
2015-03-09 16:48:22,258 [Thread-1] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] running com.testProject.metrics.MetricsThreadSafetyTest.timer
2015-03-09 16:48:22,258 [Thread-1] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] stopping com.testProject.metrics.MetricsThreadSafetyTest.timer at: 27565002600543
2015-03-09 16:48:22,258 [Thread-1] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] time: 100391225

As you can see, the measured time for the timer in Thread-0 is wrong, because it uses the startTime of the timer in Thread-1!

Is there anything wrong with my implementation of the timers?

Thanks,
Florian

[Ryan Tenney]

Hi Florian,

I think the problem is that both calls to startTimer(MetricsThreadSafetyTest.class, "timer") result in timers with the same name, which causes Thread-0's TimerContext to be overwritten from the map.  I've rewritten the test to return the TimerContext from startTimer instead of returning the name, I think you'll find this exhibits the expected behavior.  https://gist.github.com/ryantenney/91d6f98a4a9de6a3ab08

Here's a step-by-step breakdown of what I believe is happening:

// Thread-0 creates the timer 'com.testProject.metrics.MetricsThreadSafetyTest.timer' in the metric registry

2015-03-09 16:48:22,131 [Thread-0] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] starting com.testProject.metrics.MetricsThreadSafetyTest.timer at: 27564875089318

// Thread-0 stores the timer context in the map with the key 'com.testProject.metrics.MetricsThreadSafetyTest.timer'

// Thread-1 retrieves the timer 'com.testProject.metrics.MetricsThreadSafetyTest.timer' from the metric registry

2015-03-09 16:48:22,158 [Thread-1] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] starting com.testProject.metrics.MetricsThreadSafetyTest.timer at: 27564902541610

// Thread-1 stores the timer context in the map with the key 'com.testProject.metrics.MetricsThreadSafetyTest.timer', overwriting Thread-0's timer context

2015-03-09 16:48:22,231 [Thread-0] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] running com.testProject.metrics.MetricsThreadSafetyTest.timer

// Thread-0 retrieves the timer context in the map with the key 'com.testProject.metrics.MetricsThreadSafetyTest.timer', which is actually Thread-1's timer context

2015-03-09 16:48:22,233 [Thread-0] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] stopping com.testProject.metrics.MetricsThreadSafetyTest.timer at: 27564977332227

2015-03-09 16:48:22,234 [Thread-0] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] time: 75131035

2015-03-09 16:48:22,258 [Thread-1] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] running com.testProject.metrics.MetricsThreadSafetyTest.timer

// Thread-1 retrieves the timer context in the map with the key 'com.testProject.metrics.MetricsThreadSafetyTest.timer', which is also Thread-1's timer context, and calls stop on it again (the same timer context can be stopped multiple times, though I can't think of a reason that would ever be necessary or useful)

2015-03-09 16:48:22,258 [Thread-1] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] stopping com.testProject.metrics.MetricsThreadSafetyTest.timer at: 27565002600543

2015-03-09 16:48:22,258 [Thread-1] INFO  com.testProject.metrics.MetricsThreadSafetyTest - [MetricsThreadSafetyTest] time: 100391225

Cheers,

Ryan

[Florian]

Thanks Ryan, your version works perfectly!

[Steven Pearce]

Hi Ryan,

Can I ask a question regarding your gist.

You are creating a Timer and then a Context in the startTimer method. Do we have to create a new Timer every time, we want to record a duration?

I'd previously got the impression Timer could be stored and multiple threads could call Timer.time() on it to get a new context for that thread?

Thanks,

Steven.

[Ryan Tenney]

Hi Steven,

I'd discourage you from using that gist as a reference, it was Florian's test code which I copied and fixed.  You are correct that a timer is reusable and thread safe.

Ryan

[Steven Pearce]

Thanks Ryan, 

I was also confused by the JavaDocs where the description for the timer() says "creates a new Timer, and registers it". So I had assumed I had to create the Timer then store a reference to it.

But I see the github javadocs now read 

Return the {@link Timer} registered under this name; or create and registers new {@link Timer} if none is registered.

and that concurs with the use of getOrAdd I've seen after reading the source code.

So all good.

Cheers,

Steven.