Add some useful logging of "blaze query" timing.
--
MOS_MIGRATED_REVID=99302436
diff --git a/src/main/java/com/google/devtools/build/lib/query2/AbstractBlazeQueryEnvironment.java b/src/main/java/com/google/devtools/build/lib/query2/AbstractBlazeQueryEnvironment.java
index 27b0838..779ede8 100644
--- a/src/main/java/com/google/devtools/build/lib/query2/AbstractBlazeQueryEnvironment.java
+++ b/src/main/java/com/google/devtools/build/lib/query2/AbstractBlazeQueryEnvironment.java
@@ -29,6 +29,7 @@
import com.google.devtools.build.lib.pkgcache.PathPackageLocator;
import com.google.devtools.build.lib.pkgcache.TargetPatternEvaluator;
import com.google.devtools.build.lib.pkgcache.TransitivePackageLoader;
+import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.query2.engine.QueryEnvironment;
import com.google.devtools.build.lib.query2.engine.QueryEvalResult;
import com.google.devtools.build.lib.query2.engine.QueryException;
@@ -43,6 +44,7 @@
import java.util.List;
import java.util.Map;
import java.util.Set;
+import java.util.logging.Logger;
import javax.annotation.Nullable;
@@ -63,6 +65,8 @@
private final Set<Setting> settings;
private final List<QueryFunction> extraFunctions;
+ private static final Logger LOG = Logger.getLogger(AbstractBlazeQueryEnvironment.class.getName());
+
protected AbstractBlazeQueryEnvironment(boolean keepGoing,
boolean strictScope,
Predicate<Label> labelFilter,
@@ -133,6 +137,7 @@
*/
public QueryEvalResult<T> evaluateQuery(QueryExpression expr)
throws QueryException, InterruptedException {
+ long startTime = Profiler.nanoTimeMaybe();
resolvedTargetPatterns.clear();
// In the --nokeep_going case, errors are reported in the order in which the patterns are
@@ -151,6 +156,11 @@
resultNodes = expr.eval(this);
} catch (QueryException e) {
throw new QueryException(e, expr);
+ } finally {
+ long duration = Profiler.nanoTimeMaybe() - startTime;
+ if (duration > 0) {
+ LOG.info("Spent " + (duration / 1000 / 1000) + " ms evaluating query");
+ }
}
if (eventHandler.hasErrors()) {
diff --git a/src/main/java/com/google/devtools/build/lib/query2/SkyQueryEnvironment.java b/src/main/java/com/google/devtools/build/lib/query2/SkyQueryEnvironment.java
index cb0f2f6..6fd5512 100644
--- a/src/main/java/com/google/devtools/build/lib/query2/SkyQueryEnvironment.java
+++ b/src/main/java/com/google/devtools/build/lib/query2/SkyQueryEnvironment.java
@@ -39,6 +39,7 @@
import com.google.devtools.build.lib.packages.Target;
import com.google.devtools.build.lib.pkgcache.PathPackageLocator;
import com.google.devtools.build.lib.pkgcache.TargetPatternEvaluator;
+import com.google.devtools.build.lib.profiler.Profiler;
import com.google.devtools.build.lib.query2.engine.AllRdepsFunction;
import com.google.devtools.build.lib.query2.engine.QueryEvalResult;
import com.google.devtools.build.lib.query2.engine.QueryException;
@@ -69,6 +70,7 @@
import java.util.List;
import java.util.Map;
import java.util.Set;
+import java.util.logging.Logger;
import javax.annotation.Nullable;
@@ -90,6 +92,8 @@
private final String parserPrefix;
private final PathPackageLocator pkgPath;
+ private static final Logger LOG = Logger.getLogger(SkyQueryEnvironment.class.getName());
+
public SkyQueryEnvironment(boolean keepGoing, boolean strictScope, int loadingPhaseThreads,
Predicate<Label> labelFilter,
EventHandler eventHandler,
@@ -111,10 +115,15 @@
}
private void init() throws InterruptedException {
+ long startTime = Profiler.nanoTimeMaybe();
EvaluationResult<SkyValue> result =
graphFactory.prepareAndGet(universeScope, loadingPhaseThreads, eventHandler);
graph = result.getWalkableGraph();
Collection<SkyValue> values = result.values();
+ long duration = Profiler.nanoTimeMaybe() - startTime;
+ if (duration > 0) {
+ LOG.info("Spent " + (duration / 1000 / 1000) + " ms on evaluation and walkable graph");
+ }
// The universe query may fail if there are errors during its evaluation, e.g. because of
// cycles in the target graph.
