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.motam...@gmail.com> Authored: Thu Dec 1 22:01:35 2016 -0600 Committer: Joshua Cohen <jco...@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 + )); } }); }