DropWizard Metrics Meters vs Timers

Solution 1:

You're confused in part because a DW Metrics Timer IS, among other things, a DW Metrics Meter.

A Meter is exclusively concerned with rates, measured in Hz (events per second). Each Meter results in 4(?) distinct metrics being published:

• a mean (average) rate since Metrics was started
• 1, 5 and 15-minute rolling mean rates

You use a Meter by recording a value at different points in your code -- DW Metrics automatically jots down the wall time of each call along with the value you gave it, and uses these to calculate the rate at which that value is increasing:

Meter getRequests = registry.meter("some-operation.operations")
getRequests.mark() //resets the value, e.g. sets it to 0
int numberOfOps = doSomeNumberOfOperations() //takes 10 seconds, returns 333
getRequests.mark(numberOfOps) //sets the value to number of ops.

We would expect our rates to be 33.3 Hz, as 333 operations occurred and the time between the two calls to mark() was 10 seconds.

A Timer calculates these above 4 metrics (considering each Timer.Context to be one event) and adds to them a number of additional metrics:

• a count of the number of events
• min, mean and max durations seen since the start of Metrics
• standard deviation
• a "histogram," recording the duration distributed at the 50th, 97th, 98th, 99th, and 99.95 percentiles

There are something like 15 total metrics reported for each Timer.

In short: Timers report a LOT of metrics, and they can be tricky to understand, but once you do they're a quite powerful way to spot spikey behavior.

Fact is, just collecting the time spent between two points isn't a terribly useful metric. Consider: you have a block of code like this:

Timer timer = registry.timer("costly-operation.service-time")
Timer.Context context = timer.time()
costlyOperation() //service time 10 ms
context.stop()

Let's assume that costlyOperation() has a constant cost, constant load, and operates on a single thread. Inside a 1 minute reporting period, we should expect to time this operation 6000 times. Obviously, we will not be reporting the actual service time over the wire 6000x -- instead, we need some way to summarize all those operations to fit our desired reporting window. DW Metrics' Timer does this for us, automatically, once a minute (our reporting period). After 5 minutes, our metrics registry would be reporting:

• a rate of 100 (events per second)
• a 1-minute mean rate of 100
• a 5-minute mean rate of 100
• a count of 30000 (total events seen)
• a max of 10 (ms)
• a min of 10
• a mean of 10
• a 50th percentile (p50) value of 10
• a 99.9th percentile (p999) value of 10

Now, let's consider we enter a period where occasionally our operation goes completely off the rails and blocks for an extended period:

Timer timer = registry.timer("costly-operation.service-time")
Timer.Context context = timer.time()
costlyOperation() //takes 10 ms usually, but once every 1000 times spikes to 1000 ms
context.stop()

Over a 1 minute collection period, we would now see fewer than 6000 executions, as every 1000th execution takes longer. Works out to about 5505. After the first minute (6 minutes total system time) of this we would now see:

• a mean rate of 98 (events per second)
• a 1-minute mean rate of 91.75
• a 5-minute mean rate of 98.35
• a count of 35505 (total events seen)
• a max duration of 1000 (ms)
• a min duration of 10
• a mean duration of 10.13
• a 50th percentile (p50) value of 10
• a 99.9th percentile (p999) value of 1000

If you graph this, you'd see that most requests (the p50, p75, p99, etc) were completing in 10 ms, but one request out of 1000 (p99) was completed in 1s. This would also be seen as a slight reduction in the average rate (about 2%) and a sizable reduction in the 1-minute mean (nearly 9%).

If you only look at over the time mean values (either rate or duration), you'll never spot these spikes -- they get dragged into the background noise when averaged with a lot of successful operations. Similarly, just knowing the max isn't helpful, because it doesn't tell you how frequently the max occurs. This is why histograms are a powerful tool for tracking performance, and why DW Metrics' Timer publishes both a rate AND a histogram.