You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@bookkeeper.apache.org by si...@apache.org on 2018/04/25 09:10:07 UTC
[bookkeeper] branch branch-4.7 updated: Issue #1363: Fast and
Garbage-Free Codahale Statistics Timers
This is an automated email from the ASF dual-hosted git repository.
sijie pushed a commit to branch branch-4.7
in repository https://gitbox.apache.org/repos/asf/bookkeeper.git
The following commit(s) were added to refs/heads/branch-4.7 by this push:
new 31a4292 Issue #1363: Fast and Garbage-Free Codahale Statistics Timers
31a4292 is described below
commit 31a42924b6efa0a246b2c27189152cc5b1bc2baa
Author: Nicolas Michael <nm...@salesforce.com>
AuthorDate: Wed Apr 25 02:09:36 2018 -0700
Issue #1363: Fast and Garbage-Free Codahale Statistics Timers
This change introduces a new Codahale-based metrics provider "FastCodahaleMetricsProvider" in the codahale-metrics-provider artifact, which can be activated through the "statsProviderClass" config parameter (no changes made to the existing "CodahaleMetricsProvider"). This new "FastCodahaleMetricsProvider" brings a new timer implementation "FastTimer", which extends Codahale's Timer class, provides an identical API, is registered in Codahale's timer registry, and can be queried through [...]
The improvements of FastTimer over Codahale default Timer with ExponentiallyDecayingReservoirs are:
* entirely garbage-free Timer updates (only snapshot creations when querying a timer allocate a small number of Java objects)
* 3x faster Timer updates (i.e. 3x shorter code-path to update a timer)
* half the memory footprint (in default configuration)
FastTimer reduces GC pause times in our experiments as described in Issue 1363 by half (same as entirely deactivating all timers).
The primary functional differences between FastTimer and Codahale default Timer with ExponentiallyDecayingReservoirs are:
* FastTimer keeps values for a fixed, configurable time period (default: 60 seconds) rather than exponentially decaying them
* FastTimer bucketizes event times rather than storing discrete values. Percentile values depend on the bucket resolution.
Design Considerations
---------------------
The design goals of this timer implementation are for it to be
- fast (i.e. few instructions to update a timer)
- scalable (i.e. little synchronization cost for concurrent timer updates)
- garbage-free for timer updates (i.e. no object allocation for timer updates)
- space-efficient (i.e. as little memory footprint as possible while achieving first three goals)
- provide similar functionality as Codahale's default timers with ExponentiallyDecayingReservoirs
This implementation provides rate and response times over a configurable sliding time window. Data
is stored in upfront allocated circular arrays, in which each array element holds data
for one second. Data is overwritten in a circular fashion without the allocation of new data
structures and is therefore garbage-free for all timer updates.
This implementation does not store individual response times, but instead allocates bucketized counters
upfront, which are incremented for any event falling into a particular response time bucket. A
fine-grained bucket definition (intended for capturing successsful events) and a coarse-grained
bucket definition (intended to capture failure or timed-out events) are provided.
To improve scalability of concurrent timer updates, most data structures are replicated HASH_SIZE
times, and calling threads updating a timer are hashed to individual instances. Performance tests
(see below) have shown that this implementation is light-weight enough to achieve slightly better
scalability than Codahale's default timers even without hashing, and can further improve scalability
if hashing is used.
Trading off performance and scalability vs. memory footprint, we need to be conservative in the hash
size we chose. Different flavors of this timer implementation have been evaluated using JMH
micro-benchmarks (see microbenchmarks/src/main/java/org/apache/bookkeeper/stats/TimerBenchmark.java),
comparing implementations of FastTimer with a time window of 60 seconds and
- (DEV1) a HASH_SIZE of 3 for all data structures (meters, counters, min/max, and response time buckets)
- (DEV2) a HASH_SIZE of 1 for all data structures (meters, counters, min/max, and response time buckets)
- (FINAL) a HASH_SIZE of 3 for meters, counters, min/max, and no hashing for response time buckets
to the default timer implementation
- (BASE-E) Codahale Timer with ExponentiallyDecayingReservoir (default as used by bookkeeper code)
- (BASE-T) Codahale Timer with SlidingTimeWindowReservoir configured to 60 seconds
- (BASE-S) Codahale Timer with SlidingWindowReservoir configured to hold 100,000 events.
Based on results below, implementation (FINAL) was chosen as the final FastTimer implementation, as it
achieves nearly the same throughput as (DEV1) at nearly the same memory footprint as (DEV2), and
ultimately achieves roughly 3x higher throughput and scalability that Codahale's default implementation
at around half the memory footprint.
The following results have been collected on an eight core x86 server running at 3.2 GHz (updated
timers are shared across 4 threads):
```
Config Timer Impl Timers Threads ops/ms Alloc B/op Kb/TimerPair
----------------------------------------------------------------------------------------
DEV1 FastTimer (Hash 3) 1 4 11487.904 0 253
DEV1 FastTimer (Hash 3) 10 4 22621.702 0 253
DEV1 FastTimer (Hash 3) 100 4 21781.319 0 253
DEV2 FastTimer (Hash 1) 1 4 5138.143 0 88
DEV2 FastTimer (Hash 1) 10 4 22902.195 0 88
DEV2 FastTimer (Hash 1) 100 4 19173.085 0 88
FINAL FastTimer (Hash 3/1) 1 4 9291.002 0 99
FINAL FastTimer (Hash 3/1) 10 4 16379.940 0 99
FINAL FastTimer (Hash 3/1) 100 4 16751.020 0 99
BASE-E CodahaleTimer 1 4 3845.187 82.609 189
BASE-E CodahaleTimer 10 4 7262.445 35.035 189
BASE-E CodahaleTimer 100 4 7051.77 32.843 189
BASE-T CodahaleTimer/TimeWindow 1 4 102.479 90.851 174
BASE-T CodahaleTimer/TimeWindow 10 4 68.852 84.812 174
BASE-T CodahaleTimer/TimeWindow 100 4 153.444 136.436 174
BASE-S CodahaleTimer/SlidingWdw 1 4 4670.543 0 2103
BASE-S CodahaleTimer/SlidingWdw 10 4 13696.168 0 2103
BASE-S CodahaleTimer/SlidingWdw 100 4 12541.936 0 2103
```
- ops/ms is the number of timer updates per millisecond.
- Alloc B/op is the number of bytes allocated per timer update
- Kb/TimerPair is the heap footprint per pair of timers (one with fine-grained, one with coarse-grained buckets)
The following test results include snapshot creation every 109 timer updates (typically, we would assume
snapshot creation to be much less frequent), and show that also with snapshots in the mix, FastTimer outperforms
Codahale default Timers both with respect to throughput and scalability as well as object allocation:
```
Config Timer Impl Timers Threads ops/ms Alloc B/op
-------------------------------------------------------------------------
FINAL FastTimer (Hash 3/1) 1 4 1569.953 23.707
FINAL FastTimer (Hash 3/1) 10 4 7316.794 24.073
FINAL FastTimer (Hash 3/1) 100 4 6498.215 24.073
BASE-E CodahaleTimer 1 4 246.953 481.771
BASE-E CodahaleTimer 10 4 1989.134 476.807
BASE-E CodahaleTimer 100 4 1514.729 468.624
BASE-T CodahaleTimer/TimeWindow 1 4 6.063 43795.810
BASE-T CodahaleTimer/TimeWindow 10 4 44.651 33916.315
BASE-T CodahaleTimer/TimeWindow 100 4 180.431 12330.939
BASE-S CodahaleTimer/SlidingWdw 1 4 17.439 14683.756
BASE-S CodahaleTimer/SlidingWdw 10 4 107.257 14683.745
BASE-S CodahaleTimer/SlidingWdw 100 4 236.538 9767.106
```
Unfortunately Codahale does not have a Timer interface we can implement, and some Codahale
base classes are assuming instances of Timer (for example, our JettyServices instantiate a
Codahale MetricsServlet, which instantiates a Codahale MetricsModule, which only serializes
timers that are instances of Timer class into the json output stream). Unless we wanted to
reimplement or override all these base classes, we can't just implement Codahale's Metered and Sampling
interfaces. Instead we have to extend its Timer class, even though we're not using any of its
inherited functionality or data structures. The inherited (unused) member variables of Codahale Timer
consume slightly less than 512 byte per FastTimer (measured around 425 byte in Codahale 3.1).
Above memory footprint results include ~ 1 kb of inherited (unused) data structures, which comprise
around 1% of FastTimer's overall memory footprint.
In terms of functionality, FastTimer provides the same functionality as Codahale's timers
(in default configuration with ExponentiallyDecayingReservoirs), with the following exceptions:
- Statistics are kept for a fixed amount of time (rather than exponentially decayed), by
default 60 seconds. As a consequence, getMeanRate(), getOneMinuteRate(), getFiveMinuteRate()
and getFifteenMinuteRate() all return the same value if FastTimer is configured to use a
60 second time window.
- FastTimer and FastSnapshot only record bucketized instead of discrete response times. As a
consequence, the accuracy of percentiles depends on bucket granularity. FastSnapshot also
can't return discrete values: getValues() returns an empty array, and size returns 0.
Author: Nicolas Michael <nm...@salesforce.com>
Reviewers: Enrico Olivelli <eo...@gmail.com>, Sijie Guo <si...@apache.org>
This closes #1364 from nicmichael/FastTimer, closes #1363
(cherry picked from commit ed3b0105d0e1adbb118641cc39f886659d140361)
Signed-off-by: Sijie Guo <si...@apache.org>
Signed-off-by: Sijie Guo <si...@apache.org>
---
.../stats/codahale/CodahaleStatsLogger.java | 2 +-
.../codahale/FastCodahaleMetricsProvider.java} | 23 +-
.../stats/codahale/FastCodahaleStatsLogger.java | 92 ++++
.../bookkeeper/stats/codahale/FastSnapshot.java | 108 ++++
.../bookkeeper/stats/codahale/FastTimer.java | 612 +++++++++++++++++++++
.../stats/codahale/CodahaleOpStatsTest.java | 10 +
.../bookkeeper/stats/codahale/FastTimerTest.java | 219 ++++++++
.../main/resources/bookkeeper/findbugsExclude.xml | 3 +
microbenchmarks/run.sh | 2 +-
.../bookkeeper/stats/StatsLoggerBenchmark.java | 4 +-
.../bookkeeper/stats/codahale/TimerBenchmark.java | 214 +++++++
11 files changed, 1272 insertions(+), 17 deletions(-)
diff --git a/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/CodahaleStatsLogger.java b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/CodahaleStatsLogger.java
index 1f6bc18..dba2e12 100644
--- a/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/CodahaleStatsLogger.java
+++ b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/CodahaleStatsLogger.java
@@ -97,7 +97,7 @@ public class CodahaleStatsLogger implements StatsLogger {
@Override
public StatsLogger scope(String scope) {
String scopeName;
- if (0 == basename.length()) {
+ if (basename == null || 0 == basename.length()) {
scopeName = scope;
} else {
scopeName = name(basename, scope);
diff --git a/bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/CodahaleOpStatsTest.java b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastCodahaleMetricsProvider.java
similarity index 57%
copy from bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/CodahaleOpStatsTest.java
copy to bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastCodahaleMetricsProvider.java
index 54efaee..cc5e615 100644
--- a/bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/CodahaleOpStatsTest.java
+++ b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastCodahaleMetricsProvider.java
@@ -16,23 +16,18 @@
*/
package org.apache.bookkeeper.stats.codahale;
-import static org.junit.Assert.assertEquals;
-
-import org.apache.bookkeeper.stats.OpStatsData;
-import org.apache.bookkeeper.stats.OpStatsLogger;
-import org.junit.Test;
+import org.apache.bookkeeper.stats.StatsLogger;
+import org.apache.bookkeeper.stats.StatsProvider;
/**
- * Unit test of {@link CodahaleOpStatsLogger}.
+ * A {@link StatsProvider} implemented based on <i>Codahale</i> metrics library.
*/
+@SuppressWarnings("deprecation")
+public class FastCodahaleMetricsProvider extends CodahaleMetricsProvider {
-public class CodahaleOpStatsTest {
- @Test
- public void testToOpStatsData() {
- OpStatsLogger logger = new CodahaleMetricsProvider().getStatsLogger("test").getOpStatsLogger("testLogger");
- logger.registerSuccessfulValue(1);
- // the following should not throw any exception
- OpStatsData statsData = logger.toOpStatsData();
- assertEquals(1, statsData.getNumSuccessfulEvents());
+ @Override
+ public StatsLogger getStatsLogger(String name) {
+ initIfNecessary();
+ return new FastCodahaleStatsLogger(getMetrics(), name);
}
}
diff --git a/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastCodahaleStatsLogger.java b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastCodahaleStatsLogger.java
new file mode 100644
index 0000000..39ac54d
--- /dev/null
+++ b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastCodahaleStatsLogger.java
@@ -0,0 +1,92 @@
+/**
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with this
+ * work for additional information regarding copyright ownership. The ASF
+ * licenses this file to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations under
+ * the License.
+ */
+package org.apache.bookkeeper.stats.codahale;
+
+import static com.codahale.metrics.MetricRegistry.name;
+import com.codahale.metrics.MetricRegistry;
+import com.codahale.metrics.Timer;
+
+import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
+
+import java.util.Map;
+import java.util.concurrent.ConcurrentHashMap;
+
+import org.apache.bookkeeper.stats.OpStatsLogger;
+import org.apache.bookkeeper.stats.StatsLogger;
+
+/**
+ * A {@link StatsLogger} implemented based on <i>Codahale</i> metrics library.
+ */
+public class FastCodahaleStatsLogger extends CodahaleStatsLogger {
+
+ private static final ConcurrentHashMap<String, CodahaleOpStatsLogger> statsLoggerCache =
+ new ConcurrentHashMap<String, CodahaleOpStatsLogger>();
+
+ FastCodahaleStatsLogger(MetricRegistry metrics, String basename) {
+ super(metrics, basename);
+ }
+
+ @Override
+ @SuppressFBWarnings(
+ value = {
+ "JLM_JSR166_UTILCONCURRENT_MONITORENTER",
+ "AT_OPERATION_SEQUENCE_ON_CONCURRENT_ABSTRACTION"
+ },
+ justification = "We use synchronized (statsLoggerCache) to make get/put atomic")
+ public OpStatsLogger getOpStatsLogger(String statName) {
+ CodahaleOpStatsLogger logger;
+ String nameSuccess = name(basename, statName);
+ logger = statsLoggerCache.get(nameSuccess);
+ if (logger == null) {
+ synchronized (statsLoggerCache) {
+ // check again now that we have the lock
+ logger = statsLoggerCache.get(nameSuccess);
+ if (logger == null) {
+ String nameFailure = name(basename, statName + "-fail");
+ FastTimer success;
+ FastTimer failure;
+ Map<String, Timer> timers = metrics.getTimers();
+ success = timers != null ? (FastTimer) timers.get(nameSuccess) : null;
+ if (success == null) {
+ success = new FastTimer(60, FastTimer.Buckets.fine);
+ metrics.register(nameSuccess, success);
+ }
+ failure = timers != null ? (FastTimer) timers.get(nameFailure) : null;
+ if (failure == null) {
+ failure = new FastTimer(60, FastTimer.Buckets.coarse);
+ metrics.register(nameFailure, failure);
+ }
+ logger = new CodahaleOpStatsLogger(success, failure);
+ statsLoggerCache.put(nameSuccess, logger);
+ }
+ }
+ }
+ return logger;
+ }
+
+ @Override
+ public StatsLogger scope(String scope) {
+ String scopeName;
+ if (basename == null || 0 == basename.length()) {
+ scopeName = scope;
+ } else {
+ scopeName = name(basename, scope);
+ }
+ return new FastCodahaleStatsLogger(metrics, scopeName);
+ }
+
+}
diff --git a/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastSnapshot.java b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastSnapshot.java
new file mode 100644
index 0000000..ee6466e
--- /dev/null
+++ b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastSnapshot.java
@@ -0,0 +1,108 @@
+/**
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with this
+ * work for additional information regarding copyright ownership. The ASF
+ * licenses this file to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations under
+ * the License.
+ */
+package org.apache.bookkeeper.stats.codahale;
+
+import com.codahale.metrics.Snapshot;
+import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
+import java.io.OutputStream;
+
+/**
+ * A snapshot of a FastTimer.
+ */
+public class FastSnapshot extends Snapshot {
+
+ private static final long[] EMPTY_VALUES = new long[] {};
+
+ private final FastTimer timer;
+ private final long min;
+ private final long max;
+ private final long sum;
+ private final long cnt;
+ private final long[] values;
+
+ @SuppressFBWarnings(
+ value = "EI_EXPOSE_REP2",
+ justification = "long[] values is newly created array; FastTimer does not hold on to reference")
+ public FastSnapshot(FastTimer timer, long min, long max, long sum, long cnt, long[] values) {
+ this.timer = timer;
+ this.min = min;
+ this.max = max;
+ this.sum = sum;
+ this.cnt = cnt;
+ this.values = values;
+ }
+
+ @Override
+ public double getValue(double quantile) {
+ if (cnt == 0 || values == null) {
+ return 0;
+ }
+ long qcnt = 0;
+ for (int i = 0; i < values.length; i++) {
+ qcnt += values[i];
+ if (((double) qcnt) / ((double) cnt) > quantile) {
+ return timer.getBucketBound(i);
+ }
+ }
+ return timer.getBucketBound(values.length);
+ }
+
+ @Override
+ public long[] getValues() {
+ return EMPTY_VALUES; // values in this snapshot represent percentile buckets, but not discrete values
+ }
+
+ @Override
+ public int size() {
+ return 0; // values in this snapshot represent percentile buckets, but not discrete values
+ }
+
+ @Override
+ public long getMax() {
+ return max;
+ }
+
+ @Override
+ public double getMean() {
+ return cnt > 0 ? ((double) sum) / ((double) cnt) : 0;
+ }
+
+ @Override
+ public long getMin() {
+ return min;
+ }
+
+ @Override
+ public double getStdDev() {
+ if (cnt < 2 || values == null) {
+ return 0;
+ }
+ double avg = getMean();
+ double var = 0;
+ for (int i = 0; i < values.length; i++) {
+ double val = timer.getBucketValue(i);
+ var += ((double) values[i]) * Math.pow(val - avg, 2);
+ }
+ return Math.sqrt(var / ((double) cnt));
+ }
+
+ @Override
+ public void dump(OutputStream output) {
+ // values in this snapshot represent percentile buckets, but not discrete values
+ }
+
+}
\ No newline at end of file
diff --git a/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastTimer.java b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastTimer.java
new file mode 100644
index 0000000..935b95f
--- /dev/null
+++ b/bookkeeper-stats-providers/codahale-metrics-provider/src/main/java/org/apache/bookkeeper/stats/codahale/FastTimer.java
@@ -0,0 +1,612 @@
+/**
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with this
+ * work for additional information regarding copyright ownership. The ASF
+ * licenses this file to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations under
+ * the License.
+ */
+package org.apache.bookkeeper.stats.codahale;
+
+import com.codahale.metrics.Reservoir;
+import com.codahale.metrics.Snapshot;
+import com.codahale.metrics.Timer;
+
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
+
+/**
+ * A fast and (nearly) garbage-free Rate and Response Times Timer.
+ * FastTimer uses circular arrays which are allocated upfront.
+ * Timer updates or queries never allocate new objects and thus never
+ * create garbage.
+ * A small number of new objects are allocated for snapshots when
+ * calling getSnapshot().
+ */
+public class FastTimer extends Timer {
+
+ /*
+ * Design Considerations
+ * ---------------------
+ *
+ * The design goals of this timer implementation are for it to be
+ * - fast (i.e. few instructions to update a timer)
+ * - scalable (i.e. little synchronization cost for concurrent timer updates)
+ * - garbage-free for timer updates (i.e. no object allocation for timer updates)
+ * - space-efficient (i.e. as little memory footprint as possible while achieving first three goals)
+ * - provide similar functionality as Codahale's default timers with ExponentiallyDecayingReservoirs
+ *
+ * This implementation provides rate and response times over a configurable sliding time window. Data
+ * is stored in upfront allocated circular arrays, in which each array element holds data
+ * for one second. Data is overwritten in a circular fashion without the allocation of new data
+ * structures and is therefore garbage-free for all timer updates.
+ *
+ * This implementation does not store individual response times, but instead allocates bucketized counters
+ * upfront, which are incremented for any event falling into a particular response time bucket. A
+ * fine-grained bucket definition (intended for capturing successsful events) and a coarse-grained
+ * bucket definition (intended to capture failure or timed-out events) are provided.
+ *
+ * To improve scalability of concurrent timer updates, most data structures are replicated HASH_SIZE
+ * times, and calling threads updating a timer are hashed to individual instances. Performance tests
+ * (see below) have shown that this implementation is light-weight enough to achieve slightly better
+ * scalability than Codahale's default timers even without hashing, and can further improve scalability
+ * if hashing is used.
+ *
+ * Trading off performance and scalability vs. memory footprint, we need to be conservative in the hash
+ * size we chose. Different flavors of this timer implementation have been evaluated using JMH
+ * micro-benchmarks (see microbenchmarks/src/main/java/org/apache/bookkeeper/stats/TimerBenchmark.java),
+ * comparing implementations of FastTimer with a time window of 60 seconds and
+ * - (DEV1) a HASH_SIZE of 3 for all data structures (meters, counters, min/max, and response time buckets)
+ * - (DEV2) a HASH_SIZE of 1 for all data structures (meters, counters, min/max, and response time buckets)
+ * - (FINAL) a HASH_SIZE of 3 for meters, counters, min/max, and no hashing for response time buckets
+ * to the default timer implementation
+ * - (BASE-E) Codahale Timer with ExponentiallyDecayingReservoir (default as used by bookkeeper code)
+ * - (BASE-T) Codahale Timer with SlidingTimeWindowReservoir configured to 60 seconds
+ * - (BASE-S) Codahale Timer with SlidingWindowReservoir configured to hold 100,000 events.
+ *
+ * Based on results below, implementation (FINAL) was chosen as the final FastTimer implementation, as it
+ * achieves nearly the same throughput as (DEV1) at nearly the same memory footprint as (DEV2), and
+ * ultimately achieves roughly 3x higher throughput and scalability that Codahale's default implementation
+ * at around half the memory footprint.
+ *
+ * The following results have been collected on an eight core x86 server running at 3.2 GHz (updated
+ * timers are shared across 4 threads):
+ *
+ * Config Timer Impl Timers Threads ops/ms Alloc B/op Kb/TimerPair
+ * ----------------------------------------------------------------------------------------
+ * DEV1 FastTimer (Hash 3) 1 4 11487.904 0 253
+ * DEV1 FastTimer (Hash 3) 10 4 22621.702 0 253
+ * DEV1 FastTimer (Hash 3) 100 4 21781.319 0 253
+ * DEV2 FastTimer (Hash 1) 1 4 5138.143 0 88
+ * DEV2 FastTimer (Hash 1) 10 4 22902.195 0 88
+ * DEV2 FastTimer (Hash 1) 100 4 19173.085 0 88
+ * FINAL FastTimer (Hash 3/1) 1 4 9291.002 0 99
+ * FINAL FastTimer (Hash 3/1) 10 4 16379.940 0 99
+ * FINAL FastTimer (Hash 3/1) 100 4 16751.020 0 99
+ * BASE-E CodahaleTimer 1 4 3845.187 82.609 189
+ * BASE-E CodahaleTimer 10 4 7262.445 35.035 189
+ * BASE-E CodahaleTimer 100 4 7051.77 32.843 189
+ * BASE-T CodahaleTimer/TimeWindow 1 4 102.479 90.851 174
+ * BASE-T CodahaleTimer/TimeWindow 10 4 68.852 84.812 174
+ * BASE-T CodahaleTimer/TimeWindow 100 4 153.444 136.436 174
+ * BASE-S CodahaleTimer/SlidingWdw 1 4 4670.543 0 2103 (size=100000)
+ * BASE-S CodahaleTimer/SlidingWdw 10 4 13696.168 0 2103
+ * BASE-S CodahaleTimer/SlidingWdw 100 4 12541.936 0 2103
+ *
+ * - ops/ms is the number of timer updates per millisecond.
+ * - Alloc B/op is the number of bytes allocated per timer update
+ * - Kb/TimerPair is the heap footprint per pair of timers (one with fine-grained, one with coarse-grained buckets)
+ *
+ * The following test results include snapshot creation every 109 timer updates (typically, we would assume
+ * snapshot creation to be much less frequent), and show that also with snapshots in the mix, FastTimer outperforms
+ * Codahale default Timers both with respect to throughput and scalability as well as object allocation:
+ *
+ * Config Timer Impl Timers Threads ops/ms Alloc B/op
+ * -------------------------------------------------------------------------
+ * FINAL FastTimer (Hash 3/1) 1 4 1569.953 23.707
+ * FINAL FastTimer (Hash 3/1) 10 4 7316.794 24.073
+ * FINAL FastTimer (Hash 3/1) 100 4 6498.215 24.073
+ * BASE-E CodahaleTimer 1 4 246.953 481.771
+ * BASE-E CodahaleTimer 10 4 1989.134 476.807
+ * BASE-E CodahaleTimer 100 4 1514.729 468.624
+ * BASE-T CodahaleTimer/TimeWindow 1 4 6.063 43795.810
+ * BASE-T CodahaleTimer/TimeWindow 10 4 44.651 33916.315
+ * BASE-T CodahaleTimer/TimeWindow 100 4 180.431 12330.939
+ * BASE-S CodahaleTimer/SlidingWdw 1 4 17.439 14683.756
+ * BASE-S CodahaleTimer/SlidingWdw 10 4 107.257 14683.745
+ * BASE-S CodahaleTimer/SlidingWdw 100 4 236.538 9767.106
+ *
+ * Unfortunately Codahale does not have a Timer interface we can implement, and some Codahale
+ * base classes are assuming instances of Timer (for example, our JettyServices instantiate a
+ * Codahale MetricsServlet, which instantiates a Codahale MetricsModule, which only serializes
+ * timers that are instances of Timer class into the json output stream). Unless we wanted to
+ * reimplement or override all these base classes, we can't just implement Codahale's Metered and Sampling
+ * interfaces. Instead we have to extend its Timer class, even though we're not using any of its
+ * inherited functionality or data structures. The inherited (unused) member variables of Codahale Timer
+ * consume slightly less than 512 byte per FastTimer (measured around 425 byte in Codahale 3.1).
+ * Above memory footprint results include ~ 1 kb of inherited (unused) data structures, which comprise
+ * around 1% of FastTimer's overall memory footprint.
+ *
+ * In terms of functionality, FastTimer provides the same functionality as Codahale's timers
+ * (in default configuration with ExponentiallyDecayingReservoirs), with the following exceptions:
+ * - Statistics are kept for a fixed amount of time (rather than exponentially decayed), by
+ * default 60 seconds. As a consequence, getMeanRate(), getOneMinuteRate(), getFiveMinuteRate()
+ * and getFifteenMinuteRate() all return the same value if FastTimer is configured to use a
+ * 60 second time window.
+ * - FastTimer and FastSnapshot only record bucketized instead of discrete response times. As a
+ * consequence, the accuracy of percentiles depends on bucket granularity. FastSnapshot also
+ * can't return discrete values: getValues() returns an empty array, and size returns 0.
+ */
+
+ /**
+ * For improved scalability, threads are hased to meters, counters, and min/max values based on
+ * HASH_SIZE. Note that response time buckets are *not* hashed to reduce memory footprint, and we
+ * assume that concurrent updates of the same response time bucket are infrequent.
+ * The hash size could be made configurable in the future (if ever seems necessary). For now, we just
+ * hard-code it to 3 based on above performance results.
+ */
+ private static final int HASH_SIZE = 3;
+
+ /**
+ * This timer stores rate and response times on a per-second basis for a configurable amount of time
+ * (default: 60 seconds).
+ * Note that larger time windows increase the memory footprint of this timer (nearly linear).
+ */
+ private static final int TIME_WINDOW = 60;
+
+ /*
+ * Buckets for percentiles store response times according to the definition in BUCKET_SPEC in the
+ * form of { numerOfBuckets , nanosecondResolutionPerBucket }.
+ *
+ * BUCKET_SPEC_FINE:
+ * This bucket definition provides fine-grained timing for small values, and more coarse-grained timing
+ * for larger values. We expect this timer to be used primarily for I/O operations that typically
+ * range in milliseconds (or sub-milliseconds), with sporadic outliers in the single-digit second
+ * range. For values larger than 10 seconds, we only keep the maximum value, but no distribution.
+ *
+ * BUCKET_SPEC_COARSE:
+ * This bucket specification provides coarse-grained timing for events in the range of 1 - 20 seconds
+ * with 1 second granularity.
+ *
+ * If this timer is used for timing of events with significantly different value distribution,
+ * other bucket definitions may be specified.
+ *
+ * Note that a larger number of buckets increases the memory footprint of this timer nearly linear
+ * (as the number of buckets largely dominate the timer's overall memory footprint).
+ */
+ private static final long[][] BUCKET_SPEC_FINE = new long[][] {
+ { 100 , 100000}, // 100 buckets of 0.1 ms ( 0.1 - 10.0 ms)
+ { 90 , 1000000}, // 90 buckets of 1 ms ( 10 - 100 ms)
+ { 90 , 10000000}, // 90 buckets of 10 ms ( 100 - 1,000 ms)
+ { 9 , 1000000000}, // 9 buckets of 1000 ms (1,000 - 10,000 ms)
+ }; // + 1 (default) bucket for all values > 10,000 ms
+
+ private static final long[][] BUCKET_SPEC_COARSE = new long[][] {
+ { 20 , 1000000000}, // 20 buckets of 1000 ms (1,000 - 20,000 ms)
+ }; // + 1 (default) bucket for all values > 20,000 ms
+
+ /**
+ * Defines the response time buckets to use.
+ * - fine: BUCKET_SPEC_FINE
+ * - coarse: BUCKET_SPEC_COARSE
+ * - none: no response time buckets
+ */
+ public enum Buckets {
+ fine,
+ coarse,
+ none
+ }
+
+ // index into the second dimension of BUCKET_SPEC arrays
+ private static final int BS_NUMBUCKETS = 0;
+ private static final int BS_RESOLUTION = 1;
+
+ /*
+ * approximate space requirements for an instance of FastTimer:
+ * 4096 + (TIME_WINDOW + 2) * ((HASH_SIZE * 28) + (NUMBUCKETS * 4))
+ *
+ * For timeWindow=60 and Buckets.fine: ~ 81 kb
+ * For timeWindow=60 and Buckets.coarse: ~ 14 kb
+ */
+
+ private final long[][] bucketSpec;
+ private final int numBuckets;
+ private final long[] bucketBounds;
+ private final int timeWindow;
+ private final int startTime;
+
+ private final AtomicLong[] counter; // indexed by [hash]
+ private final Object[] locks; // indexed by [hash]
+ private final int[] lastTime;
+ private int lastTimeBucket = 0;
+
+ private final int[][] meter; // indexed by [hash][time]
+ private final int[][] buckets; // indexed by [bucket][time]
+ private final long[][] min; // indexed by [hash][time]
+ private final long[][] max; // indexed by [hash][time]
+ private final long[][] sum; // indexed by [hash][time]
+
+ /**
+ * A Dummy reservoir implementation.
+ * Since we have to extend Codahale's Timer class (see above), we inherit all its member
+ * objects as well. By default, Timer instantiates a ExponentiallyDecayingReservoir. Since
+ * we're not making use of it, we instead instantiate our own DummyReservoir to reduce
+ * memory footprint.
+ */
+ private static class DummyReservoir implements Reservoir {
+
+ @Override
+ public int size() {
+ return 0;
+ }
+
+ @Override
+ public void update(long value) {
+ }
+
+ @Override
+ public Snapshot getSnapshot() {
+ return null;
+ }
+
+ }
+
+ /**
+ * Constructs a new timer with default time window (60 seconds) and
+ * default time buckets (fine).
+ */
+ public FastTimer() {
+ this(TIME_WINDOW, Buckets.fine);
+ }
+
+ /**
+ * Constructs a new timer.
+ * @param timeWindowSeconds the time window (in seconds) for this timer
+ * @param buckets the type of buckets to use for response times
+ */
+ public FastTimer(int timeWindowSeconds, Buckets buckets) {
+ super(new DummyReservoir());
+ this.timeWindow = timeWindowSeconds + 2; // 2 extra seconds for housekeeping
+
+ switch (buckets) {
+ case fine:
+ bucketSpec = BUCKET_SPEC_FINE;
+ break;
+ case coarse:
+ bucketSpec = BUCKET_SPEC_COARSE;
+ break;
+ default:
+ bucketSpec = null;
+ }
+
+ // initialize buckets
+ int bucketCnt = 0;
+ for (int i = 0; bucketSpec != null && i < bucketSpec.length; i++) {
+ bucketCnt += bucketSpec[i][BS_NUMBUCKETS];
+ }
+ numBuckets = (bucketCnt > 0 ? bucketCnt + 1 : 0);
+ if (numBuckets > 0) {
+ bucketBounds = new long[bucketSpec.length];
+ long bound = 0;
+ for (int i = 0; i < bucketSpec.length; i++) {
+ bound += bucketSpec[i][BS_NUMBUCKETS] * bucketSpec[i][BS_RESOLUTION];
+ bucketBounds[i] = bound;
+ }
+ } else {
+ bucketBounds = null;
+ }
+
+ this.startTime = getTime();
+
+ counter = new AtomicLong[HASH_SIZE];
+ for (int i = 0; i < counter.length; i++) {
+ counter[i] = new AtomicLong(0);
+ }
+ meter = new int[HASH_SIZE][timeWindow];
+ if (numBuckets > 0) {
+ this.buckets = new int[numBuckets][timeWindow];
+ } else {
+ this.buckets = null;
+ }
+ sum = new long[HASH_SIZE][timeWindow];
+ min = new long[HASH_SIZE][timeWindow];
+ max = new long[HASH_SIZE][timeWindow];
+
+ lastTime = new int[HASH_SIZE];
+ locks = new Object[HASH_SIZE];
+ for (int h = 0; h < locks.length; h++) {
+ locks[h] = new Object();
+ }
+ }
+
+ /**
+ * Returns the number of response time buckets used by this timer.
+ * @return the number of response time buckets
+ */
+ public int getNumberOfBuckets() {
+ return numBuckets;
+ }
+
+ /**
+ * Figure out which percentile bucket an event of a given duration belongs into.
+ * @param duration the duration (in nanoseconds)
+ * @return the bucket
+ */
+ public int getBucket(long duration) {
+ if (numBuckets == 0) {
+ return -1;
+ }
+ int bucket = 0;
+ long lowbound = 0;
+ for (int i = 0; i < bucketSpec.length; i++) {
+ if (duration <= bucketBounds[i]) {
+ return bucket + (int) ((duration - lowbound - 1) / bucketSpec[i][BS_RESOLUTION]);
+ } else {
+ bucket += bucketSpec[i][BS_NUMBUCKETS];
+ lowbound = bucketBounds[i];
+ }
+ }
+ return numBuckets - 1;
+ }
+
+ /**
+ * Returns the upper bucket bound (inclusive) of a given bucket.
+ * @param b the bucket
+ * @return the bound (in nanoseconds)
+ */
+ public long getBucketBound(int b) {
+ if (numBuckets == 0) {
+ return -1;
+ }
+ int bucket = 0;
+ long lowbound = 0;
+ for (int i = 0; i < bucketSpec.length; i++) {
+ if (b < bucket + bucketSpec[i][BS_NUMBUCKETS]) {
+ return lowbound + ((long) ((b + 1) - bucket)) * bucketSpec[i][BS_RESOLUTION];
+ } else {
+ bucket += bucketSpec[i][BS_NUMBUCKETS];
+ lowbound = bucketBounds[i];
+ }
+ }
+ return Long.MAX_VALUE;
+ }
+
+ /**
+ * Returns the average value of a given bucket (the mean between its lower and upper bound).
+ * @param b the bucket
+ * @return the average value (in nanoseconds)
+ */
+ public long getBucketValue(int b) {
+ if (numBuckets == 0) {
+ return -1;
+ }
+ if (b == 0) {
+ return getBucketBound(0) / 2;
+ }
+ if (b == numBuckets - 1) {
+ return 2 * getBucketBound(numBuckets - 2);
+ }
+ return (getBucketBound(b - 1) + getBucketBound(b)) / 2;
+ }
+
+ /**
+ * Hashes a thread to a hash index.
+ * @return the hash index
+ */
+ private int getHash() {
+ // hashing threads to timers is cheaper than ThreadLocal timers
+ return (int) (Thread.currentThread().getId() % HASH_SIZE);
+ }
+
+ /**
+ * Returns the current absolute time (in seconds).
+ * @return the current absolute time (in seconds)
+ */
+ protected int getTime() {
+ return (int) TimeUnit.NANOSECONDS.toSeconds(System.nanoTime());
+ }
+
+ /**
+ * Returns the current second (relative to start time) and, if necessary, performs house-keeping.
+ * @param hash the hash of the calling thread
+ * @return the current time since start (in seconds)
+ */
+ private int getNow(int hash) {
+ int now = getTime() - startTime;
+
+ // check whether we need to do housekeeping
+ if (now > lastTime[hash]) {
+ synchronized (locks[hash]) {
+ // now that we have the lock, check again
+ if (now > lastTime[hash]) {
+ int tstop = (now + 2) % timeWindow;
+
+ // clear meter for next time period
+ for (int t = (lastTime[hash] + 2) % timeWindow; t != tstop; t = (t + 1) % timeWindow) {
+ meter[hash][t] = 0;
+ }
+
+ // clear histo for next time period
+ for (int t = (lastTime[hash] + 2) % timeWindow; t != tstop; t = (t + 1) % timeWindow) {
+ sum[hash][t] = 0;
+ min[hash][t] = 0;
+ max[hash][t] = 0;
+ }
+
+ lastTime[hash] = now;
+ }
+ }
+ }
+
+ // check whether we need to do bucket housekeeping
+ // (we have to do this separately since buckets aren't hashed)
+ if (numBuckets > 0 && now > lastTimeBucket) {
+ synchronized (buckets) {
+ // now that we have the lock, check again
+ if (now > lastTimeBucket) {
+ int tstop = (now + 2) % timeWindow;
+ for (int b = 0; b < numBuckets; b++) {
+ synchronized (buckets[b]) {
+ for (int t = (lastTimeBucket + 2) % timeWindow; t != tstop; t = (t + 1) % timeWindow) {
+ buckets[b][t] = 0;
+ }
+ }
+ }
+ lastTimeBucket = now;
+ }
+ }
+ }
+
+ return now % timeWindow;
+ }
+
+ /**
+ * Returns the average per-second rate of events this timer has seen.
+ * The computed rate is calculated for past seconds (not including the current second, which is still being
+ * updated). If the specified time exceeds the time window of this timer, the only rate of the configured time
+ * window is reported.
+ * @param seconds the number of seconds over which to calculate the average rate
+ * @return the average rate (per second).
+ */
+ public double getRate(int seconds) {
+ seconds = Math.min(seconds, timeWindow - 2);
+ int t = getNow(getHash()) - 1; // start from last completed second
+ int secFrom = t - seconds;
+ long sum = 0;
+ for (int h = 0; h < HASH_SIZE; h++) {
+ for (int i = t; i > secFrom; i--) {
+ // no need to synchronize for reading (meter (int) is written atomically)
+ sum += meter[h][(timeWindow + i) % timeWindow];
+ }
+ }
+ return ((double) sum) / (double) seconds;
+ }
+
+ /**
+ * Returns the all-time count of events this timer has seen.
+ * @return the all-time count of events
+ */
+ @Override
+ public long getCount() {
+ long sum = 0;
+ for (AtomicLong c : counter) {
+ sum += c.get();
+ }
+ return sum;
+ }
+
+ @Override
+ public double getFifteenMinuteRate() {
+ return getRate(15 * 60);
+ }
+
+ @Override
+ public double getFiveMinuteRate() {
+ return getRate(5 * 60);
+ }
+
+ @Override
+ public double getMeanRate() {
+ return getRate(Integer.MAX_VALUE);
+ }
+
+ @Override
+ public double getOneMinuteRate() {
+ return getRate(60);
+ }
+
+ /**
+ * Returns a snapshot of this timer.
+ * The computed snapshot is calculated over the complete time interval supported by
+ * this timer.
+ * @return a snapshot of this timer
+ */
+ @Override
+ public Snapshot getSnapshot() {
+ long sum = 0;
+ long cnt = 0;
+ long min = 0;
+ long max = 0;
+
+ // get time and trigger housekeeping
+ int now = getNow(0) - 1; // start from last completed second
+ int secFrom = now - (timeWindow - 2);
+
+ for (int i = 1; i < HASH_SIZE; i++) {
+ getNow(i);
+ }
+
+ long[] buckets = (numBuckets > 0 ? new long[numBuckets] : null);
+ for (int i = now; i > secFrom; i--) {
+ int t = (timeWindow + i) % timeWindow;
+ for (int h = 0; h < HASH_SIZE; h++) {
+ synchronized (locks[h]) {
+ sum += this.sum[h][t];
+ cnt += this.meter[h][t];
+ if ((this.min[h][t] < min && this.min[h][t] > 0) || min == 0) {
+ min = this.min[h][t];
+ }
+ if (this.max[h][t] > max) {
+ max = this.max[h][t];
+ }
+ }
+ }
+ // no need to synchronize for reading (buckets (int) is written atomically)
+ for (int b = 0; b < numBuckets; b++) {
+ buckets[b] += this.buckets[b][t];
+ }
+ }
+
+ return new FastSnapshot(this, min, max, sum, cnt, buckets);
+ }
+
+ /**
+ * Add an event to this timer.
+ * @param duration the time duration of the event
+ * @param unit the unit of time duration
+ */
+ @Override
+ public void update(long duration, TimeUnit unit) {
+ update(unit.toNanos(duration));
+ }
+
+ /**
+ * Add an event to this timer.
+ * @param duration the time duration of the event (in nanoseconds)
+ */
+ private void update(long duration) {
+ if (duration < 1) {
+ // we can't time anything that took less than 1 ns (caller gave us wrong value)
+ duration = 1;
+ }
+ int h = getHash();
+ int t = getNow(h);
+ counter[h].incrementAndGet();
+
+ int b = getBucket(duration);
+ synchronized (locks[h]) {
+ meter[h][t]++;
+ sum[h][t] += duration;
+ if (duration < min[h][t] || min[h][t] == 0) {
+ min[h][t] = duration;
+ }
+ if (duration > max[h][t]) {
+ max[h][t] = duration;
+ }
+ }
+ if (numBuckets > 0) {
+ synchronized (buckets[b]) {
+ buckets[b][t]++;
+ }
+ }
+ }
+
+}
diff --git a/bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/CodahaleOpStatsTest.java b/bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/CodahaleOpStatsTest.java
index 54efaee..3d69ddb 100644
--- a/bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/CodahaleOpStatsTest.java
+++ b/bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/CodahaleOpStatsTest.java
@@ -35,4 +35,14 @@ public class CodahaleOpStatsTest {
OpStatsData statsData = logger.toOpStatsData();
assertEquals(1, statsData.getNumSuccessfulEvents());
}
+
+ @Test
+ public void testToFastOpStatsData() {
+ OpStatsLogger logger = new FastCodahaleMetricsProvider().getStatsLogger("test").getOpStatsLogger("testLogger");
+ logger.registerSuccessfulValue(1);
+ // the following should not throw any exception
+ OpStatsData statsData = logger.toOpStatsData();
+ assertEquals(1, statsData.getNumSuccessfulEvents());
+ }
+
}
diff --git a/bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/FastTimerTest.java b/bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/FastTimerTest.java
new file mode 100644
index 0000000..34ae5c3
--- /dev/null
+++ b/bookkeeper-stats-providers/codahale-metrics-provider/src/test/java/org/apache/bookkeeper/stats/codahale/FastTimerTest.java
@@ -0,0 +1,219 @@
+/**
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with this
+ * work for additional information regarding copyright ownership. The ASF
+ * licenses this file to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations under
+ * the License.
+ */
+package org.apache.bookkeeper.stats.codahale;
+
+import static org.junit.Assert.assertEquals;
+
+import com.codahale.metrics.Snapshot;
+
+import java.util.ArrayList;
+import java.util.Random;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicInteger;
+
+import org.junit.Test;
+
+/**
+ * Unit tests for FastTimer.
+ *
+ */
+public class FastTimerTest {
+
+ /*
+ * To simplify testing, we're over-riding the time source used by FastTimer with some
+ * fake time we're incrementing manually. This speeds-up testing (we don't have to wait
+ * for real seconds to elapse) and also guarantees deterministic behavior for the unit
+ * test.
+ */
+ private static AtomicInteger mockedTime = new AtomicInteger(0);
+
+ private int incSec() {
+ return mockedTime.incrementAndGet();
+ }
+
+ private FastTimer getMockedFastTimer(int timeWindowSeconds, FastTimer.Buckets buckets) {
+ return new FastTimer(timeWindowSeconds, buckets) {
+ @Override
+ protected int getTime() {
+ return mockedTime.get();
+ }
+ };
+ }
+
+ @Test
+ public void testBuckets() {
+ FastTimer t = new FastTimer(1, FastTimer.Buckets.fine);
+ for (int b = 0; b < t.getNumberOfBuckets(); b++) {
+ long lowerBound = b > 0 ? t.getBucketBound(b - 1) + 1 : 0;
+ long bucketMean = t.getBucketValue(b);
+ long upperBound = t.getBucketBound(b);
+ System.out.println(String.format("Bucket %3d [%12d - %12d], avg=%12d",
+ b, lowerBound, upperBound, bucketMean));
+ assertEquals(String.format("bucket for lowerBound value %d", lowerBound),
+ b, t.getBucket(lowerBound));
+ assertEquals(String.format("bucket for bucketMean value %d", bucketMean),
+ b, t.getBucket(bucketMean));
+ assertEquals(String.format("bucket for upperBound value %d", upperBound),
+ b, t.getBucket(upperBound));
+ if (b > 0) {
+ assertEquals(String.format("bucket before bucket %d", b), b - 1, t.getBucket(lowerBound - 1));
+ }
+ if (b + 1 < t.getNumberOfBuckets()) {
+ assertEquals(String.format("bucket after bucket %d", b), b + 1, t.getBucket(upperBound + 1));
+ }
+ }
+ }
+
+ @Test
+ public void testFunctional() {
+ FastTimer t = getMockedFastTimer(1, FastTimer.Buckets.fine);
+ for (int i = 0; i <= 10000; i++) {
+ t.update(i, TimeUnit.MICROSECONDS);
+ }
+ incSec(); // advance mocked time to next second
+ Snapshot s = t.getSnapshot();
+ assertEquals("FastTimer.getCount()", 10001, t.getCount());
+ assertEquals("FastSnapshot.getMin()", 1, s.getMin());
+ assertEquals("FastSnapshot.getMax()", TimeUnit.MICROSECONDS.toNanos(10000), s.getMax());
+ assertEquals("FastSnapshot.getMean()", TimeUnit.MICROSECONDS.toNanos(5000), (long) s.getMean());
+ assertEquals("FastSnapshot.getMedian()", TimeUnit.MICROSECONDS.toNanos(5000), (long) s.getMedian());
+ assertEquals("FastSnapshot.getValue(0.1)", TimeUnit.MICROSECONDS.toNanos(1000), (long) s.getValue(0.1));
+ assertEquals("FastSnapshot.getValue(0.9)", TimeUnit.MICROSECONDS.toNanos(9000), (long) s.getValue(0.9));
+ assertEquals("FastSnapshot.getValue(0.99)", TimeUnit.MICROSECONDS.toNanos(9900), (long) s.getValue(0.99));
+ }
+
+ @Test
+ public void testTimer() {
+ // load definitions for testing the timer
+ // following 3 array lengths must match: each element defines values for one phase
+ final int timeRange[] = new int[] { 90, 190, 50, 90, 100, 100 };
+ final int timeBase[] = new int[] { 10, 10, 50, 10, 0, 0 };
+ final int rate[] = new int[] { 1000, 1000, 1000, 1000, 0, 1 };
+
+ final int window = 5; // use a 5 second window for testing
+ FastTimer t = getMockedFastTimer(window, FastTimer.Buckets.fine);
+ Random r = new Random(12345); // fixed random seed for deterministic value distribution
+ int phase = 0;
+ int sec = 0;
+
+ long count = 0;
+ // start generating test load for each of the configured phases
+ while (phase < timeRange.length) {
+ for (int i = 0; i < rate[phase]; i++) {
+ t.update(r.nextInt(timeRange[phase]) + timeBase[phase], TimeUnit.MILLISECONDS);
+ count++;
+ }
+ incSec(); // advance mocked time to next second
+ if (++sec % window == 0) {
+ // every WINDOW seconds, check the timer values
+ Snapshot s = t.getSnapshot();
+ System.out.println(String.format(
+ "phase %3d: count=%10d, rate=%6.0f, min=%6.1f, avg=%6.1f, q99=%6.1f, max=%6.1f",
+ phase, t.getCount(), t.getMeanRate(), ((double) s.getMin()) / 1000000.0,
+ s.getMean() / 1000000.0, s.getValue(0.99) / 1000000.0, ((double) s.getMax()) / 1000000.0));
+
+ // check count (events the timer has ever seen)
+ assertEquals("FastTimer.getCount()", count, t.getCount());
+ // check rate (should be precisely the configured rate)
+ assertEquals("FastTimer.getMeanRate()", rate[phase],
+ (int) Math.round(t.getMeanRate()));
+ assertEquals("FastTimer.getOneMinuteRate()", rate[phase],
+ (int) Math.round(t.getOneMinuteRate()));
+ assertEquals("FastTimer.getFiveMinuteRate()", rate[phase],
+ (int) Math.round(t.getFiveMinuteRate()));
+ assertEquals("FastTimer.getFifteenMinuteRate()", rate[phase],
+ (int) Math.round(t.getFifteenMinuteRate()));
+ // at rates > 1000 (with fixed seed), we know that the following checks will be successful
+ if (t.getMeanRate() >= 1000) {
+ // check minimum value == lower bound
+ assertEquals("FastSnapshot.getMin()", timeBase[phase], s.getMin() / 1000000);
+ // check maximum value == upper bound
+ assertEquals("FastSnapshot.getMax()", timeBase[phase] + timeRange[phase] - 1,
+ (s.getMax() / 1000000));
+ // check 99th percentile == upper bound
+ assertEquals("FastSnapshot.getValue(0.99)",
+ t.getBucketBound(t.getBucket(
+ TimeUnit.MILLISECONDS.toNanos(timeBase[phase] + timeRange[phase] - 1))),
+ (long) s.getValue(0.99));
+ // check mean is within 10% of configured mean
+ assertEquals("FastSnapshot.getMean()", (timeBase[phase] + (timeRange[phase] / 2)) / 10,
+ (int) (Math.round(s.getMean() / 1000000) / 10));
+ }
+
+ // start next phase
+ phase++;
+ }
+ }
+ }
+
+ @Test
+ public void testTimerMultiThreaded() {
+ final int window = 5; // use a 5 second window for testing
+ FastTimer t = getMockedFastTimer(window, FastTimer.Buckets.fine);
+
+ // start 10 threads, which each update the timer 1000 times
+ ArrayList<Thread> threads = new ArrayList<Thread>();
+ for (int i = 0; i < 10; i++) {
+ Thread thread = new Thread(() -> {
+ for (int j = 0; j < 1000; j++) {
+ t.update(10, TimeUnit.MILLISECONDS);
+ }
+ });
+ threads.add(thread);
+ thread.start();
+ }
+ // wait for 10 threads to finish
+ for (Thread thread : threads) {
+ try {
+ thread.join();
+ } catch (InterruptedException e) {
+ // ignore
+ }
+ }
+ incSec(); // advance mocked time to next second
+
+ assertEquals("FastTimer.getCount()", 10000, t.getCount());
+ assertEquals("FastTimer.getMeanRate()", 2000, (int) Math.round(t.getMeanRate()));
+
+ Snapshot s = t.getSnapshot();
+ assertEquals("FastSnapshot.getMin()", 10, s.getMin() / 1000000);
+ assertEquals("FastSnapshot.getMax()", 10, (s.getMax() / 1000000));
+ assertEquals("FastSnapshot.getValue(0.99)", 10, Math.round(s.getValue(0.99) / 1000000));
+ assertEquals("FastSnapshot.getMean()", 10, (int) Math.round(s.getMean() / 1000000));
+ }
+
+ @Test
+ public void testTimerNoBuckets() {
+ final int window = 5; // use a 5 second window for testing
+ FastTimer t = getMockedFastTimer(window, FastTimer.Buckets.none);
+
+ for (int i = 0; i < 1000; i++) {
+ t.update(10, TimeUnit.MILLISECONDS);
+ }
+ incSec(); // advance mocked time to next second
+
+ assertEquals("FastTimer.getCount()", 1000, t.getCount());
+ assertEquals("FastTimer.getMeanRate()", 200, (int) Math.round(t.getMeanRate()));
+
+ Snapshot s = t.getSnapshot();
+ assertEquals("FastSnapshot.getMin()", 10, s.getMin() / 1000000);
+ assertEquals("FastSnapshot.getMax()", 10, (s.getMax() / 1000000));
+ assertEquals("FastSnapshot.getValue(0.99)", 0, Math.round(s.getValue(0.99) / 1000000));
+ assertEquals("FastSnapshot.getMean()", 10, (int) Math.round(s.getMean() / 1000000));
+ }
+
+}
diff --git a/buildtools/src/main/resources/bookkeeper/findbugsExclude.xml b/buildtools/src/main/resources/bookkeeper/findbugsExclude.xml
index c5f7f07..7bed0b7 100644
--- a/buildtools/src/main/resources/bookkeeper/findbugsExclude.xml
+++ b/buildtools/src/main/resources/bookkeeper/findbugsExclude.xml
@@ -124,6 +124,9 @@
<Class name="~org\.apache\.bookkeeper\.stats\.generated.*" />
</Match>
<Match>
+ <Class name="~org\.apache\.bookkeeper\.stats\.codahale\.generated.*" />
+ </Match>
+ <Match>
<Class name="~org\.apache\.bookkeeper\.common\.generated.*" />
</Match>
diff --git a/microbenchmarks/run.sh b/microbenchmarks/run.sh
index 0d59321..6d1348c 100755
--- a/microbenchmarks/run.sh
+++ b/microbenchmarks/run.sh
@@ -15,5 +15,5 @@
# See the License for the specific language governing permissions and
# limitations under the License.
-java -Xms1G -Xmx1G -Djdk.nio.maxCachedBufferSize=0 -Djava.net.preferIPv4Stack=true -Duser.timezone=UTC -XX:-MaxFDLimit -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:+ResizeTLAB -XX:-ResizePLAB -XX:MetaspaceSize=128m -XX:MinMetaspaceFreeRatio=50 -XX:MaxMetaspaceFreeRatio=80 -XX:+ParallelRefProcEnabled -XX:StackShadowPages=20 -XX:+UseCompressedOops -XX:+DisableExplicitGC -XX:StringTableSize=1000003 -XX:InitiatingHeapOccupancyPercent=40 -jar target/benchmarks.jar -prof gc -prof stack:lines=5;ti [...]
+java -Xms1G -Xmx1G -Djdk.nio.maxCachedBufferSize=0 -Djava.net.preferIPv4Stack=true -Duser.timezone=UTC -XX:-MaxFDLimit -XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:+ResizeTLAB -XX:-ResizePLAB -XX:MetaspaceSize=128m -XX:MinMetaspaceFreeRatio=50 -XX:MaxMetaspaceFreeRatio=80 -XX:+ParallelRefProcEnabled -XX:StackShadowPages=20 -XX:+UseCompressedOops -XX:+DisableExplicitGC -XX:StringTableSize=1000003 -XX:InitiatingHeapOccupancyPercent=40 -jar target/benchmarks.jar $@ -prof gc -prof stack:lines=5 [...]
diff --git a/microbenchmarks/src/main/java/org/apache/bookkeeper/stats/StatsLoggerBenchmark.java b/microbenchmarks/src/main/java/org/apache/bookkeeper/stats/StatsLoggerBenchmark.java
index 9b5bdc0..0a2cd06 100644
--- a/microbenchmarks/src/main/java/org/apache/bookkeeper/stats/StatsLoggerBenchmark.java
+++ b/microbenchmarks/src/main/java/org/apache/bookkeeper/stats/StatsLoggerBenchmark.java
@@ -28,6 +28,7 @@ import org.apache.bookkeeper.stats.OpStatsLogger;
import org.apache.bookkeeper.stats.StatsLogger;
import org.apache.bookkeeper.stats.StatsProvider;
import org.apache.bookkeeper.stats.codahale.CodahaleMetricsProvider;
+import org.apache.bookkeeper.stats.codahale.FastCodahaleMetricsProvider;
import org.apache.bookkeeper.stats.prometheus.PrometheusMetricsProvider;
import org.apache.bookkeeper.stats.twitter.ostrich.OstrichProvider;
import org.apache.bookkeeper.stats.twitter.science.TwitterStatsProvider;
@@ -58,13 +59,14 @@ public class StatsLoggerBenchmark {
static {
providers.put("Prometheus", PrometheusMetricsProvider::new);
providers.put("Codahale", CodahaleMetricsProvider::new);
+ providers.put("FastCodahale", FastCodahaleMetricsProvider::new);
providers.put("Twitter", TwitterStatsProvider::new);
providers.put("Ostrich", OstrichProvider::new);
}
@State(Scope.Benchmark)
public static class LoggerState {
- @Param({ "Prometheus" })//, "Codahale", "Twitter", "Ostrich" })
+ @Param({ "Prometheus", "Codahale", "FastCodahale", "Twitter", "Ostrich" })
private String statsProvider;
private Counter counter;
diff --git a/microbenchmarks/src/main/java/org/apache/bookkeeper/stats/codahale/TimerBenchmark.java b/microbenchmarks/src/main/java/org/apache/bookkeeper/stats/codahale/TimerBenchmark.java
new file mode 100644
index 0000000..5d1cf06
--- /dev/null
+++ b/microbenchmarks/src/main/java/org/apache/bookkeeper/stats/codahale/TimerBenchmark.java
@@ -0,0 +1,214 @@
+/**
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with this
+ * work for additional information regarding copyright ownership. The ASF
+ * licenses this file to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations under
+ * the License.
+ */
+package org.apache.bookkeeper.stats.codahale;
+
+import java.util.concurrent.ThreadLocalRandom;
+import java.util.concurrent.TimeUnit;
+
+import org.apache.bookkeeper.stats.OpStatsLogger;
+import org.apache.bookkeeper.stats.StatsLogger;
+import org.apache.bookkeeper.stats.codahale.CodahaleMetricsProvider;
+import org.apache.bookkeeper.stats.codahale.FastCodahaleMetricsProvider;
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.BenchmarkMode;
+import org.openjdk.jmh.annotations.Fork;
+import org.openjdk.jmh.annotations.Level;
+import org.openjdk.jmh.annotations.Measurement;
+import org.openjdk.jmh.annotations.Mode;
+import org.openjdk.jmh.annotations.OutputTimeUnit;
+import org.openjdk.jmh.annotations.Param;
+import org.openjdk.jmh.annotations.Scope;
+import org.openjdk.jmh.annotations.Setup;
+import org.openjdk.jmh.annotations.State;
+import org.openjdk.jmh.annotations.Threads;
+import org.openjdk.jmh.annotations.Warmup;
+
+/**
+ * Microbenchmarks for default and improved (fast) Codahale timers.
+ * To run:
+ * build project from command line (mvn clean install).
+ * execute ./run.sh
+ * Specify argument "TimerBenchmark" to only run this benchmark.
+ */
+public class TimerBenchmark {
+
+ /**
+ * Type of Timer.
+ */
+ public enum TimerType {
+ CodahaleTimer,
+ FastTimer
+ }
+
+ /**
+ * Thread-local state.
+ */
+ @State(Scope.Thread)
+ public static class MyState {
+
+ @Param
+ public TimerType timerType;
+
+ @Param({"1", "10", "100"})
+ public int timersPerThread;
+
+ private static OpStatsLogger[] timers;
+ private int timerIdx = 0;
+
+ private static long[] times;
+ private int timeIdx = 0;
+
+ @Setup(Level.Trial)
+ public void doSetup() throws Exception {
+ StatsLogger logger = null;
+ switch (timerType) {
+ case CodahaleTimer:
+ logger = new CodahaleMetricsProvider().getStatsLogger("test");
+ break;
+ case FastTimer:
+ logger = new FastCodahaleMetricsProvider().getStatsLogger("test");
+ break;
+ }
+
+ synchronized (MyState.class) {
+ // timers (and response times) are shared across threads to test
+ // concurrency of timer updates.
+ if (timers == null) {
+ timers = new OpStatsLogger[timersPerThread];
+ for (int i = 0; i < timersPerThread; i++) {
+ timers[i] = logger.getOpStatsLogger("test-timer-" + i);
+ }
+
+ // just a bunch of random response times to not always hit the same bucket
+ times = new long[1000];
+ for (int i = 0; i < times.length; i++) {
+ times[i] = Math.abs(ThreadLocalRandom.current().nextLong() % 1000);
+ }
+ }
+ }
+ }
+
+ public OpStatsLogger getTimer() {
+ return timers[(timerIdx++) % timers.length];
+ }
+
+ public long getTime() {
+ return times[(timeIdx++) % times.length];
+ }
+
+ public boolean isGetSnapshot() {
+ // create a snapshot every 109 operations (typically snapshot creations will be much more infrequent)
+ // 109 is prime, guaranteeing that we will create snapshots across all timers
+ if (timeIdx % 109 == 0) {
+ timeIdx++;
+ return true;
+ } else {
+ return false;
+ }
+ }
+
+ }
+
+ /**
+ * Tests the performance of (concurrent) timer updates.
+ * Note that test duration must exceed TIME_WINDOW (default: 60) to trigger
+ * FastTimer's housekeeping. Manual tests show little performance difference
+ * for longer running tests (since housekeeping is infrequent and cheap), so
+ * we keep the test duration low to not have tests run for too long.
+ * @param state
+ */
+ @Benchmark
+ @BenchmarkMode(Mode.Throughput)
+ @OutputTimeUnit(TimeUnit.MILLISECONDS)
+ @Warmup(iterations = 2, time = 3, timeUnit = TimeUnit.SECONDS)
+ @Measurement(iterations = 2, time = 10, timeUnit = TimeUnit.SECONDS)
+ @Threads(4)
+ @Fork(value = 1, warmups = 1)
+ public void timerTest(MyState state) {
+ state.getTimer().registerSuccessfulEvent(state.getTime(), TimeUnit.MILLISECONDS);
+ }
+
+ /**
+ * Tests the performance of (concurrent) timer updates with
+ * the creation of snapshots. We expect snapshot creation to
+ * be infrequent (e.g. once every N seconds), while timer updates
+ * are frequent (for many timers hundreds or thousands of times
+ * per second). Here we're testing the creation of snapshots at
+ * a rate much higher than we would expect in real life.
+ * @param state
+ */
+ @Benchmark
+ @BenchmarkMode(Mode.Throughput)
+ @OutputTimeUnit(TimeUnit.MILLISECONDS)
+ @Warmup(iterations = 2, time = 3, timeUnit = TimeUnit.SECONDS)
+ @Measurement(iterations = 2, time = 10, timeUnit = TimeUnit.SECONDS)
+ @Threads(4)
+ @Fork(value = 1, warmups = 1)
+ public void timerTestWithSnapshots(MyState state) {
+ OpStatsLogger timer = state.getTimer();
+ if (state.isGetSnapshot()) {
+ timer.toOpStatsData();
+ } else {
+ timer.registerSuccessfulEvent(state.getTime(), TimeUnit.MILLISECONDS);
+ }
+ }
+
+ /**
+ * Test routing for manual testing of memory footprint of default Codahale Timer vs. improved FastTimer.
+ * JMH can't do that, so we have a small stand-alone test routine here.
+ * Run with: java -Xmx1g -cp target/benchmarks.jar org.apache.bookkeeper.stats.codahale.TimerBenchmark <codahale|fast>
+ * @param args
+ */
+ public static void main(String[] args) {
+ if (args.length != 1 ||
+ (!args[0].equalsIgnoreCase("codahale") && !args[0].equalsIgnoreCase("fast"))) {
+ System.out.println("usage: " + TimerBenchmark.class.getCanonicalName() + " <codahale|fast>");
+ System.exit(1);
+ }
+ StatsLogger logger = null;
+ if (args[0].equalsIgnoreCase("codahale")) {
+ logger = new CodahaleMetricsProvider().getStatsLogger("test");
+ } else {
+ logger = new FastCodahaleMetricsProvider().getStatsLogger("test");
+ }
+ System.out.println("Using " + logger.getClass().getCanonicalName());
+ System.out.println("Creating 1000 OpStatsLoggers (2000 Timers) and updating each of them 1000 times ...");
+ OpStatsLogger[] timers = new OpStatsLogger[1000];
+ for (int i=0; i<timers.length; i++) {
+ timers[i] = logger.getOpStatsLogger("test-timer-" + i);
+ }
+ long[] times = new long[199]; // 199 is prime, so each timer will get each time
+ for (int i = 0; i < times.length; i++) {
+ times[i] = Math.abs(ThreadLocalRandom.current().nextLong() % 1000);
+ }
+ for (int i=0; i<1000 * timers.length; i++) {
+ timers[i % timers.length].registerSuccessfulEvent(times[i % times.length], TimeUnit.MILLISECONDS);
+ timers[i % timers.length].registerFailedEvent(times[i % times.length], TimeUnit.MILLISECONDS);
+ }
+ times = null; // let it become garbage
+ System.out.println("Done.");
+ System.out.println("Now run 'jmap -histo:live <pid>' on this JVM to get a heap histogram, then kill this JVM.");
+ while(true) {
+ try {
+ TimeUnit.MILLISECONDS.sleep(1000);
+ } catch(Exception e) {
+ // ignore
+ }
+ }
+ }
+
+}
--
To stop receiving notification emails like this one, please contact
sijie@apache.org.