Repository: aurora Updated Branches: refs/heads/master 98eb99aaa -> fadfd554d
Currently snapshot times are exposed for the entire snapshot save/apply operation. This patch provides the means to collect finer grained metrics on individual fields in a snapshot. Bugs closed: AURORA-1870 Reviewed at https://reviews.apache.org/r/55105/ Project: http://git-wip-us.apache.org/repos/asf/aurora/repo Commit: http://git-wip-us.apache.org/repos/asf/aurora/commit/fadfd554 Tree: http://git-wip-us.apache.org/repos/asf/aurora/tree/fadfd554 Diff: http://git-wip-us.apache.org/repos/asf/aurora/diff/fadfd554 Branch: refs/heads/master Commit: fadfd554dc400e58aefc82b699adb62357a7577e Parents: 98eb99a Author: Mehrdad Nurolahzade <[email protected]> Authored: Fri Feb 24 20:31:20 2017 -0800 Committer: Mehrdad Nurolahzade <[email protected]> Committed: Fri Feb 24 20:31:20 2017 -0800 ---------------------------------------------------------------------- .../aurora/common/stats/SlidingStats.java | 86 ++++++++++- .../aurora/common/stats/SlidingStatsTest.java | 142 +++++++++++++++++++ .../storage/log/SnapshotStoreImpl.java | 42 +++++- .../storage/log/SnapshotStoreImplIT.java | 33 +++++ 4 files changed, 295 insertions(+), 8 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/aurora/blob/fadfd554/commons/src/main/java/org/apache/aurora/common/stats/SlidingStats.java ---------------------------------------------------------------------- diff --git a/commons/src/main/java/org/apache/aurora/common/stats/SlidingStats.java b/commons/src/main/java/org/apache/aurora/common/stats/SlidingStats.java index f7a5ae4..f2590bb 100644 --- a/commons/src/main/java/org/apache/aurora/common/stats/SlidingStats.java +++ b/commons/src/main/java/org/apache/aurora/common/stats/SlidingStats.java @@ -16,6 +16,9 @@ package org.apache.aurora.common.stats; import java.util.concurrent.atomic.AtomicLong; import org.apache.aurora.common.base.MorePreconditions; +import org.apache.aurora.common.util.Clock; + +import static java.util.Objects.requireNonNull; /** * Tracks event statistics over a sliding window of time. An event is something that has a @@ -25,11 +28,70 @@ import org.apache.aurora.common.base.MorePreconditions; */ public class SlidingStats { + /** + * An abstraction for an action to be timed by SlidingStats. + * + * @param <V> The result of the successfully completed action. + * @param <E> The exception type that the action might throw. + */ + @FunctionalInterface + public interface Timeable<V, E extends Exception> { + + /** + * A convenient typedef for action that throws no checked exceptions - it runs quietly. + * + * @param <V> The result of the successfully completed action. + */ + @FunctionalInterface + interface Quiet<V> extends Timeable<V, RuntimeException> { + // empty + } + + /** + * Encapsulates an action with no result. + * + * @param <E> The exception type that the action might throw. + */ + @FunctionalInterface + interface NoResult<E extends Exception> extends Timeable<Void, E> { + @Override + default Void invoke() throws E { + execute(); + return null; + } + + /** + * Similar to {@link Timeable#invoke()} except no result is returned. + * + * @throws E If action fails. + */ + void execute() throws E; + + /** + * A convenient typedef for action with no result that throws no checked exceptions - it runs + * quietly. + */ + @FunctionalInterface + interface Quiet extends NoResult<RuntimeException> { + // empty + } + } + + /** + * Abstracts an action that has a result, but may also throw a specific exception. + * + * @return The result of the successfully completed action. + * @throws E If action fails. + */ + V invoke() throws E; + } + private static final int DEFAULT_WINDOW_SIZE = 1; private final AtomicLong total; private final AtomicLong events; private final Stat<Double> perEventLatency; + private final Clock clock; /** * Creates a new sliding statistic with the given name @@ -38,7 +100,7 @@ public class SlidingStats { * @param totalUnitDisplay String to display for the total counter unit. */ public SlidingStats(String name, String totalUnitDisplay) { - this(name, totalUnitDisplay, DEFAULT_WINDOW_SIZE); + this(name, totalUnitDisplay, DEFAULT_WINDOW_SIZE, Clock.SYSTEM_CLOCK); } /** @@ -47,8 +109,9 @@ public class SlidingStats { * @param name Name for this stat collection. * @param totalUnitDisplay String to display for the total counter unit. * @param windowSize The window size for the per second Rate and Ratio stats. + * @param clock The clock abstraction to use for timing in {@link #time(Timeable)} calls. */ - public SlidingStats(String name, String totalUnitDisplay, int windowSize) { + public SlidingStats(String name, String totalUnitDisplay, int windowSize, Clock clock) { MorePreconditions.checkNotBlank(name); String totalDisplay = name + "_" + totalUnitDisplay + "_total"; @@ -58,6 +121,7 @@ public class SlidingStats { perEventLatency = Stats.export(Ratio.of(name + "_" + totalUnitDisplay + "_per_event", Rate.of(totalDisplay + "_per_sec", total).withWindowSize(windowSize).build(), Rate.of(eventDisplay + "_per_sec", events).withWindowSize(windowSize).build())); + this.clock = requireNonNull(clock); } public AtomicLong getTotalCounter() { @@ -86,6 +150,24 @@ public class SlidingStats { events.incrementAndGet(); } + /** + * Accumulates counter by the nanoseconds it takes to execute the supplied action. + * + * @param action An action that produces result of type V and may throw exception E. + * @param <V> The return type of action. + * @param <E> The exception type that might be thrown by action. + * @return The value returned by action. + * @throws E A subclass of {@link Exception} that might be thrown by action. + */ + public <V, E extends Exception> V time(Timeable<V, E> action) throws E { + long start = clock.nowNanos(); + try { + return action.invoke(); + } finally { + accumulate(clock.nowNanos() - start); + } + } + @Override public String toString() { return total + " " + events; http://git-wip-us.apache.org/repos/asf/aurora/blob/fadfd554/commons/src/test/java/org/apache/aurora/common/stats/SlidingStatsTest.java ---------------------------------------------------------------------- diff --git a/commons/src/test/java/org/apache/aurora/common/stats/SlidingStatsTest.java b/commons/src/test/java/org/apache/aurora/common/stats/SlidingStatsTest.java new file mode 100644 index 0000000..5b58624 --- /dev/null +++ b/commons/src/test/java/org/apache/aurora/common/stats/SlidingStatsTest.java @@ -0,0 +1,142 @@ +/** + * Licensed 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.aurora.common.stats; + +import org.apache.aurora.common.quantity.Amount; +import org.apache.aurora.common.quantity.Time; +import org.apache.aurora.common.stats.SlidingStats.Timeable; +import org.apache.aurora.common.util.testing.FakeClock; +import org.junit.Before; +import org.junit.Test; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNull; +import static org.junit.Assert.fail; + +public class SlidingStatsTest { + + private static final long OPERATION_TIME = 5L; + private static final Amount<Long, Time> OPERATION_TIME_AMOUNT = + Amount.of(OPERATION_TIME, Time.NANOSECONDS); + + private FakeClock clock; + private TimedActions actions; + private SlidingStats stat; + + @Before + public void setUp() { + clock = new FakeClock(); + actions = new TimedActions(clock); + stat = new SlidingStats("a", "nanos", 1, clock); + } + + @Test + public void testAccumulate() { + assertEquals(0L, stat.getEventCounter().get()); + assertEquals(0L, stat.getTotalCounter().get()); + + stat.accumulate(100L); + + assertEquals(1L, stat.getEventCounter().get()); + assertEquals(100L, stat.getTotalCounter().get()); + } + + @Test + public void testTimeable() { + String value = stat.time(() -> actions.quietAction("World")); + assertEquals("HelloWorld", value); + assertEquals(1L, stat.getEventCounter().get()); + assertEquals(OPERATION_TIME, stat.getTotalCounter().get()); + } + + @Test + public void testNoResultQuietTimeable() { + stat.time((Timeable.NoResult.Quiet) actions::noResultQuietAction); + assertEquals(1L, stat.getEventCounter().get()); + assertEquals(OPERATION_TIME, stat.getTotalCounter().get()); + } + + @Test + public void testTimeableThrowsException() { + String value = null; + try { + value = stat.time(actions::action); + fail("Should have thrown exception."); + } catch (Exception e) { + assertEquals("Expected!", e.getMessage()); + } + assertNull(value); + assertEquals(1L, stat.getEventCounter().get()); + assertEquals(OPERATION_TIME, stat.getTotalCounter().get()); + } + + @Test + public void testNoResultTimeableThrowsException() { + try { + stat.time((Timeable.NoResult<Exception>) actions::noResultAction); + fail("Should have thrown exception."); + } catch (Exception e) { + assertEquals("Expected!", e.getMessage()); + } + assertEquals(1L, stat.getEventCounter().get()); + assertEquals(OPERATION_TIME, stat.getTotalCounter().get()); + } + + @Test + public void testQuietTimeableThrowsRuntimeException() { + String value = null; + try { + value = stat.time(actions::quietExceptionalAction); + fail("Should have thrown exception."); + } catch (RuntimeException e) { + assertEquals("Expected!", e.getMessage()); + } + assertNull(value); + assertEquals(1L, stat.getEventCounter().get()); + assertEquals(OPERATION_TIME, stat.getTotalCounter().get()); + } + + private static class TimedActions { + private FakeClock clock; + + public TimedActions(FakeClock clock) { + this.clock = clock; + } + + String action() throws Exception{ + clock.advance(OPERATION_TIME_AMOUNT); + throw new Exception("Expected!"); + } + + String quietAction(String input) { + clock.advance(OPERATION_TIME_AMOUNT); + return "Hello" + input; + } + + String quietExceptionalAction() { + clock.advance(OPERATION_TIME_AMOUNT); + throw new RuntimeException("Expected!"); + } + + void noResultAction() throws Exception { + clock.advance(OPERATION_TIME_AMOUNT); + throw new Exception("Expected!"); + } + + void noResultQuietAction() { + clock.advance(OPERATION_TIME_AMOUNT); + System.gc(); + } + } +} http://git-wip-us.apache.org/repos/asf/aurora/blob/fadfd554/src/main/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImpl.java ---------------------------------------------------------------------- diff --git a/src/main/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImpl.java b/src/main/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImpl.java index 7aa111e..81a8cca 100644 --- a/src/main/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImpl.java +++ b/src/main/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImpl.java @@ -30,13 +30,19 @@ import javax.inject.Inject; import javax.inject.Qualifier; import javax.sql.DataSource; +import com.google.common.annotations.VisibleForTesting; import com.google.common.base.Joiner; import com.google.common.base.Optional; +import com.google.common.cache.CacheBuilder; +import com.google.common.cache.CacheLoader; +import com.google.common.cache.LoadingCache; import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableSet; import com.google.common.collect.Lists; import org.apache.aurora.common.inject.TimedInterceptor.Timed; +import org.apache.aurora.common.stats.SlidingStats; +import org.apache.aurora.common.stats.SlidingStats.Timeable; import org.apache.aurora.common.util.BuildInfo; import org.apache.aurora.common.util.Clock; import org.apache.aurora.gen.HostAttributes; @@ -76,6 +82,11 @@ import static java.util.Objects.requireNonNull; */ public class SnapshotStoreImpl implements SnapshotStore<Snapshot> { + @VisibleForTesting + static final String SNAPSHOT_SAVE = "snapshot_save_"; + @VisibleForTesting + static final String SNAPSHOT_RESTORE = "snapshot_restore_"; + private static final Logger LOG = LoggerFactory.getLogger(SnapshotStoreImpl.class); /** @@ -473,7 +484,7 @@ public class SnapshotStoreImpl implements SnapshotStore<Snapshot> { // one of the field closures is mean and tries to apply a timestamp. long timestamp = clock.nowMillis(); for (SnapshotField field : snapshotFields) { - field.saveToSnapshot(storeProvider, snapshot); + field.save(storeProvider, snapshot); } SchedulerMetadata metadata = new SchedulerMetadata() @@ -495,16 +506,35 @@ public class SnapshotStoreImpl implements SnapshotStore<Snapshot> { LOG.info("Restoring snapshot."); for (SnapshotField field : snapshotFields) { - field.restoreFromSnapshot(storeProvider, snapshot); + field.restore(storeProvider, snapshot); } }); } - private interface SnapshotField { - String getName(); + abstract class SnapshotField { + + abstract String getName(); + + abstract void saveToSnapshot(MutableStoreProvider storeProvider, Snapshot snapshot); + + abstract void restoreFromSnapshot(MutableStoreProvider storeProvider, Snapshot snapshot); - void saveToSnapshot(MutableStoreProvider storeProvider, Snapshot snapshot); + void save(MutableStoreProvider storeProvider, Snapshot snapshot) { + stats.getUnchecked(SNAPSHOT_SAVE + getName()) + .time((Timeable.NoResult.Quiet) () -> saveToSnapshot(storeProvider, snapshot)); + } - void restoreFromSnapshot(MutableStoreProvider storeProvider, Snapshot snapshot); + void restore(MutableStoreProvider storeProvider, Snapshot snapshot) { + stats.getUnchecked(SNAPSHOT_RESTORE + getName()) + .time((Timeable.NoResult.Quiet) () -> restoreFromSnapshot(storeProvider, snapshot)); + } } + + private final LoadingCache<String, SlidingStats> stats = CacheBuilder.newBuilder().build( + new CacheLoader<String, SlidingStats>() { + @Override + public SlidingStats load(String name) throws Exception { + return new SlidingStats(name, "nanos"); + } + }); } http://git-wip-us.apache.org/repos/asf/aurora/blob/fadfd554/src/test/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImplIT.java ---------------------------------------------------------------------- diff --git a/src/test/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImplIT.java b/src/test/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImplIT.java index f56a162..ca95256 100644 --- a/src/test/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImplIT.java +++ b/src/test/java/org/apache/aurora/scheduler/storage/log/SnapshotStoreImplIT.java @@ -21,6 +21,7 @@ import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableMap; import com.google.common.collect.ImmutableSet; +import org.apache.aurora.common.stats.Stats; import org.apache.aurora.common.util.testing.FakeBuildInfo; import org.apache.aurora.common.util.testing.FakeClock; import org.apache.aurora.gen.Attribute; @@ -76,8 +77,11 @@ import static org.apache.aurora.scheduler.storage.db.DbModule.testModuleWithWork import static org.apache.aurora.scheduler.storage.db.DbUtil.createStorage; import static org.apache.aurora.scheduler.storage.db.DbUtil.createStorageInjector; import static org.apache.aurora.scheduler.storage.log.SnapshotStoreImpl.ALL_H2_STORE_FIELDS; +import static org.apache.aurora.scheduler.storage.log.SnapshotStoreImpl.SNAPSHOT_RESTORE; +import static org.apache.aurora.scheduler.storage.log.SnapshotStoreImpl.SNAPSHOT_SAVE; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertNotNull; import static org.junit.Assert.assertNull; import static org.junit.Assert.assertTrue; @@ -106,6 +110,7 @@ public class SnapshotStoreImplIT { hydrateFields, createStorageInjector(testModuleWithWorkQueue()).getInstance(MigrationManager.class), TaskTestUtil.THRIFT_BACKFILL); + Stats.flush(); } private static Snapshot makeComparable(Snapshot snapshot) { @@ -124,11 +129,14 @@ public class SnapshotStoreImplIT { Snapshot snapshot1 = snapshotStore.createSnapshot(); assertEquals(expected(), makeComparable(snapshot1)); assertFalse(snapshot1.isExperimentalTaskStore()); + assertSnapshotSaveStats(ALL_H2_STORE_FIELDS, 1L); snapshotStore.applySnapshot(snapshot1); Snapshot snapshot2 = snapshotStore.createSnapshot(); assertEquals(expected(), makeComparable(snapshot2)); assertEquals(makeComparable(snapshot1), makeComparable(snapshot2)); + assertSnapshotRestoreStats(ALL_H2_STORE_FIELDS, 1L); + assertSnapshotSaveStats(ALL_H2_STORE_FIELDS, 2L); } @Test @@ -139,6 +147,7 @@ public class SnapshotStoreImplIT { Snapshot snapshot1 = snapshotStore.createSnapshot(); assertEquals(expected(), makeComparable(snapshot1)); assertFalse(snapshot1.isExperimentalTaskStore()); + assertSnapshotSaveStats(ALL_H2_STORE_FIELDS, 1L); setUpStore(true, ALL_H2_STORE_FIELDS); snapshotStore.applySnapshot(snapshot1); @@ -146,6 +155,8 @@ public class SnapshotStoreImplIT { assertTrue(snapshot2.isExperimentalTaskStore()); assertEquals(expected(), makeComparable(snapshot2)); assertEquals(makeComparable(snapshot1), makeComparable(snapshot2)); + assertSnapshotRestoreStats(ALL_H2_STORE_FIELDS, 1L); + assertSnapshotSaveStats(ALL_H2_STORE_FIELDS, 1L); } @Test @@ -156,6 +167,7 @@ public class SnapshotStoreImplIT { Snapshot snapshot1 = snapshotStore.createSnapshot(); assertEquals(expected(), makeComparable(snapshot1)); assertTrue(snapshot1.isExperimentalTaskStore()); + assertSnapshotSaveStats(ALL_H2_STORE_FIELDS, 1L); setUpStore(false, ALL_H2_STORE_FIELDS); snapshotStore.applySnapshot(snapshot1); @@ -163,6 +175,8 @@ public class SnapshotStoreImplIT { assertFalse(snapshot2.isExperimentalTaskStore()); assertEquals(expected(), makeComparable(snapshot2)); assertEquals(makeComparable(snapshot1), makeComparable(snapshot2)); + assertSnapshotRestoreStats(ALL_H2_STORE_FIELDS, 1L); + assertSnapshotSaveStats(ALL_H2_STORE_FIELDS, 1L); } @Test @@ -186,11 +200,14 @@ public class SnapshotStoreImplIT { Snapshot snapshot1 = snapshotStore.createSnapshot(); assertEquals(expected(), makeComparable(snapshot1)); assertTrue(snapshot1.isExperimentalTaskStore()); + assertSnapshotSaveStats(ALL_H2_STORE_FIELDS, 1L); snapshotStore.applySnapshot(snapshot1); Snapshot snapshot2 = snapshotStore.createSnapshot(); assertEquals(expected(), makeComparable(snapshot2)); assertEquals(makeComparable(snapshot1), makeComparable(snapshot2)); + assertSnapshotRestoreStats(ALL_H2_STORE_FIELDS, 1L); + assertSnapshotSaveStats(ALL_H2_STORE_FIELDS, 2L); } @Test @@ -200,6 +217,8 @@ public class SnapshotStoreImplIT { Snapshot backfilled = snapshotStore.createSnapshot(); assertEquals(expected(), makeComparable(backfilled)); + assertSnapshotRestoreStats(ALL_H2_STORE_FIELDS, 1L); + assertSnapshotSaveStats(ALL_H2_STORE_FIELDS, 1L); } private static final IScheduledTask TASK = TaskTestUtil.makeTask("id", JOB_KEY); @@ -306,4 +325,18 @@ public class SnapshotStoreImplIT { ); }); } + + private void assertSnapshotSaveStats(Set<String> stats, long count) { + for (String stat : stats) { + assertEquals(count, Stats.getVariable(SNAPSHOT_SAVE + stat + "_events").read()); + assertNotNull(Stats.getVariable(SNAPSHOT_SAVE + stat + "_nanos_total")); + } + } + + private void assertSnapshotRestoreStats(Set<String> stats, long count) { + for (String stat : stats) { + assertEquals(count, Stats.getVariable(SNAPSHOT_RESTORE + stat + "_events").read()); + assertNotNull(Stats.getVariable(SNAPSHOT_RESTORE + stat + "_nanos_total")); + } + } }
