Clean up Profiler a bit PiperOrigin-RevId: 199849102
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java b/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java index 98fc311..69da2de 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
@@ -188,29 +188,28 @@ @ThreadCompatible private final class TaskData { final long threadId; - final long startTime; - long duration = 0L; + final long startTimeNanos; final int id; final int parentId; - int[] counts; // number of invocations per ProfilerTask type - long[] durations; // time spend in the task per ProfilerTask type final ProfilerTask type; final String description; - TaskData(long startTime, TaskData parent, ProfilerTask eventType, String description) { + long duration; + int[] counts; // number of invocations per ProfilerTask type + long[] durations; // time spend in the task per ProfilerTask type + + TaskData(long startTimeNanos, TaskData parent, ProfilerTask eventType, String description) { threadId = Thread.currentThread().getId(); counts = null; durations = null; id = taskId.incrementAndGet(); parentId = (parent == null ? 0 : parent.id); - this.startTime = startTime; + this.startTimeNanos = startTimeNanos; this.type = eventType; this.description = Preconditions.checkNotNull(description); } - /** - * Aggregates information about an *immediate* subtask. - */ + /** Aggregates information about an *immediate* subtask. */ public void aggregateChild(ProfilerTask type, long duration) { int index = type.ordinal(); if (counts == null) { @@ -266,8 +265,8 @@ get().add(create(clock.nanoTime(), eventType, description)); } - public TaskData create(long startTime, ProfilerTask eventType, String description) { - return new TaskData(startTime, peek(), eventType, description); + public TaskData create(long startTimeNanos, ProfilerTask eventType, String description) { + return new TaskData(startTimeNanos, peek(), eventType, description); } @Override @@ -506,9 +505,14 @@ * @param clock a {@code BlazeClock.instance()} * @param execStartTimeNanos execution start time in nanos obtained from {@code clock.nanoTime()} */ - public synchronized void start(ProfiledTaskKinds profiledTaskKinds, OutputStream stream, - String comment, boolean recordAllDurations, Clock clock, long execStartTimeNanos) - throws IOException { + public synchronized void start( + ProfiledTaskKinds profiledTaskKinds, + OutputStream stream, + String comment, + boolean recordAllDurations, + Clock clock, + long execStartTimeNanos) + throws IOException { Preconditions.checkState(!isActive(), "Profiler already active"); taskStack = new TaskStack(); taskQueue = new ConcurrentLinkedQueue<>(); @@ -625,14 +629,14 @@ try { // Allocate the sink once to avoid GC ByteBuffer sink = ByteBuffer.allocate(1024); - while (!taskQueue.isEmpty()) { + TaskData data; + while ((data = taskQueue.poll()) != null) { sink.clear(); - TaskData data = taskQueue.poll(); VarInt.putVarLong(data.threadId, sink); VarInt.putVarInt(data.id, sink); VarInt.putVarInt(data.parentId, sink); - VarInt.putVarLong(data.startTime - profileStartTime, sink); + VarInt.putVarLong(data.startTimeNanos - profileStartTime, sink); VarInt.putVarLong(data.duration, sink); // To save space (and improve performance), convert all description @@ -700,14 +704,14 @@ * Adds task directly to the main queue bypassing task stack. Used for simple tasks that are known * to not have any subtasks. * - * @param startTime task start time (obtained through {@link Profiler#nanoTimeMaybe()}) + * @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 startTime, long duration, ProfilerTask type, String description) { + private void logTask(long startTimeNanos, long duration, ProfilerTask type, String description) { Preconditions.checkNotNull(description); - Preconditions.checkState(startTime > 0, "startTime was %s", startTime); + Preconditions.checkState(startTimeNanos > 0, "startTime was %s", startTimeNanos); if (duration < 0) { // See note in Clock#nanoTime, which is used by Profiler#nanoTimeMaybe. duration = 0; @@ -729,7 +733,7 @@ parent.aggregateChild(type, duration); } if (wasTaskSlowEnoughToRecord(type, duration)) { - TaskData data = localStack.create(startTime, type, description); + TaskData data = localStack.create(startTimeNanos, type, description); data.duration = duration; if (out != null) { localQueue.add(data); @@ -795,7 +799,7 @@ } /** Used to log "events" - tasks with zero duration. */ - public void logEvent(ProfilerTask type, String description) { + void logEvent(ProfilerTask type, String description) { if (isActive() && isProfiling(type)) { logTask(clock.nanoTime(), 0, type, description); } @@ -842,7 +846,7 @@ type, data, taskStack); - data.duration = endTime - data.startTime; + data.duration = endTime - data.startTimeNanos; if (data.parentId > 0) { taskStack.peek().aggregateChild(data.type, data.duration); } @@ -869,19 +873,4 @@ logEvent(ProfilerTask.PHASE, phase.description); } } - - /** - * Convenience method to log spawn tasks. - * - * TODO(bazel-team): Right now method expects single string of the spawn action - * as task description (usually either argv[0] or a name of the main executable - * in case of complex shell commands). Maybe it should accept Command object - * and create more user friendly description. - */ - public void logSpawn(long startTime, String arg0) { - if (isActive() && isProfiling(ProfilerTask.SPAWN)) { - logTask(startTime, clock.nanoTime() - startTime, ProfilerTask.SPAWN, arg0); - } - } - }
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java b/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java index 8f7e3d1..39c9c86 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java
@@ -26,25 +26,25 @@ * Add new Tasks at the end (before Unknown) to not break the profiles that people have created! * The profile file format uses the ordinal() of this enumeration to identify the task. */ - PHASE("build phase marker", -1, 0x336699, 0), - ACTION("action processing", -1, 0x666699, 0), - ACTION_BUILDER("parallel builder completion queue", -1, 0xCC3399, 0), - ACTION_SUBMIT("execution queue submission", -1, 0xCC3399, 0), + PHASE("build phase marker", 0x336699), + ACTION("action processing", 0x666699), + __ACTION_BUILDER("parallel builder completion queue", 0xCC3399), // unused + __ACTION_SUBMIT("execution queue submission", 0xCC3399), // unused ACTION_CHECK("action dependency checking", 10000000, 0x999933, 0), - ACTION_EXECUTE("action execution", -1, 0x99CCFF, 0), + ACTION_EXECUTE("action execution", 0x99CCFF), ACTION_LOCK("action resource lock", 10000000, 0xCC9933, 0), ACTION_RELEASE("action resource release", 10000000, 0x006666, 0), - ACTION_GRAPH("action graph dependency", -1, 0x3399FF, 0), + __ACTION_GRAPH("action graph dependency", 0x3399FF), // unused ACTION_UPDATE("update action information", 10000000, 0x993300, 0), - ACTION_COMPLETE("complete action execution", -1, 0xCCCC99, 0), - INFO("general information", -1, 0x000066, 0), - EXCEPTION("exception", -1, 0xFFCC66, 0), - CREATE_PACKAGE("package creation", -1, 0x6699CC, 0), - PACKAGE_VALIDITY_CHECK("package validity check", -1, 0x336699, 0), - SPAWN("local process spawn", -1, 0x663366, 0), - REMOTE_EXECUTION("remote action execution", -1, 0x9999CC, 0), - LOCAL_EXECUTION("local action execution", -1, 0xCCCCCC, 0), - SCANNER("include scanner", -1, 0x669999, 0), + ACTION_COMPLETE("complete action execution", 0xCCCC99), + INFO("general information", 0x000066), + __EXCEPTION("exception", 0xFFCC66), // unused + CREATE_PACKAGE("package creation", 0x6699CC), + __PACKAGE_VALIDITY_CHECK("package validity check", 0x336699), // unused + __SPAWN("local process spawn", 0x663366), // unused + REMOTE_EXECUTION("remote action execution", 0x9999CC), + LOCAL_EXECUTION("local action execution", 0xCCCCCC), + SCANNER("include scanner", 0x669999), // 30 is a good number because the slowest items are stored in a heap, with temporarily // one more element, and with 31 items, a heap becomes a complete binary tree LOCAL_PARSE("Local parse to prepare for remote execution", 50000000, 0x6699CC, 30), @@ -68,36 +68,38 @@ VFS_VMFS_DIR("VMFS readdir", 10000000, 0x0066CC, 0, true), VFS_VMFS_READ("VMFS read", 10000000, 0x99CC33, 0, true), WAIT("thread wait", 5000000, 0x66CCCC, 0), - CONFIGURED_TARGET("configured target creation", -1, 0x663300, 0), - TRANSITIVE_CLOSURE("transitive closure creation", -1, 0x996600, 0), - TEST("for testing only", -1, 0x000000, 0), - SKYFRAME_EVAL("skyframe evaluator", -1, 0xCC9900, 0), - SKYFUNCTION("skyfunction", -1, 0xCC6600, 0), - CRITICAL_PATH("critical path", -1, 0x666699, 0), - CRITICAL_PATH_COMPONENT("critical path component", -1, 0x666699, 0), - HANDLE_GC_NOTIFICATION("gc notification", -1, 0x996633, 0), - INCLUSION_LOOKUP("inclusion lookup", -1, 0x000000, 0), - INCLUSION_PARSE("inclusion parse", -1, 0x000000, 0), - PROCESS_SCAN("process scan", -1, 0x000000, 0), - LOOP_OUTPUT_ARTIFACTS("loop output artifacts"), - LOCATE_RELATIVE("locate relative"), - CONSTRUCT_INCLUDE_PATHS("construct include paths"), - PARSE_AND_HINTS_RESULTS("parse and hints results"), - PROCESS_RESULTS_AND_ENQUEUE("process results and enqueue"), + __CONFIGURED_TARGET("configured target creation", 0x663300), // unused + __TRANSITIVE_CLOSURE("transitive closure creation", 0x996600), // unused + __TEST("for testing only", 0x000000), // unused + SKYFRAME_EVAL("skyframe evaluator", 0xCC9900), + SKYFUNCTION("skyfunction", 0xCC6600), + CRITICAL_PATH("critical path", 0x666699), + CRITICAL_PATH_COMPONENT("critical path component", 0x666699), + HANDLE_GC_NOTIFICATION("gc notification", 0x996633), + __INCLUSION_LOOKUP("inclusion lookup", 0x000000), // unused + __INCLUSION_PARSE("inclusion parse", 0x000000), // unused + __PROCESS_SCAN("process scan", 0x000000), // unused + __LOOP_OUTPUT_ARTIFACTS("loop output artifacts"), // unused + __LOCATE_RELATIVE("locate relative"), // unused + __CONSTRUCT_INCLUDE_PATHS("construct include paths"), // unused + __PARSE_AND_HINTS_RESULTS("parse and hints results"), // unused + __PROCESS_RESULTS_AND_ENQUEUE("process results and enqueue"), // unused SKYLARK_PARSER("Skylark Parser"), - SKYLARK_USER_FN("Skylark user function call", -1, 0xCC0033, 0), - SKYLARK_BUILTIN_FN("Skylark builtin function call", -1, 0x990033, 0), - SKYLARK_USER_COMPILED_FN("Skylark compiled user function call", -1, 0xCC0033, 0), - ACTION_FS_STAGING("Staging per-action file system", -1, 0x000000, 0), - UNKNOWN("Unknown event", -1, 0x339966, 0); + SKYLARK_USER_FN("Skylark user function call", -0xCC0033), + SKYLARK_BUILTIN_FN("Skylark builtin function call", 0x990033), + SKYLARK_USER_COMPILED_FN("Skylark compiled user function call", 0xCC0033), + ACTION_FS_STAGING("Staging per-action file system", 0x000000), + UNKNOWN("Unknown event", 0x339966); // Size of the ProfilerTask value space. public static final int TASK_COUNT = ProfilerTask.values().length; /** Human readable description for the task. */ public final String description; - /** Threshold for skipping tasks in the profile in nanoseconds, unless --record_full_profiler_data - * is used */ + /** + * Threshold for skipping tasks in the profile in nanoseconds, unless --record_full_profiler_data + * is used. + */ public final long minDuration; /** Default color of the task, when rendered in a chart. */ public final int color; @@ -106,6 +108,10 @@ /** True if the metric records VFS operations */ private final boolean vfs; + ProfilerTask(String description, int color) { + this(description, /* minDuration= */ -1, color, /* slowestInstanceCount= */ 0, /*vfs=*/ false); + } + ProfilerTask(String description, long minDuration, int color, int slowestInstanceCount) { this(description, minDuration, color, slowestInstanceCount, /*vfs=*/ false); }
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/analysis/ProfileInfo.java b/src/main/java/com/google/devtools/build/lib/profiler/analysis/ProfileInfo.java index 88cb5b8..6104674 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/analysis/ProfileInfo.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/analysis/ProfileInfo.java
@@ -448,7 +448,6 @@ // TODO(bazel-team): (2010) In one case, this list took 277MB of heap. Ideally it should be // replaced with a trie. private final List<String> descriptionList; - private final Map<Task, Task> parallelBuilderCompletionQueueTasks; public final Map<Long, Task[]> tasksByThread; public final List<Task> allTasksById; public List<Task> rootTasksById; // Not final due to the late initialization. @@ -468,7 +467,6 @@ descriptionList = Lists.newArrayListWithExpectedSize(10000); tasksByThread = Maps.newHashMap(); - parallelBuilderCompletionQueueTasks = Maps.newHashMap(); allTasksById = Lists.newArrayListWithExpectedSize(50000); phaseTasks = Lists.newArrayList(); actionDependencyMap = Maps.newHashMapWithExpectedSize(10000); @@ -681,43 +679,6 @@ return duration; } - - /** - * Builds map of dependencies between ACTION tasks based on dependencies - * between ACTION_GRAPH tasks - */ - private Task buildActionTaskTree(Task actionGraphTask, List<Task> actionTasksByDescription) { - Task actionTask = actionGraphTask.relatedTask; - if (actionTask == null) { - actionTask = actionTasksByDescription.get(actionGraphTask.descIndex); - if (actionTask == null) { - // If we cannot find ACTION task that corresponds to the ACTION_GRAPH task, - // most likely scenario is that we dealing with either aborted or failed - // build. In this case we will find or create fake zero-duration action - // task and still reconstruct dependency graph. - actionTask = new Task(-1, --fakeActionId, 0, 0, 0, - ProfilerTask.ACTION, actionGraphTask.descIndex, new CompactStatistics((byte[]) null)); - actionTask.calculateRootStats(); - actionTasksByDescription.set(actionGraphTask.descIndex, actionTask); - } - actionGraphTask.relatedTask = actionTask; - } - if (actionGraphTask.subtasks.length != 0) { - List<Task> list = Lists.newArrayListWithCapacity(actionGraphTask.subtasks.length); - for (Task task : actionGraphTask.subtasks) { - if (task.type == ProfilerTask.ACTION_GRAPH) { - list.add(buildActionTaskTree(task, actionTasksByDescription)); - } - } - if (!list.isEmpty()) { - Task[] actionPrerequisites = list.toArray(new Task[list.size()]); - Arrays.sort(actionPrerequisites); - actionDependencyMap.put(actionTask, actionPrerequisites); - } - } - return actionTask; - } - /** * Builds map of dependencies between ACTION tasks based on dependencies * between ACTION_GRAPH tasks. Root of that dependency tree would be @@ -740,32 +701,9 @@ } } List<Task> list = new ArrayList<>(); - for (Task task : getTasksForPhase(analysisPhaseTask)) { - if (task.type == ProfilerTask.ACTION_GRAPH) { - list.add(buildActionTaskTree(task, actionTasksByDescription)); - } - } Task[] actionPrerequisites = list.toArray(new Task[list.size()]); Arrays.sort(actionPrerequisites); actionDependencyMap.put(executionPhaseTask, actionPrerequisites); - - // Scan through all execution phase tasks to identify ACTION_SUBMIT tasks and associate - // them with ACTION task counterparts. ACTION_SUBMIT tasks are not necessarily root - // tasks so we need to scan ALL tasks. - for (Task task : allTasksById.subList(executionPhaseTask.id, allTasksById.size())) { - if (task.type == ProfilerTask.ACTION_SUBMIT) { - Task actionTask = actionTasksByDescription.get(task.descIndex); - if (actionTask != null) { - task.relatedTask = actionTask; - actionTask.relatedTask = task; - } - } else if (task.type == ProfilerTask.ACTION_BUILDER) { - Task actionTask = actionTasksByDescription.get(task.descIndex); - if (actionTask != null) { - parallelBuilderCompletionQueueTasks.put(actionTask, task); - } - } - } } /** @@ -903,19 +841,7 @@ * ACTION task start time and ACTION_SUBMIT task start time). */ public long getActionWaitTime(Task actionTask) { - // Light critical path does not record wait time. - if (actionTask.type == ProfilerTask.CRITICAL_PATH_COMPONENT) { - return 0; - } - Preconditions.checkArgument(actionTask.type == ProfilerTask.ACTION); - if (actionTask.relatedTask != null) { - Preconditions.checkState(actionTask.relatedTask.type == ProfilerTask.ACTION_SUBMIT); - long time = actionTask.startTime - actionTask.relatedTask.startTime; - Preconditions.checkState(time >= 0); - return time; - } else { - return 0L; // submission time is not available. - } + return 0L; // submission time is not available. } /** @@ -928,15 +854,7 @@ return 0; } Preconditions.checkArgument(actionTask.type == ProfilerTask.ACTION); - Task related = parallelBuilderCompletionQueueTasks.get(actionTask); - if (related != null) { - Preconditions.checkState(related.type == ProfilerTask.ACTION_BUILDER); - long time = related.startTime - (actionTask.startTime + actionTask.durationNanos); - Preconditions.checkState(time >= 0); - return time; - } else { - return 0L; // queue task is not available. - } + return 0L; // queue task is not available. } /**
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/chart/AggregatingChartCreator.java b/src/main/java/com/google/devtools/build/lib/profiler/chart/AggregatingChartCreator.java index b6d66eb..30f0e3a 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/chart/AggregatingChartCreator.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/chart/AggregatingChartCreator.java
@@ -38,17 +38,12 @@ public class AggregatingChartCreator implements ChartCreator { /** The tasks in the 'actions' category. */ - private static final Set<ProfilerTask> ACTION_TASKS = EnumSet.of(ProfilerTask.ACTION, - ProfilerTask.ACTION_SUBMIT); + private static final Set<ProfilerTask> ACTION_TASKS = EnumSet.of(ProfilerTask.ACTION); /** The tasks in the 'blaze internal' category. */ private static final Set<ProfilerTask> BLAZE_TASKS = EnumSet.of( ProfilerTask.CREATE_PACKAGE, - ProfilerTask.PACKAGE_VALIDITY_CHECK, - ProfilerTask.CONFIGURED_TARGET, - ProfilerTask.TRANSITIVE_CLOSURE, - ProfilerTask.EXCEPTION, ProfilerTask.INFO, ProfilerTask.UNKNOWN);
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathHtml.java b/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathHtml.java index 101a27e..4d1cd83 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathHtml.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathHtml.java
@@ -58,11 +58,6 @@ close(); lnOpen("tr"); - element("td", "colspan", "3", "Worker thread scheduling delays"); - element("td", TimeUtilities.prettyTime(criticalPathStats.getWorkerWaitTime())); - close(); // tr - - lnOpen("tr"); element("td", "colspan", "3", "Main thread scheduling delays"); element("td", TimeUtilities.prettyTime(criticalPathStats.getMainThreadWaitTime())); close(); // tr
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java b/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java index bf10535..3236935 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java
@@ -54,10 +54,6 @@ lnPrintf( TWO_COLUMN_FORMAT, - "Worker thread scheduling delays", - TimeUtilities.prettyTime(criticalPathStats.getWorkerWaitTime())); - lnPrintf( - TWO_COLUMN_FORMAT, "Main thread scheduling delays", TimeUtilities.prettyTime(criticalPathStats.getMainThreadWaitTime()));
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java index 1184b22..a6dcecc 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java
@@ -162,10 +162,8 @@ } } - long graphTime = execPhase.getTotalDurationNanos(ProfilerTask.ACTION_GRAPH); - long execTime = execPhase.getPhaseDurationNanos() - graphTime; + long execTime = execPhase.getPhaseDurationNanos(); - printTwoColumnStatistic("Action dependency map creation", graphTime); printTwoColumnStatistic("Actual execution time", execTime); CriticalPathHtml criticalPaths = null;
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java index 71be9dc..5f1d42b 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java
@@ -122,8 +122,7 @@ } lnPrint("=== EXECUTION PHASE INFORMATION ===\n"); - long graphTime = execPhase.getTotalDurationNanos(ProfilerTask.ACTION_GRAPH); - long execTime = execPhase.getPhaseDurationNanos() - graphTime; + long execTime = execPhase.getPhaseDurationNanos(); if (prepPhase.wasExecuted()) { lnPrintf( @@ -142,8 +141,6 @@ TimeUtilities.prettyTime(finishPhase.getPhaseDurationNanos())); } printLn(); - lnPrintf( - TWO_COLUMN_FORMAT, "Action dependency map creation", TimeUtilities.prettyTime(graphTime)); lnPrintf(TWO_COLUMN_FORMAT, "Actual execution time", TimeUtilities.prettyTime(execTime)); CriticalPathText criticalPaths = null;
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/statistics/CriticalPathStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/statistics/CriticalPathStatistics.java index 4c6f87c..6498192 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/statistics/CriticalPathStatistics.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/statistics/CriticalPathStatistics.java
@@ -56,7 +56,7 @@ })), typeFilter("the dependency checking", ProfilerTask.ACTION_CHECK), typeFilter("the execution setup", ProfilerTask.ACTION_EXECUTE), - typeFilter("local execution", ProfilerTask.SPAWN, ProfilerTask.LOCAL_EXECUTION), + typeFilter("local execution", ProfilerTask.LOCAL_EXECUTION), typeFilter("the include scanner", ProfilerTask.SCANNER), typeFilter( "Remote execution (cumulative)", @@ -89,7 +89,6 @@ */ private final CriticalPathEntry optimalPath; - private final long workerWaitTime; private final long mainThreadWaitTime; public CriticalPathStatistics(ProfileInfo info) { @@ -100,19 +99,15 @@ info.analyzeCriticalPath(DEFAULT_FILTER, optimalPath); if (totalPath == null || totalPath.isComponent()) { - this.workerWaitTime = 0; this.mainThreadWaitTime = 0; criticalPathDurations = Collections.emptyList(); return; } // Worker thread pool scheduling delays for the actual critical path. - long workerWaitTime = 0; long mainThreadWaitTime = 0; for (CriticalPathEntry entry = totalPath; entry != null; entry = entry.next) { - workerWaitTime += info.getActionWaitTime(entry.task); mainThreadWaitTime += info.getActionQueueTime(entry.task); } - this.workerWaitTime = workerWaitTime; this.mainThreadWaitTime = mainThreadWaitTime; criticalPathDurations = getCriticalPathDurations(info); @@ -134,14 +129,6 @@ } /** - * @see ProfileInfo#getActionWaitTime(Task) - * @return the sum of all action wait times on the total critical path - */ - public long getWorkerWaitTime() { - return workerWaitTime; - } - - /** * @see ProfileInfo#getActionQueueTime(Task) * @return the mainThreadWaitTime */
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java index 51cfb27..dcdca11 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
@@ -263,8 +263,11 @@ /** * Conditionally enable profiling. */ - private final boolean initProfiler(CommandEnvironment env, CommonCommandOptions options, - UUID buildID, long execStartTimeNanos) { + private final boolean initProfiler( + CommandEnvironment env, + CommonCommandOptions options, + UUID buildID, + long execStartTimeNanos) { OutputStream out = null; boolean recordFullProfilerData = false; ProfiledTaskKinds profiledTasks = ProfiledTaskKinds.NONE; @@ -283,10 +286,14 @@ profiledTasks = ProfiledTaskKinds.SLOWEST; } if (profiledTasks != ProfiledTaskKinds.NONE) { - Profiler.instance().start(profiledTasks, out, + Profiler.instance().start( + profiledTasks, + out, getProductName() + " profile for " + env.getOutputBase() + " at " + new Date() + ", build ID: " + buildID, - recordFullProfilerData, clock, execStartTimeNanos); + recordFullProfilerData, + clock, + execStartTimeNanos); return true; } } catch (IOException e) {
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java b/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java index ae2f93f..c3d9bbe 100644 --- a/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java +++ b/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java
@@ -23,7 +23,7 @@ * Microbenchmarks for the overhead of {@link AutoProfiler} over using {@link Profiler} manually. */ public class AutoProfilerBenchmark { - private final ProfilerTask profilerTaskType = ProfilerTask.TEST; + private final ProfilerTask profilerTaskType = ProfilerTask.INFO; @BeforeExperiment void startProfiler() throws Exception {
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java index 5840294..fc6853a 100644 --- a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java +++ b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
@@ -86,7 +86,7 @@ profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", false, BlazeClock.instance(), BlazeClock.instance().nanoTime()); profiler.startTask(ProfilerTask.ACTION, "action task"); - profiler.logEvent(ProfilerTask.TEST, "event"); + profiler.logEvent(ProfilerTask.INFO, "event"); profiler.completeTask(ProfilerTask.ACTION); profiler.stop(); ProfileInfo info = ProfileInfo.loadProfile(cacheFile); @@ -99,7 +99,7 @@ task = info.allTasksById.get(1); assertThat(task.id).isEqualTo(2); - assertThat(task.type).isEqualTo(ProfilerTask.TEST); + assertThat(task.type).isEqualTo(ProfilerTask.INFO); assertThat(task.getDescription()).isEqualTo("event"); } @@ -325,7 +325,7 @@ Thread thread1 = new Thread() { @Override public void run() { for (int i = 0; i < 10000; i++) { - Profiler.instance().logEvent(ProfilerTask.TEST, "thread1"); + Profiler.instance().logEvent(ProfilerTask.INFO, "thread1"); } } }; @@ -333,19 +333,19 @@ Thread thread2 = new Thread() { @Override public void run() { for (int i = 0; i < 10000; i++) { - Profiler.instance().logEvent(ProfilerTask.TEST, "thread2"); + Profiler.instance().logEvent(ProfilerTask.INFO, "thread2"); } } }; long id2 = thread2.getId(); profiler.startTask(ProfilerTask.PHASE, "main task"); - profiler.logEvent(ProfilerTask.TEST, "starting threads"); + profiler.logEvent(ProfilerTask.INFO, "starting threads"); thread1.start(); thread2.start(); thread2.join(); thread1.join(); - profiler.logEvent(ProfilerTask.TEST, "joined"); + profiler.logEvent(ProfilerTask.INFO, "joined"); profiler.completeTask(ProfilerTask.PHASE); profiler.stop(); @@ -379,7 +379,7 @@ Thread thread1 = new Thread() { @Override public void run() { for (int i = 0; i < 100; i++) { - Profiler.instance().logEvent(ProfilerTask.TEST, "thread1"); + Profiler.instance().logEvent(ProfilerTask.INFO, "thread1"); } } }; @@ -393,24 +393,24 @@ new Thread() { @Override public void run() { - profiler.startTask(ProfilerTask.TEST, "complex task"); + profiler.startTask(ProfilerTask.INFO, "complex task"); for (int i = 0; i < 100; i++) { - Profiler.instance().logEvent(ProfilerTask.TEST, "thread2a"); + Profiler.instance().logEvent(ProfilerTask.INFO, "thread2a"); } - profiler.completeTask(ProfilerTask.TEST); + profiler.completeTask(ProfilerTask.INFO); try { profiler.markPhase(ProfilePhase.EXECUTE); } catch (InterruptedException e) { throw new IllegalStateException(e); } for (int i = 0; i < 100; i++) { - Profiler.instance().logEvent(ProfilerTask.TEST, "thread2b"); + Profiler.instance().logEvent(ProfilerTask.INFO, "thread2b"); } } }; thread2.start(); thread2.join(); - profiler.logEvent(ProfilerTask.TEST, "last task"); + profiler.logEvent(ProfilerTask.INFO, "last task"); clock.advanceMillis(1); profiler.stop(); @@ -441,10 +441,10 @@ profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "phase test", false, BlazeClock.instance(), BlazeClock.instance().nanoTime()); for (int i = 0; i < 100; i++) { - profiler.startTask(ProfilerTask.TEST, "outer task " + i); + profiler.startTask(ProfilerTask.INFO, "outer task " + i); clock.advanceMillis(1); - profiler.logEvent(ProfilerTask.TEST, "inner task " + i); - profiler.completeTask(ProfilerTask.TEST); + profiler.logEvent(ProfilerTask.INFO, "inner task " + i); + profiler.completeTask(ProfilerTask.INFO); } profiler.stop(); @@ -470,11 +470,11 @@ Path dataFile = cacheDir.getRelative("profile5.dat"); profiler.start(ProfiledTaskKinds.ALL, dataFile.getOutputStream(), "phase test", false, BlazeClock.instance(), BlazeClock.instance().nanoTime()); - profiler.startTask(ProfilerTask.TEST, "outer task"); - profiler.logEvent(ProfilerTask.EXCEPTION, "inner task"); - profiler.completeTask(ProfilerTask.TEST); + profiler.startTask(ProfilerTask.INFO, "outer task"); + profiler.logEvent(ProfilerTask.PHASE, "inner task"); + profiler.completeTask(ProfilerTask.INFO); profiler.startTask(ProfilerTask.SCANNER, "outer task 2"); - profiler.logSimpleTask(Profiler.nanoTimeMaybe(), ProfilerTask.TEST, "inner task 2"); + profiler.logSimpleTask(Profiler.nanoTimeMaybe(), ProfilerTask.INFO, "inner task 2"); profiler.completeTask(ProfilerTask.SCANNER); profiler.stop(); @@ -482,7 +482,7 @@ ProfileInfo info = ProfileInfo.loadProfile(dataFile); info.calculateStats(); assertThat(info.isCorruptedOrIncomplete()).isFalse(); - assertThat(info.getStatsForType(ProfilerTask.TEST, info.rootTasksById).count).isEqualTo(2); + assertThat(info.getStatsForType(ProfilerTask.INFO, info.rootTasksById).count).isEqualTo(3); assertThat(info.getStatsForType(ProfilerTask.UNKNOWN, info.rootTasksById).count).isEqualTo(0); // Now replace "TEST" type with something unsupported - e.g. "XXXX". @@ -492,7 +492,7 @@ in.close(); assertThat(len).isLessThan(buffer.length); // Validate that file was completely decoded. String content = new String(buffer, ISO_8859_1); - int infoIndex = content.indexOf("TEST"); + int infoIndex = content.indexOf("INFO"); assertThat(infoIndex).isGreaterThan(0); content = content.substring(0, infoIndex) + "XXXX" + content.substring(infoIndex + 4); OutputStream out = new DeflaterOutputStream(dataFile.getOutputStream(), @@ -504,10 +504,10 @@ info = ProfileInfo.loadProfile(dataFile); info.calculateStats(); assertThat(info.isCorruptedOrIncomplete()).isFalse(); - assertThat(info.getStatsForType(ProfilerTask.TEST, info.rootTasksById).count).isEqualTo(0); + assertThat(info.getStatsForType(ProfilerTask.INFO, info.rootTasksById).count).isEqualTo(0); assertThat(info.getStatsForType(ProfilerTask.SCANNER, info.rootTasksById).count).isEqualTo(1); - assertThat(info.getStatsForType(ProfilerTask.EXCEPTION, info.rootTasksById).count).isEqualTo(1); - assertThat(info.getStatsForType(ProfilerTask.UNKNOWN, info.rootTasksById).count).isEqualTo(2); + assertThat(info.getStatsForType(ProfilerTask.PHASE, info.rootTasksById).count).isEqualTo(1); + assertThat(info.getStatsForType(ProfilerTask.UNKNOWN, info.rootTasksById).count).isEqualTo(3); } @Test @@ -528,7 +528,7 @@ Path cacheFile = cacheDir.getRelative("profile1.dat"); profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "testResilenceToNonDecreasingNanoTimes", false, badClock, initialNanoTime); - profiler.logSimpleTask(badClock.nanoTime(), ProfilerTask.TEST, "some task"); + profiler.logSimpleTask(badClock.nanoTime(), ProfilerTask.INFO, "some task"); profiler.stop(); } }