| // Copyright (C) 2019 The Android Open Source Project |
| // |
| // 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 com.google.gerrit.server.logging; |
| |
| import static com.google.common.truth.Truth.assertThat; |
| |
| import com.google.auto.value.AutoValue; |
| import com.google.common.collect.ImmutableList; |
| import com.google.common.collect.ImmutableMap; |
| import com.google.gerrit.extensions.registration.DynamicSet; |
| import com.google.gerrit.extensions.registration.RegistrationHandle; |
| import com.google.gerrit.metrics.Description; |
| import com.google.gerrit.metrics.Field; |
| import com.google.gerrit.metrics.MetricMaker; |
| import com.google.gerrit.metrics.Timer0; |
| import com.google.gerrit.metrics.Timer1; |
| import com.google.gerrit.metrics.Timer2; |
| import com.google.gerrit.metrics.Timer3; |
| import com.google.gerrit.testing.InMemoryModule; |
| import com.google.inject.Guice; |
| import com.google.inject.Inject; |
| import com.google.inject.Injector; |
| import java.util.ArrayList; |
| import java.util.List; |
| import java.util.Map; |
| import java.util.Optional; |
| import org.junit.After; |
| import org.junit.Before; |
| import org.junit.Test; |
| |
| public class PerformanceLogContextTest { |
| @Inject private DynamicSet<PerformanceLogger> performanceLoggers; |
| |
| // In this test setup this gets the DisabledMetricMaker injected. This means it doesn't record any |
| // metric, but performance log records are still created. |
| @Inject private MetricMaker metricMaker; |
| |
| private TestPerformanceLogger testPerformanceLogger; |
| private RegistrationHandle performanceLoggerRegistrationHandle; |
| |
| @Before |
| public void setup() { |
| Injector injector = Guice.createInjector(new InMemoryModule()); |
| injector.injectMembers(this); |
| |
| testPerformanceLogger = new TestPerformanceLogger(); |
| performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger); |
| } |
| |
| @After |
| public void cleanup() { |
| performanceLoggerRegistrationHandle.remove(); |
| |
| LoggingContext.getInstance().clearPerformanceLogEntries(); |
| LoggingContext.getInstance().performanceLogging(false); |
| } |
| |
| @Test |
| public void traceTimersInsidePerformanceLogContextCreatePerformanceLog() { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| |
| try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); |
| |
| TraceContext.newTimer("test1").close(); |
| TraceContext.newTimer("test2", "foo", "bar").close(); |
| TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close(); |
| TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close(); |
| TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4") |
| .close(); |
| |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(5); |
| } |
| |
| assertThat(testPerformanceLogger.logEntries()) |
| .containsExactly( |
| PerformanceLogEntry.create("test1", ImmutableMap.of()), |
| PerformanceLogEntry.create("test2", ImmutableMap.of("foo", Optional.of("bar"))), |
| PerformanceLogEntry.create( |
| "test3", ImmutableMap.of("foo1", Optional.of("bar1"), "foo2", Optional.of("bar2"))), |
| PerformanceLogEntry.create( |
| "test4", |
| ImmutableMap.of( |
| "foo1", |
| Optional.of("bar1"), |
| "foo2", |
| Optional.of("bar2"), |
| "foo3", |
| Optional.of("bar3"))), |
| PerformanceLogEntry.create( |
| "test5", |
| ImmutableMap.of( |
| "foo1", |
| Optional.of("bar1"), |
| "foo2", |
| Optional.of("bar2"), |
| "foo3", |
| Optional.of("bar3"), |
| "foo4", |
| Optional.of("bar4")))) |
| .inOrder(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| } |
| |
| @Test |
| public void traceTimersInsidePerformanceLogContextCreatePerformanceLogNullValuesAllowed() { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| |
| try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); |
| |
| TraceContext.newTimer("test1").close(); |
| TraceContext.newTimer("test2", "foo", null).close(); |
| TraceContext.newTimer("test3", "foo1", null, "foo2", null).close(); |
| TraceContext.newTimer("test4", "foo1", null, "foo2", null, "foo3", null).close(); |
| TraceContext.newTimer("test5", "foo1", null, "foo2", null, "foo3", null, "foo4", null) |
| .close(); |
| |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(5); |
| } |
| |
| assertThat(testPerformanceLogger.logEntries()) |
| .containsExactly( |
| PerformanceLogEntry.create("test1", ImmutableMap.of()), |
| PerformanceLogEntry.create("test2", ImmutableMap.of("foo", Optional.empty())), |
| PerformanceLogEntry.create( |
| "test3", ImmutableMap.of("foo1", Optional.empty(), "foo2", Optional.empty())), |
| PerformanceLogEntry.create( |
| "test4", |
| ImmutableMap.of( |
| "foo1", Optional.empty(), "foo2", Optional.empty(), "foo3", Optional.empty())), |
| PerformanceLogEntry.create( |
| "test5", |
| ImmutableMap.of( |
| "foo1", |
| Optional.empty(), |
| "foo2", |
| Optional.empty(), |
| "foo3", |
| Optional.empty(), |
| "foo4", |
| Optional.empty()))) |
| .inOrder(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| } |
| |
| @Test |
| public void traceTimersOutsidePerformanceLogContextDoNotCreatePerformanceLog() { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| |
| TraceContext.newTimer("test1").close(); |
| TraceContext.newTimer("test2", "foo", "bar").close(); |
| TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close(); |
| TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close(); |
| TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4") |
| .close(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| assertThat(testPerformanceLogger.logEntries()).isEmpty(); |
| } |
| |
| @Test |
| public void |
| traceTimersInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() { |
| // Remove test performance logger so that there are no registered performance loggers. |
| performanceLoggerRegistrationHandle.remove(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| |
| try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| |
| TraceContext.newTimer("test1").close(); |
| TraceContext.newTimer("test2", "foo", "bar").close(); |
| TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close(); |
| TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close(); |
| TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4") |
| .close(); |
| |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| } |
| |
| assertThat(testPerformanceLogger.logEntries()).isEmpty(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| } |
| |
| @Test |
| public void timerMetricsInsidePerformanceLogContextCreatePerformanceLog() { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| |
| try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); |
| |
| Timer0 timer0 = |
| metricMaker.newTimer("test1/latency", new Description("Latency metric for testing")); |
| timer0.start().close(); |
| |
| Timer1<String> timer1 = |
| metricMaker.newTimer( |
| "test2/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo")); |
| timer1.start("value1").close(); |
| |
| Timer2<String, String> timer2 = |
| metricMaker.newTimer( |
| "test3/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo"), |
| Field.ofString("bar")); |
| timer2.start("value1", "value2").close(); |
| |
| Timer3<String, String, String> timer3 = |
| metricMaker.newTimer( |
| "test4/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo"), |
| Field.ofString("bar"), |
| Field.ofString("baz")); |
| timer3.start("value1", "value2", "value3").close(); |
| |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(4); |
| } |
| |
| assertThat(testPerformanceLogger.logEntries()) |
| .containsExactly( |
| PerformanceLogEntry.create("test1/latency", ImmutableMap.of()), |
| PerformanceLogEntry.create( |
| "test2/latency", ImmutableMap.of("field1", Optional.of("value1"))), |
| PerformanceLogEntry.create( |
| "test3/latency", |
| ImmutableMap.of("field1", Optional.of("value1"), "field2", Optional.of("value2"))), |
| PerformanceLogEntry.create( |
| "test4/latency", |
| ImmutableMap.of( |
| "field1", |
| Optional.of("value1"), |
| "field2", |
| Optional.of("value2"), |
| "field3", |
| Optional.of("value3")))) |
| .inOrder(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| } |
| |
| @Test |
| public void timerMetricsInsidePerformanceLogContextCreatePerformanceLogNullValuesAllowed() { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| |
| try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); |
| |
| Timer1<String> timer1 = |
| metricMaker.newTimer( |
| "test1/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo")); |
| timer1.start(null).close(); |
| |
| Timer2<String, String> timer2 = |
| metricMaker.newTimer( |
| "test2/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo"), |
| Field.ofString("bar")); |
| timer2.start(null, null).close(); |
| |
| Timer3<String, String, String> timer3 = |
| metricMaker.newTimer( |
| "test3/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo"), |
| Field.ofString("bar"), |
| Field.ofString("baz")); |
| timer3.start(null, null, null).close(); |
| |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(3); |
| } |
| |
| assertThat(testPerformanceLogger.logEntries()) |
| .containsExactly( |
| PerformanceLogEntry.create( |
| "test1/latency", ImmutableMap.of("field1", Optional.empty())), |
| PerformanceLogEntry.create( |
| "test2/latency", |
| ImmutableMap.of("field1", Optional.empty(), "field2", Optional.empty())), |
| PerformanceLogEntry.create( |
| "test3/latency", |
| ImmutableMap.of( |
| "field1", |
| Optional.empty(), |
| "field2", |
| Optional.empty(), |
| "field3", |
| Optional.empty()))) |
| .inOrder(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| } |
| |
| @Test |
| public void timerMetricsOutsidePerformanceLogContextDoNotCreatePerformanceLog() { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| |
| Timer0 timer0 = |
| metricMaker.newTimer("test1/latency", new Description("Latency metric for testing")); |
| timer0.start().close(); |
| |
| Timer1<String> timer1 = |
| metricMaker.newTimer( |
| "test2/latency", new Description("Latency metric for testing"), Field.ofString("foo")); |
| timer1.start("value1").close(); |
| |
| Timer2<String, String> timer2 = |
| metricMaker.newTimer( |
| "test3/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo"), |
| Field.ofString("bar")); |
| timer2.start("value1", "value2").close(); |
| |
| Timer3<String, String, String> timer3 = |
| metricMaker.newTimer( |
| "test4/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo"), |
| Field.ofString("bar"), |
| Field.ofString("baz")); |
| timer3.start("value1", "value2", "value3").close(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| assertThat(testPerformanceLogger.logEntries()).isEmpty(); |
| } |
| |
| @Test |
| public void |
| timerMetricssInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() { |
| // Remove test performance logger so that there are no registered performance loggers. |
| performanceLoggerRegistrationHandle.remove(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| |
| try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| |
| Timer0 timer0 = |
| metricMaker.newTimer("test1/latency", new Description("Latency metric for testing")); |
| timer0.start().close(); |
| |
| Timer1<String> timer1 = |
| metricMaker.newTimer( |
| "test2/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo")); |
| timer1.start("value1").close(); |
| |
| Timer2<String, String> timer2 = |
| metricMaker.newTimer( |
| "test3/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo"), |
| Field.ofString("bar")); |
| timer2.start("value1", "value2").close(); |
| |
| Timer3<String, String, String> timer3 = |
| metricMaker.newTimer( |
| "test4/latency", |
| new Description("Latency metric for testing"), |
| Field.ofString("foo"), |
| Field.ofString("bar"), |
| Field.ofString("baz")); |
| timer3.start("value1", "value2", "value3").close(); |
| |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| } |
| |
| assertThat(testPerformanceLogger.logEntries()).isEmpty(); |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| } |
| |
| @Test |
| public void nestingPerformanceLogContextsIsPossible() { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| |
| try (PerformanceLogContext traceContext1 = new PerformanceLogContext(performanceLoggers)) { |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); |
| |
| TraceContext.newTimer("test1").close(); |
| |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1); |
| |
| try (PerformanceLogContext traceContext2 = new PerformanceLogContext(performanceLoggers)) { |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); |
| |
| TraceContext.newTimer("test2").close(); |
| TraceContext.newTimer("test3").close(); |
| |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(2); |
| } |
| |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1); |
| } |
| assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); |
| assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); |
| } |
| |
| private static class TestPerformanceLogger implements PerformanceLogger { |
| private List<PerformanceLogEntry> logEntries = new ArrayList<>(); |
| |
| @Override |
| public void log(String operation, long durationMs, Map<String, Optional<Object>> metaData) { |
| logEntries.add(PerformanceLogEntry.create(operation, metaData)); |
| } |
| |
| ImmutableList<PerformanceLogEntry> logEntries() { |
| return ImmutableList.copyOf(logEntries); |
| } |
| } |
| |
| @AutoValue |
| abstract static class PerformanceLogEntry { |
| static PerformanceLogEntry create(String operation, Map<String, Optional<Object>> metaData) { |
| return new AutoValue_PerformanceLogContextTest_PerformanceLogEntry( |
| operation, ImmutableMap.copyOf(metaData)); |
| } |
| |
| abstract String operation(); |
| |
| abstract ImmutableMap<String, Object> metaData(); |
| } |
| } |