Log number of elements for long NestedSet expansion.
Current logging for NestedSet expansion reports the time spent on getting
elements from all of the sets. Split the time measurements to be done at a
NestedSet level and add elements count to the log.
PiperOrigin-RevId: 296058096
diff --git a/src/main/java/com/google/devtools/build/lib/rules/cpp/CppCompileAction.java b/src/main/java/com/google/devtools/build/lib/rules/cpp/CppCompileAction.java
index 2485bff..75f2681 100644
--- a/src/main/java/com/google/devtools/build/lib/rules/cpp/CppCompileAction.java
+++ b/src/main/java/com/google/devtools/build/lib/rules/cpp/CppCompileAction.java
@@ -15,6 +15,7 @@
import com.google.common.annotations.VisibleForTesting;
import com.google.common.base.Preconditions;
+import com.google.common.base.Stopwatch;
import com.google.common.base.Throwables;
import com.google.common.collect.ImmutableCollection;
import com.google.common.collect.ImmutableList;
@@ -61,7 +62,6 @@
import com.google.devtools.build.lib.collect.nestedset.Order;
import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadCompatible;
import com.google.devtools.build.lib.packages.StarlarkSemanticsOptions;
-import com.google.devtools.build.lib.profiler.AutoProfiler;
import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.profiler.ProfilerTask;
import com.google.devtools.build.lib.profiler.SilentCloseable;
@@ -88,6 +88,7 @@
import java.io.IOException;
import java.io.InputStream;
import java.nio.charset.StandardCharsets;
+import java.time.Duration;
import java.util.ArrayList;
import java.util.Collection;
import java.util.HashSet;
@@ -99,7 +100,6 @@
import java.util.Set;
import java.util.UUID;
import java.util.concurrent.ExecutionException;
-import java.util.concurrent.TimeUnit;
import java.util.logging.Logger;
import javax.annotation.Nullable;
@@ -108,6 +108,7 @@
public class CppCompileAction extends AbstractAction implements IncludeScannable, CommandAction {
private static final Logger logger = Logger.getLogger(CppCompileAction.class.getName());
+ private static final Duration BLOCKED_NESTED_SET_EXPANSION_THRESHOLD = Duration.ofSeconds(5);
private static final PathFragment BUILD_PATH_FRAGMENT = PathFragment.create("BUILD");
private static final boolean VALIDATION_DEBUG_WARN = false;
@@ -588,19 +589,16 @@
// used modules. Combining the NestedSets of transitive deps of the top-level modules also
// gives us an effective way to compute and store discoveredModules.
Set<Artifact> topLevel = new LinkedHashSet<>(usedModules);
- try (AutoProfiler ignored =
- AutoProfiler.logged("nested set expansion", logger, TimeUnit.SECONDS.toMillis(5))) {
- for (NestedSet<? extends Artifact> transitive : transitivelyUsedModules.values()) {
- // It is better to iterate over each nested set here instead of creating a joint one and
- // iterating over it, as this makes use of NestedSet's memoization (each of them has likely
- // been iterated over before). Don't use Set.removeAll() here as that iterates over the
- // smaller set (topLevel, which would support efficient lookup) and looks up in the larger
- // one (transitive, which is a linear scan).
- // We get a collection view of the NestedSet in a way that can throw an InterruptedException
- // because a NestedSet may contain a future.
- for (Artifact module : transitive.toListInterruptibly()) {
- topLevel.remove(module);
- }
+ for (NestedSet<? extends Artifact> transitive : transitivelyUsedModules.values()) {
+ // It is better to iterate over each nested set here instead of creating a joint one and
+ // iterating over it, as this makes use of NestedSet's memoization (each of them has likely
+ // been iterated over before). Don't use Set.removeAll() here as that iterates over the
+ // smaller set (topLevel, which would support efficient lookup) and looks up in the larger one
+ // (transitive, which is a linear scan).
+ // We get a collection view of the NestedSet in a way that can throw an InterruptedException
+ // because a NestedSet may contain a future.
+ for (Artifact module : modulesToListInterruptibly(transitive)) {
+ topLevel.remove(module);
}
}
NestedSetBuilder<Artifact> topLevelModulesBuilder = NestedSetBuilder.stableOrder();
@@ -622,6 +620,20 @@
return additionalInputs;
}
+ private static ImmutableList<? extends Artifact> modulesToListInterruptibly(
+ NestedSet<? extends Artifact> nestedSet) throws InterruptedException {
+ Stopwatch blockedStopwatch = Stopwatch.createStarted();
+ ImmutableList<? extends Artifact> modules = nestedSet.toListInterruptibly();
+ Duration blockedDuration = blockedStopwatch.elapsed();
+ if (BLOCKED_NESTED_SET_EXPANSION_THRESHOLD.compareTo(blockedDuration) < 0) {
+ logger.info(
+ String.format(
+ "Spent %d milliseconds doing nested set expansion, %d elements",
+ blockedDuration.toMillis(), modules.size()));
+ }
+ return modules;
+ }
+
@Override
public Artifact getPrimaryInput() {
return getSourceFile();
