Skip to content

Commit be5354b

Browse files
Googlercopybara-github
Googler
authored and
copybara-github
committed
Add worker memory usage to the bazel profiler.
For every 200 milliseconds the WorkerMetricsCollector going to collect worker metrics and send it to the Profiler. Right now we collect only summary memory usage of all workers. PiperOrigin-RevId: 460457868 Change-Id: I27b06bd4fec2609abc2caf6ff39caf0f03a92b81
1 parent 52bca19 commit be5354b

21 files changed

Lines changed: 504 additions & 243 deletions

‎src/main/java/com/google/devtools/build/lib/BUILD‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -370,6 +370,7 @@ java_library(
370370
"//src/main/java/com/google/devtools/build/lib/vfs:output_service",
371371
"//src/main/java/com/google/devtools/build/lib/vfs:pathfragment",
372372
"//src/main/java/com/google/devtools/build/lib/windows",
373+
"//src/main/java/com/google/devtools/build/lib/worker:worker_metric",
373374
"//src/main/java/com/google/devtools/build/skyframe",
374375
"//src/main/java/com/google/devtools/build/skyframe:skyframe-objects",
375376
"//src/main/java/com/google/devtools/common/options",

‎src/main/java/com/google/devtools/build/lib/metrics/BUILD‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,7 @@ java_library(
4343
"//src/main/java/com/google/devtools/build/lib/clock",
4444
"//src/main/java/com/google/devtools/build/lib/profiler",
4545
"//src/main/java/com/google/devtools/build/lib/skyframe:execution_finished_event",
46-
"//src/main/java/com/google/devtools/build/lib/worker",
46+
"//src/main/java/com/google/devtools/build/lib/worker:worker_metric",
4747
"//src/main/java/com/google/devtools/build/skyframe:skyframe_graph_stats_event",
4848
"//src/main/java/com/google/devtools/common/options",
4949
"//third_party:error_prone_annotations",

‎src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java‎

Lines changed: 9 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,9 @@
1313
// limitations under the License.
1414
package com.google.devtools.build.lib.metrics;
1515

16+
import static com.google.common.collect.ImmutableList.toImmutableList;
17+
18+
import com.google.common.collect.ImmutableList;
1619
import com.google.common.collect.ImmutableMap;
1720
import com.google.common.eventbus.AllowConcurrentEvents;
1821
import com.google.common.eventbus.Subscribe;
@@ -49,13 +52,11 @@
4952
import com.google.devtools.build.lib.runtime.SpawnStats;
5053
import com.google.devtools.build.lib.skyframe.ExecutionFinishedEvent;
5154
import com.google.devtools.build.lib.worker.WorkerMetric;
52-
import com.google.devtools.build.lib.worker.WorkerMetricsEvent;
55+
import com.google.devtools.build.lib.worker.WorkerMetricsCollector;
5356
import com.google.devtools.build.skyframe.SkyframeGraphStatsEvent;
5457
import com.google.errorprone.annotations.CanIgnoreReturnValue;
5558
import java.time.Duration;
56-
import java.util.ArrayList;
5759
import java.util.Comparator;
58-
import java.util.List;
5960
import java.util.Map;
6061
import java.util.concurrent.ConcurrentHashMap;
6162
import java.util.concurrent.atomic.AtomicInteger;
@@ -79,7 +80,6 @@ class MetricsCollector {
7980
private final TimingMetrics.Builder timingMetrics = TimingMetrics.newBuilder();
8081
private final ArtifactMetrics.Builder artifactMetrics = ArtifactMetrics.newBuilder();
8182
private final BuildGraphMetrics.Builder buildGraphMetrics = BuildGraphMetrics.newBuilder();
82-
private final List<WorkerMetrics> workerMetricsList = new ArrayList<>();
8383
private final SpawnStats spawnStats = new SpawnStats();
8484

8585
@CanIgnoreReturnValue
@@ -190,12 +190,10 @@ private void postBuildMetricsEvent() {
190190
env.getEventBus().post(new BuildMetricsEvent(createBuildMetrics()));
191191
}
192192

193-
@SuppressWarnings("unused")
194-
@Subscribe
195-
private void onWorkerMetricsEvent(WorkerMetricsEvent workerMetricsEvent) {
196-
for (WorkerMetric workerMetric : workerMetricsEvent.getWorkerMetrics()) {
197-
workerMetricsList.add(workerMetric.toProto());
198-
}
193+
private ImmutableList<WorkerMetrics> createWorkerMetrics() {
194+
return WorkerMetricsCollector.instance().collectMetrics().stream()
195+
.map(WorkerMetric::toProto)
196+
.collect(toImmutableList());
199197
}
200198

201199
private BuildMetrics createBuildMetrics() {
@@ -208,7 +206,7 @@ private BuildMetrics createBuildMetrics() {
208206
.setCumulativeMetrics(createCumulativeMetrics())
209207
.setArtifactMetrics(artifactMetrics.build())
210208
.setBuildGraphMetrics(buildGraphMetrics.build())
211-
.addAllWorkerMetrics(workerMetricsList)
209+
.addAllWorkerMetrics(createWorkerMetrics())
212210
.build();
213211
}
214212

‎src/main/java/com/google/devtools/build/lib/profiler/BUILD‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@ java_library(
3232
"//src/main/java/com/google/devtools/build/lib/concurrent",
3333
"//src/main/java/com/google/devtools/build/lib/unix:procmeminfo_parser",
3434
"//src/main/java/com/google/devtools/build/lib/util:os",
35+
"//src/main/java/com/google/devtools/build/lib/worker:worker_metric",
3536
"//src/main/java/com/google/devtools/common/options",
3637
"//third_party:auto_value",
3738
"//third_party:error_prone_annotations",

‎src/main/java/com/google/devtools/build/lib/profiler/CollectLocalResourceUsage.java‎

Lines changed: 46 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,8 @@
2020
import com.google.devtools.build.lib.bugreport.BugReporter;
2121
import com.google.devtools.build.lib.unix.ProcMeminfoParser;
2222
import com.google.devtools.build.lib.util.OS;
23+
import com.google.devtools.build.lib.worker.WorkerMetric;
24+
import com.google.devtools.build.lib.worker.WorkerMetricsCollector;
2325
import com.google.errorprone.annotations.concurrent.GuardedBy;
2426
import com.sun.management.OperatingSystemMXBean;
2527
import java.io.IOException;
@@ -32,9 +34,10 @@
3234
public class CollectLocalResourceUsage extends Thread {
3335
// TODO(twerth): Make these configurable.
3436
private static final Duration BUCKET_DURATION = Duration.ofSeconds(1);
35-
private static final long LOCAL_CPU_SLEEP_MILLIS = 200;
37+
private static final Duration LOCAL_RESOURCES_COLLECT_SLEEP_INTERVAL = Duration.ofMillis(200);
3638

3739
private final BugReporter bugReporter;
40+
private final boolean collectWorkerDataInProfiler;
3841

3942
private volatile boolean stopLocalUsageCollection;
4043
private volatile boolean profilingStarted;
@@ -51,10 +54,20 @@ public class CollectLocalResourceUsage extends Thread {
5154
@GuardedBy("this")
5255
private TimeSeries systemMemoryUsage;
5356

57+
@GuardedBy("this")
58+
private TimeSeries workersMemoryUsage;
59+
5460
private Stopwatch stopwatch;
5561

56-
CollectLocalResourceUsage(BugReporter bugReporter) {
62+
private final WorkerMetricsCollector workerMetricsCollector;
63+
64+
CollectLocalResourceUsage(
65+
BugReporter bugReporter,
66+
WorkerMetricsCollector workerMetricsCollector,
67+
boolean collectWorkerDataInProfiler) {
5768
this.bugReporter = checkNotNull(bugReporter);
69+
this.collectWorkerDataInProfiler = collectWorkerDataInProfiler;
70+
this.workerMetricsCollector = workerMetricsCollector;
5871
}
5972

6073
@Override
@@ -74,6 +87,11 @@ public void run() {
7487
systemMemoryUsage =
7588
new TimeSeries(
7689
/* startTimeMillis= */ stopwatch.elapsed().toMillis(), BUCKET_DURATION.toMillis());
90+
if (collectWorkerDataInProfiler) {
91+
workersMemoryUsage =
92+
new TimeSeries(
93+
/* startTimeMillis= */ stopwatch.elapsed().toMillis(), BUCKET_DURATION.toMillis());
94+
}
7795
}
7896
OperatingSystemMXBean osBean =
7997
(OperatingSystemMXBean) ManagementFactory.getOperatingSystemMXBean();
@@ -83,7 +101,7 @@ public void run() {
83101
profilingStarted = true;
84102
while (!stopLocalUsageCollection) {
85103
try {
86-
Thread.sleep(LOCAL_CPU_SLEEP_MILLIS);
104+
Thread.sleep(LOCAL_RESOURCES_COLLECT_SLEEP_INTERVAL.toMillis());
87105
} catch (InterruptedException e) {
88106
return;
89107
}
@@ -124,6 +142,17 @@ public void run() {
124142
memoryUsage = -1;
125143
}
126144

145+
int workerMemoryUsageMb = 0;
146+
if (collectWorkerDataInProfiler) {
147+
workerMemoryUsageMb =
148+
this.workerMetricsCollector.collectMetrics().stream()
149+
.map(WorkerMetric::getWorkerStat)
150+
.filter(x -> x != null)
151+
.mapToInt(WorkerMetric.WorkerStat::getUsedMemoryInKB)
152+
.sum()
153+
/ 1024;
154+
}
155+
127156
double deltaNanos = nextElapsed.minus(previousElapsed).toNanos();
128157
double cpuLevel = (nextCpuTimeNanos - previousCpuTimeNanos) / deltaNanos;
129158
synchronized (this) {
@@ -133,14 +162,18 @@ public void run() {
133162
if (localMemoryUsage != null && memoryUsage != -1) {
134163
long memoryUsageMb = memoryUsage / (1024 * 1024);
135164
localMemoryUsage.addRange(
136-
previousElapsed.toMillis(), nextElapsed.toMillis(), memoryUsageMb);
165+
previousElapsed.toMillis(), nextElapsed.toMillis(), (double) memoryUsageMb);
137166
}
138167
if (systemCpuUsage != null) {
139168
systemCpuUsage.addRange(previousElapsed.toMillis(), nextElapsed.toMillis(), systemUsage);
140169
}
141170
if (systemMemoryUsage != null) {
142171
systemMemoryUsage.addRange(
143-
previousElapsed.toMillis(), nextElapsed.toMillis(), systemMemoryUsageMb);
172+
previousElapsed.toMillis(), nextElapsed.toMillis(), (double) systemMemoryUsageMb);
173+
}
174+
if (collectWorkerDataInProfiler && (workersMemoryUsage != null)) {
175+
workersMemoryUsage.addRange(
176+
previousElapsed.toMillis(), nextElapsed.toMillis(), (double) workerMemoryUsageMb);
144177
}
145178
}
146179
previousElapsed = nextElapsed;
@@ -178,14 +211,20 @@ synchronized void logCollectedData() {
178211
logCollectedData(
179212
profiler, systemMemoryUsage, ProfilerTask.SYSTEM_MEMORY_USAGE, startTimeNanos, len);
180213
systemMemoryUsage = null;
214+
215+
if (collectWorkerDataInProfiler) {
216+
logCollectedData(
217+
profiler, workersMemoryUsage, ProfilerTask.WORKERS_MEMORY_USAGE, startTimeNanos, len);
218+
}
219+
workersMemoryUsage = null;
181220
}
182221

183222
private static void logCollectedData(
184223
Profiler profiler, TimeSeries timeSeries, ProfilerTask type, long startTimeNanos, int len) {
185-
double[] localCpuUsageValues = timeSeries.toDoubleArray(len);
224+
double[] localResourceValues = timeSeries.toDoubleArray(len);
186225
for (int i = 0; i < len; i++) {
187226
long eventTimeNanos = startTimeNanos + i * BUCKET_DURATION.toNanos();
188-
profiler.logEventAtTime(eventTimeNanos, type, String.valueOf(localCpuUsageValues[i]));
227+
profiler.logEventAtTime(eventTimeNanos, type, String.valueOf(localResourceValues[i]));
189228
}
190229
}
191230
}

‎src/main/java/com/google/devtools/build/lib/profiler/Profiler.java‎

Lines changed: 33 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,7 @@
2828
import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadSafe;
2929
import com.google.devtools.build.lib.profiler.PredicateBasedStatRecorder.RecorderAndPredicate;
3030
import com.google.devtools.build.lib.profiler.StatRecorder.VfsHeuristics;
31+
import com.google.devtools.build.lib.worker.WorkerMetricsCollector;
3132
import com.google.gson.stream.JsonWriter;
3233
import com.sun.management.OperatingSystemMXBean;
3334
import java.io.BufferedOutputStream;
@@ -107,7 +108,7 @@ private SlowTask(TaskData taskData) {
107108
@Override
108109
public int compareTo(SlowTask other) {
109110
long delta = durationNanos - other.durationNanos;
110-
if (delta < 0) { // Very clumsy
111+
if (delta < 0) { // Very clumsy
111112
return -1;
112113
} else if (delta > 0) {
113114
return 1;
@@ -274,7 +275,7 @@ Iterable<SlowTask> getSlowestTasks() {
274275
final StatRecorder[] tasksHistograms = new StatRecorder[ProfilerTask.values().length];
275276

276277
/** Thread that collects local cpu usage data (if enabled). */
277-
private CollectLocalResourceUsage cpuUsageThread;
278+
private CollectLocalResourceUsage resourceUsageThread;
278279

279280
private TimeSeries actionCountTimeSeries;
280281
private long actionCountStartTime;
@@ -296,8 +297,10 @@ private void initHistograms() {
296297
VfsHeuristics.vfsTypeHeuristics;
297298
List<RecorderAndPredicate> recorders = new ArrayList<>(vfsHeuristics.size());
298299
for (Map.Entry<String, ? extends Predicate<? super String>> e : vfsHeuristics.entrySet()) {
299-
recorders.add(new RecorderAndPredicate(
300-
new SingleStatRecorder(task + " " + e.getKey(), HISTOGRAM_BUCKETS), e.getValue()));
300+
recorders.add(
301+
new RecorderAndPredicate(
302+
new SingleStatRecorder(task + " " + e.getKey(), HISTOGRAM_BUCKETS),
303+
e.getValue()));
301304
}
302305
tasksHistograms[task.ordinal()] = new PredicateBasedStatRecorder(recorders);
303306
} else {
@@ -325,8 +328,7 @@ public static Profiler instance() {
325328
}
326329

327330
/**
328-
* Returns the nanoTime of the current profiler instance, or an arbitrary
329-
* constant if not active.
331+
* Returns the nanoTime of the current profiler instance, or an arbitrary constant if not active.
330332
*/
331333
public static long nanoTimeMaybe() {
332334
if (instance.isActive()) {
@@ -387,6 +389,8 @@ public synchronized void start(
387389
boolean includePrimaryOutput,
388390
boolean includeTargetLabel,
389391
boolean collectTaskHistograms,
392+
boolean collectWorkerDataInProfiler,
393+
WorkerMetricsCollector workerMetricsCollector,
390394
BugReporter bugReporter)
391395
throws IOException {
392396
Preconditions.checkState(!isActive(), "Profiler already active");
@@ -442,9 +446,11 @@ public synchronized void start(
442446
profileCpuStartTime = getProcessCpuTime();
443447

444448
// Start collecting Bazel and system-wide CPU metric collection.
445-
cpuUsageThread = new CollectLocalResourceUsage(bugReporter);
446-
cpuUsageThread.setDaemon(true);
447-
cpuUsageThread.start();
449+
resourceUsageThread =
450+
new CollectLocalResourceUsage(
451+
bugReporter, workerMetricsCollector, collectWorkerDataInProfiler);
452+
resourceUsageThread.setDaemon(true);
453+
resourceUsageThread.start();
448454
}
449455

450456
/**
@@ -482,9 +488,8 @@ private void collectActionCounts() {
482488
}
483489

484490
/**
485-
* Disable profiling and complete profile file creation.
486-
* Subsequent calls to beginTask/endTask will no longer
487-
* be recorded in the profile.
491+
* Disable profiling and complete profile file creation. Subsequent calls to beginTask/endTask
492+
* will no longer be recorded in the profile.
488493
*/
489494
public synchronized void stop() throws IOException {
490495
if (!isActive()) {
@@ -493,15 +498,15 @@ public synchronized void stop() throws IOException {
493498

494499
collectActionCounts();
495500

496-
if (cpuUsageThread != null) {
497-
cpuUsageThread.stopCollecting();
501+
if (resourceUsageThread != null) {
502+
resourceUsageThread.stopCollecting();
498503
try {
499-
cpuUsageThread.join();
504+
resourceUsageThread.join();
500505
} catch (InterruptedException e) {
501506
Thread.currentThread().interrupt();
502507
}
503-
cpuUsageThread.logCollectedData();
504-
cpuUsageThread = null;
508+
resourceUsageThread.logCollectedData();
509+
resourceUsageThread = null;
505510
}
506511

507512
// Log a final event to update the duration of ProfilePhase.FINISH.
@@ -522,9 +527,7 @@ public synchronized void stop() throws IOException {
522527
}
523528
}
524529

525-
/**
526-
* Returns true iff profiling is currently enabled.
527-
*/
530+
/** Returns true iff profiling is currently enabled. */
528531
public boolean isActive() {
529532
return profileStartTime != 0L;
530533
}
@@ -1058,9 +1061,8 @@ private static boolean isGCThread(String threadName) {
10581061
}
10591062

10601063
/**
1061-
* Saves all gathered information from taskQueue queue to the file.
1062-
* Method is invoked internally by the Timer-based thread and at the end of
1063-
* profiling session.
1064+
* Saves all gathered information from taskQueue queue to the file. Method is invoked internally
1065+
* by the Timer-based thread and at the end of profiling session.
10641066
*/
10651067
@Override
10661068
public void run() {
@@ -1154,7 +1156,8 @@ public void run() {
11541156
|| data.type == ProfilerTask.LOCAL_MEMORY_USAGE
11551157
|| data.type == ProfilerTask.ACTION_COUNTS
11561158
|| data.type == ProfilerTask.SYSTEM_CPU_USAGE
1157-
|| data.type == ProfilerTask.SYSTEM_MEMORY_USAGE) {
1159+
|| data.type == ProfilerTask.SYSTEM_MEMORY_USAGE
1160+
|| data.type == ProfilerTask.WORKERS_MEMORY_USAGE) {
11581161
// Skip counts equal to zero. They will show up as a thin line in the profile.
11591162
if ("0.0".equals(data.description)) {
11601163
continue;
@@ -1182,6 +1185,9 @@ public void run() {
11821185
case SYSTEM_MEMORY_USAGE:
11831186
writer.name("cname").value("bad");
11841187
break;
1188+
case WORKERS_MEMORY_USAGE:
1189+
writer.name("cname").value("rail_animation");
1190+
break;
11851191
default:
11861192
// won't happen
11871193
}
@@ -1211,6 +1217,9 @@ public void run() {
12111217
case SYSTEM_MEMORY_USAGE:
12121218
writer.name("system memory").value(data.description);
12131219
break;
1220+
case WORKERS_MEMORY_USAGE:
1221+
writer.name("workers memory").value(data.description);
1222+
break;
12141223
default:
12151224
// won't happen
12161225
}

‎src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -69,6 +69,7 @@ public enum ProfilerTask {
6969
SYSTEM_CPU_USAGE("CPU usage (total)"),
7070
LOCAL_MEMORY_USAGE("Memory usage (Bazel)"),
7171
SYSTEM_MEMORY_USAGE("Memory usage (total)"),
72+
WORKERS_MEMORY_USAGE("Workers memory usage"),
7273
STARLARK_PARSER("Starlark Parser", Threshold.FIFTY_MILLIS),
7374
STARLARK_USER_FN("Starlark user function call", Threshold.FIFTY_MILLIS),
7475
STARLARK_BUILTIN_FN("Starlark builtin function call", Threshold.FIFTY_MILLIS),

0 commit comments

Comments
 (0)