diff options
3 files changed, 295 insertions, 195 deletions
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/AutoProfiler.java b/src/main/java/com/google/devtools/build/lib/profiler/AutoProfiler.java new file mode 100644 index 0000000000..bdb7462e65 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/AutoProfiler.java @@ -0,0 +1,295 @@ +// Copyright 2015 Google Inc. All rights reserved. +// +// 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.devtools.build.lib.profiler; + +import com.google.common.base.Preconditions; +import com.google.devtools.build.lib.util.BlazeClock; +import com.google.devtools.build.lib.util.Clock; + +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; +import java.util.concurrent.atomic.AtomicReference; +import java.util.logging.Logger; + +/** + * A convenient way to actively get access to timing information (e.g. for logging and/or + * profiling purposes) with minimal boilerplate. The lack of boilerplate comes at a performance + * cost; do not use {@link AutoProfiler} on performance critical code. + * + * <p>The intended usage is: + * + * <pre> + * {@code + * try (AutoProfiler p = AutoProfiler.logged("<description of your code>")) { + * // Your code here. + * } + * } + * </pre> + * + * <p>but if the try-with-resources pattern is too cumbersome, you can also do + * + * <pre> + * {@code + * AutoProfiler p = AutoProfiler.logged("<description of your code>"); + * // Your code here. + * long elapsedTimeNanos = p.completeAndGetElapsedTimeNanos(); + * } + * </pre> + * + * <p>An {@link AutoProfiler} can also automatically talk to the active {@link Profiler} instance: + * + * <pre> + * {@code + * try (AutoProfiler p = AutoProfiler.profiled("<description of your code>")) { + * // Your code here. + * } + * } + * </pre> + */ +public class AutoProfiler implements AutoCloseable { + private static final AtomicReference<Clock> CLOCK_REF = new AtomicReference<>(null); + private static final AtomicReference<LoggingElapsedTimeReceiverFactory> + LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF = new AtomicReference<>( + LoggingElapsedTimeReceiver.FACTORY); + + private final ElapsedTimeReceiver elapsedTimeReceiver; + private final long startTimeNanos; + private final AtomicBoolean closed = new AtomicBoolean(false); + + private AutoProfiler(ElapsedTimeReceiver elapsedTimeReceiver, long startTimeNanos) { + this.elapsedTimeReceiver = elapsedTimeReceiver; + this.startTimeNanos = startTimeNanos; + } + + /** A opaque receiver of elapsed time information. */ + public interface ElapsedTimeReceiver { + /** + * Receives the elapsed time of the lifetime of an {@link AutoProfiler} instance. + * + * <p>Note that System#nanoTime isn't guaranteed to be non-decreasing, so implementations should + * check for non-positive {@code elapsedTimeNanos} if they care about this sort of thing. + */ + void accept(long elapsedTimeNanos); + } + + /** + * Sets the clock to use. May be called before trying to call any of the other static methods; + * otherwise {@link BlazeClock#instance} will be used. + * + * <p>Calling this more than once (e.g. after calling any of the other static methods) results in + * unspecified behavior. + */ + public static void setClock(Clock clock) { + CLOCK_REF.set(clock); + } + + private static long nanoTime() { + Clock clock = CLOCK_REF.get(); + return clock != null ? clock.nanoTime() : BlazeClock.instance().nanoTime(); + } + + /** + * Factory to use for creating {@link ElapsedTimeReceiver} instances for servicing + * {@link #logged} et al. + */ + public interface LoggingElapsedTimeReceiverFactory { + ElapsedTimeReceiver create(String taskDescription, Logger logger, TimeUnit timeUnit); + } + + /** + * Inject a custom {@link LoggingElapsedTimeReceiverFactory} for servicing {@link #logged} et al. + * + * <p>Use this if you want custom logging behavior. + */ + public static void setLoggingElapsedTimeReceiverFactory( + LoggingElapsedTimeReceiverFactory factory) { + LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF.set(factory); + } + + /** + * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time in milliseconds to + * the given {@link Logger}. + * + * <p>The returned {@link AutoProfiler} is thread-safe. + */ + public static AutoProfiler logged(String taskDescription, Logger logger) { + return logged(taskDescription, logger, TimeUnit.MILLISECONDS); + } + + /** + * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time the given + * {@link TimeUnit} to the given {@link Logger}. + * + * <p>The returned {@link AutoProfiler} is thread-safe. + */ + public static AutoProfiler logged(String taskDescription, Logger logger, TimeUnit timeUnit) { + return create(LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF.get().create( + taskDescription, logger, timeUnit)); + } + + /** + * Returns an {@link AutoProfiler} that, when closed, records the elapsed time using + * {@link Profiler}. + * + * <p>The returned {@link AutoProfiler} is thread-safe. + */ + public static AutoProfiler profiled(Object object, ProfilerTask profilerTaskType) { + return create(new ProfilingElapsedTimeReceiver(object, profilerTaskType)); + } + + /** + * Returns an {@link AutoProfiler} that, when closed, records the elapsed time using + * {@link Profiler} and also logs it (in milliseconds) to the given {@link Logger}. + * + * <p>The returned {@link AutoProfiler} is thread-safe. + */ + public static AutoProfiler profiledAndLogged(String taskDescription, + ProfilerTask profilerTaskType, Logger logger) { + ElapsedTimeReceiver profilingReceiver = + new ProfilingElapsedTimeReceiver(taskDescription, profilerTaskType); + ElapsedTimeReceiver loggingReceiver = LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF.get().create( + taskDescription, logger, TimeUnit.MILLISECONDS); + return create(new SequencedElapsedTimeReceiver(profilingReceiver, loggingReceiver)); + } + + /** + * Returns an {@link AutoProfiler} that doesn't do anything when closed and so is only useful for + * {@link #completeAndGetElapsedTimeNanos()}. + */ + public static AutoProfiler timed() { + return create(NULL_RECEIVER); + } + + /** + * Returns an {@link AutoProfiler} that, when closed, invokes the given + * {@link ElapsedTimeReceiver}. + * + * <p>The returned {@link AutoProfiler} is as thread-safe as the given + * {@link ElapsedTimeReceiver} is. + */ + public static AutoProfiler create(ElapsedTimeReceiver elapsedTimeReceiver) { + return new AutoProfiler(elapsedTimeReceiver, nanoTime()); + } + + /** + * Manually completes the profiling (useful to trigger the underlying action on completion). + * + * <p>At most one of {@link #complete}, {@link #completeAndGetElapsedTimeNanos} and {@link #close} + * may be called. + */ + public void complete() { + close(); + } + + /** + * Manually completes the profiling and returns the elapsed time in nanoseconds. + * + * <p>At most one of {@link #complete}, {@link #completeAndGetElapsedTimeNanos} and {@link #close} + * may be called. + */ + public long completeAndGetElapsedTimeNanos() { + long elapsedTimeNanos = nanoTime() - startTimeNanos; + Preconditions.checkState(closed.compareAndSet(false, true)); + elapsedTimeReceiver.accept(elapsedTimeNanos); + return elapsedTimeNanos; + } + + /** + * Automatically completes the profiling. + * + * <p>At most one of {@link #complete}, {@link #completeAndGetElapsedTimeNanos} and {@link #close} + * may be called. + */ + @Override + public void close() { + long elapsedTimeNanos = nanoTime() - startTimeNanos; + Preconditions.checkState(closed.compareAndSet(false, true)); + elapsedTimeReceiver.accept(elapsedTimeNanos); + } + + private static final ElapsedTimeReceiver NULL_RECEIVER = new ElapsedTimeReceiver() { + @Override + public void accept(long elapsedTimeNanos) { + } + }; + + private static class SequencedElapsedTimeReceiver implements ElapsedTimeReceiver { + private final ElapsedTimeReceiver firstReceiver; + private final ElapsedTimeReceiver secondReceiver; + + private SequencedElapsedTimeReceiver(ElapsedTimeReceiver firstReceiver, + ElapsedTimeReceiver secondReceiver) { + this.firstReceiver = firstReceiver; + this.secondReceiver = secondReceiver; + } + + @Override + public void accept(long elapsedTimeNanos) { + firstReceiver.accept(elapsedTimeNanos); + secondReceiver.accept(elapsedTimeNanos); + } + } + + private static class LoggingElapsedTimeReceiver implements ElapsedTimeReceiver { + private static final LoggingElapsedTimeReceiverFactory FACTORY = + new LoggingElapsedTimeReceiverFactory() { + @Override + public ElapsedTimeReceiver create(String taskDescription, Logger logger, + TimeUnit timeUnit) { + return new LoggingElapsedTimeReceiver(taskDescription, logger, timeUnit); + } + }; + + private final String taskDescription; + private final Logger logger; + private final TimeUnit timeUnit; + + private LoggingElapsedTimeReceiver(String taskDescription, Logger logger, TimeUnit timeUnit) { + this.taskDescription = taskDescription; + this.logger = logger; + this.timeUnit = timeUnit; + } + + @Override + public void accept(long elapsedTimeNanos) { + if (elapsedTimeNanos > 0) { + logger.info(String.format("Spent %d %s doing %s", + timeUnit.convert(elapsedTimeNanos, TimeUnit.NANOSECONDS), + timeUnit.toString().toLowerCase(), + taskDescription)); + } + } + } + + private static class ProfilingElapsedTimeReceiver implements ElapsedTimeReceiver { + private final long startTimeNanos; + private final Object object; + private final ProfilerTask profilerTaskType; + + private ProfilingElapsedTimeReceiver(Object object, ProfilerTask profilerTaskType) { + this.startTimeNanos = Profiler.nanoTimeMaybe(); + this.object = object; + this.profilerTaskType = profilerTaskType; + } + + @Override + public void accept(long elapsedTimeNanos) { + if (elapsedTimeNanos > 0) { + Profiler.instance().logSimpleTaskDuration(startTimeNanos, elapsedTimeNanos, + profilerTaskType, object); + } + } + } +} + diff --git a/src/main/java/com/google/devtools/build/lib/util/AutoProfiler.java b/src/main/java/com/google/devtools/build/lib/util/AutoProfiler.java deleted file mode 100644 index 46b00f9599..0000000000 --- a/src/main/java/com/google/devtools/build/lib/util/AutoProfiler.java +++ /dev/null @@ -1,141 +0,0 @@ -// Copyright 2015 Google Inc. All rights reserved. -// -// 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.devtools.build.lib.util; - -import com.google.common.base.Preconditions; - -import java.util.concurrent.TimeUnit; -import java.util.concurrent.atomic.AtomicBoolean; -import java.util.logging.Logger; - -/** - * A convenient way to actively get access to timing information (e.g. for logging purposes) with - * minimal boilerplate. Contrast with {@link Profiler}, which records profiling data for offline - * consumption. - * - * <p>The intended usage is: - * - * <pre> - * {@code - * try (AutoProfiler profiler = AutoProfiler.createLoggingProfiler("Your stuff")) { - * // Your code here. - * } - * } - * </pre> - * - * <p>but if the try-with-resources pattern is too cumbersome, you can also do - * - * <pre> - * {@code - * AutoProfiler profiler = AutoProfiler.createLoggingProfiler("Your stuff"); - * // Your code here. - * profiler.close(); - * } - * </pre> - */ -public class AutoProfiler implements AutoCloseable { - private static final Logger LOG = Logger.getLogger(AutoProfiler.class.getName()); - - private final ElapsedTimeReceiver elapsedTimeReceiver; - private final long startTimeNanos; - private final AtomicBoolean closed = new AtomicBoolean(false); - - private AutoProfiler(ElapsedTimeReceiver elapsedTimeReceiver, long startTimeNanos) { - this.elapsedTimeReceiver = elapsedTimeReceiver; - this.startTimeNanos = startTimeNanos; - } - - /** A opaque receiver of elapsed time information. */ - public interface ElapsedTimeReceiver { - /** - * Receives the elapsed time of the lifetime of an {@link AutoProfiler} instance. - * - * <p>Note that System#nanoTime isn't guaranteed to be non-decreasing, so implementations should - * check for non-positive {@code elapsedTimeNanos} if they care about this sort of thing. - */ - void accept(long elapsedTimeNanos); - } - - /** - * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time in milliseconds to a - * default logger. - * - * <p>The returned {@link AutoProfiler} is thread-safe. - */ - public static AutoProfiler create(String taskDescription) { - return create(taskDescription, LOG); - } - - /** - * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time in milliseconds to - * the given {@link Logger}. - * - * <p>The returned {@link AutoProfiler} is thread-safe. - */ - public static AutoProfiler create(String taskDescription, Logger logger) { - return create(taskDescription, logger, TimeUnit.MILLISECONDS); - } - - /** - * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time the given - * {@link TimeUnit} to the given {@link Logger}. - * - * <p>The returned {@link AutoProfiler} is thread-safe. - */ - public static AutoProfiler create(String taskDescription, Logger logger, TimeUnit timeUnit) { - return create(new LoggingElapsedTimeReceiver(taskDescription, logger, timeUnit)); - } - - /** - * Returns an {@link AutoProfiler} that, when closed, invokes the given - * {@link ElapsedTimeReceiver}. - * - * <p>The returned {@link AutoProfiler} is as thread-safe as the given - * {@link ElapsedTimeReceiver} is. - */ - public static AutoProfiler create(ElapsedTimeReceiver elapsedTimeReceiver) { - return new AutoProfiler(elapsedTimeReceiver, BlazeClock.nanoTime()); - } - - /** Can be called at most once. */ - @Override - public void close() { - long elapsedTimeNanos = BlazeClock.nanoTime() - startTimeNanos; - Preconditions.checkState(closed.compareAndSet(false, true)); - elapsedTimeReceiver.accept(elapsedTimeNanos); - } - - private static class LoggingElapsedTimeReceiver implements ElapsedTimeReceiver { - private final String taskDescription; - private final Logger logger; - private final TimeUnit timeUnit; - - private LoggingElapsedTimeReceiver(String taskDescription, Logger logger, TimeUnit timeUnit) { - this.taskDescription = taskDescription; - this.logger = logger; - this.timeUnit = timeUnit; - } - - @Override - public void accept(long elapsedTimeNanos) { - if (elapsedTimeNanos > 0) { - logger.info(String.format("Spent %d %s doing %s", - timeUnit.convert(elapsedTimeNanos, TimeUnit.NANOSECONDS), - timeUnit.toString(), - taskDescription)); - } - } - } -} - diff --git a/src/test/java/com/google/devtools/build/lib/util/AutoProfilerTest.java b/src/test/java/com/google/devtools/build/lib/util/AutoProfilerTest.java deleted file mode 100644 index cb87e4d356..0000000000 --- a/src/test/java/com/google/devtools/build/lib/util/AutoProfilerTest.java +++ /dev/null @@ -1,54 +0,0 @@ -// Copyright 2015 Google Inc. All rights reserved. -// -// 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.devtools.build.lib.util; - -import static com.google.common.truth.Truth.assertThat; - -import com.google.devtools.build.lib.testutil.ManualClock; -import com.google.devtools.build.lib.util.AutoProfiler.ElapsedTimeReceiver; -import org.junit.Before; -import org.junit.Test; -import org.junit.runner.RunWith; -import org.junit.runners.JUnit4; - -import java.util.concurrent.atomic.AtomicLong; - -/** Tests for {@link AutoProfiler}. */ -@RunWith(JUnit4.class) -public class AutoProfilerTest { - - private ManualClock clock; - - @Before - public void init() { - clock = new ManualClock(); - BlazeClock.setClock(clock); - } - - @Test - public void simple() { - final AtomicLong elapsedTime = new AtomicLong(); - ElapsedTimeReceiver receiver = new ElapsedTimeReceiver() { - @Override - public void accept(long elapsedTimeNanos) { - elapsedTime.set(elapsedTimeNanos); - } - }; - try (AutoProfiler profiler = AutoProfiler.create(receiver)) { - clock.advanceMillis(42); - } - assertThat(elapsedTime.get()).isEqualTo(42 * 1000 * 1000); - } -} - |