diff options
Diffstat (limited to 'src/main/java/com')
3 files changed, 68 insertions, 19 deletions
diff --git a/src/main/java/com/google/devtools/build/lib/exec/FileWriteStrategy.java b/src/main/java/com/google/devtools/build/lib/exec/FileWriteStrategy.java index e0c51ddc45..9c476bc648 100644 --- a/src/main/java/com/google/devtools/build/lib/exec/FileWriteStrategy.java +++ b/src/main/java/com/google/devtools/build/lib/exec/FileWriteStrategy.java @@ -48,7 +48,9 @@ public final class FileWriteStrategy implements FileWriteActionContext { public void exec(Executor executor, AbstractFileWriteAction action, FileOutErr outErr, ActionExecutionContext actionExecutionContext) throws ExecException, InterruptedException { EventHandler reporter = executor == null ? null : executor.getEventHandler(); - try (AutoProfiler p = AutoProfiler.logged("running " + action.prettyPrint(), LOG)) { + try (AutoProfiler p = + AutoProfiler.logged( + "running " + action.prettyPrint(), LOG, /*minTimeForLoggingInMilliseconds=*/ 100)) { try { Path outputPath = Iterables.getOnlyElement(action.getOutputs()).getPath(); try (OutputStream out = new BufferedOutputStream(outputPath.getOutputStream())) { diff --git a/src/main/java/com/google/devtools/build/lib/exec/SymlinkTreeStrategy.java b/src/main/java/com/google/devtools/build/lib/exec/SymlinkTreeStrategy.java index 3cb558dda6..f2b769533a 100644 --- a/src/main/java/com/google/devtools/build/lib/exec/SymlinkTreeStrategy.java +++ b/src/main/java/com/google/devtools/build/lib/exec/SymlinkTreeStrategy.java @@ -46,7 +46,9 @@ public final class SymlinkTreeStrategy implements SymlinkTreeActionContext { ActionExecutionContext actionExecutionContext) throws ActionExecutionException, InterruptedException { Executor executor = actionExecutionContext.getExecutor(); - try (AutoProfiler p = AutoProfiler.logged("running " + action.prettyPrint(), LOG)) { + try (AutoProfiler p = + AutoProfiler.logged( + "running " + action.prettyPrint(), LOG, /*minTimeForLoggingInMilliseconds=*/ 100)) { try { SymlinkTreeHelper helper = new SymlinkTreeHelper( action.getInputManifest().getExecPath(), 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 index 33977ea58e..bec813a5ce 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/AutoProfiler.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/AutoProfiler.java @@ -22,6 +22,8 @@ import java.util.concurrent.atomic.AtomicBoolean; import java.util.concurrent.atomic.AtomicReference; import java.util.logging.Logger; +import javax.annotation.Nullable; + /** * 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 @@ -104,7 +106,8 @@ public class AutoProfiler implements AutoCloseable { * {@link #logged} et al. */ public interface LoggingElapsedTimeReceiverFactory { - ElapsedTimeReceiver create(String taskDescription, Logger logger, TimeUnit timeUnit); + ElapsedTimeReceiver create( + String taskDescription, Logger logger, long minTimeForLogging, TimeUnit timeUnit); } /** @@ -128,14 +131,31 @@ public class AutoProfiler implements AutoCloseable { } /** - * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time the given + * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time in 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)); + return create( + LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF + .get() + .create(taskDescription, logger, 0L, timeUnit)); + } + + /** + * Returns an {@link AutoProfiler} that, when closed, logs the elapsed time in milliseconds to the + * given {@link Logger} if it is greater than {@code minTimeForLoggingInMilliseconds}. + * + * <p>The returned {@link AutoProfiler} is thread-safe. + */ + public static AutoProfiler logged( + String taskDescription, Logger logger, long minTimeForLoggingInMilliseconds) { + return create( + LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF + .get() + .create( + taskDescription, logger, minTimeForLoggingInMilliseconds, TimeUnit.MILLISECONDS)); } /** @@ -158,8 +178,10 @@ public class AutoProfiler implements AutoCloseable { ProfilerTask profilerTaskType, Logger logger) { ElapsedTimeReceiver profilingReceiver = new ProfilingElapsedTimeReceiver(taskDescription, profilerTaskType); - ElapsedTimeReceiver loggingReceiver = LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF.get().create( - taskDescription, logger, TimeUnit.MILLISECONDS); + ElapsedTimeReceiver loggingReceiver = + LOGGING_ELAPSED_TIME_RECEIVER_FACTORY_REF + .get() + .create(taskDescription, logger, 0L, TimeUnit.MILLISECONDS); return create(new SequencedElapsedTimeReceiver(profilingReceiver, loggingReceiver)); } @@ -241,33 +263,56 @@ public class AutoProfiler implements AutoCloseable { } } - private static class LoggingElapsedTimeReceiver implements ElapsedTimeReceiver { + /** + * {@link ElapsedTimeReceiver} that logs a message in {@link #accept} if the elapsed time is at + * least a given threshold. + */ + public 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); + public ElapsedTimeReceiver create( + String taskDescription, Logger logger, long minTimeForLogging, TimeUnit timeUnit) { + return new LoggingElapsedTimeReceiver( + taskDescription, logger, minTimeForLogging, timeUnit); } }; private final String taskDescription; - private final Logger logger; + protected final Logger logger; private final TimeUnit timeUnit; + private final long minNanosForLogging; - private LoggingElapsedTimeReceiver(String taskDescription, Logger logger, TimeUnit timeUnit) { + protected LoggingElapsedTimeReceiver( + String taskDescription, Logger logger, long minTimeForLogging, TimeUnit timeUnit) { this.taskDescription = taskDescription; this.logger = logger; this.timeUnit = timeUnit; + this.minNanosForLogging = timeUnit.toNanos(minTimeForLogging); } - @Override - public void accept(long elapsedTimeNanos) { - if (elapsedTimeNanos > 0) { - logger.info(String.format("Spent %d %s doing %s", + /** + * Returns a message about the amount of time spent doing a task if {@code elapsedTimeNanos} is + * at least {@link #minNanosForLogging} and null otherwise. + */ + @Nullable + protected String loggingMessage(long elapsedTimeNanos) { + if (elapsedTimeNanos >= minNanosForLogging) { + return String.format( + "Spent %d %s doing %s", timeUnit.convert(elapsedTimeNanos, TimeUnit.NANOSECONDS), timeUnit.toString().toLowerCase(), - taskDescription)); + taskDescription); + } else { + return null; + } + } + + @Override + public void accept(long elapsedTimeNanos) { + String logMessage = loggingMessage(elapsedTimeNanos); + if (logMessage != null) { + logger.info(logMessage); } } } |