aurora-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From jco...@apache.org
Subject aurora git commit: Changes to intercept and time mybatis invocations
Date Fri, 02 Dec 2016 04:01:56 GMT
Repository: aurora
Updated Branches:
  refs/heads/master 16e4651d5 -> 3ea0331d4


Changes to intercept and time mybatis invocations

MyBatis allows us to intercept calls within the execution of a mapped statement. This allows
us to
time various mapped statements and ultimately gain more insight on the performance of the
database
module.

This patch introduces an interceptor on MyBatis on `updates` and `query` mapped statements.
I used
the following convention to create name for the newly collected stats:
mybatis.<<the id of the mapped statement>>

After interception the process is very similar to the one in @Timed-interceptor. SlidingStats
can be
used to export interval averages, total milliseconds and the event counts.

__example stats (from ./vars.json)__
mybatis.create_tables_events 1
mybatis.create_tables_events_per_sec 0.0
mybatis.create_tables_nanos_per_event 0.0
mybatis.create_tables_nanos_total 592633784
mybatis.create_tables_nanos_total_per_sec 0.0
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.selectAll_events 3
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.selectAll_events_per_sec 0.0
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.selectAll_nanos_per_event 0.0
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.selectAll_nanos_total 2858362
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.selectAll_nanos_total_per_sec
0.0
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.select_events 333
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.select_events_per_sec 0.0
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.select_nanos_per_event 0.0
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.select_nanos_total 85745680
mybatis.org.apache.aurora.scheduler.storage.db.AttributeMapper.select_nanos_total_per_sec
0.0

Reviewed at https://reviews.apache.org/r/54107/


Project: http://git-wip-us.apache.org/repos/asf/aurora/repo
Commit: http://git-wip-us.apache.org/repos/asf/aurora/commit/3ea0331d
Tree: http://git-wip-us.apache.org/repos/asf/aurora/tree/3ea0331d
Diff: http://git-wip-us.apache.org/repos/asf/aurora/diff/3ea0331d

Branch: refs/heads/master
Commit: 3ea0331d4cccef7d885e76ea6795e64183fe1b8d
Parents: 16e4651
Author: Reza Motamedi <reza.motamedi@gmail.com>
Authored: Thu Dec 1 22:01:35 2016 -0600
Committer: Joshua Cohen <jcohen@apache.org>
Committed: Thu Dec 1 22:01:35 2016 -0600

