Skip to content

Commit

Permalink
Log the timestamp at which the build's peak post-GC heap occurred.
Browse files Browse the repository at this point in the history 
PiperOrigin-RevId: 347645371
  • Loading branch information
@justinhorvitz @copybara-github
justinhorvitz authored and copybara-github committed Dec 15, 2020
1 parent d07bd14 commit 7428006
Show file tree
Hide file tree
Showing 6 changed files with 150 additions and 122 deletions.
1 change: 1 addition & 0 deletions src/main/java/com/google/devtools/build/lib/bazel/BUILD
View file
Original file line number Diff line number Diff line change
Expand Up @@ -125,6 +125,7 @@ java_library(
"//src/main/java/com/google/devtools/build/lib/buildeventservice",
"//src/main/java/com/google/devtools/build/lib/collect/nestedset:options",
"//src/main/java/com/google/devtools/build/lib/dynamic",
"//src/main/java/com/google/devtools/build/lib/metrics:memory-use-recorder",
"//src/main/java/com/google/devtools/build/lib/metrics:metrics_module",
"//src/main/java/com/google/devtools/build/lib/network:noop_connectivity",
"//src/main/java/com/google/devtools/build/lib/outputfilter",
Expand Down
18 changes: 8 additions & 10 deletions src/main/java/com/google/devtools/build/lib/metrics/BUILD
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,11 +10,9 @@ filegroup(
visibility = ["//src:__subpackages__"],
)

EVENT_SRCS = ["BuildMetricsEvent.java"]

java_library(
name = "event",
srcs = EVENT_SRCS,
srcs = ["BuildMetricsEvent.java"],
deps = [
"//src/main/java/com/google/devtools/build/lib/buildeventstream",
"//src/main/java/com/google/devtools/build/lib/buildeventstream/proto:build_event_stream_java_proto",
Expand All @@ -26,22 +24,20 @@ java_library(
name = "metrics_module",
srcs = glob(
["*.java"],
exclude = EVENT_SRCS,
exclude = [
"BuildMetricsEvent.java",
"PostGCMemoryUseRecorder.java",
],
),
exports = [
":event",
],
deps = [
":event",
":memory-use-recorder",
"//src/main/java/com/google/devtools/build/lib:runtime",
"//src/main/java/com/google/devtools/build/lib/actions",
"//src/main/java/com/google/devtools/build/lib/analysis:analysis_phase_complete_event",
"//src/main/java/com/google/devtools/build/lib/analysis:config/build_configuration",
"//src/main/java/com/google/devtools/build/lib/buildeventstream/proto:build_event_stream_java_proto",
"//src/main/java/com/google/devtools/build/lib/profiler",
"//src/main/java/com/google/devtools/build/lib/util:string",
"//src/main/java/com/google/devtools/common/options",
"//third_party:flogger",
"//third_party:guava",
],
)
Expand All @@ -55,7 +51,9 @@ java_library(
"//src/main/java/com/google/devtools/build/lib/profiler",
"//src/main/java/com/google/devtools/build/lib/util:string",
"//src/main/java/com/google/devtools/common/options",
"//third_party:auto_value",
"//third_party:flogger",
"//third_party:guava",
"//third_party:jsr305",
],
)
12 changes: 6 additions & 6 deletions src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,12 +25,12 @@
import com.google.devtools.build.lib.buildeventstream.BuildEventStreamProtos.BuildMetrics.TimingMetrics;
import com.google.devtools.build.lib.buildtool.BuildPrecompleteEvent;
import com.google.devtools.build.lib.metrics.MetricsModule.Options;
import com.google.devtools.build.lib.metrics.PostGCMemoryUseRecorder.PeakHeap;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.runtime.CommandEnvironment;
import java.lang.management.ManagementFactory;
import java.lang.management.MemoryMXBean;
import java.time.Duration;
import java.util.Optional;
import java.util.concurrent.atomic.AtomicLong;

class MetricsCollector {
Expand All @@ -45,7 +45,7 @@ class MetricsCollector {
private int packagesLoaded;
private static long analysisTimeInMs;

MetricsCollector(CommandEnvironment env) {
private MetricsCollector(CommandEnvironment env) {
this.env = env;
Options options = env.getOptions().getOptions(Options.class);
this.bepPublishUsedHeapSizePostBuild =
Expand Down Expand Up @@ -101,10 +101,10 @@ private MemoryMetrics createMemoryMetrics() {
MemoryMXBean memBean = ManagementFactory.getMemoryMXBean();
memoryMetrics.setUsedHeapSizePostBuild(memBean.getHeapMemoryUsage().getUsed());
}
Optional<Long> peakPostGcHeapSize = PostGCMemoryUseRecorder.get().getPeakPostGCHeapMemoryUsed();
if (peakPostGcHeapSize.isPresent()) {
memoryMetrics.setPeakPostGcHeapSize(peakPostGcHeapSize.get());
}
PostGCMemoryUseRecorder.get()
.getPeakPostGcHeap()
.map(PeakHeap::bytes)
.ifPresent(memoryMetrics::setPeakPostGcHeapSize);
return memoryMetrics.build();
}

Expand Down
73 changes: 41 additions & 32 deletions src/main/java/com/google/devtools/build/lib/metrics/PostGCMemoryUseRecorder.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@

package com.google.devtools.build.lib.metrics;

import com.google.auto.value.AutoValue;
import com.google.common.annotations.VisibleForTesting;
import com.google.common.base.Supplier;
import com.google.common.collect.ImmutableList;
Expand All @@ -38,6 +39,7 @@
import java.lang.management.MemoryUsage;
import java.util.Map;
import java.util.Optional;
import javax.annotation.concurrent.GuardedBy;
import javax.management.Notification;
import javax.management.NotificationEmitter;
import javax.management.NotificationListener;
Expand All @@ -57,6 +59,7 @@
* <p>This allows us to measure sizeof(data) by measuring sizeof(heap used) immediately after a full
* GC.
*/
@SuppressWarnings("GoodTime") // Using long timestamps for consistency with code base.
public final class PostGCMemoryUseRecorder implements NotificationListener {
private static PostGCMemoryUseRecorder instance = null;

Expand All @@ -69,11 +72,26 @@ public static synchronized PostGCMemoryUseRecorder get() {

private static final GoogleLogger logger = GoogleLogger.forEnclosingClass();

// Protected by PostGCMemoryUseRecorder's lock.
private Optional<Long> peakPostGCHeapMemoryUsed = Optional.empty();
/** The memory use and time of a build's peak post-GC heap. */
@AutoValue
public abstract static class PeakHeap {

// Protected by PostGcMemoryUseRecorder's lock. Set to true iff a GarbageCollectionNotification
// reported that we were using no memory.
PeakHeap() {}

public abstract long bytes();

public abstract long timestampMillis();

static PeakHeap create(long bytes, long timestampMillis) {
return new AutoValue_PostGCMemoryUseRecorder_PeakHeap(bytes, timestampMillis);
}
}

@GuardedBy("this")
private Optional<PeakHeap> peakHeap = Optional.empty();

// Set to true iff a GarbageCollectionNotification reported that we were using no memory.
@GuardedBy("this")
private boolean memoryUsageReportedZero = false;

@VisibleForTesting
Expand All @@ -88,24 +106,22 @@ public static synchronized PostGCMemoryUseRecorder get() {
}
}

public synchronized Optional<Long> getPeakPostGCHeapMemoryUsed() {
return peakPostGCHeapMemoryUsed;
public synchronized Optional<PeakHeap> getPeakPostGcHeap() {
return peakHeap;
}

public synchronized boolean wasMemoryUsageReportedZero() {
return memoryUsageReportedZero;
}

public synchronized void reset() {
peakPostGCHeapMemoryUsed = Optional.empty();
peakHeap = Optional.empty();
memoryUsageReportedZero = false;
}

private synchronized void updatePostGCHeapMemoryUsed(long used) {
if (peakPostGCHeapMemoryUsed.isPresent()) {
peakPostGCHeapMemoryUsed = Optional.of(Math.max(used, peakPostGCHeapMemoryUsed.get()));
} else {
peakPostGCHeapMemoryUsed = Optional.of(used);
private synchronized void updatePostGCHeapMemoryUsed(long used, long timestampMillis) {
if (!peakHeap.isPresent() || used > peakHeap.get().bytes()) {
peakHeap = Optional.of(PeakHeap.create(used, timestampMillis));
}
}

Expand All @@ -115,10 +131,6 @@ private synchronized void updateMemoryUsageReportedZero(boolean value) {

@Override
public void handleNotification(Notification notification, Object handback) {
doHandleNotification(notification, handback);
}

public void doHandleNotification(Notification notification, Object handback) {
if (!notification
.getType()
.equals(GarbageCollectionNotificationInfo.GARBAGE_COLLECTION_NOTIFICATION)) {
Expand All @@ -127,9 +139,9 @@ public void doHandleNotification(Notification notification, Object handback) {

GarbageCollectionNotificationInfo info =
GarbageCollectionNotificationInfo.from((CompositeData) notification.getUserData());
long durationNs = info.getGcInfo().getDuration() * 1_000_000;
long end = Profiler.nanoTimeMaybe();
if (wasStopTheWorldGc(info)) {
long durationNs = info.getGcInfo().getDuration() * 1_000_000;
long end = Profiler.nanoTimeMaybe();
Profiler.instance()
.logSimpleTask(
end - durationNs,
Expand All @@ -146,7 +158,7 @@ public void doHandleNotification(Notification notification, Object handback) {
for (MemoryUsage mu : mem.values()) {
used += mu.getUsed();
}
updatePostGCHeapMemoryUsed(used);
updatePostGCHeapMemoryUsed(used, notification.getTimeStamp());
if (used > 0) {
logger.atInfo().log("Memory use after full GC: %d", used);
} else {
Expand All @@ -158,7 +170,7 @@ public void doHandleNotification(Notification notification, Object handback) {
}

/** Module to support "blaze info peak-heap-size". */
public static class PostGCMemoryUseRecorderModule extends BlazeModule {
public static final class PostGCMemoryUseRecorderModule extends BlazeModule {
@Override
public void serverInit(OptionsParsingResult startupOptions, ServerBuilder builder) {
builder.addInfoItems(new PeakMemInfoItem());
Expand All @@ -172,28 +184,25 @@ public void beforeCommand(CommandEnvironment env) {
}
}

static class PeakMemInfoItem extends InfoItem {
private static final class PeakMemInfoItem extends InfoItem {
PeakMemInfoItem() {
super(
"peak-heap-size",
"The peak amount of used memory in bytes after any call to System.gc().",
true);
/*hidden=*/ true);
}

@Override
public byte[] get(Supplier<BuildConfiguration> configurationSupplier, CommandEnvironment env) {
if (PostGCMemoryUseRecorder.get().getPeakPostGCHeapMemoryUsed().isPresent()) {
return print(
StringUtilities.prettyPrintBytes(
PostGCMemoryUseRecorder.get().getPeakPostGCHeapMemoryUsed().get()));
} else {
return print("unknown");
}
return PostGCMemoryUseRecorder.get()
.getPeakPostGcHeap()
.map(peak -> print(StringUtilities.prettyPrintBytes(peak.bytes())))
.orElseGet(() -> print("unknown"));
}
}

/** Module to run a full GC after a build is complete on a Blaze server. * */
public static class GcAfterBuildModule extends BlazeModule {
public static final class GcAfterBuildModule extends BlazeModule {

private boolean forceGc = false;

Expand All @@ -211,7 +220,7 @@ public static class Options extends OptionsBase {
}

@Override
public Iterable<Class<? extends OptionsBase>> getCommandOptions(Command command) {
public ImmutableList<Class<? extends OptionsBase>> getCommandOptions(Command command) {
return ImmutableList.of(Options.class);
}

Expand All @@ -228,7 +237,7 @@ public void beforeCommand(CommandEnvironment env) {

@Override
public void afterCommand() {
if (forceGc && !PostGCMemoryUseRecorder.get().getPeakPostGCHeapMemoryUsed().isPresent()) {
if (forceGc && !PostGCMemoryUseRecorder.get().getPeakPostGcHeap().isPresent()) {
System.gc();
}
}
Expand Down
1 change: 1 addition & 0 deletions src/test/java/com/google/devtools/build/lib/metrics/BUILD
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ java_test(
srcs = glob(["*.java"]),
deps = [
"//src/main/java/com/google/devtools/build/lib/metrics:memory-use-recorder",
"//src/test/java/com/google/devtools/build/lib/testutil",
"//third_party:guava",
"//third_party:junit4",
"//third_party:mockito",
Expand Down
Loading

0 comments on commit 7428006

Please sign in to comment.