aurora-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From mehr...@apache.org
Subject aurora git commit: 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.
Date Sat, 25 Feb 2017 04:38:03 GMT
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 <mehrdad@apache.org>
Authored: Fri Feb 24 20:31:20 2017 -0800
Committer: Mehrdad Nurolahzade <mnurolahzade@twitter.com>
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"));
+    }
+  }
 }


Mime
View raw message