----------------------------------------------------------------------
 build.gradle                                    |   2 +
 .../aurora/scheduler/storage/db/DbModule.java   |   8 +
 .../storage/db/InstrumentingInterceptor.java    | 139 ++++++++++++++++
 .../db/InstrumentingInterceptorTest.java        | 162 +++++++++++++++++++
 .../storage/mem/InMemTaskStoreTest.java         |  12 +-
 .../storage/mem/MemCronJobStoreTest.java        |  10 ++
 6 files changed, 332 insertions(+), 1 deletion(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/aurora/blob/3ea0331d/build.gradle
----------------------------------------------------------------------
diff --git a/build.gradle b/build.gradle
index 2f23b85..7064bca 100644
--- a/build.gradle
+++ b/build.gradle
@@ -388,6 +388,8 @@ dependencies {
 
   testCompile "com.sun.jersey:jersey-client:${jerseyRev}"
   testCompile "junit:junit:${junitRev}"
+  testCompile "org.powermock:powermock-module-junit4:1.6.4"
+  testCompile "org.powermock:powermock-api-easymock:1.6.4"
 }
 
 // For normal developer builds, avoid running the often-time-consuming code quality checks.

http://git-wip-us.apache.org/repos/asf/aurora/blob/3ea0331d/src/main/java/org/apache/aurora/scheduler/storage/db/DbModule.java
----------------------------------------------------------------------
diff --git a/src/main/java/org/apache/aurora/scheduler/storage/db/DbModule.java b/src/main/java/org/apache/aurora/scheduler/storage/db/DbModule.java
index e7287ce..d1a1964 100644
--- a/src/main/java/org/apache/aurora/scheduler/storage/db/DbModule.java
+++ b/src/main/java/org/apache/aurora/scheduler/storage/db/DbModule.java
@@ -73,6 +73,10 @@ public final class DbModule extends PrivateModule {
       help = "Whether to use the experimental database-backed task store.")
   public static final Arg<Boolean> USE_DB_TASK_STORE = Arg.create(false);
 
+  @CmdLine(name = "enable_db_metrics",
+      help = "Whether to use MyBatis interceptor to measure the timing of intercepted Statements.")
+  private static final Arg<Boolean> ENABLE_DB_METRICS = Arg.create(true);
+
   @CmdLine(name = "slow_query_log_threshold",
       help = "Log all queries that take at least this long to execute.")
   private static final Arg<Amount<Long, Time>> SLOW_QUERY_LOG_THRESHOLD =
@@ -247,6 +251,10 @@ public final class DbModule extends PrivateModule {
     install(new MyBatisModule() {
       @Override
       protected void initialize() {
+        if (ENABLE_DB_METRICS.get()) {
+          addInterceptorClass(InstrumentingInterceptor.class);
+        }
+
         bindProperties(binder(), ImmutableMap.of("JDBC.schema", jdbcSchema));
         install(JdbcHelper.H2_IN_MEMORY_NAMED);
 

http://git-wip-us.apache.org/repos/asf/aurora/blob/3ea0331d/src/main/java/org/apache/aurora/scheduler/storage/db/InstrumentingInterceptor.java
----------------------------------------------------------------------
diff --git a/src/main/java/org/apache/aurora/scheduler/storage/db/InstrumentingInterceptor.java
b/src/main/java/org/apache/aurora/scheduler/storage/db/InstrumentingInterceptor.java
new file mode 100644
index 0000000..caf1d64
--- /dev/null
+++ b/src/main/java/org/apache/aurora/scheduler/storage/db/InstrumentingInterceptor.java
@@ -0,0 +1,139 @@
+/**
+ * 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.scheduler.storage.db;
+
+import java.util.Properties;
+import java.util.function.Function;
+import javax.annotation.Nonnull;
+import javax.inject.Inject;
+
+import com.google.common.annotations.VisibleForTesting;
+import com.google.common.cache.CacheBuilder;
+import com.google.common.cache.CacheLoader;
+import com.google.common.cache.LoadingCache;
+
+import org.apache.aurora.common.stats.SlidingStats;
+import org.apache.aurora.common.util.Clock;
+import org.apache.ibatis.cache.CacheKey;
+import org.apache.ibatis.executor.Executor;
+import org.apache.ibatis.mapping.BoundSql;
+import org.apache.ibatis.mapping.MappedStatement;
+import org.apache.ibatis.plugin.Interceptor;
+import org.apache.ibatis.plugin.Intercepts;
+import org.apache.ibatis.plugin.Invocation;
+import org.apache.ibatis.plugin.Plugin;
+import org.apache.ibatis.plugin.Signature;
+import org.apache.ibatis.session.ResultHandler;
+import org.apache.ibatis.session.RowBounds;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import static java.util.Objects.requireNonNull;
+
+/**
+ * A Mybatis Executor invocation interceptor that exports timing information for update and
query
+ * mapped statements.
+ *
+ * Currently intercepting the following invocations:
+ * 1. update(MappedStatement ms, Object parameter)
+ * 2. query(MappedStatement ms, Object parameter, RowBounds rowBounds,
+ *      ResultHandler resultHandler, CacheKey cacheKey, BoundSql boundSql)
+ * 3. query(MappedStatement ms, Object parameter, RowBounds rowBounds,
+ *      ResultHandler resultHandler)
+ * 4. queryCursor(MappedStatement ms, Object parameter, RowBounds rowBounds)
+ *
+ * more signatures can be added from: org.apache.ibatis.executors
+ */
+@Intercepts({
+    @Signature(
+        type = Executor.class,
+        method = "update",
+        args = {MappedStatement.class, Object.class}),
+    @Signature(type = Executor.class,
+        method = "query",
+        args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class,
+            CacheKey.class, BoundSql.class}),
+    @Signature(type = Executor.class,
+        method = "query",
+        args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
+    @Signature(type = Executor.class,
+        method = "queryCursor",
+        args = {MappedStatement.class, Object.class, RowBounds.class})
+    })
+public class InstrumentingInterceptor implements Interceptor {
+  private static final String INVALID_INVOCATION_METRIC_NAME = "invalid_invocations";
+  private static final String STATS_NAME_PREFIX = "mybatis.";
+  private static final Logger LOG = LoggerFactory.getLogger(InstrumentingInterceptor.class);
+  private final Clock clock;
+  private final LoadingCache<String, SlidingStats> stats;
+
+  @Inject
+  public InstrumentingInterceptor(Clock clock) {
+    this(clock, (String name) -> new SlidingStats(name, "nanos"));
+  }
+
+  @VisibleForTesting
+  public InstrumentingInterceptor(Clock clock, Function<String, SlidingStats> statsFactory)
{
+    this.clock = requireNonNull(clock);
+
+    this.stats = CacheBuilder.newBuilder().build(new CacheLoader<String, SlidingStats>()
{
+      @Override public SlidingStats load(String statsName) {
+        return statsFactory.apply(STATS_NAME_PREFIX + statsName);
+      }
+    });
+  }
+
+  private String generateStatsName(Invocation invocation) {
+    if (firstArgumentIsMappedStatement(invocation)) {
+      MappedStatement statement = (MappedStatement) invocation.getArgs()[0];
+      return statement.getId();
+    }
+
+    LOG.warn("Received invocation for unknown or invalid target. Invocation target: {}. "
+            + "Invocation method: {}. Using metric name '{}' instead.",
+        invocation.getTarget(),
+        invocation.getMethod(),
+        INVALID_INVOCATION_METRIC_NAME);
+    return INVALID_INVOCATION_METRIC_NAME;
+  }
+
+  private boolean firstArgumentIsMappedStatement(Invocation invocation) {
+    return invocation != null
+        && invocation.getArgs() != null
+        && invocation.getArgs()[0] instanceof MappedStatement;
+  }
+
+  @Override
+  public Object intercept(@Nonnull Invocation invocation) throws Throwable {
+    long start = clock.nowNanos();
+    try {
+      return invocation.proceed();
+    } finally {
+      String statsName = generateStatsName(invocation);
+      SlidingStats stat = stats.get(statsName);
+      stat.accumulate(clock.nowNanos() - start);
+    }
+  }
+
+  @Override
+  public Object plugin(Object target) {
+    return Plugin.wrap(target, this);
+  }
+
+  @Override
+  public void setProperties(Properties properties) {
+    // intentionally left empty as instructed in http://www.mybatis.org/mybatis-3/configuration.html
+  }
+}

http://git-wip-us.apache.org/repos/asf/aurora/blob/3ea0331d/src/test/java/org/apache/aurora/scheduler/storage/db/InstrumentingInterceptorTest.java
----------------------------------------------------------------------
diff --git a/src/test/java/org/apache/aurora/scheduler/storage/db/InstrumentingInterceptorTest.java
b/src/test/java/org/apache/aurora/scheduler/storage/db/InstrumentingInterceptorTest.java
new file mode 100644
index 0000000..c7d437f
--- /dev/null
+++ b/src/test/java/org/apache/aurora/scheduler/storage/db/InstrumentingInterceptorTest.java
@@ -0,0 +1,162 @@
+/**
+ * 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.scheduler.storage.db;
+
+import java.lang.reflect.Method;
+import java.util.concurrent.atomic.AtomicLong;
+
+import org.apache.aurora.common.stats.SlidingStats;
+import org.apache.aurora.common.stats.Stats;
+import org.apache.aurora.common.testing.easymock.EasyMockTest;
+import org.apache.aurora.common.util.Clock;
+import org.apache.ibatis.mapping.MappedStatement;
+import org.apache.ibatis.plugin.Invocation;
+
+import org.junit.Before;
+import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.powermock.api.easymock.PowerMock;
+import org.powermock.core.classloader.annotations.PrepareForTest;
+import org.powermock.modules.junit4.PowerMockRunner;
+
+import static org.easymock.EasyMock.expect;
+import static org.easymock.EasyMock.expectLastCall;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertNull;
+
+import static junit.framework.TestCase.assertNotNull;
+
+@RunWith(PowerMockRunner.class)
+@PrepareForTest({MappedStatement.class, Method.class})
+public class InstrumentingInterceptorTest extends EasyMockTest {
+  private InstrumentingInterceptor interceptor;
+  private Invocation invocation;
+  private SlidingStats slidingStats;
+
+  private Clock mockClock;
+
+  @Before
+  public void setUp() throws Exception {
+    invocation = createMock(Invocation.class);
+    mockClock = createMock(Clock.class);
+    slidingStats = createMock(SlidingStats.class);
+    interceptor = new InstrumentingInterceptor(mockClock, name -> slidingStats);
+  }
+
+  private void expectGetArgs(Object[] args, int times) {
+    expect(invocation.getArgs()).andReturn(args).times(times);
+  }
+
+  @Test
+  public void testStatIsCreatedOnce() throws Throwable {
+    final AtomicLong factoryCallCount = new AtomicLong(0);
+    interceptor = new InstrumentingInterceptor(mockClock, name -> {
+      factoryCallCount.incrementAndGet();
+      return slidingStats;
+    });
+
+    String statName = "test";
+    MappedStatement fakeMappedStatement = createMock(MappedStatement.class);
+    Object[] args = new Object[] {fakeMappedStatement};
+
+    expect(mockClock.nowNanos()).andReturn(0L).andReturn(1000L);
+
+    expectGetArgs(args, 3);
+
+    expect(fakeMappedStatement.getId()).andReturn(statName);
+    expect(invocation.proceed()).andReturn("result");
+
+    slidingStats.accumulate(1000);
+    expectLastCall();
+
+    expect(mockClock.nowNanos()).andReturn(0L).andReturn(1000L);
+
+    expectGetArgs(args, 3);
+
+    expect(fakeMappedStatement.getId()).andReturn(statName);
+    expect(invocation.proceed()).andReturn("result");
+
+    slidingStats.accumulate(1000);
+    expectLastCall();
+
+    control.replay();
+
+    // Perform the test
+    interceptor.intercept(invocation);
+
+    assertEquals(1L, factoryCallCount.get());
+    interceptor.intercept(invocation);
+    assertEquals(1L, factoryCallCount.get());
+  }
+
+  @Test
+  public void testInterceptMarksMetrics() throws Throwable {
+    MappedStatement fakeMappedStatement = createMock(MappedStatement.class);
+    Object[] args = new Object[] {fakeMappedStatement};
+
+    expect(mockClock.nowNanos()).andReturn(0L).andReturn(1000L);
+
+    expectGetArgs(args, 3);
+
+    expect(fakeMappedStatement.getId()).andReturn("test");
+    expect(invocation.proceed()).andReturn("result");
+
+    slidingStats.accumulate(1000);
+    expectLastCall();
+
+    control.replay();
+
+    // Perform the test
+    Object res = interceptor.intercept(invocation);
+    assertEquals("result", res);
+  }
+
+  @Test
+  public void testInterceptNotAMappedStatement() throws Throwable {
+    interceptor = new InstrumentingInterceptor(mockClock);
+    Method mockMethod = PowerMock.createMock(Method.class);
+
+    Object notAMappedStatement = new Object();
+    Object[] args = new Object[] {notAMappedStatement};
+
+    expect(mockClock.nowNanos()).andReturn(0L).andReturn(1000L);
+
+    expectGetArgs(args, 2);
+
+    expect(invocation.getMethod()).andReturn(mockMethod);
+    expect(invocation.getTarget()).andReturn("test");
+    expect(invocation.proceed()).andReturn(null);
+
+    control.replay();
+
+    assertNull(Stats.getVariable("mybatis.invalid_invocations_nanos_total"));
+    assertNull(Stats.getVariable("mybatis.invalid_invocations_nanos_total_per_sec"));
+    assertNull(Stats.getVariable("mybatis.invalid_invocations_events"));
+    assertNull(Stats.getVariable("mybatis.invalid_invocations_nanos_per_event"));
+    assertNull(Stats.getVariable("mybatis.invalid_invocations_events_per_sec"));
+
+    interceptor.intercept(invocation);
+
+    // upon interception of invocation that does not have a valid MappedStatement use
+    // invalid_invocations as the name
+    assertNotNull(Stats.getVariable("mybatis.invalid_invocations_nanos_total"));
+    assertNotNull(Stats.getVariable("mybatis.invalid_invocations_nanos_total_per_sec"));
+    assertNotNull(Stats.getVariable("mybatis.invalid_invocations_events"));
+    assertNotNull(Stats.getVariable("mybatis.invalid_invocations_nanos_per_event"));
+    assertNotNull(Stats.getVariable("mybatis.invalid_invocations_events_per_sec"));
+
+    assertEquals(1000L, Stats.getVariable("mybatis.invalid_invocations_nanos_total").read());
+    assertEquals(1L, Stats.getVariable("mybatis.invalid_invocations_events").read());
+  }
+}

http://git-wip-us.apache.org/repos/asf/aurora/blob/3ea0331d/src/test/java/org/apache/aurora/scheduler/storage/mem/InMemTaskStoreTest.java
----------------------------------------------------------------------
diff --git a/src/test/java/org/apache/aurora/scheduler/storage/mem/InMemTaskStoreTest.java
b/src/test/java/org/apache/aurora/scheduler/storage/mem/InMemTaskStoreTest.java
index 2e560c0..02719c3 100644
--- a/src/test/java/org/apache/aurora/scheduler/storage/mem/InMemTaskStoreTest.java
+++ b/src/test/java/org/apache/aurora/scheduler/storage/mem/InMemTaskStoreTest.java
@@ -19,16 +19,20 @@ import com.google.inject.AbstractModule;
 import com.google.inject.Module;
 import com.google.inject.util.Modules;
 
+import org.apache.aurora.common.stats.SlidingStats;
 import org.apache.aurora.common.stats.StatsProvider;
+import org.apache.aurora.common.util.Clock;
 import org.apache.aurora.scheduler.base.Tasks;
 import org.apache.aurora.scheduler.storage.AbstractTaskStoreTest;
 import org.apache.aurora.scheduler.storage.Storage.MutateWork.NoResult;
 import org.apache.aurora.scheduler.storage.TaskStore;
 import org.apache.aurora.scheduler.storage.db.DbModule;
+import org.apache.aurora.scheduler.storage.db.InstrumentingInterceptor;
 import org.apache.aurora.scheduler.testing.FakeStatsProvider;
 import org.junit.Test;
 
 import static org.apache.aurora.common.inject.Bindings.KeyFactory.PLAIN;
+import static org.easymock.EasyMock.createMock;
 import static org.junit.Assert.assertEquals;
 
 public class InMemTaskStoreTest extends AbstractTaskStoreTest {
@@ -44,14 +48,20 @@ public class InMemTaskStoreTest extends AbstractTaskStoreTest {
           @Override
           protected void configure() {
             bind(StatsProvider.class).toInstance(statsProvider);
+
+            // bindings for mybatis interceptor
+            SlidingStats slidingStats = createMock(SlidingStats.class);
+            bind(InstrumentingInterceptor.class).toInstance(new InstrumentingInterceptor(
+                Clock.SYSTEM_CLOCK, s -> slidingStats
+            ));
           }
         });
   }
 
   @Test
   public void testSecondaryIndexConsistency() {
-    // Test for regression of AURORA-1305.
     storage.write((NoResult.Quiet) storeProvider -> {
+    // Test for regression of AURORA-1305.
       TaskStore.Mutable taskStore = storeProvider.getUnsafeTaskStore();
       taskStore.saveTasks(ImmutableSet.of(TASK_A));
       taskStore.deleteTasks(Tasks.ids(TASK_A));

http://git-wip-us.apache.org/repos/asf/aurora/blob/3ea0331d/src/test/java/org/apache/aurora/scheduler/storage/mem/MemCronJobStoreTest.java
----------------------------------------------------------------------
diff --git a/src/test/java/org/apache/aurora/scheduler/storage/mem/MemCronJobStoreTest.java
b/src/test/java/org/apache/aurora/scheduler/storage/mem/MemCronJobStoreTest.java
index 79999e1..82e0329 100644
--- a/src/test/java/org/apache/aurora/scheduler/storage/mem/MemCronJobStoreTest.java
+++ b/src/test/java/org/apache/aurora/scheduler/storage/mem/MemCronJobStoreTest.java
@@ -18,12 +18,16 @@ import com.google.inject.AbstractModule;
 import com.google.inject.Module;
 import com.google.inject.util.Modules;
 
+import org.apache.aurora.common.stats.SlidingStats;
 import org.apache.aurora.common.stats.StatsProvider;
+import org.apache.aurora.common.util.Clock;
 import org.apache.aurora.scheduler.storage.AbstractCronJobStoreTest;
 import org.apache.aurora.scheduler.storage.db.DbModule;
+import org.apache.aurora.scheduler.storage.db.InstrumentingInterceptor;
 import org.apache.aurora.scheduler.testing.FakeStatsProvider;
 
 import static org.apache.aurora.common.inject.Bindings.KeyFactory.PLAIN;
+import static org.easymock.EasyMock.createMock;
 
 public class MemCronJobStoreTest extends AbstractCronJobStoreTest {
   @Override
@@ -34,6 +38,12 @@ public class MemCronJobStoreTest extends AbstractCronJobStoreTest {
           @Override
           protected void configure() {
             bind(StatsProvider.class).toInstance(new FakeStatsProvider());
+
+            // bindings for mybatis interceptor
+            SlidingStats slidingStats = createMock(SlidingStats.class);
+            bind(InstrumentingInterceptor.class).toInstance(new InstrumentingInterceptor(
+                Clock.SYSTEM_CLOCK, s -> slidingStats
+            ));
           }
         });
   }


Mime
View raw message