| // Copyright 2014 The Bazel Authors. 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 static com.google.common.base.Preconditions.checkNotNull; |
| import static com.google.common.base.Preconditions.checkState; |
| |
| import com.google.common.annotations.VisibleForTesting; |
| import com.google.common.base.Predicate; |
| import com.google.common.collect.ImmutableList; |
| import com.google.common.collect.ImmutableSet; |
| import com.google.common.collect.Iterables; |
| import com.google.common.collect.Maps; |
| import com.google.common.util.concurrent.ListenableFuture; |
| import com.google.common.util.concurrent.MoreExecutors; |
| import com.google.devtools.build.lib.clock.Clock; |
| import com.google.devtools.build.lib.collect.Extrema; |
| import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadCompatible; |
| import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadSafe; |
| import com.google.devtools.build.lib.profiler.PredicateBasedStatRecorder.RecorderAndPredicate; |
| import com.google.devtools.build.lib.profiler.StatRecorder.VfsHeuristics; |
| import com.google.gson.stream.JsonWriter; |
| import com.sun.management.OperatingSystemMXBean; |
| import java.io.IOException; |
| import java.io.OutputStream; |
| import java.lang.management.ManagementFactory; |
| import java.time.Duration; |
| import java.util.ArrayList; |
| import java.util.Arrays; |
| import java.util.EnumSet; |
| import java.util.LinkedHashMap; |
| import java.util.List; |
| import java.util.Map; |
| import java.util.Objects; |
| import java.util.PriorityQueue; |
| import java.util.Set; |
| import java.util.UUID; |
| import java.util.concurrent.TimeUnit; |
| import java.util.concurrent.atomic.AtomicLong; |
| import java.util.concurrent.atomic.AtomicReference; |
| import java.util.function.Supplier; |
| import java.util.zip.GZIPOutputStream; |
| import javax.annotation.Nullable; |
| |
| /** |
| * Blaze internal profiler. Provides facility to report various Blaze tasks and store them |
| * (asynchronously) in the file for future analysis. |
| * |
| * <p>Implemented as singleton so any caller should use Profiler.instance() to obtain reference. |
| * |
| * <p>Internally, profiler uses two data structures - ThreadLocal task stack to track nested tasks |
| * and single ConcurrentLinkedQueue to gather all completed tasks. |
| * |
| * <p>Also, due to the nature of the provided functionality (instrumentation of all Blaze |
| * components), build.lib.profiler package will be used by almost every other Blaze package, so |
| * special attention should be paid to avoid any dependencies on the rest of the Blaze code, |
| * including build.lib.util and build.lib.vfs. This is important because build.lib.util and |
| * build.lib.vfs contain Profiler invocations and any dependency on those two packages would create |
| * circular relationship. |
| * |
| * <p> |
| * |
| * @see ProfilerTask enum for recognized task types. |
| */ |
| @ThreadSafe |
| @SuppressWarnings("GoodTime") // This code is very performance sensitive. |
| public final class Profiler { |
| /** The profiler (a static singleton instance). Inactive by default. */ |
| private static final Profiler instance = new Profiler(); |
| |
| private static final int HISTOGRAM_BUCKETS = 20; |
| |
| private static final Duration ACTION_COUNT_BUCKET_DURATION = Duration.ofMillis(200); |
| |
| /** File format enum. */ |
| public enum Format { |
| JSON_TRACE_FILE_FORMAT, |
| JSON_TRACE_FILE_COMPRESSED_FORMAT |
| } |
| |
| /** A task that was very slow. */ |
| public static final class SlowTask implements Comparable<SlowTask> { |
| final long durationNanos; |
| final String description; |
| final ProfilerTask type; |
| |
| private SlowTask(TaskData taskData) { |
| this.durationNanos = taskData.durationNanos; |
| this.description = taskData.description; |
| this.type = taskData.type; |
| } |
| |
| @Override |
| public int compareTo(SlowTask other) { |
| long delta = durationNanos - other.durationNanos; |
| if (delta < 0) { // Very clumsy |
| return -1; |
| } else if (delta > 0) { |
| return 1; |
| } else { |
| return 0; |
| } |
| } |
| |
| public long getDurationNanos() { |
| return durationNanos; |
| } |
| |
| public String getDescription() { |
| return description; |
| } |
| |
| public ProfilerTask getType() { |
| return type; |
| } |
| } |
| |
| /** |
| * Container for the single task record. |
| * |
| * <p>Class itself is not thread safe, but all access to it from Profiler methods is. |
| */ |
| @ThreadCompatible |
| static class TaskData implements TraceData { |
| final long threadId; |
| final long startTimeNanos; |
| final ProfilerTask type; |
| final String description; |
| |
| long durationNanos; |
| |
| TaskData( |
| long threadId, |
| long startTimeNanos, |
| long durationNanos, |
| ProfilerTask eventType, |
| String description) { |
| this.threadId = threadId; |
| this.startTimeNanos = startTimeNanos; |
| this.durationNanos = durationNanos; |
| this.type = eventType; |
| this.description = checkNotNull(description); |
| } |
| |
| TaskData(long threadId, long startTimeNanos, ProfilerTask eventType, String description) { |
| this(threadId, startTimeNanos, /* durationNanos= */ -1, eventType, description); |
| } |
| |
| TaskData(long threadId, long startTimeNanos, long durationNanos, String description) { |
| this.type = ProfilerTask.UNKNOWN; |
| this.threadId = threadId; |
| this.startTimeNanos = startTimeNanos; |
| this.durationNanos = durationNanos; |
| this.description = description; |
| } |
| |
| @Override |
| public String toString() { |
| return "Thread " + threadId + ", type " + type + ", " + description; |
| } |
| |
| @Override |
| public void writeTraceData(JsonWriter jsonWriter, long profileStartTimeNanos) |
| throws IOException { |
| String eventType = durationNanos == 0 ? "i" : "X"; |
| jsonWriter.setIndent(" "); |
| jsonWriter.beginObject(); |
| jsonWriter.setIndent(""); |
| if (type == null) { |
| jsonWriter.setIndent(" "); |
| } else { |
| jsonWriter.name("cat").value(type.description); |
| } |
| jsonWriter.name("name").value(description); |
| jsonWriter.name("ph").value(eventType); |
| jsonWriter |
| .name("ts") |
| .value(TimeUnit.NANOSECONDS.toMicros(startTimeNanos - profileStartTimeNanos)); |
| if (durationNanos != 0) { |
| jsonWriter.name("dur").value(TimeUnit.NANOSECONDS.toMicros(durationNanos)); |
| } |
| jsonWriter.name("pid").value(1); |
| |
| if (this instanceof ActionTaskData) { |
| ActionTaskData actionTaskData = (ActionTaskData) this; |
| if (actionTaskData.primaryOutputPath != null) { |
| // Primary outputs are non-mergeable, thus incompatible with slim profiles. |
| jsonWriter.name("out").value(actionTaskData.primaryOutputPath); |
| } |
| if (actionTaskData.targetLabel != null || actionTaskData.mnemonic != null) { |
| jsonWriter.name("args"); |
| jsonWriter.beginObject(); |
| if (actionTaskData.targetLabel != null) { |
| jsonWriter.name("target").value(actionTaskData.targetLabel); |
| } |
| if (actionTaskData.mnemonic != null) { |
| jsonWriter.name("mnemonic").value(actionTaskData.mnemonic); |
| } |
| jsonWriter.endObject(); |
| } |
| } |
| if (type == ProfilerTask.CRITICAL_PATH_COMPONENT) { |
| jsonWriter.name("args"); |
| jsonWriter.beginObject(); |
| jsonWriter.name("tid").value(threadId); |
| jsonWriter.endObject(); |
| } |
| jsonWriter |
| .name("tid") |
| .value( |
| type == ProfilerTask.CRITICAL_PATH_COMPONENT |
| ? ThreadMetadata.CRITICAL_PATH_THREAD_ID |
| : threadId); |
| jsonWriter.endObject(); |
| } |
| } |
| |
| /** |
| * Similar to TaskData, specific for profiled actions. Depending on options, adds additional |
| * action specific information such as primary output path and target label. This is only meant to |
| * be used for ProfilerTask.ACTION. |
| */ |
| static final class ActionTaskData extends TaskData { |
| @Nullable final String primaryOutputPath; |
| @Nullable final String targetLabel; |
| @Nullable final String mnemonic; |
| |
| ActionTaskData( |
| long threadId, |
| long startTimeNanos, |
| long durationNanos, |
| ProfilerTask eventType, |
| @Nullable String mnemonic, |
| String description, |
| @Nullable String primaryOutputPath, |
| @Nullable String targetLabel) { |
| super(threadId, startTimeNanos, durationNanos, eventType, description); |
| this.primaryOutputPath = primaryOutputPath; |
| this.targetLabel = targetLabel; |
| this.mnemonic = mnemonic; |
| } |
| } |
| |
| /** |
| * Aggregator class that keeps track of the slowest tasks of the specified type. |
| * |
| * <p><code>extremaAggregators</p> is sharded so that all threads need not compete for the same |
| * lock if they do the same operation at the same time. Access to an individual {@link Extrema} |
| * is synchronized on the {@link Extrema} instance itself. |
| */ |
| private static final class SlowestTaskAggregator { |
| private static final int SHARDS = 16; |
| private static final int SIZE = 30; |
| |
| @SuppressWarnings({"unchecked", "rawtypes"}) |
| private final Extrema<SlowTask>[] extremaAggregators = new Extrema[SHARDS]; |
| |
| SlowestTaskAggregator() { |
| for (int i = 0; i < SHARDS; i++) { |
| extremaAggregators[i] = Extrema.max(SIZE); |
| } |
| } |
| |
| // @ThreadSafe |
| void add(TaskData taskData) { |
| Extrema<SlowTask> extrema = |
| extremaAggregators[(int) (Thread.currentThread().getId() % SHARDS)]; |
| synchronized (extrema) { |
| extrema.aggregate(new SlowTask(taskData)); |
| } |
| } |
| |
| // @ThreadSafe |
| void clear() { |
| for (int i = 0; i < SHARDS; i++) { |
| Extrema<SlowTask> extrema = extremaAggregators[i]; |
| synchronized (extrema) { |
| extrema.clear(); |
| } |
| } |
| } |
| |
| // @ThreadSafe |
| ImmutableList<SlowTask> getSlowestTasks() { |
| // This is slow, but since it only happens during the end of the invocation, it's OK. |
| Extrema<SlowTask> mergedExtrema = Extrema.max(SIZE); |
| for (int i = 0; i < SHARDS; i++) { |
| Extrema<SlowTask> extrema = extremaAggregators[i]; |
| synchronized (extrema) { |
| for (SlowTask task : extrema.getExtremeElements()) { |
| mergedExtrema.aggregate(task); |
| } |
| } |
| } |
| return mergedExtrema.getExtremeElements(); |
| } |
| } |
| |
| private Clock clock; |
| private Set<ProfilerTask> profiledTasks; |
| private volatile long profileStartTime; |
| private volatile boolean recordAllDurations = false; |
| private Duration profileCpuStartTime; |
| |
| /** |
| * The reference to the current writer, if any. If the referenced writer is null, then disk writes |
| * are disabled. This can happen when slowest task recording is enabled. |
| */ |
| private final AtomicReference<JsonTraceFileWriter> writerRef = new AtomicReference<>(); |
| |
| private final SlowestTaskAggregator[] slowestTasks = |
| new SlowestTaskAggregator[ProfilerTask.values().length]; |
| |
| @VisibleForTesting |
| final StatRecorder[] tasksHistograms = new StatRecorder[ProfilerTask.values().length]; |
| |
| /** Collects local cpu usage data (if enabled). */ |
| private LocalResourceCollector localResourceCollector; |
| |
| private TimeSeries actionCountTimeSeries; |
| private TimeSeries actionCacheCountTimeSeries; |
| private Duration actionCountStartTime; |
| private boolean collectTaskHistograms; |
| private boolean includePrimaryOutput; |
| private boolean includeTargetLabel; |
| |
| private Profiler() { |
| initHistograms(); |
| for (ProfilerTask task : ProfilerTask.values()) { |
| if (task.collectsSlowestInstances) { |
| slowestTasks[task.ordinal()] = new SlowestTaskAggregator(); |
| } |
| } |
| } |
| |
| private void initHistograms() { |
| for (ProfilerTask task : ProfilerTask.values()) { |
| if (task.isVfs()) { |
| Map<String, ? extends Predicate<? super String>> vfsHeuristics = |
| VfsHeuristics.vfsTypeHeuristics; |
| List<RecorderAndPredicate> recorders = new ArrayList<>(vfsHeuristics.size()); |
| for (Map.Entry<String, ? extends Predicate<? super String>> e : vfsHeuristics.entrySet()) { |
| recorders.add( |
| new RecorderAndPredicate( |
| new SingleStatRecorder(task + " " + e.getKey(), HISTOGRAM_BUCKETS), |
| e.getValue())); |
| } |
| tasksHistograms[task.ordinal()] = new PredicateBasedStatRecorder(recorders); |
| } else { |
| tasksHistograms[task.ordinal()] = new SingleStatRecorder(task, HISTOGRAM_BUCKETS); |
| } |
| } |
| } |
| |
| /** |
| * Returns task histograms. This must be called between calls to {@link #start} and {@link #stop}, |
| * or the returned recorders are all empty. Note that the returned recorders may still be modified |
| * concurrently (but at least they are thread-safe, so that's good). |
| * |
| * <p>The stat recorders are indexed by {@code ProfilerTask#ordinal}. |
| */ |
| // TODO(ulfjack): This returns incomplete data by design. Maybe we should return the histograms on |
| // stop instead? However, this is currently only called from one location in a module, and that |
| // can't call stop itself. What to do? |
| public synchronized ImmutableList<StatRecorder> getTasksHistograms() { |
| return isActive() ? ImmutableList.copyOf(tasksHistograms) : ImmutableList.of(); |
| } |
| |
| public static Profiler instance() { |
| return instance; |
| } |
| |
| /** |
| * Returns the nanoTime of the current profiler instance, or an arbitrary constant if not active. |
| */ |
| public static long nanoTimeMaybe() { |
| if (instance.isActive()) { |
| return instance.clock.nanoTime(); |
| } |
| return -1; |
| } |
| |
| // Returns the elapsed wall clock time since the profile has been started or null if inactive. |
| @Nullable |
| public static Duration elapsedTimeMaybe() { |
| if (instance.isActive()) { |
| return Duration.ofNanos(instance.clock.nanoTime()) |
| .minus(Duration.ofNanos(instance.profileStartTime)); |
| } |
| return null; |
| } |
| |
| private static Duration getProcessCpuTime() { |
| OperatingSystemMXBean bean = |
| (OperatingSystemMXBean) ManagementFactory.getOperatingSystemMXBean(); |
| return Duration.ofNanos(bean.getProcessCpuTime()); |
| } |
| |
| // Returns the CPU time since the profile has been started or null if inactive. |
| @Nullable |
| public static Duration getProcessCpuTimeMaybe() { |
| if (instance().isActive()) { |
| return getProcessCpuTime().minus(instance().profileCpuStartTime); |
| } |
| return null; |
| } |
| |
| /** |
| * Enable profiling. |
| * |
| * <p>Subsequent calls to beginTask/endTask will be recorded in the provided output stream. Please |
| * note that stream performance is extremely important and buffered streams should be utilized. |
| * |
| * @param profiledTasks which of {@link ProfilerTask}s to track |
| * @param stream output stream to store profile data. Note: passing unbuffered stream object |
| * reference may result in significant performance penalties |
| * @param recordAllDurations iff true, record all tasks regardless of their duration; otherwise |
| * some tasks may get aggregated if they finished quick enough |
| * @param clock a {@code BlazeClock.instance()} |
| * @param execStartTimeNanos execution start time in nanos obtained from {@code clock.nanoTime()} |
| */ |
| public synchronized void start( |
| ImmutableSet<ProfilerTask> profiledTasks, |
| OutputStream stream, |
| Format format, |
| String outputBase, |
| UUID buildID, |
| boolean recordAllDurations, |
| Clock clock, |
| long execStartTimeNanos, |
| boolean slimProfile, |
| boolean includePrimaryOutput, |
| boolean includeTargetLabel, |
| boolean collectTaskHistograms, |
| LocalResourceCollector localResourceCollector) |
| throws IOException { |
| checkState(!isActive(), "Profiler already active"); |
| initHistograms(); |
| |
| this.profiledTasks = profiledTasks.isEmpty() ? profiledTasks : EnumSet.copyOf(profiledTasks); |
| this.clock = clock; |
| this.actionCountStartTime = Duration.ofNanos(clock.nanoTime()); |
| this.actionCountTimeSeries = new TimeSeries(actionCountStartTime, ACTION_COUNT_BUCKET_DURATION); |
| this.actionCacheCountTimeSeries = |
| new TimeSeries(actionCountStartTime, ACTION_COUNT_BUCKET_DURATION); |
| this.collectTaskHistograms = collectTaskHistograms; |
| this.includePrimaryOutput = includePrimaryOutput; |
| this.includeTargetLabel = includeTargetLabel; |
| this.recordAllDurations = recordAllDurations; |
| |
| JsonTraceFileWriter writer = null; |
| if (stream != null && format != null) { |
| switch (format) { |
| case JSON_TRACE_FILE_FORMAT: |
| writer = |
| new JsonTraceFileWriter(stream, execStartTimeNanos, slimProfile, outputBase, buildID); |
| break; |
| case JSON_TRACE_FILE_COMPRESSED_FORMAT: |
| writer = |
| new JsonTraceFileWriter( |
| new GZIPOutputStream(stream), |
| execStartTimeNanos, |
| slimProfile, |
| outputBase, |
| buildID); |
| } |
| writer.start(); |
| } |
| this.writerRef.set(writer); |
| |
| // Activate profiler. |
| profileStartTime = execStartTimeNanos; |
| profileCpuStartTime = getProcessCpuTime(); |
| |
| this.localResourceCollector = localResourceCollector; |
| // Start collecting Bazel and system-wide CPU metric collection. |
| this.localResourceCollector.start(); |
| } |
| |
| /** |
| * Returns task histograms. This must be called between calls to {@link #start} and {@link #stop}, |
| * or the returned list is empty. |
| */ |
| // TODO(ulfjack): This returns incomplete data by design. Also see getTasksHistograms. |
| public synchronized Iterable<SlowTask> getSlowestTasks() { |
| List<Iterable<SlowTask>> slowestTasksByType = new ArrayList<>(); |
| |
| for (SlowestTaskAggregator aggregator : slowestTasks) { |
| if (aggregator != null) { |
| slowestTasksByType.add(aggregator.getSlowestTasks()); |
| } |
| } |
| |
| return Iterables.concat(slowestTasksByType); |
| } |
| |
| private void collectActionCounts() { |
| Duration endTime = Duration.ofNanos(clock.nanoTime()); |
| int len = (int) endTime.minus(actionCountStartTime).dividedBy(ACTION_COUNT_BUCKET_DURATION) + 1; |
| Map<ProfilerTask, double[]> counterSeriesMap = new LinkedHashMap<>(); |
| if (actionCountTimeSeries != null) { |
| double[] actionCountValues = actionCountTimeSeries.toDoubleArray(len); |
| actionCountTimeSeries = null; |
| counterSeriesMap.put(ProfilerTask.ACTION_COUNTS, actionCountValues); |
| } |
| if (actionCacheCountTimeSeries != null) { |
| double[] actionCacheCountValues = actionCacheCountTimeSeries.toDoubleArray(len); |
| actionCacheCountTimeSeries = null; |
| counterSeriesMap.put(ProfilerTask.ACTION_CACHE_COUNTS, actionCacheCountValues); |
| } |
| if (!counterSeriesMap.isEmpty()) { |
| instance.logCounters(counterSeriesMap, actionCountStartTime, ACTION_COUNT_BUCKET_DURATION); |
| } |
| } |
| |
| /** |
| * Disable profiling and complete profile file creation. Subsequent calls to beginTask/endTask |
| * will no longer be recorded in the profile. |
| */ |
| public synchronized void stop() throws IOException { |
| if (!isActive()) { |
| return; |
| } |
| |
| collectActionCounts(); |
| |
| localResourceCollector.stop(); |
| |
| // Log a final event to update the duration of ProfilePhase.FINISH. |
| logEvent(ProfilerTask.INFO, "Finishing"); |
| JsonTraceFileWriter writer = writerRef.getAndSet(null); |
| if (writer != null) { |
| writer.shutdown(); |
| writer = null; |
| } |
| Arrays.fill(tasksHistograms, null); |
| profileStartTime = 0L; |
| profileCpuStartTime = null; |
| |
| for (SlowestTaskAggregator aggregator : slowestTasks) { |
| if (aggregator != null) { |
| aggregator.clear(); |
| } |
| } |
| } |
| |
| /** Returns true iff profiling is currently enabled. */ |
| public boolean isActive() { |
| return profileStartTime != 0L; |
| } |
| |
| public boolean isProfiling(ProfilerTask type) { |
| return profiledTasks.contains(type); |
| } |
| |
| /** |
| * Unless --record_full_profiler_data is given we drop small tasks and add their time to the |
| * parents duration. |
| */ |
| private boolean wasTaskSlowEnoughToRecord(ProfilerTask type, long duration) { |
| return (recordAllDurations || duration >= type.minDuration); |
| } |
| |
| /** Adds a whole action count series to the writer bypassing histogram and subtask creation. */ |
| public void logCounters( |
| Map<ProfilerTask, double[]> counterSeriesMap, |
| Duration profileStart, |
| Duration bucketDuration) { |
| JsonTraceFileWriter currentWriter = writerRef.get(); |
| if (isActive() && currentWriter != null) { |
| CounterSeriesTraceData counterSeriesTraceData = |
| new CounterSeriesTraceData(counterSeriesMap, profileStart, bucketDuration); |
| currentWriter.enqueue(counterSeriesTraceData); |
| } |
| } |
| |
| /** |
| * Adds task directly to the main queue bypassing task stack. Used for simple tasks that are known |
| * to not have any subtasks. |
| * |
| * @param startTimeNanos task start time (obtained through {@link Profiler#nanoTimeMaybe()}) |
| * @param duration task duration |
| * @param type task type |
| * @param description task description. May be stored until end of build. |
| */ |
| private void logTask( |
| long threadId, long startTimeNanos, long duration, ProfilerTask type, String description) { |
| checkNotNull(description); |
| checkState(!description.isEmpty(), "No description -> not helpful"); |
| if (duration < 0) { |
| // See note in Clock#nanoTime, which is used by Profiler#nanoTimeMaybe. |
| duration = 0; |
| } |
| |
| StatRecorder statRecorder = tasksHistograms[type.ordinal()]; |
| if (collectTaskHistograms && statRecorder != null) { |
| statRecorder.addStat((int) Duration.ofNanos(duration).toMillis(), description); |
| } |
| |
| if (isActive() && startTimeNanos >= 0 && isProfiling(type)) { |
| // Store instance fields as local variables so they are not nulled out from under us by |
| // #clear. |
| JsonTraceFileWriter currentWriter = writerRef.get(); |
| if (wasTaskSlowEnoughToRecord(type, duration)) { |
| TaskData data = new TaskData(threadId, startTimeNanos, type, description); |
| data.durationNanos = duration; |
| if (currentWriter != null) { |
| currentWriter.enqueue(data); |
| } |
| |
| SlowestTaskAggregator aggregator = slowestTasks[type.ordinal()]; |
| |
| if (aggregator != null) { |
| aggregator.add(data); |
| } |
| } |
| } |
| } |
| |
| /** |
| * Used externally to submit simple task (one that does not have any subtasks). Depending on the |
| * minDuration attribute of the task type, task may be just aggregated into the parent task and |
| * not stored directly. |
| * |
| * @param startTimeNanos task start time (obtained through {@link Profiler#nanoTimeMaybe()}) |
| * @param type task type |
| * @param description task description. May be stored until the end of the build. |
| */ |
| public void logSimpleTask(long startTimeNanos, ProfilerTask type, String description) { |
| if (clock != null) { |
| logTask( |
| Thread.currentThread().getId(), |
| startTimeNanos, |
| clock.nanoTime() - startTimeNanos, |
| type, |
| description); |
| } |
| } |
| |
| /** |
| * Used externally to submit simple task (one that does not have any subtasks). Depending on the |
| * minDuration attribute of the task type, task may be just aggregated into the parent task and |
| * not stored directly. |
| * |
| * <p>Note that start and stop time must both be acquired from the same clock instance. |
| * |
| * @param startTimeNanos task start time |
| * @param stopTimeNanos task stop time |
| * @param type task type |
| * @param description task description. May be stored until the end of the build. |
| */ |
| public void logSimpleTask( |
| long startTimeNanos, long stopTimeNanos, ProfilerTask type, String description) { |
| logTask( |
| Thread.currentThread().getId(), |
| startTimeNanos, |
| stopTimeNanos - startTimeNanos, |
| type, |
| description); |
| } |
| |
| /** |
| * Used externally to submit simple task (one that does not have any subtasks). Depending on the |
| * minDuration attribute of the task type, task may be just aggregated into the parent task and |
| * not stored directly. |
| * |
| * @param startTimeNanos task start time (obtained through {@link Profiler#nanoTimeMaybe()}) |
| * @param duration the duration of the task |
| * @param type task type |
| * @param description task description. May be stored until the end of the build. |
| */ |
| public void logSimpleTaskDuration( |
| long startTimeNanos, Duration duration, ProfilerTask type, String description) { |
| logTask(Thread.currentThread().getId(), startTimeNanos, duration.toNanos(), type, description); |
| } |
| |
| /** Used to log "events" happening at a specific time - tasks with zero duration. */ |
| public void logEventAtTime(long atTimeNanos, ProfilerTask type, String description) { |
| logTask(Thread.currentThread().getId(), atTimeNanos, 0, type, description); |
| } |
| |
| /** Used to log "events" - tasks with zero duration. */ |
| @VisibleForTesting |
| void logEvent(ProfilerTask type, String description) { |
| logEventAtTime(clock.nanoTime(), type, description); |
| } |
| |
| private SilentCloseable reallyProfile(long laneId, ProfilerTask type, String description) { |
| final long startTimeNanos = clock.nanoTime(); |
| return () -> completeTask(laneId, startTimeNanos, type, description); |
| } |
| |
| /** |
| * Records the beginning of a task as specified, and returns a {@link SilentCloseable} instance |
| * that ends the task. This lets the system do the work of ending the task, with the compiler |
| * giving a warning if the returned instance is not closed. |
| * |
| * <p>Use of this method allows to support nested task monitoring. For tasks that are known to not |
| * have any subtasks, logSimpleTask() should be used instead. |
| * |
| * <p>Use like this: |
| * |
| * <pre>{@code |
| * try (SilentCloseable c = Profiler.instance().profile(type, "description")) { |
| * // Your code here. |
| * } |
| * }</pre> |
| * |
| * @param type predefined task type - see ProfilerTask for available types. |
| * @param description task description. May be stored until the end of the build. |
| */ |
| public SilentCloseable profile(ProfilerTask type, String description) { |
| return profile(Thread.currentThread().getId(), type, description); |
| } |
| |
| private SilentCloseable profile(long laneId, ProfilerTask type, String description) { |
| return (isActive() && isProfiling(type)) ? reallyProfile(laneId, type, description) : NOP; |
| } |
| |
| /** |
| * Version of {@link #profile(ProfilerTask, String)} that avoids creating string unless actually |
| * profiling. |
| */ |
| public SilentCloseable profile(ProfilerTask type, Supplier<String> description) { |
| return profile(Thread.currentThread().getId(), type, description); |
| } |
| |
| private SilentCloseable profile(long laneId, ProfilerTask type, Supplier<String> description) { |
| return (isActive() && isProfiling(type)) ? reallyProfile(laneId, type, description.get()) : NOP; |
| } |
| |
| /** |
| * Records the beginning of a task as specified, and returns a {@link SilentCloseable} instance |
| * that ends the task. This lets the system do the work of ending the task, with the compiler |
| * giving a warning if the returned instance is not closed. |
| * |
| * <p>Use of this method allows to support nested task monitoring. For tasks that are known to not |
| * have any subtasks, logSimpleTask() should be used instead. |
| * |
| * <p>This is a convenience method that uses {@link ProfilerTask#INFO}. |
| * |
| * <p>Use like this: |
| * |
| * <pre>{@code |
| * try (SilentCloseable c = Profiler.instance().profile("description")) { |
| * // Your code here. |
| * } |
| * }</pre> |
| * |
| * @param description task description. May be stored until the end of the build. |
| */ |
| public SilentCloseable profile(String description) { |
| return profile(ProfilerTask.INFO, description); |
| } |
| |
| /** |
| * Similar to {@link #profile}, but specific to action-related events. Takes an extra argument: |
| * primaryOutput. |
| */ |
| public SilentCloseable profileAction( |
| ProfilerTask type, |
| String mnemonic, |
| String description, |
| String primaryOutput, |
| String targetLabel) { |
| checkNotNull(description); |
| if (isActive() && isProfiling(type)) { |
| final long startTimeNanos = clock.nanoTime(); |
| return () -> |
| completeAction( |
| Thread.currentThread().getId(), |
| startTimeNanos, |
| type, |
| description, |
| mnemonic, |
| includePrimaryOutput ? primaryOutput : null, |
| includeTargetLabel ? targetLabel : null); |
| } else { |
| return NOP; |
| } |
| } |
| |
| public SilentCloseable profileAction( |
| ProfilerTask type, String description, String primaryOutput, String targetLabel) { |
| return profileAction(type, /* mnemonic= */ null, description, primaryOutput, targetLabel); |
| } |
| |
| private static final SilentCloseable NOP = () -> {}; |
| |
| private boolean countAction(ProfilerTask type, TaskData taskData) { |
| return type == ProfilerTask.ACTION |
| || (type == ProfilerTask.INFO && "discoverInputs".equals(taskData.description)); |
| } |
| |
| public void completeTask(long startTimeNanos, ProfilerTask type, String description) { |
| completeTask(Thread.currentThread().getId(), startTimeNanos, type, description); |
| } |
| |
| /** Records the end of the task. */ |
| private void completeTask( |
| long laneId, long startTimeNanos, ProfilerTask type, String description) { |
| if (isActive()) { |
| long endTimeNanos = clock.nanoTime(); |
| long duration = endTimeNanos - startTimeNanos; |
| if (wasTaskSlowEnoughToRecord(type, duration)) { |
| recordTask(new TaskData(laneId, startTimeNanos, duration, type, description)); |
| } |
| } |
| } |
| |
| private void completeAction( |
| long threadId, |
| long startTimeNanos, |
| ProfilerTask type, |
| String description, |
| String mnemonic, |
| @Nullable String primaryOutput, |
| @Nullable String targetLabel) { |
| if (isActive()) { |
| long endTimeNanos = clock.nanoTime(); |
| long duration = endTimeNanos - startTimeNanos; |
| boolean shouldRecordTask = wasTaskSlowEnoughToRecord(type, duration); |
| if (shouldRecordTask) { |
| recordTask( |
| new ActionTaskData( |
| threadId, |
| startTimeNanos, |
| duration, |
| type, |
| mnemonic, |
| description, |
| primaryOutput, |
| targetLabel)); |
| } |
| } |
| } |
| |
| private void recordTask(TaskData data) { |
| JsonTraceFileWriter writer = writerRef.get(); |
| if (writer != null) { |
| writer.enqueue(data); |
| } |
| long endTimeNanos = data.startTimeNanos + data.durationNanos; |
| if (actionCountTimeSeries != null && countAction(data.type, data)) { |
| synchronized (this) { |
| actionCountTimeSeries.addRange( |
| Duration.ofNanos(data.startTimeNanos), Duration.ofNanos(endTimeNanos)); |
| } |
| } |
| if (actionCacheCountTimeSeries != null && data.type == ProfilerTask.ACTION_CHECK) { |
| synchronized (this) { |
| actionCacheCountTimeSeries.addRange( |
| Duration.ofNanos(data.startTimeNanos), Duration.ofNanos(endTimeNanos)); |
| } |
| } |
| SlowestTaskAggregator aggregator = slowestTasks[data.type.ordinal()]; |
| if (aggregator != null) { |
| aggregator.add(data); |
| } |
| } |
| |
| /** Convenience method to log phase marker tasks. */ |
| public void markPhase(ProfilePhase phase) throws InterruptedException { |
| MemoryProfiler.instance().markPhase(phase); |
| if (isActive() && isProfiling(ProfilerTask.PHASE)) { |
| logEvent(ProfilerTask.PHASE, phase.description); |
| } |
| } |
| |
| static class ProfilerTaskType { |
| private final String format; |
| |
| public ProfilerTaskType(String format) { |
| this.format = format; |
| } |
| |
| public String getName(long index) { |
| return String.format(format, index); |
| } |
| |
| @Override |
| public boolean equals(Object obj) { |
| if (!(obj instanceof ProfilerTaskType)) { |
| return false; |
| } |
| |
| if (this == obj) { |
| return true; |
| } |
| |
| var that = (ProfilerTaskType) obj; |
| return Objects.equals(this.format, that.format); |
| } |
| |
| @Override |
| public int hashCode() { |
| return Objects.hashCode(format); |
| } |
| } |
| |
| public ProfilerTaskType createTaskType(String format) { |
| return new ProfilerTaskType(format); |
| } |
| |
| /** |
| * A profiler has a specific lane id. All trace events emitted by it are associated with its lane |
| * id instead of Thread.currentThread().getId(). |
| */ |
| public static class ScopedProfiler { |
| private final boolean active; |
| private final long laneId; |
| |
| public ScopedProfiler(boolean active, long laneId) { |
| this.active = active; |
| this.laneId = laneId; |
| } |
| |
| public SilentCloseable profile(String description) { |
| if (!active) { |
| return () -> {}; |
| } |
| return Profiler.instance().profile(laneId, ProfilerTask.INFO, description); |
| } |
| } |
| |
| /** |
| * An interface used to supply a {@link ListenableFuture} with the given {@link ScopedProfiler}. |
| */ |
| public interface FutureSupplier<T> { |
| ListenableFuture<T> get(ScopedProfiler profiler); |
| } |
| |
| public <T> ListenableFuture<T> profileAsync( |
| ProfilerTaskType type, String description, FutureSupplier<T> futureSupplier) { |
| if (!(isActive() && isProfiling(ProfilerTask.INFO))) { |
| return futureSupplier.get(new ScopedProfiler(/* active= */ false, 0)); |
| } |
| |
| long laneId = laneIdGenerator.acquire(type); |
| final long startTimeNanos = clock.nanoTime(); |
| var scopedProfiler = new ScopedProfiler(/* active= */ true, laneId); |
| var future = futureSupplier.get(scopedProfiler); |
| future.addListener( |
| () -> { |
| long endTimeNanos = clock.nanoTime(); |
| long duration = endTimeNanos - startTimeNanos; |
| recordTask( |
| new TaskData(laneId, startTimeNanos, duration, ProfilerTask.INFO, description)); |
| laneIdGenerator.release(type, laneId); |
| }, |
| MoreExecutors.directExecutor()); |
| return future; |
| } |
| |
| private static final long LANE_ID_BASE = 1_000_000; |
| private final AtomicLong nextLaneId = new AtomicLong(LANE_ID_BASE); |
| private final TaskTypeLaneIdGenerator laneIdGenerator = new TaskTypeLaneIdGenerator(); |
| |
| private class TaskTypeLaneIdGenerator { |
| private final Map<ProfilerTaskType, LaneIdGenerator> typeToLaneIdGenerator = |
| Maps.newConcurrentMap(); |
| |
| public long acquire(ProfilerTaskType type) { |
| var laneIdGenerator = |
| typeToLaneIdGenerator.computeIfAbsent(type, unused -> new LaneIdGenerator(type)); |
| return laneIdGenerator.acquire(); |
| } |
| |
| public void release(ProfilerTaskType type, long laneId) { |
| var laneIdGenerator = checkNotNull(typeToLaneIdGenerator.get(type)); |
| laneIdGenerator.release(laneId); |
| } |
| } |
| |
| private class LaneIdGenerator { |
| private final ProfilerTaskType type; |
| private final PriorityQueue<Long> availableLaneIds = new PriorityQueue<>(); |
| |
| private int count = 0; |
| |
| private LaneIdGenerator(ProfilerTaskType type) { |
| this.type = type; |
| } |
| |
| public synchronized long acquire() { |
| if (!availableLaneIds.isEmpty()) { |
| return availableLaneIds.poll(); |
| } |
| var newLaneId = Profiler.this.nextLaneId.getAndIncrement(); |
| var threadMetadata = new ThreadMetadata(type.getName(count++), newLaneId, LANE_ID_BASE); |
| var writer = Profiler.this.writerRef.get(); |
| if (writer != null) { |
| writer.enqueue(threadMetadata); |
| } |
| return newLaneId; |
| } |
| |
| public synchronized void release(long laneId) { |
| availableLaneIds.add(laneId); |
| } |
| } |
| } |
