Add functionality to MemoryProfiler to do multiple garbage collections at the end of the build in an effort to get an accurate measurement of used memory.

PiperOrigin-RevId: 187337487

9 files changed, 221 insertions, 26 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/buildtool/BuildTool.java b/src/main/java/com/google/devtools/build/lib/buildtool/BuildTool.java
index adc6b18113..c793faf1d6 100644
--- a/src/main/java/com/google/devtools/build/lib/buildtool/BuildTool.java
+++ b/src/main/java/com/google/devtools/build/lib/buildtool/BuildTool.java
@@ -300,8 +300,9 @@ public final class BuildTool {
         if (errorMessage != null) {
           throw new BuildFailedException(errorMessage);
         }
-        // Return.
+        // Will return after profiler line below.
       }
+      Profiler.instance().markPhase(ProfilePhase.FINISH);
     } catch (RuntimeException e) {
       // Print an error message for unchecked runtime exceptions. This does not concern Error
       // subclasses such as OutOfMemoryError.
diff --git a/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionTool.java b/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionTool.java
index 2b607d8a56..7adb3b5f93 100644
--- a/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionTool.java
+++ b/src/main/java/com/google/devtools/build/lib/buildtool/ExecutionTool.java
@@ -482,8 +482,6 @@ public class ExecutionTool {
         actionContextProvider.executionPhaseEnding();
       }
 
-      Profiler.instance().markPhase(ProfilePhase.FINISH);
-
       if (buildCompleted) {
         saveActionCache(actionCache);
       }
@@ -518,7 +516,8 @@ public class ExecutionTool {
     }
   }
 
