Add some useful logging of "blaze query" timing.

--
MOS_MIGRATED_REVID=99302436

2 files changed, 19 insertions, 0 deletions

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 27b0838d1a..779ede8210 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.PackageProvider;
 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.LinkedHashSet;
 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 @@ public abstract class AbstractBlazeQueryEnvironment<T> implements QueryEnvironme
   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 abstract class AbstractBlazeQueryEnvironment<T> implements QueryEnvironme
    */
   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 @@ public abstract class AbstractBlazeQueryEnvironment<T> implements QueryEnvironme
       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 cb0f2f69e9..6fd5512ef8 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.Rule;
 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.LinkedHashSet;
 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 @@ public class SkyQueryEnvironment extends AbstractBlazeQueryEnvironment<Target> {
   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 @@ public class SkyQueryEnvironment extends AbstractBlazeQueryEnvironment<Target> {
   }
 
   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.