This is an automated email from the ASF dual-hosted git repository.
sijie pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/bookkeeper.git
The following commit(s) were added to refs/heads/master by this push:
new ed3b010 Issue #1363: Fast and Garbage-Free Codahale Statistics Timers
ed3b010 is described below
commit ed3b0105d0e1adbb118641cc39f886659d140361
Author: Nicolas Michael <[email protected]>
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 <[email protected]>
Reviewers: Enrico Olivelli <[email protected]>, Sijie Guo
<[email protected]>
This closes #1364 from nicmichael/FastTimer, closes #1363
---
.../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
[email protected].
