/* * Copyright (C) 2016 Google Inc. * * 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.copybara.profiler; import static com.google.common.truth.Truth.assertThat; import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableMap; import com.google.common.testing.FakeTicker; import com.google.common.testing.TestLogHandler; import com.google.common.util.concurrent.MoreExecutors; import com.google.copybara.profiler.Profiler.ProfilerTask; import com.google.copybara.testing.profiler.RecordingListener; import com.google.copybara.testing.profiler.RecordingListener.EventType; import com.google.copybara.testing.profiler.RecordingListener.TaskWithType; import java.util.concurrent.CountDownLatch; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; import java.util.concurrent.TimeUnit; import java.util.logging.Level; import java.util.logging.Logger; import java.util.logging.LogRecord; import org.junit.Before; import org.junit.Test; import org.junit.runner.RunWith; import org.junit.runners.JUnit4; @RunWith(JUnit4.class) public class ProfilerTest { private Profiler profiler; private RecordingListener recordingCallback; private FakeTicker ticker; @Before public void setUp() throws Exception { ticker = new FakeTicker().setAutoIncrementStep(1, TimeUnit.NANOSECONDS); profiler = new Profiler(ticker); recordingCallback = new RecordingListener(); // We don't record anything before start try (ProfilerTask ignore = profiler.start("bar")) { profiler.simpleTask("foo", 10, 20); } assertThat(recordingCallback.events).isEmpty(); profiler.init(ImmutableList.of(recordingCallback)); } @Test public void reentrantTest() { try (ProfilerTask ignore = profiler.start("task1")) { try (ProfilerTask ignore2 = profiler.start("task2")) { profiler.simpleTask("task3", ticker.read(), ticker.read()); profiler.simpleTask("task4", ticker.read(), ticker.read()); } try (ProfilerTask ignore2 = profiler.start("task5")) { profiler.simpleTask("task6", ticker.read(), ticker.read()); profiler.simpleTask("task7", ticker.read(), ticker.read()); } } profiler.stop(); assertThat(recordingCallback.events).isEqualTo(ImmutableList.of( new TaskWithType(EventType.START, new Task("//copybara", 0, -1)), new TaskWithType(EventType.START, new Task("//copybara/task1", 1, -1)), new TaskWithType(EventType.START, new Task("//copybara/task1/task2", 2, -1)), new TaskWithType(EventType.START, new Task("//copybara/task1/task2/task3", 3, -1)), new TaskWithType(EventType.END, new Task("//copybara/task1/task2/task3", 3, 4)), new TaskWithType(EventType.START, new Task("//copybara/task1/task2/task4", 5, -1)), new TaskWithType(EventType.END, new Task("//copybara/task1/task2/task4", 5, 6)), new TaskWithType(EventType.END, new Task("//copybara/task1/task2", 2, 7)), new TaskWithType(EventType.START, new Task("//copybara/task1/task5", 8, -1)), new TaskWithType(EventType.START, new Task("//copybara/task1/task5/task6", 9, -1)), new TaskWithType(EventType.END, new Task("//copybara/task1/task5/task6", 9, 10)), new TaskWithType(EventType.START, new Task("//copybara/task1/task5/task7", 11, -1)), new TaskWithType(EventType.END, new Task("//copybara/task1/task5/task7", 11, 12)), new TaskWithType(EventType.END, new Task("//copybara/task1/task5", 8, 13)), new TaskWithType(EventType.END, new Task("//copybara/task1", 1, 14)), new TaskWithType(EventType.END, new Task("//copybara", 0, 15)))); // We don't record events once stopped. recordingCallback.events.clear(); try (ProfilerTask ignore = profiler.start("bar")) { profiler.simpleTask("foo", 10, 20); } assertThat(recordingCallback.events).isEmpty(); } @Test public void testThreadCreatedInRootListener() { profiler = new Profiler(ticker); profiler.init(ImmutableList.of(new Listener() { @Override public void taskStarted(Task task) { } @Override public void taskFinished(Task task) { if (task.isFinished() && task.getDescription().equals("//copybara")) { // This thread inherits from the profiler thread. Thread unused = new Thread(); } } })); profiler.simpleTask("task1", ticker.read(), ticker.read()); profiler.stop(); } @Test public void multiThreadTest() { ExecutorService executorService = Executors.newFixedThreadPool(2); try (ProfilerTask ignore = profiler.start("task1")) { // Sequence the two invocations to have repetible tests CountDownLatch latch = new CountDownLatch(1); executorService.submit(() -> { try (ProfilerTask ignored = profiler.start("task2")) { profiler.simpleTask("task3", ticker.read(), ticker.read()); profiler.simpleTask("task4", ticker.read(), ticker.read()); } latch.countDown(); }); executorService.submit(() -> { try { latch.await(); } catch (InterruptedException e) { throw new IllegalStateException(e); } try (ProfilerTask ignored = profiler.start("task5")) { profiler.simpleTask("task6", ticker.read(), ticker.read()); profiler.simpleTask("task7", ticker.read(), ticker.read()); } }); MoreExecutors.shutdownAndAwaitTermination(executorService, 20, TimeUnit.SECONDS); } profiler.stop(); assertThat(recordingCallback.events).containsExactly( new TaskWithType(EventType.START, new Task("//copybara", 0, -1)), new TaskWithType(EventType.START, new Task("//copybara/task1", 1, -1)), new TaskWithType(EventType.START, new Task("//copybara/task1/task2", 2, -1)), new TaskWithType(EventType.START, new Task("//copybara/task1/task2/task3", 3, -1)), new TaskWithType(EventType.END, new Task("//copybara/task1/task2/task3", 3, 4)), new TaskWithType(EventType.START, new Task("//copybara/task1/task2/task4", 5, -1)), new TaskWithType(EventType.END, new Task("//copybara/task1/task2/task4", 5, 6)), new TaskWithType(EventType.END, new Task("//copybara/task1/task2", 2, 7)), new TaskWithType(EventType.START, new Task("//copybara/task1/task5", 8, -1)), new TaskWithType(EventType.START, new Task("//copybara/task1/task5/task6", 9, -1)), new TaskWithType(EventType.END, new Task("//copybara/task1/task5/task6", 9, 10)), new TaskWithType(EventType.START, new Task("//copybara/task1/task5/task7", 11, -1)), new TaskWithType(EventType.END, new Task("//copybara/task1/task5/task7", 11, 12)), new TaskWithType(EventType.END, new Task("//copybara/task1/task5", 8, 13)), new TaskWithType(EventType.END, new Task("//copybara/task1", 1, 14)), new TaskWithType(EventType.END, new Task("//copybara", 0, 15))); } @Test public void testNoCallback() { Profiler profiler = new Profiler(ticker); profiler.init(ImmutableList.of()); try (ProfilerTask ignore = profiler.start("bar")) { profiler.simpleTask("foo", 10, 20); } profiler.stop(); long time = ticker.advance(42).read(); // Nothing was created in the stack. We cannot get the queue without forcing initialization // so we change the ticker and see that the value is a detached with start=42. IOW: Created // when we do tasQueue.get() here: assertThat(profiler.taskQueue.get()).containsExactly( new Task("//detached_thread", time + 1, -1)); } @Test public void testListenerLogging() { // Keep a strong reference to the Logger we use to capture log records for the duration of the // test to avoid any potential race conditions with the weak referencing used by the JDK // // TODO: This could be migrated to use the package level logger name, which would be less // fragile against code being moved around. Logger loggerUnderTest = Logger.getLogger(LogProfilerListener.class.getCanonicalName()); TestLogHandler assertingHandler = new TestLogHandler(); assertingHandler.setLevel(Level.FINE); loggerUnderTest.addHandler(assertingHandler); profiler = new Profiler(ticker); profiler.init(ImmutableList.of(new LogProfilerListener())); try (ProfilerTask ignore = profiler.start("testListenerLogging")) { // do something } LogRecord record = assertingHandler.getStoredLogRecords().get(0); assertThat(record.getMessage()).contains("testListenerLogging"); assertThat(record.getSourceClassName()).contains(this.getClass().getName()); loggerUnderTest.removeHandler(assertingHandler); } @Test public void testTaskType() { assertThat(profiler.taskType("profiler_test")) .isEqualTo(ImmutableMap.of("type", "profiler_test")); } }