-  private void prepare(PackageRoots packageRoots) throws ExecutorInitException {
+  private void prepare(PackageRoots packageRoots)
+      throws ExecutorInitException, InterruptedException {
     Optional<ImmutableMap<PackageIdentifier, Root>> packageRootMap =
         packageRoots.getPackageRootsMap();
     if (!packageRootMap.isPresent()) {
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/MemoryProfiler.java b/src/main/java/com/google/devtools/build/lib/profiler/MemoryProfiler.java
index 0be0b1c9c6..59e995a3e0 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/MemoryProfiler.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/MemoryProfiler.java
@@ -14,10 +14,18 @@
 
 package com.google.devtools.build.lib.profiler;
 
+import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.Splitter;
+import com.google.devtools.common.options.OptionsParsingException;
 import java.io.OutputStream;
 import java.io.PrintStream;
 import java.lang.management.ManagementFactory;
+import java.lang.management.MemoryMXBean;
 import java.lang.management.MemoryUsage;
+import java.time.Duration;
+import java.util.Iterator;
+import java.util.NoSuchElementException;
+import javax.annotation.Nullable;
 
 /**
  * Blaze memory profiler.
@@ -46,10 +54,18 @@ public final class MemoryProfiler {
 
   private PrintStream memoryProfile;
   private ProfilePhase currentPhase;
+  private long heapUsedMemoryAtFinish;
+  @Nullable private MemoryProfileStableHeapParameters memoryProfileStableHeapParameters;
+
+  public synchronized void setStableMemoryParameters(
+      MemoryProfileStableHeapParameters memoryProfileStableHeapParameters) {
+    this.memoryProfileStableHeapParameters = memoryProfileStableHeapParameters;
+  }
 
   public synchronized void start(OutputStream out) {
     this.memoryProfile = (out == null) ? null : new PrintStream(out);
     this.currentPhase = ProfilePhase.INIT;
+    heapUsedMemoryAtFinish = 0;
   }
 
   public synchronized void stop() {
@@ -57,19 +73,28 @@ public final class MemoryProfiler {
       memoryProfile.close();
       memoryProfile = null;
     }
+    heapUsedMemoryAtFinish = 0;
   }
 
-  public synchronized void markPhase(ProfilePhase nextPhase) {
+  public synchronized long getHeapUsedMemoryAtFinish() {
+    return heapUsedMemoryAtFinish;
+  }
+
+  public synchronized void markPhase(ProfilePhase nextPhase) throws InterruptedException {
     if (memoryProfile != null) {
+      MemoryMXBean bean = ManagementFactory.getMemoryMXBean();
+      prepareBean(nextPhase, bean, (duration) -> Thread.sleep(duration.toMillis()));
       String name = currentPhase.description;
-      ManagementFactory.getMemoryMXBean().gc();
-      MemoryUsage memoryUsage = ManagementFactory.getMemoryMXBean().getHeapMemoryUsage();
+      MemoryUsage memoryUsage = bean.getHeapMemoryUsage();
       memoryProfile.println(name + ":heap:init:" + memoryUsage.getInit());
       memoryProfile.println(name + ":heap:used:" + memoryUsage.getUsed());
       memoryProfile.println(name + ":heap:commited:" + memoryUsage.getCommitted());
       memoryProfile.println(name + ":heap:max:" + memoryUsage.getMax());
+      if (nextPhase == ProfilePhase.FINISH) {
+        heapUsedMemoryAtFinish = memoryUsage.getUsed();
+      }
 
-      memoryUsage = ManagementFactory.getMemoryMXBean().getNonHeapMemoryUsage();
+      memoryUsage = bean.getNonHeapMemoryUsage();
       memoryProfile.println(name + ":non-heap:init:" + memoryUsage.getInit());
       memoryProfile.println(name + ":non-heap:used:" + memoryUsage.getUsed());
       memoryProfile.println(name + ":non-heap:commited:" + memoryUsage.getCommitted());
@@ -77,4 +102,71 @@ public final class MemoryProfiler {
       currentPhase = nextPhase;
     }
   }
+
+  @VisibleForTesting
+  synchronized void prepareBean(ProfilePhase nextPhase, MemoryMXBean bean, Sleeper sleeper)
+      throws InterruptedException {
+    bean.gc();
+    if (nextPhase == ProfilePhase.FINISH && memoryProfileStableHeapParameters != null) {
+      for (int i = 1; i < memoryProfileStableHeapParameters.numTimesToDoGc; i++) {
+        sleeper.sleep(memoryProfileStableHeapParameters.timeToSleepBetweenGcs);
+        bean.gc();
+      }
+    }
+  }
+
+  /**
+   * Parameters that control how {@code MemoryProfiler} tries to get a stable heap at the end of the
+   * build.
+   */
+  public static class MemoryProfileStableHeapParameters {
+    private final int numTimesToDoGc;
+    private final Duration timeToSleepBetweenGcs;
+
+    private MemoryProfileStableHeapParameters(int numTimesToDoGc, Duration timeToSleepBetweenGcs) {
+      this.numTimesToDoGc = numTimesToDoGc;
+      this.timeToSleepBetweenGcs = timeToSleepBetweenGcs;
+    }
+
+    /** Converter for {@code MemoryProfileStableHeapParameters} option. */
+    public static class Converter
+        implements com.google.devtools.common.options.Converter<MemoryProfileStableHeapParameters> {
+      private static final Splitter SPLITTER = Splitter.on(',');
+
+      @Override
+      public MemoryProfileStableHeapParameters convert(String input)
+          throws OptionsParsingException {
+        Iterator<String> values = SPLITTER.split(input).iterator();
+        try {
+          int numTimesToDoGc = Integer.parseInt(values.next());
+          int numSecondsToSleepBetweenGcs = Integer.parseInt(values.next());
+          if (values.hasNext()) {
+            throw new OptionsParsingException("Expected exactly 2 comma-separated integer values");
+          }
+          if (numTimesToDoGc <= 0) {
+            throw new OptionsParsingException("Number of times to GC must be positive");
+          }
+          if (numSecondsToSleepBetweenGcs < 0) {
+            throw new OptionsParsingException(
+                "Number of seconds to sleep between GC's must be positive");
+          }
+          return new MemoryProfileStableHeapParameters(
+              numTimesToDoGc, Duration.ofSeconds(numSecondsToSleepBetweenGcs));
+        } catch (NumberFormatException | NoSuchElementException nfe) {
+          throw new OptionsParsingException(
+              "Expected exactly 2 comma-separated integer values", nfe);
+        }
+      }
+
+      @Override
+      public String getTypeDescription() {
+        return "two integers, separated by a comma";
+      }
+    }
+  }
+
+  @VisibleForTesting
+  interface Sleeper {
+    void sleep(Duration duration) throws InterruptedException;
+  }
 }
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 0b126555d3..d453967041 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
@@ -886,10 +886,8 @@ public final class Profiler {
     }
   }
 
-  /**
-   * Convenience method to log phase marker tasks.
-   */
-  public void markPhase(ProfilePhase phase) {
+  /** Convenience method to log phase marker tasks. */
+  public void markPhase(ProfilePhase phase) throws InterruptedException {
     MemoryProfiler.instance().markPhase(phase);
     if (isActive() && isProfiling(ProfilerTask.PHASE)) {
       Preconditions.checkState(taskStack.isEmpty(), "Phase tasks must not be nested");
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 df1692fdd5..6932d9ea18 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
@@ -407,6 +407,8 @@ public final class BlazeRuntime {
 
     if (options.memoryProfilePath != null) {
       Path memoryProfilePath = env.getWorkingDirectory().getRelative(options.memoryProfilePath);
+      MemoryProfiler.instance()
+          .setStableMemoryParameters(options.memoryProfileStableHeapParameters);
       try {
         MemoryProfiler.instance().start(memoryProfilePath.getOutputStream());
       } catch (IOException e) {
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java b/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java
index 238eb225d6..ea9c7fa057 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java
@@ -15,6 +15,7 @@ package com.google.devtools.build.lib.runtime;
 
 import static com.google.common.base.Strings.isNullOrEmpty;
 
+import com.google.devtools.build.lib.profiler.MemoryProfiler.MemoryProfileStableHeapParameters;
 import com.google.devtools.build.lib.runtime.CommandLineEvent.ToolCommandLineEvent;
 import com.google.devtools.build.lib.util.OptionsUtils;
 import com.google.devtools.build.lib.vfs.PathFragment;
@@ -229,11 +230,26 @@ public class CommonCommandOptions extends OptionsBase {
     documentationCategory = OptionDocumentationCategory.UNDOCUMENTED,
     effectTags = {OptionEffectTag.AFFECTS_OUTPUTS, OptionEffectTag.BAZEL_MONITORING},
     converter = OptionsUtils.PathFragmentConverter.class,
-    help = "If set, write memory usage data to the specified file at phase ends."
+    help =
+        "If set, write memory usage data to the specified file at phase ends and stable heap to"
+            + " master log at end of build."
   )
   public PathFragment memoryProfilePath;
 
   @Option(
+    name = "memory_profile_stable_heap_parameters",
+    defaultValue = "1,0",
+    documentationCategory = OptionDocumentationCategory.LOGGING,
+    effectTags = {OptionEffectTag.BAZEL_MONITORING},
+    converter = MemoryProfileStableHeapParameters.Converter.class,
+    help =
+        "Tune memory profile's computation of stable heap at end of build. Should be two integers "
+            + "separated by a comma. First parameter is the number of GCs to perform. Second "
+            + "parameter is the number of seconds to wait between GCs."
+  )
+  public MemoryProfileStableHeapParameters memoryProfileStableHeapParameters;
+
+  @Option(
     name = "experimental_oom_more_eagerly_threshold",
     defaultValue = "100",
     documentationCategory = OptionDocumentationCategory.EXECUTION_STRATEGY,
@@ -362,4 +378,5 @@ public class CommonCommandOptions extends OptionsBase {
             + "or the bad combination should be checked for programmatically."
   )
   public List<String> deprecationWarnings;
+
 }
diff --git a/src/test/java/com/google/devtools/build/lib/BUILD b/src/test/java/com/google/devtools/build/lib/BUILD
index 9f741f6503..72f1f9fd6c 100644
--- a/src/test/java/com/google/devtools/build/lib/BUILD
+++ b/src/test/java/com/google/devtools/build/lib/BUILD
@@ -977,7 +977,9 @@ java_test(
         "//src/main/java/com/google/devtools/build/lib/profiler",
         "//src/main/java/com/google/devtools/build/lib/profiler:profiler-output",
         "//src/main/java/com/google/devtools/build/lib/vfs",
+        "//third_party:guava",
         "//third_party:jsr305",
+        "//third_party:mockito",
     ],
 )
 
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/MemoryProfilerTest.java b/src/test/java/com/google/devtools/build/lib/profiler/MemoryProfilerTest.java
new file mode 100644
index 0000000000..c00a1336ca
--- /dev/null
+++ b/src/test/java/com/google/devtools/build/lib/profiler/MemoryProfilerTest.java
@@ -0,0 +1,78 @@
+// Copyright 2018 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.truth.Truth.assertThat;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+
+import com.google.common.io.ByteStreams;
+import com.google.devtools.build.lib.profiler.MemoryProfiler.MemoryProfileStableHeapParameters;
+import com.google.devtools.build.lib.profiler.MemoryProfiler.Sleeper;
+import java.lang.management.MemoryMXBean;
+import java.time.Duration;
+import java.util.ArrayList;
+import java.util.List;
+import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.junit.runners.JUnit4;
+import org.mockito.Mockito;
+
+/** Tests for {@link MemoryProfiler}. */
+@RunWith(JUnit4.class)
+public class MemoryProfilerTest {
+  @Test
+  public void profilerDoesOneGcAndNoSleepNormally() throws Exception {
+    MemoryProfiler profiler = MemoryProfiler.instance();
+    profiler.setStableMemoryParameters(
+        new MemoryProfileStableHeapParameters.Converter().convert("1,10"));
+    profiler.start(ByteStreams.nullOutputStream());
+    MemoryMXBean bean = Mockito.mock(MemoryMXBean.class);
+    RecordingSleeper sleeper = new RecordingSleeper();
+    profiler.prepareBean(ProfilePhase.ANALYZE, bean, sleeper);
+    assertThat(sleeper.sleeps).isEmpty();
+    verify(bean, times(1)).gc();
+    profiler.prepareBean(ProfilePhase.FINISH, bean, sleeper);
+    verify(bean, times(2)).gc();
+    assertThat(sleeper.sleeps).isEmpty();
+  }
+
+  @Test
+  public void profilerDoesOneGcAndNoSleepExceptInFinish() throws Exception {
+    MemoryProfiler profiler = MemoryProfiler.instance();
+    profiler.setStableMemoryParameters(
+        new MemoryProfileStableHeapParameters.Converter().convert("3,10"));
+    profiler.start(ByteStreams.nullOutputStream());
+    MemoryMXBean bean = Mockito.mock(MemoryMXBean.class);
+    RecordingSleeper sleeper = new RecordingSleeper();
+    profiler.prepareBean(ProfilePhase.ANALYZE, bean, sleeper);
+    assertThat(sleeper.sleeps).isEmpty();
+    verify(bean, times(1)).gc();
+    profiler.prepareBean(ProfilePhase.FINISH, bean, sleeper);
+    assertThat(sleeper.sleeps)
+        .containsExactly(Duration.ofSeconds(10), Duration.ofSeconds(10))
+        .inOrder();
+    verify(bean, times(4)).gc();
+  }
+
+  private static class RecordingSleeper implements Sleeper {
+    private final List<Duration> sleeps = new ArrayList<>();
+
+    @Override
+    public void sleep(Duration duration) {
+      sleeps.add(duration);
+    }
+  }
+}
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 2f988dd96a..ffc7e7f31a 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
@@ -308,19 +308,25 @@ public class ProfilerTest extends FoundationTestCase {
     thread1.join();
     clock.advanceMillis(1);
     profiler.markPhase(ProfilePhase.ANALYZE);
-    Thread thread2 = new Thread() {
-      @Override public void run() {
-        profiler.startTask(ProfilerTask.TEST, "complex task");
-        for (int i = 0; i < 100; i++) {
-          Profiler.instance().logEvent(ProfilerTask.TEST, "thread2a");
-        }
-        profiler.completeTask(ProfilerTask.TEST);
-        profiler.markPhase(ProfilePhase.EXECUTE);
-        for (int i = 0; i < 100; i++) {
-          Profiler.instance().logEvent(ProfilerTask.TEST, "thread2b");
-        }
-      }
-    };
+    Thread thread2 =
+        new Thread() {
+          @Override
+          public void run() {
+            profiler.startTask(ProfilerTask.TEST, "complex task");
+            for (int i = 0; i < 100; i++) {
+              Profiler.instance().logEvent(ProfilerTask.TEST, "thread2a");
+            }
+            profiler.completeTask(ProfilerTask.TEST);
+            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");
+            }
+          }
+        };
     thread2.start();
     thread2.join();
     profiler.logEvent(ProfilerTask.TEST, "last task");