From 7428006dd67cb6bd4e390253cc8ce89065792821 Mon Sep 17 00:00:00 2001 From: jhorvitz Date: Tue, 15 Dec 2020 10:42:06 -0800 Subject: [PATCH] Log the timestamp at which the build's peak post-GC heap occurred. PiperOrigin-RevId: 347645371 --- .../com/google/devtools/build/lib/bazel/BUILD | 1 + .../google/devtools/build/lib/metrics/BUILD | 18 +- .../build/lib/metrics/MetricsCollector.java | 12 +- .../lib/metrics/PostGCMemoryUseRecorder.java | 73 ++++---- .../google/devtools/build/lib/metrics/BUILD | 1 + .../metrics/PostGCMemoryUseRecorderTest.java | 167 ++++++++++-------- 6 files changed, 150 insertions(+), 122 deletions(-) diff --git a/src/main/java/com/google/devtools/build/lib/bazel/BUILD b/src/main/java/com/google/devtools/build/lib/bazel/BUILD index b9aa1584969e22..8145ade1745634 100644 --- a/src/main/java/com/google/devtools/build/lib/bazel/BUILD +++ b/src/main/java/com/google/devtools/build/lib/bazel/BUILD @@ -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", diff --git a/src/main/java/com/google/devtools/build/lib/metrics/BUILD b/src/main/java/com/google/devtools/build/lib/metrics/BUILD index 904e96c0b126f6..bd9ac360354e04 100644 --- a/src/main/java/com/google/devtools/build/lib/metrics/BUILD +++ b/src/main/java/com/google/devtools/build/lib/metrics/BUILD @@ -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", @@ -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", ], ) @@ -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", ], ) diff --git a/src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java b/src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java index 0caf700cf51840..7a0395c79cac36 100644 --- a/src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java +++ b/src/main/java/com/google/devtools/build/lib/metrics/MetricsCollector.java @@ -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 { @@ -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 = @@ -101,10 +101,10 @@ private MemoryMetrics createMemoryMetrics() { MemoryMXBean memBean = ManagementFactory.getMemoryMXBean(); memoryMetrics.setUsedHeapSizePostBuild(memBean.getHeapMemoryUsage().getUsed()); } - Optional peakPostGcHeapSize = PostGCMemoryUseRecorder.get().getPeakPostGCHeapMemoryUsed(); - if (peakPostGcHeapSize.isPresent()) { - memoryMetrics.setPeakPostGcHeapSize(peakPostGcHeapSize.get()); - } + PostGCMemoryUseRecorder.get() + .getPeakPostGcHeap() + .map(PeakHeap::bytes) + .ifPresent(memoryMetrics::setPeakPostGcHeapSize); return memoryMetrics.build(); } diff --git a/src/main/java/com/google/devtools/build/lib/metrics/PostGCMemoryUseRecorder.java b/src/main/java/com/google/devtools/build/lib/metrics/PostGCMemoryUseRecorder.java index 85d2cb25d22551..d1d51a36574a83 100644 --- a/src/main/java/com/google/devtools/build/lib/metrics/PostGCMemoryUseRecorder.java +++ b/src/main/java/com/google/devtools/build/lib/metrics/PostGCMemoryUseRecorder.java @@ -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; @@ -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; @@ -57,6 +59,7 @@ *

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; @@ -69,11 +72,26 @@ public static synchronized PostGCMemoryUseRecorder get() { private static final GoogleLogger logger = GoogleLogger.forEnclosingClass(); - // Protected by PostGCMemoryUseRecorder's lock. - private Optional 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 = Optional.empty(); + + // Set to true iff a GarbageCollectionNotification reported that we were using no memory. + @GuardedBy("this") private boolean memoryUsageReportedZero = false; @VisibleForTesting @@ -88,8 +106,8 @@ public static synchronized PostGCMemoryUseRecorder get() { } } - public synchronized Optional getPeakPostGCHeapMemoryUsed() { - return peakPostGCHeapMemoryUsed; + public synchronized Optional getPeakPostGcHeap() { + return peakHeap; } public synchronized boolean wasMemoryUsageReportedZero() { @@ -97,15 +115,13 @@ public synchronized boolean wasMemoryUsageReportedZero() { } 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)); } } @@ -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)) { @@ -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, @@ -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 { @@ -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()); @@ -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 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; @@ -211,7 +220,7 @@ public static class Options extends OptionsBase { } @Override - public Iterable> getCommandOptions(Command command) { + public ImmutableList> getCommandOptions(Command command) { return ImmutableList.of(Options.class); } @@ -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(); } } diff --git a/src/test/java/com/google/devtools/build/lib/metrics/BUILD b/src/test/java/com/google/devtools/build/lib/metrics/BUILD index b88d4cee1f94f4..fcf1bfafe1ec33 100644 --- a/src/test/java/com/google/devtools/build/lib/metrics/BUILD +++ b/src/test/java/com/google/devtools/build/lib/metrics/BUILD @@ -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", diff --git a/src/test/java/com/google/devtools/build/lib/metrics/PostGCMemoryUseRecorderTest.java b/src/test/java/com/google/devtools/build/lib/metrics/PostGCMemoryUseRecorderTest.java index 7b67cf0263c660..7ccac5c94df06d 100644 --- a/src/test/java/com/google/devtools/build/lib/metrics/PostGCMemoryUseRecorderTest.java +++ b/src/test/java/com/google/devtools/build/lib/metrics/PostGCMemoryUseRecorderTest.java @@ -26,6 +26,8 @@ import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableMap; +import com.google.devtools.build.lib.metrics.PostGCMemoryUseRecorder.PeakHeap; +import com.google.devtools.build.lib.testutil.ManualClock; import com.sun.management.GarbageCollectionNotificationInfo; import com.sun.management.GcInfo; import java.lang.management.GarbageCollectorMXBean; @@ -43,24 +45,9 @@ /** Unit tests for {@link PostGCMemoryUseRecorder}. */ @RunWith(JUnit4.class) -public class PostGCMemoryUseRecorderTest { +public final class PostGCMemoryUseRecorderTest { - private GarbageCollectorMXBean createMXBeanWithName(String name) { - GarbageCollectorMXBean b = - mock( - GarbageCollectorMXBean.class, - withSettings().extraInterfaces(NotificationEmitter.class)); - when(b.getName()).thenReturn(name); - return b; - } - - private List createGCBeans(String[] names) { - List beans = new ArrayList<>(); - for (String n : names) { - beans.add(createMXBeanWithName(n)); - } - return beans; - } + private final ManualClock clock = new ManualClock(); @Test public void listenToSingleNonCopyGC() { @@ -90,50 +77,10 @@ public void dontListenToCopyGC() { any(NotificationListener.class), any(NotificationFilter.class), any()); } - private static MemoryUsage createMockMemoryUsage(long used) { - MemoryUsage mu = mock(MemoryUsage.class); - when(mu.getUsed()).thenReturn(used); - return mu; - } - - private static Notification createMockNotification( - String type, String action, Map memUsed) { - return createMockNotification(type, action, "dummycause", memUsed); - } - - private static Notification createMockNotification( - String type, String action, String cause, Map memUsed) { - ImmutableMap.Builder memUsageMap = ImmutableMap.builder(); - for (Map.Entry e : memUsed.entrySet()) { - memUsageMap.put(e.getKey(), createMockMemoryUsage(e.getValue())); - } - GcInfo gcInfo = mock(GcInfo.class); - when(gcInfo.getMemoryUsageAfterGc()).thenReturn(memUsageMap.build()); - - GarbageCollectionNotificationInfo notInfo = - new GarbageCollectionNotificationInfo("DummyGCName", action, cause, gcInfo); - - Notification n = mock(Notification.class); - when(n.getType()).thenReturn(type); - when(n.getUserData()).thenReturn(notInfo.toCompositeData(null)); - return n; - } - - private static Notification createMajorGCNotification(Map memUsed) { - return createMockNotification( - GarbageCollectionNotificationInfo.GARBAGE_COLLECTION_NOTIFICATION, - "end of major GC", - memUsed); - } - - private static Notification createMajorGCNotification(long used) { - return createMajorGCNotification(ImmutableMap.of("Foo", used)); - } - @Test public void peakHeapStartsAbsent() { PostGCMemoryUseRecorder rec = new PostGCMemoryUseRecorder(new ArrayList<>()); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).isEmpty(); + assertThat(rec.getPeakPostGcHeap()).isEmpty(); } @Test @@ -141,7 +88,7 @@ public void peakHeapAbsentAfterReset() { PostGCMemoryUseRecorder rec = new PostGCMemoryUseRecorder(new ArrayList<>()); rec.handleNotification(createMajorGCNotification(1000L), null); rec.reset(); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).isEmpty(); + assertThat(rec.getPeakPostGcHeap()).isEmpty(); } @Test @@ -154,30 +101,44 @@ public void noGcCauseEventsNotIgnored() { /*cause=*/ "No GC", ImmutableMap.of("somepool", 100L)); - underTest.doHandleNotification(notificationWithNoGcCause, /*handback=*/ null); + underTest.handleNotification(notificationWithNoGcCause, /*handback=*/ null); - assertThat(underTest.getPeakPostGCHeapMemoryUsed()).hasValue(100L); + assertThat(underTest.getPeakPostGcHeap()) + .hasValue(PeakHeap.create(100, clock.currentTimeMillis())); } @Test public void peakHeapIncreasesWhenBigger() { PostGCMemoryUseRecorder rec = new PostGCMemoryUseRecorder(new ArrayList<>()); + + clock.advanceMillis(1); rec.handleNotification(createMajorGCNotification(1000L), null); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).hasValue(1000L); - rec.handleNotification(createMajorGCNotification(1001L), null); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).hasValue(1001L); - rec.handleNotification(createMajorGCNotification(2001L), null); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).hasValue(2001L); + assertThat(rec.getPeakPostGcHeap()).hasValue(PeakHeap.create(1000, clock.currentTimeMillis())); + + clock.advanceMillis(1); + rec.handleNotification(createMajorGCNotification(1001), null); + assertThat(rec.getPeakPostGcHeap()).hasValue(PeakHeap.create(1001, clock.currentTimeMillis())); + + clock.advanceMillis(1); + rec.handleNotification(createMajorGCNotification(2001), null); + assertThat(rec.getPeakPostGcHeap()).hasValue(PeakHeap.create(2001, clock.currentTimeMillis())); } @Test public void peakHeapDoesntDecrease() { PostGCMemoryUseRecorder rec = new PostGCMemoryUseRecorder(new ArrayList<>()); - rec.handleNotification(createMajorGCNotification(1000L), null); - rec.handleNotification(createMajorGCNotification(500L), null); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).hasValue(1000L); - rec.handleNotification(createMajorGCNotification(999L), null); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).hasValue(1000L); + + clock.advanceMillis(1); + rec.handleNotification(createMajorGCNotification(1000), null); + PeakHeap expected = PeakHeap.create(1000, clock.currentTimeMillis()); + + clock.advanceMillis(1); + rec.handleNotification(createMajorGCNotification(500), null); + assertThat(rec.getPeakPostGcHeap()).hasValue(expected); + + clock.advanceMillis(1); + rec.handleNotification(createMajorGCNotification(999), null); + assertThat(rec.getPeakPostGcHeap()).hasValue(expected); } @Test @@ -187,7 +148,7 @@ public void ignoreNonGCNotification() { createMockNotification( "some other notification", "end of major GC", ImmutableMap.of("Foo", 1000L)), null); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).isEmpty(); + assertThat(rec.getPeakPostGcHeap()).isEmpty(); } @Test @@ -199,7 +160,7 @@ public void ignoreNonMajorGCNotification() { "end of minor GC", ImmutableMap.of("Foo", 1000L)), null); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).isEmpty(); + assertThat(rec.getPeakPostGcHeap()).isEmpty(); } @Test @@ -207,7 +168,7 @@ public void sumMemUsageInfo() { PostGCMemoryUseRecorder rec = new PostGCMemoryUseRecorder(new ArrayList<>()); rec.handleNotification( createMajorGCNotification(ImmutableMap.of("Foo", 111L, "Bar", 222L, "Qux", 333L)), null); - assertThat(rec.getPeakPostGCHeapMemoryUsed()).hasValue(666L); + assertThat(rec.getPeakPostGcHeap()).hasValue(PeakHeap.create(666, clock.currentTimeMillis())); } @Test @@ -230,4 +191,62 @@ public void memoryUsageReportedZeroDoesntGetSet() { createMajorGCNotification(ImmutableMap.of("Foo", 123L, "Bar", 456L, "Qux", 789L)), null); assertThat(rec.wasMemoryUsageReportedZero()).isFalse(); } + + private static GarbageCollectorMXBean createMXBeanWithName(String name) { + GarbageCollectorMXBean b = + mock( + GarbageCollectorMXBean.class, + withSettings().extraInterfaces(NotificationEmitter.class)); + when(b.getName()).thenReturn(name); + return b; + } + + private static List createGCBeans(String[] names) { + List beans = new ArrayList<>(); + for (String n : names) { + beans.add(createMXBeanWithName(n)); + } + return beans; + } + + private static MemoryUsage createMockMemoryUsage(long used) { + MemoryUsage mu = mock(MemoryUsage.class); + when(mu.getUsed()).thenReturn(used); + return mu; + } + + private Notification createMockNotification( + String type, String action, Map memUsed) { + return createMockNotification(type, action, "dummycause", memUsed); + } + + private Notification createMockNotification( + String type, String action, String cause, Map memUsed) { + ImmutableMap.Builder memUsageMap = ImmutableMap.builder(); + for (Map.Entry e : memUsed.entrySet()) { + memUsageMap.put(e.getKey(), createMockMemoryUsage(e.getValue())); + } + GcInfo gcInfo = mock(GcInfo.class); + when(gcInfo.getMemoryUsageAfterGc()).thenReturn(memUsageMap.build()); + + GarbageCollectionNotificationInfo notInfo = + new GarbageCollectionNotificationInfo("DummyGCName", action, cause, gcInfo); + + Notification n = mock(Notification.class); + when(n.getType()).thenReturn(type); + when(n.getUserData()).thenReturn(notInfo.toCompositeData(null)); + when(n.getTimeStamp()).thenReturn(clock.currentTimeMillis()); + return n; + } + + private Notification createMajorGCNotification(Map memUsed) { + return createMockNotification( + GarbageCollectionNotificationInfo.GARBAGE_COLLECTION_NOTIFICATION, + "end of major GC", + memUsed); + } + + private Notification createMajorGCNotification(long used) { + return createMajorGCNotification(ImmutableMap.of("Foo", used)); + } }